Subject: Re: bug#47419: 27.1; Misleading profiler info

From: Stefan Monnier <[email-masked]>
Date: Fri, 26 Mar 2021 21:55:05 -0400

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