GNU bug report logs -
#47419
Misleading profiler info
Previous Next
To reply to this bug, email your comments to 47419 AT debbugs.gnu.org.
Toggle the display of automated, internal messages from the tracker.
Report forwarded
to
bug-gnu-emacs <at> gnu.org:
bug#47419; Package
emacs.
(Fri, 26 Mar 2021 19:58:02 GMT)
Full text and
rfc822 format available.
Acknowledgement sent
to
scame <laszlomail <at> protonmail.com>:
New bug report received and forwarded. Copy sent to
bug-gnu-emacs <at> gnu.org.
(Fri, 26 Mar 2021 19:58:02 GMT)
Full text and
rfc822 format available.
Message #5 received at submit <at> debbugs.gnu.org (full text, mbox):
[Message part 1 (text/plain, inline)]
As discussed on emacs-help I'm posting this example here which
reorders the file and runs slowly.
Though it's an sql dump file with long lines, the file is navigable without
any problem or slowness. Only this snippet runs slowly.
Here's the snippet:
(progn
(goto-char (point-min))
(when (search-forward "INSERT INTO `test2` (`aa`, `bb`) VALUES" nil t)
(beginning-of-line)
(while (looking-at "INSERT INTO `test2`.+,\\([0-9]+\\));")
(let ((item (match-string 1))
(line (buffer-substring (line-beginning-position) (line-end-position))))
(message item)
(save-excursion
(re-search-backward (concat "INSERT INTO `test1`.+"
"VALUES ("
item
","))
(end-of-line)
(insert "\n" line))
(delete-region (line-beginning-position) (1+ (line-end-position)))
))))
And the example file to run it on is attached. (anonymized sql dump)
[dump.zip (application/x-zip-compressed, attachment)]
Information forwarded
to
bug-gnu-emacs <at> gnu.org:
bug#47419; Package
emacs.
(Sat, 27 Mar 2021 01:56:01 GMT)
Full text and
rfc822 format available.
Message #8 received at 47419 <at> debbugs.gnu.org (full text, mbox):
retitle 47419 Misleading profiler info
thanks
> As discussed on emacs-help I'm posting this example here which
> reorders the file and runs slowly.
[ Right, but the issue was with the profiler info. ]
> Though it's an sql dump file with long lines, the file is navigable without
> any problem or slowness. Only this snippet runs slowly.
I think I can explain to you why it's going slow:
> (re-search-backward (concat "INSERT INTO `test1`.+"
> "VALUES ("
> item
> ","))
The ".+" will first match the whole long rest of the line, after which
the regexp matcher will try to match "VALUES (item,", which will fail,
so the matcher will go back trying with .+ matching one char less, and
try to match "VALUES (item," again, etc for every char on the long line.
You can speed it up significantly by tightening the regexp,
e.g. replacing .+ with [\s\t]+. It's still not superfast because our
regexp engine is not tuned for that kind of situation, but it's better.
> And the example file to run it on is attached. (anonymized sql dump)
And the real problem (the one for which I wanted the bug report) is that
the profiler indeed gives a bogus profile (see below) where
`re-search-backwards` doesn't appear at all and all the time is
attributed to `save-excursion` instead.
-- Stefan
16896 99% - command-execute
16896 99% - call-interactively
16844 99% - funcall-interactively
16812 99% - ielm-return
16812 99% - ielm-send-input
16810 99% - ielm-eval-input
16810 99% - eval
16810 99% - progn
16810 99% - when
16810 99% - if
16808 99% - progn
16808 99% - while
16808 99% - let
16784 99% save-excursion
2 0% - comint-send-input
2 0% - run-hook-with-args
1 0% - ansi-color-process-output
1 0% ansi-color-apply-on-region
1 0% comint-postoutput-scroll-to-bottom
26 0% - minibuffer-complete
26 0% - completion-in-region
26 0% - completion--in-region
26 0% - #<compiled -0xd2d77d7>
26 0% - apply
26 0% - #<compiled -0x124ef90>
26 0% - completion--in-region-1
26 0% - completion--do-completion
16 0% - completion-try-completion
16 0% - completion--nth-completion
16 0% - completion--some
16 0% - #<compiled 0x6a1b8f8>
8 0% - completion-basic-try-completion
8 0% - try-completion
8 0% - #<compiled 0x5d9a79d>
8 0% complete-with-action
8 0% - completion-pcm-try-completion
8 0% - completion-pcm--find-all-completions
8 0% - completion-pcm--all-completions
8 0% - all-completions
8 0% - #<compiled 0x5d9a79d>
8 0% complete-with-action
10 0% - minibuffer-completion-help
6 0% - completion-all-completions
6 0% - completion--nth-completion
6 0% - completion--some
6 0% - #<compiled 0xfa1b8f8>
3 0% - completion-basic-all-completions
3 0% - completion-pcm--all-completions
3 0% - all-completions
3 0% - #<compiled 0x5d9a79d>
3 0% complete-with-action
3 0% - completion-pcm-all-completions
3 0% - completion-pcm--find-all-completions
3 0% - completion-pcm--all-completions
3 0% - all-completions
3 0% - #<compiled 0x5d9a79d>
3 0% complete-with-action
4 0% - temp-buffer-window-show
4 0% - display-buffer
2 0% - display-buffer-at-bottom
1 0% - walk-window-tree
1 0% - walk-window-tree-1
1 0% - walk-window-tree-1
1 0% - #<compiled 0x1d0989cf>
1 0% window-in-direction
1 0% - window-main-window
1 0% - walk-window-tree
1 0% walk-window-tree-1
2 0% - display-buffer-reuse-window
1 0% - window--display-buffer
1 0% - #<compiled -0x11648b70>
1 0% - display-completion-list
1 0% - run-hooks
1 0% - completion-setup-function
1 0% substitute-command-keys
1 0% window--maybe-raise-frame
6 0% - execute-extended-command
4 0% - sit-for
4 0% - redisplay
1 0% - redisplay_internal (C function)
1 0% - funcall
1 0% - #<compiled 0xadd045f>
1 0% - gui-backend-selection-exists-p
1 0% - apply
1 0% #<compiled 0xb23922>
1 0% - command-execute
1 0% - call-interactively
1 0% - funcall-interactively
1 0% profiler-report
52 0% - byte-code
52 0% - read-extended-command
52 0% - completing-read
52 0% - completing-read-default
34 0% - read-from-minibuffer
1 0% - timer-event-handler
1 0% - apply
1 0% #<compiled -0x14c1276f>
1 0% - redisplay_internal (C function)
1 0% - eval
1 0% if
50 0% - ...
50 0% Automatic GC
3 0% - timer-event-handler
3 0% - apply
2 0% - #<compiled -0xabec6a9>
1 0% - comint-output-filter
1 0% - run-hook-with-args
1 0% comint-postoutput-scroll-to-bottom
1 0% redisplay
1 0% - blink-cursor-start
1 0% add-hook
Changed bug title to 'Misleading profiler info' from '27.1; slow running of snippet which reorders the file'
Request was from
Stefan Monnier <monnier <at> iro.umontreal.ca>
to
control <at> debbugs.gnu.org.
(Sat, 27 Mar 2021 01:56:02 GMT)
Full text and
rfc822 format available.
Information forwarded
to
bug-gnu-emacs <at> gnu.org:
bug#47419; Package
emacs.
(Sat, 27 Mar 2021 04:14:02 GMT)
Full text and
rfc822 format available.
Message #13 received at 47419 <at> debbugs.gnu.org (full text, mbox):
>
> You can speed it up significantly by tightening the regexp,
> e.g. replacing .+ with [\s\t]+. It's still not superfast because our
> regexp engine is not tuned for that kind of situation, but it's better.
Right, thanks. I would have tried tightening the regexp if the profiler had
told me that was the problem, but as you write it incorrectly attributed
the slowness to the save-exursion call which put me on the wrong track
thinking it was some internal emacs bug.
This bug report was last modified 4 years and 177 days ago.
Previous Next
GNU bug tracking system
Copyright (C) 1999 Darren O. Benham,
1997,2003 nCipher Corporation Ltd,
1994-97 Ian Jackson.