bug#14786: 24.3.50; `field-end' is now very slow

bug#14786: 24.3.50; `field-end' is now very slow

[Drew Adams]

I'm not very good at measuring processing time.  If you need more info
about that then someone will need to remind me what functions to use for
measuring.

Here's what I see:

I put the cursor on, say, the first file or dir name in a large Dired
buffer (1860 lines).  I do `M-: (field-end nil)'.

In Emacs 22, 23, and even 24.3, the result appears immediately - no
perceptible delay.  In recent Emacs 24 (e.g., this build), the result
appears after several seconds - 3 to 4 sec.

This is a really noticeable difference.  It makes certain interactive
interactions nearly unusable.  Can something be done about this, or
is it perhaps an inevitable consequence of some feature that has been
added recently?

In GNU Emacs 24.3.50.1 (i686-pc-mingw32)
 of 2013-07-01 on LEG570
Bzr revision: 113246 lekktu@gmail.com-20130701165437-ea20s94hqwp3ttaj
Windowing system distributor `Microsoft Corp.', version 6.1.7601
Configured using:
 `configure --prefix=/c/usr --enable-checking CFLAGS='-O0 -g3'
 CPPFLAGS='-DGLYPH_DEBUG=1 -I/c/usr/include''

bug#14786: 24.3.50; `field-end' is now very slow

[Eli Zaretskii]

> Date: Wed, 3 Jul 2013 22:34:31 -0700 (PDT)
> From: Drew Adams <drew.adams@oracle.com>
> 
> I'm not very good at measuring processing time.  If you need more info
> about that then someone will need to remind me what functions to use for
> measuring.

profiler-start and profiler-report.

> I put the cursor on, say, the first file or dir name in a large Dired
> buffer (1860 lines).  I do `M-: (field-end nil)'.
> 
> In Emacs 22, 23, and even 24.3, the result appears immediately - no
> perceptible delay.  In recent Emacs 24 (e.g., this build), the result
> appears after several seconds - 3 to 4 sec.

I cannot reproduce this with yesterday's trunk.  Does this happen for
you in "emacs -Q"?

bug#14786: 24.3.50; `field-end' is now very slow

[Drew Adams]

[-- Attachment #1: Type: text/plain, Size: 11326 bytes --]

> > I put the cursor on, say, the first file or dir name in a large Dired
> > buffer (1860 lines).  I do `M-: (field-end nil)'.
> >
> > In Emacs 22, 23, and even 24.3, the result appears immediately - no
> > perceptible delay.  In recent Emacs 24 (e.g., this build), the result
> > appears after several seconds - 3 to 4 sec.
> 
> I cannot reproduce this with yesterday's trunk.  Does this happen for
> you in "emacs -Q"?

Sorry, the description was incomplete.

1. emacs -Q

2. Load library dired-details.el, from Emacs Wiki:
http://www.emacswiki.org/emacs/download/dired-details.el

3. C-x d ; in some directory that has lots of files

4.  M-x dired-details-toggle

5. M-x dired-details-toggle ; (optional, so you see all info)

6. Position the cursor on a file or dir name near the beginning of
the list.

7. M-: (field-end nil)

The result appears after a few seconds (I'm guessing about 4 sec
in the directory I used).

Do the same thing in previous Emacs versions (including as recent
as 24.3, at least), and the result appears immediately.

I tried `M-x profiler-start', then `M-: (field-end nil)', then
`M-x profiler-report', then `M-x profiler-stop'.  Then I wrote each
buffer to a file using C-x C-w.  The files are attached.

This is what I saw in *Memory-Profiler-Report...*:

- command-execute                                          42,437,777   0%
  - call-interactively                                     42,437,777   0%
    - byte-code                                            39,515,026  -4%
      - read-extended-command                              19,764,987  -2%
        - completing-read                                  19,764,987  -2%
          - completing-read-default                        19,764,987  -2%
            - read-from-minibuffer                         19,764,586  -2%
              - redisplay_internal (C function)            19,740,876  -2%
                - find-image                               19,740,876  -2%
                  - image-search-load-path                 19,740,876  -2%
                      image-search-load-path               18,166,368  -3%
              - command-execute                                 1,208   0%
                - call-interactively                               40   0%
                  - minibuffer-complete-and-exit                   40   0%
                      minibuffer--complete-and-exit                40   0%
      - read--expression                                   19,750,039  -2%
        - read-from-minibuffer                             19,749,638  -2%
          - redisplay_internal (C function)                19,723,328  -2%
            - find-image                                   19,723,328  -2%
              - image-search-load-path                     19,723,328  -2%
                  image-search-load-path                   18,148,820  -3%
          - command-execute                                       808   0%
            - call-interactively                                  680   0%
              - self-insert-command                               680   0%
                - blink-paren-post-self-insert-function           680   0%
                  - blink-matching-open                           680   0%
                    - sit-for                                     480   0%
                        redisplay                                 320   0%
                        read-event                                160   0%
    - execute-extended-command                              2,025,794   2%
      - command-execute                                     1,980,502   2%
        - call-interactively                                1,980,494   2%
          - profiler-report                                 1,979,210   2%
            - profiler-report-cpu                           1,076,878   1%
              - profiler-cpu-profile                          944,730   1%
                  profiler-make-profile                         1,198   0%
              - profiler-report-profile-other-window          132,148   0%
                - profiler-report-setup-buffer                132,148   0%
                  - profiler-report-setup-buffer-1            131,636   0%
                      profiler-report-make-buffer-name        131,104   0%
                  - profiler-report-render-calltree               512   0%
                    - profiler-report-rerender-calltree           512   0%
                      - profiler-report-render-calltree           512   0%
                        - profiler-report-header-line-f           512   0%
                            replace-regexp-in-string              512   0%
            - profiler-report-memory                          902,332   1%
                profiler-memory-profile                       902,332   1%
          - profiler-start                                      1,284   0%
              message                                           1,284   0%
    - eval-expression                                         745,480   0%
        eval                                                  745,480   0%
    - profiler-report                                         151,477   0%
      - profiler-report-cpu                                   151,477   0%
        - profiler-report-profile-other-window                151,477   0%
          - switch-to-buffer-other-window                     143,289   0%
            - pop-to-buffer                                   143,289   0%
              - display-buffer                                143,289   0%
                - display-buffer--maybe-pop-up-frame-or       143,289   0%
                  - display-buffer-pop-up-window              143,289   0%
                    - window--try-to-split-window             143,289   0%
                      - funcall                               143,289   0%
                        - split-window-sensibly               143,289   0%
                          - split-window-below                143,289   0%
                            - split-window                    143,289   0%
                                byte-code                     143,289   0%
          - profiler-report-setup-buffer                        8,188   0%
            - profiler-report-render-calltree                   8,188   0%
              - profiler-report-rerender-calltree               8,188   0%
                - profiler-report-render-calltree-1             8,188   0%
                  - profiler-calltree-build                     8,188   0%
                    - profiler-calltree-compute-percent         8,188   0%
                      - profiler-calltree-walk                  8,188   0%
                        - profiler-calltree-walk                8,188   0%
                          - profiler-calltree-walk              8,188   0%
                            - profiler-calltree-walk            8,188   0%
                                #<compiled 0xd6dff9>            8,188   0%
- redisplay_internal (C function)                          40,759,238  -2%
  - find-image                                             39,446,656  -4%
    - image-search-load-path                               39,446,656  -4%
        image-search-load-path                             36,297,640   4%
  - tool-bar-make-keymap                                    1,312,070   1%
    - tool-bar-make-keymap-1                                1,312,070   1%
      - mapcar                                              1,312,070   1%
        - #<compiled 0x4cb765>                              1,312,070   1%
          - eval                                            1,312,070   1%
            - find-image                                    1,312,070   1%
                image-search-load-path                      1,312,070   1%
  - kill-this-buffer-enabled-p                                    512   0%
      byte-code                                                   512   0%

And this in *CPU-Profiler-Report..*:

- command-execute                                                 215  98%
  - call-interactively                                            215  98%
    - eval-expression                                             204  93%
        eval                                                      204  93%
    - byte-code                                                    10   4%
      - read--expression                                            5   2%
        - read-from-minibuffer                                      4   1%
          - redisplay_internal (C function)                         2   0%
            - find-image                                            2   0%
              - image-search-load-path                              2   0%
                  image-search-load-path                            2   0%
          - command-execute                                         1   0%
            - call-interactively                                    1   0%
              - self-insert-command                                 1   0%
                - blink-paren-post-self-insert-fun                  1   0%
                  - blink-matching-open                             1   0%
                      sit-for                                       1   0%
      - read-extended-command                                       5   2%
        - completing-read                                           5   2%
          - completing-read-default                                 5   2%
            - read-from-minibuffer                                  4   1%
              - redisplay_internal (C function)                     2   0%
                - find-image                                        2   0%
                  - image-search-load-path                          2   0%
                      image-search-load-path                        2   0%
    - execute-extended-command                                      1   0%
      - command-execute                                             1   0%
        - call-interactively                                        1   0%
          - profiler-report                                         1   0%
            - profiler-report-cpu                                   1   0%
                profiler-cpu-profile                                1   0%
  Automatic GC                                                      2   0%
- redisplay_internal (C function)                                   1   0%
  - find-image                                                      1   0%
    - image-search-load-path                                        1   0%
        image-search-load-path                                      1   0%

HTH.



BTW -

1. Is there an easier way to open everything up like that?  All I could
find was to hit TAB or RET or i on each line.  PITA.

2. Seems like the mode line info should also (or instead) appear in the
buffer as a title, so it gets picked up by C-x h.

3. The numeric columns should have headers.  No idea what the numbers
mean - what units for the first column, percentage of what (what
compared to what) for the second column.

[-- Attachment #2: throw-prof-cpu.txt --]
[-- Type: text/plain, Size: 1912 bytes --]


[profiler-profile "24.3" cpu #s(hash-table size 65 test equal rehash-size 1.5 rehash-threshold 0.8 data ([nil nil nil nil nil nil nil nil nil nil nil nil nil nil nil nil] 5 [image-search-load-path image-search-load-path find-image redisplay_internal\ \(C\ function\) read-from-minibuffer read--expression byte-code call-interactively command-execute nil nil nil nil nil nil nil] 2 [read-from-minibuffer read--expression byte-code call-interactively command-execute nil nil nil nil nil nil nil nil nil nil nil] 1 [read--expression byte-code call-interactively command-execute nil nil nil nil nil nil nil nil nil nil nil nil] 1 [sit-for blink-matching-open blink-paren-post-self-insert-function self-insert-command call-interactively command-execute read-from-minibuffer read--expression byte-code call-interactively command-execute nil nil nil nil nil] 1 [eval eval-expression call-interactively command-execute nil nil nil nil nil nil nil nil nil nil nil nil] 204 [image-search-load-path image-search-load-path find-image redisplay_internal\ \(C\ function\) nil nil nil nil nil nil nil nil nil nil nil nil] 1 [image-search-load-path image-search-load-path find-image redisplay_internal\ \(C\ function\) read-from-minibuffer completing-read-default completing-read read-extended-command byte-code call-interactively command-execute nil nil nil nil nil] 2 [read-from-minibuffer completing-read-default completing-read read-extended-command byte-code call-interactively command-execute nil nil nil nil nil nil nil nil nil] 2 [completing-read-default completing-read read-extended-command byte-code call-interactively command-execute nil nil nil nil nil nil nil nil nil nil] 1 [profiler-cpu-profile profiler-report-cpu profiler-report call-interactively command-execute execute-extended-command call-interactively command-execute nil nil nil nil nil nil nil nil] 1 [Automatic\ GC] 2)) (20949 57121 639000 0) nil]

[-- Attachment #3: throw-prof-mem.txt --]
[-- Type: text/plain, Size: 6530 bytes --]


[profiler-profile "24.3" memory #s(hash-table size 65 test equal rehash-size 1.5 rehash-threshold 0.8 data ([message profiler-start call-interactively command-execute execute-extended-command call-interactively command-execute nil nil nil nil nil nil nil nil nil] 1284 [profiler-start call-interactively command-execute execute-extended-command call-interactively command-execute nil nil nil nil nil nil nil nil nil nil] 0 [image-search-load-path find-image eval "#<compiled 0x4cb765>" mapcar tool-bar-make-keymap-1 tool-bar-make-keymap redisplay_internal\ \(C\ function\) nil nil nil nil nil nil nil nil] 1312070 [nil nil nil nil nil nil nil nil nil nil nil nil nil nil nil nil] 36564 [byte-code kill-this-buffer-enabled-p redisplay_internal\ \(C\ function\) nil nil nil nil nil nil nil nil nil nil nil nil nil] 512 [image-search-load-path find-image redisplay_internal\ \(C\ function\) nil nil nil nil nil nil nil nil nil nil nil nil nil] 3149016 [image-search-load-path image-search-load-path find-image redisplay_internal\ \(C\ function\) nil nil nil nil nil nil nil nil nil nil nil nil] 36297640 [read--expression byte-code call-interactively command-execute nil nil nil nil nil nil nil nil nil nil nil nil] 401 [read-from-minibuffer read--expression byte-code call-interactively command-execute nil nil nil nil nil nil nil nil nil nil nil] 25502 [image-search-load-path find-image redisplay_internal\ \(C\ function\) read-from-minibuffer read--expression byte-code call-interactively command-execute nil nil nil nil nil nil nil nil] 1574508 [image-search-load-path image-search-load-path find-image redisplay_internal\ \(C\ function\) read-from-minibuffer read--expression byte-code call-interactively command-execute nil nil nil nil nil nil nil] 18148820 [command-execute read-from-minibuffer read--expression byte-code call-interactively command-execute nil nil nil nil nil nil nil nil nil nil] 128 [blink-matching-open blink-paren-post-self-insert-function self-insert-command call-interactively command-execute read-from-minibuffer read--expression byte-code call-interactively command-execute nil nil nil nil nil nil] 200 [redisplay sit-for blink-matching-open blink-paren-post-self-insert-function self-insert-command call-interactively command-execute read-from-minibuffer read--expression byte-code call-interactively command-execute nil nil nil nil] 320 [read-event sit-for blink-matching-open blink-paren-post-self-insert-function self-insert-command call-interactively command-execute read-from-minibuffer read--expression byte-code call-interactively command-execute nil nil nil nil] 160 [eval eval-expression call-interactively command-execute nil nil nil nil nil nil nil nil nil nil nil nil] 745480 [completing-read-default completing-read read-extended-command byte-code call-interactively command-execute nil nil nil nil nil nil nil nil nil nil] 401 [read-from-minibuffer completing-read-default completing-read read-extended-command byte-code call-interactively command-execute nil nil nil nil nil nil nil nil nil] 22502 [image-search-load-path find-image redisplay_internal\ \(C\ function\) read-from-minibuffer completing-read-default completing-read read-extended-command byte-code call-interactively command-execute nil nil nil nil nil nil] 1574508 [image-search-load-path image-search-load-path find-image redisplay_internal\ \(C\ function\) read-from-minibuffer completing-read-default completing-read read-extended-command byte-code call-interactively command-execute nil nil nil nil nil] 18166368 [command-execute read-from-minibuffer completing-read-default completing-read read-extended-command byte-code call-interactively command-execute nil nil nil nil nil nil nil nil] 1168 [minibuffer--complete-and-exit minibuffer-complete-and-exit call-interactively command-execute read-from-minibuffer completing-read-default completing-read read-extended-command byte-code call-interactively command-execute nil nil nil nil nil] 40 [execute-extended-command call-interactively command-execute nil nil nil nil nil nil nil nil nil nil nil nil nil] 45292 [command-execute execute-extended-command call-interactively command-execute nil nil nil nil nil nil nil nil nil nil nil nil] 8 [profiler-cpu-profile profiler-report-cpu profiler-report call-interactively command-execute execute-extended-command call-interactively command-execute nil nil nil nil nil nil nil nil] 943532 [profiler-make-profile profiler-cpu-profile profiler-report-cpu profiler-report call-interactively command-execute execute-extended-command call-interactively command-execute nil nil nil nil nil nil nil] 1198 [profiler-report-make-buffer-name profiler-report-setup-buffer-1 profiler-report-setup-buffer profiler-report-profile-other-window profiler-report-cpu profiler-report call-interactively command-execute execute-extended-command call-interactively command-execute nil nil nil nil nil] 131104 [profiler-report-setup-buffer-1 profiler-report-setup-buffer profiler-report-profile-other-window profiler-report-cpu profiler-report call-interactively command-execute execute-extended-command call-interactively command-execute nil nil nil nil nil nil] 532 ["#<compiled 0xd6dff9>" profiler-calltree-walk profiler-calltree-walk profiler-calltree-walk profiler-calltree-walk profiler-calltree-compute-percentages profiler-calltree-build profiler-report-render-calltree-1 profiler-report-rerender-calltree profiler-report-render-calltree profiler-report-setup-buffer profiler-report-profile-other-window profiler-report-cpu profiler-report call-interactively command-execute] 8188 [replace-regexp-in-string profiler-report-header-line-format profiler-report-render-calltree-1 profiler-report-rerender-calltree profiler-report-render-calltree profiler-report-setup-buffer profiler-report-profile-other-window profiler-report-cpu profiler-report call-interactively command-execute execute-extended-command call-interactively command-execute nil nil] 512 [byte-code split-window split-window-below split-window-sensibly funcall window--try-to-split-window display-buffer-pop-up-window display-buffer--maybe-pop-up-frame-or-window display-buffer pop-to-buffer switch-to-buffer-other-window profiler-report-profile-other-window profiler-report-cpu profiler-report call-interactively command-execute] 143289 [profiler-memory-profile profiler-report-memory profiler-report call-interactively command-execute execute-extended-command call-interactively command-execute nil nil nil nil nil nil nil nil] 902332)) (20949 57121 697000 0) nil]

bug#14786: 24.3.50; `field-end' is now very slow

[Eli Zaretskii]

> Date: Thu, 4 Jul 2013 13:57:52 -0700 (PDT)
> From: Drew Adams <drew.adams@oracle.com>
> Cc: 14786@debbugs.gnu.org
> 
> 1. emacs -Q
> 
> 2. Load library dired-details.el, from Emacs Wiki:
> http://www.emacswiki.org/emacs/download/dired-details.el
> 
> 3. C-x d ; in some directory that has lots of files
> 
> 4.  M-x dired-details-toggle
> 
> 5. M-x dired-details-toggle ; (optional, so you see all info)
> 
> 6. Position the cursor on a file or dir name near the beginning of
> the list.
> 
> 7. M-: (field-end nil)
> 
> The result appears after a few seconds (I'm guessing about 4 sec
> in the directory I used).
> 
> Do the same thing in previous Emacs versions (including as recent
> as 24.3, at least), and the result appears immediately.

Not exactly immediately, but approximately 4 to 5 times faster.

The problem is that dired-details floods the Dired buffer with
overlays.  When there are so many overlays, searching for an end of a
non-existent property takes a lot of time, because Emacs needs to
examine every overlay in the buffer.

What happened between Emacs 24.3 and the current trunk is that the
call

    GET_OVERLAYS_AT (XINT (position), overlay_vec, noverlays, NULL, 0);

in get_char_property_and_overlay got roughly 4 to 5 times slower.  I
don't know why this slowdown happened, but it just moved the time
needed by field-end from below the annoyance threshold to well above
it.

If someone can find out why GET_OVERLAYS_AT is now slower, we could
see if that could be fixed.  But it's quite possible that the change
which caused that fixed some bug that we don't want to re-introduce.
In any case, I think having so many overlays in a buffer is asking for
trouble.

bug#14786: 24.3.50; `field-end' is now very slow

[Drew Adams]

> > The result appears after a few seconds (I'm guessing about 4 sec
> > in the directory I used).
> >
> > Do the same thing in previous Emacs versions (including as recent
> > as 24.3, at least), and the result appears immediately.
> 
> Not exactly immediately, but approximately 4 to 5 times faster.

OK.  I was describing the user experience.  Less than a second is
quick enough for a large Dired buffer.  Four seconds it not.

> The problem is that dired-details floods the Dired buffer with
> overlays.  When there are so many overlays, searching for an end of
> a non-existent property takes a lot of time, because Emacs needs to
> examine every overlay in the buffer.

OK.

> What happened between Emacs 24.3 and the current trunk is that the
> call GET_OVERLAYS_AT (XINT (position), overlay_vec, noverlays, NULL, 0);
> in get_char_property_and_overlay got roughly 4 to 5 times slower.  I
> don't know why this slowdown happened, but it just moved the time
> needed by field-end from below the annoyance threshold to well above
> it.

I agree with your characterization in the last phrase.

> If someone can find out why GET_OVERLAYS_AT is now slower, we could
> see if that could be fixed.  But it's quite possible that the change
> which caused that fixed some bug that we don't want to re-introduce.
> In any case, I think having so many overlays in a buffer is asking for
> trouble.

Agreed, in general.  Emacs does make heavy use of overlays here and
there, and I don't see that possibility disappearing.  I hope this bug
(performance regression) can be fixed.  It is not particular to
dired-details.el, though that is one place that it can easily be
noticed.

For my info: When such a code change is made, is there no log of the
reason behind the change?  If it was to fix a bug, for instance,
wouldn't that bug # be noted?

bug#14786: 24.3.50; `field-end' is now very slow

[Eli Zaretskii]

> Date: Fri, 5 Jul 2013 10:06:41 -0700 (PDT)
> From: Drew Adams <drew.adams@oracle.com>
> Cc: 14786@debbugs.gnu.org
> 
> For my info: When such a code change is made, is there no log of the
> reason behind the change?

Every change comes with a change log.  The reason is not always stated
in the change log, it can sometimes be in the comments to the changed
code or in some discussion that led to the change (preferably cited in
the change log).

> If it was to fix a bug, for instance, wouldn't that bug # be noted?

Yes, definitely.

bug#14786: 24.3.50; `field-end' is now very slow

[Lars Ingebrigtsen]

Drew Adams <drew.adams@oracle.com> writes:

>> > I put the cursor on, say, the first file or dir name in a large Dired
>> > buffer (1860 lines).  I do `M-: (field-end nil)'.
>> >
>> > In Emacs 22, 23, and even 24.3, the result appears immediately - no
>> > perceptible delay.  In recent Emacs 24 (e.g., this build), the result
>> > appears after several seconds - 3 to 4 sec.
>> 
>> I cannot reproduce this with yesterday's trunk.  Does this happen for
>> you in "emacs -Q"?
>
> Sorry, the description was incomplete.
>
> 1. emacs -Q
>
> 2. Load library dired-details.el, from Emacs Wiki:
> http://www.emacswiki.org/emacs/download/dired-details.el
>
> 3. C-x d ; in some directory that has lots of files
>
> 4.  M-x dired-details-toggle
>
> 5. M-x dired-details-toggle ; (optional, so you see all info)
>
> 6. Position the cursor on a file or dir name near the beginning of
> the list.
>
> 7. M-: (field-end nil)
>
> The result appears after a few seconds (I'm guessing about 4 sec
> in the directory I used).

I tried reproducing this in Emacs 27.2, but was unable to -- the
`(field-end nil)' was instantaneous for me.

Are you still seeing this issue in recent Emacs versions?

-- 
(domestic pets only, the antidote for overdose, milk.)
   bloggy blog: http://lars.ingebrigtsen.no

bug#14786: [External] : Re: bug#14786: 24.3.50; `field-end' is now very slow

[Drew Adams]

> I tried reproducing this in Emacs 27.2, but was unable to -- the
> `(field-end nil)' was instantaneous for me.
> 
> Are you still seeing this issue in recent Emacs versions?

No.  Trying that recipe now, in Emacs 27.2, I don't
notice the problem.

bug#14786: [External] : Re: bug#14786: 24.3.50; `field-end' is now very slow

[Lars Ingebrigtsen]

Drew Adams <drew.adams@oracle.com> writes:

>> I tried reproducing this in Emacs 27.2, but was unable to -- the
>> `(field-end nil)' was instantaneous for me.
>> 
>> Are you still seeing this issue in recent Emacs versions?
>
> No.  Trying that recipe now, in Emacs 27.2, I don't
> notice the problem.

Thanks for checking; I'm closing this bug report, then.

-- 
(domestic pets only, the antidote for overdose, milk.)
   bloggy blog: http://lars.ingebrigtsen.no