Long delay after M-x commandname

Long delay after M-x commandname

[Eduardo Ochs]

Hi list,

this is not a bug report YET - I am looking for more information
first.

Yesterday I noticed that when I was invoking commands with M-x
commandname and using tab for completing parts of the name then
sometimes there would be a long delay - sometimes as long as 10
seconds, but my laptop is quite old - between the RET and the
execution of the command. This delay was big on emacs28 and
practically imperceptible on emacs27. I have several versions of
emacs28 here, with names like emacs28_512 for the one correponding to
HEAD~512 and emacs28_0 for HEAD, and I noticed that this delay was
growing in recent versions: small in HEAD~256, bigger in HEAD~128,
much bigger in HEAD~0.

I _guess_ that these delays are caused by the code that generates
messages like this one:

  You can run the command `find-eev-install-intro' with `M-x f--i-i'.

What do I need to learn to understand what is going on, and to prepare
a proper bug report? A quick grepping shows that this message is
generated by `execute-extended-command' in simple.el, but what else?

  Thanks in advance,
    Eduardo Ochs
    http://angg.twu.net/#eev

Re: Long delay after M-x commandname

[Stefan Monnier via Users list for the GNU Emacs text editor]

Eduardo Ochs [2021-10-10 21:45:39] wrote:

> Hi list,
>
> this is not a bug report YET - I am looking for more information
> first.
>
> Yesterday I noticed that when I was invoking commands with M-x
> commandname and using tab for completing parts of the name then
> sometimes there would be a long delay - sometimes as long as 10
> seconds, but my laptop is quite old - between the RET and the
> execution of the command. This delay was big on emacs28 and
> practically imperceptible on emacs27. I have several versions of
> emacs28 here, with names like emacs28_512 for the one correponding to
> HEAD~512 and emacs28_0 for HEAD, and I noticed that this delay was
> growing in recent versions: small in HEAD~256, bigger in HEAD~128,
> much bigger in HEAD~0.
>
> I _guess_ that these delays are caused by the code that generates
> messages like this one:
>
>   You can run the command `find-eev-install-intro' with `M-x f--i-i'.

This message can be suppressed with `extended-command-suggest-shorter`.

It can take work to find that shortest replacement (it's a kind of
brute-force algorithm which tries all combinations of increasing length
until one works), indeed, tho usually it's negligible.  I'm surprised
the time taken has changed significantly recently  That code has been
the same Emacs-26, AFAIK.  The completion data has an impact on the
performance, so maybe that's what's going on, but it still seems
surprising you'd see such a progressive slowdown.


        Stefan

Re: Long delay after M-x commandname

[Eli Zaretskii]

> Date: Mon, 11 Oct 2021 00:03:19 -0400
> From:  Stefan Monnier via Users list for the GNU Emacs text editor <help-gnu-emacs@gnu.org>
> 
> Eduardo Ochs [2021-10-10 21:45:39] wrote:
> 
> > Yesterday I noticed that when I was invoking commands with M-x
> > commandname and using tab for completing parts of the name then
> > sometimes there would be a long delay - sometimes as long as 10
> > seconds, but my laptop is quite old - between the RET and the
> > execution of the command. This delay was big on emacs28 and
> > practically imperceptible on emacs27. I have several versions of
> > emacs28 here, with names like emacs28_512 for the one correponding to
> > HEAD~512 and emacs28_0 for HEAD, and I noticed that this delay was
> > growing in recent versions: small in HEAD~256, bigger in HEAD~128,
> > much bigger in HEAD~0.
> >
> > I _guess_ that these delays are caused by the code that generates
> > messages like this one:
> >
> >   You can run the command `find-eev-install-intro' with `M-x f--i-i'.
> 
> This message can be suppressed with `extended-command-suggest-shorter`.
> 
> It can take work to find that shortest replacement (it's a kind of
> brute-force algorithm which tries all combinations of increasing length
> until one works), indeed, tho usually it's negligible.  I'm surprised
> the time taken has changed significantly recently  That code has been
> the same Emacs-26, AFAIK.  The completion data has an impact on the
> performance, so maybe that's what's going on, but it still seems
> surprising you'd see such a progressive slowdown.

FWIW, I don't see any delay in "emacs -Q", so I think the question
becomes what kind of customizations and packages loaded could
significantly increase that time.

Re: Long delay after M-x commandname

[Michael Heerdegen]

Stefan Monnier via Users list for the GNU Emacs text editor
<help-gnu-emacs@gnu.org> writes:

> It can take work to find that shortest replacement (it's a kind of
> brute-force algorithm which tries all combinations of increasing length
> until one works) [...]

I would expect that working with decreasing lengths and stop when there
are no more solutions would be more efficient (since starting with tiny
lengths has nearly no chance of success, especially when having a lot of
interned symbols, and the smaller lengths also seem to have the higher
costs.)

Apart from that, I get a significant improvement if I move the commandp
test out of the `try-completion' call and filter the obarray once for a
list of commands.

I will try to suggest a patch for the bug report.  For the
`find-eev-install-intro' test case I get 0.6 instead of 2.5 seconds
here.

Michael.

Re: Long delay after M-x commandname

[Michael Heerdegen]

Eduardo Ochs <eduardoochs@gmail.com> writes:

> I _guess_ that these delays are caused by the code that generates
> messages like this one:

Adding to what already has been mentioned: There is a `sit-for' of (by
default) 2 seconds for displaying the found shorter version of the input.
But that doesn't explain 10 seconds.

If you can reproduce your problem, my first debugging approach would be
to enable `debug-on-quit' and hit C-g when there is a delay, and look
what Emacs was actually doing at that moment.

Michael.

Re: Long delay after M-x commandname

[Eduardo Ochs]

On Mon, 11 Oct 2021 at 21:20, Michael Heerdegen
<michael_heerdegen@web.de> wrote:
>
> Eduardo Ochs <eduardoochs@gmail.com> writes:
>
> > I _guess_ that these delays are caused by the code that generates
> > messages like this one:
>
> Adding to what already has been mentioned: There is a `sit-for' of (by
> default) 2 seconds for displaying the found shorter version of the input.
> But that doesn't explain 10 seconds.
>
> If you can reproduce your problem, my first debugging approach would be
> to enable `debug-on-quit' and hit C-g when there is a delay, and look
> what Emacs was actually doing at that moment.
>
> Michael.


Hi Michael,

I can reproduce it without M-x.

This takes 10 seconds:

  (execute-extended-command--shorter   "find-eev-quick-intro" "find-eev-qui")

This executes very quickly:

  (execute-extended-command--shorter-1 "find-eev-quick-intro" 12)

If I run `(setq debug-on-quit t)' and I hit a C-g during the execution
of the sexp that takes a long time I get a "*Backtrace*" buffer whose
top lines are these ones,

Debugger entered--Lisp error: (quit)
  all-completions("" [find-udfile magit-section-show-headings
org-element-paragraph-separate calendar-forward-week
archive-proper-file-start
tramp-completion-handle-file-name-all-completions
archive--file-desc-mode lua-backward-up-list
speedbar-check-vc-this-line access-label find-operatorspacepage
c-electric-lt-gt pcomplete-stub c-state-min-scan-pos
gnus-article-nndoc-name vterm-keymap-exceptions
magit-buffer-lock-functions magit-xref-insert-button
speedbar-file-regexp gnus-agent-group-covered-p
org-table--descriptor-line raw-text-dos message-expand-name-databases
transient:magit-diff-refresh:--irreversible-delete
find-oofficestylestext c-make-ml-string-opener-re-function
smie-config--guess-value compilation-error-list
find-sexptotarget-links lua-is-continuing-statement-p-1
c-list-found-types vc-annotate tramp-sudoedit-handle-set-file-acl
org-table-get-range vc-bzr-shelve-menu gamr
widget-face-sample-face-get nnimap-status-message int-file-name
he-line-search-regexp nnmail-message-id-cache-file discard-new
filename-and-process smime-buffer-as-string-region keyid check-declare
org-at-keyword-p angle-bracket-arglist-escape bibtex-text-in-string
zot ...] commandp)
  completion-pcm--all-completions("" (any "-" any-delim "ee")
[find-udfile magit-section-show-headings
org-element-paragraph-separate calendar-forward-week
archive-proper-file-start
tramp-completion-handle-file-name-all-completions
archive--file-desc-mode lua-backward-up-list
speedbar-check-vc-this-line access-label find-operatorspacepage
c-electric-lt-gt pcomplete-stub c-state-min-scan-pos
gnus-article-nndoc-name vterm-keymap-exceptions
magit-buffer-lock-functions magit-xref-insert-button
speedbar-file-regexp gnus-agent-group-covered-p
org-table--descriptor-line raw-text-dos message-expand-name-databases
transient:magit-diff-refresh:--irreversible-delete
find-oofficestylestext c-make-ml-string-opener-re-function
smie-config--guess-value compilation-error-list
find-sexptotarget-links lua-is-continuing-statement-p-1
c-list-found-types vc-annotate tramp-sudoedit-handle-set-file-acl
org-table-get-range vc-bzr-shelve-menu gamr
widget-face-sample-face-get nnimap-status-message int-file-name
he-line-search-regexp nnmail-message-id-cache-file discard-new
filename-and-process smime-buffer-as-string-region keyid check-declare
org-at-keyword-p angle-bracket-arglist-escape bibtex-text-in-string
zot ...] commandp)
  completion-pcm--find-all-completions("-ee" [find-udfile
magit-section-show-headings org-element-paragraph-separate
calendar-forward-week archive-proper-file-start
tramp-completion-handle-file-name-all-completions
archive--file-desc-mode lua-backward-up-list
speedbar-check-vc-this-line access-label find-operatorspacepage
c-electric-lt-gt pcomplete-stub c-state-min-scan-pos
gnus-article-nndoc-name vterm-keymap-exceptions
magit-buffer-lock-functions magit-xref-insert-button
speedbar-file-regexp gnus-agent-group-covered-p
org-table--descriptor-line raw-text-dos message-expand-name-databases
transient:magit-diff-refresh:--irreversible-delete
find-oofficestylestext c-make-ml-string-opener-re-function
smie-config--guess-value compilation-error-list
find-sexptotarget-links lua-is-continuing-statement-p-1
c-list-found-types vc-annotate tramp-sudoedit-handle-set-file-acl
org-table-get-range vc-bzr-shelve-menu gamr
widget-face-sample-face-get nnimap-status-message int-file-name
he-line-search-regexp nnmail-message-id-cache-file discard-new
filename-and-process smime-buffer-as-string-region keyid check-declare
org-at-keyword-p angle-bracket-arglist-escape bibtex-text-in-string
zot ...] commandp 3 nil)
  completion-pcm-try-completion("-ee" [find-udfile
magit-section-show-headings org-element-paragraph-separate
calendar-forward-week archive-proper-file-start
tramp-completion-handle-file-name-all-completions
archive--file-desc-mode lua-backward-up-list
speedbar-check-vc-this-line access-label find-operatorspacepage
c-electric-lt-gt pcomplete-stub c-state-min-scan-pos
gnus-article-nndoc-name vterm-keymap-exceptions
magit-buffer-lock-functions magit-xref-insert-button
speedbar-file-regexp gnus-agent-group-covered-p
org-table--descriptor-line raw-text-dos message-expand-name-databases
transient:magit-diff-refresh:--irreversible-delete
find-oofficestylestext c-make-ml-string-opener-re-function
smie-config--guess-value compilation-error-list
find-sexptotarget-links lua-is-continuing-statement-p-1
c-list-found-types vc-annotate tramp-sudoedit-handle-set-file-acl
org-table-get-range vc-bzr-shelve-menu gamr
widget-face-sample-face-get nnimap-status-message int-file-name
he-line-search-regexp nnmail-message-id-cache-file discard-new
filename-and-process smime-buffer-as-string-region keyid check-declare
org-at-keyword-p angle-bracket-arglist-escape bibtex-text-in-string
zot ...] commandp 3)
  #f(compiled-function (style) #<bytecode
-0xd2f42ee755385a2>)(partial-completion)
  completion--some(#f(compiled-function (style) #<bytecode
-0xd2f42ee755385a2>) (basic partial-completion emacs22))
  completion--nth-completion(1 "-ee" [find-udfile
magit-section-show-headings org-element-paragraph-separate
calendar-forward-week archive-proper-file-start
tramp-completion-handle-file-name-all-completions
archive--file-desc-mode lua-backward-up-list
speedbar-check-vc-this-line access-label find-operatorspacepage
c-electric-lt-gt pcomplete-stub c-state-min-scan-pos
gnus-article-nndoc-name vterm-keymap-exceptions
magit-buffer-lock-functions magit-xref-insert-button
speedbar-file-regexp gnus-agent-group-covered-p
org-table--descriptor-line raw-text-dos message-expand-name-databases
transient:magit-diff-refresh:--irreversible-delete
find-oofficestylestext c-make-ml-string-opener-re-function
smie-config--guess-value compilation-error-list
find-sexptotarget-links lua-is-continuing-statement-p-1
c-list-found-types vc-annotate tramp-sudoedit-handle-set-file-acl
org-table-get-range vc-bzr-shelve-menu gamr
widget-face-sample-face-get nnimap-status-message int-file-name
he-line-search-regexp nnmail-message-id-cache-file discard-new
filename-and-process smime-buffer-as-string-region keyid check-declare
org-at-keyword-p angle-bracket-arglist-escape bibtex-text-in-string
zot ...] commandp 3 nil)
  completion-try-completion("-ee" [find-udfile
magit-section-show-headings org-element-paragraph-separate
calendar-forward-week archive-proper-file-start
tramp-completion-handle-file-name-all-completions
archive--file-desc-mode lua-backward-up-list
speedbar-check-vc-this-line access-label find-operatorspacepage
c-electric-lt-gt pcomplete-stub c-state-min-scan-pos
gnus-article-nndoc-name vterm-keymap-exceptions
magit-buffer-lock-functions magit-xref-insert-button
speedbar-file-regexp gnus-agent-group-covered-p
org-table--descriptor-line raw-text-dos message-expand-name-databases
transient:magit-diff-refresh:--irreversible-delete
find-oofficestylestext c-make-ml-string-opener-re-function
smie-config--guess-value compilation-error-list
find-sexptotarget-links lua-is-continuing-statement-p-1
c-list-found-types vc-annotate tramp-sudoedit-handle-set-file-acl
org-table-get-range vc-bzr-shelve-menu gamr
widget-face-sample-face-get nnimap-status-message int-file-name
he-line-search-regexp nnmail-message-id-cache-file discard-new
filename-and-process smime-buffer-as-string-region keyid check-declare
org-at-keyword-p angle-bracket-arglist-escape bibtex-text-in-string
zot ...] commandp 3)
  execute-extended-command--shorter("find-eev-quick-intro" "find-eev-qui")

I repeated that 10 times and in all the times the "*Backtrace*" buffer
had something like this:

  #f(compiled-function (style) #<bytecode
-0xd2f4350b61385a2>)(partial-completion)
  completion--some(...)
  completion--nth-completion(...)
  completion-try-completion(...)

Cheers,
  Eduardo Ochs
  http://angg.twu.net/#eev

Re: Long delay after M-x commandname

[Michael Heerdegen]

Eduardo Ochs <eduardoochs@gmail.com> writes:

> This takes 10 seconds:
>
>   (execute-extended-command--shorter "find-eev-quick-intro"
> "find-eev-qui")

Wow - takes 36 seconds for me.  In emacs -Q still 2 or 3 seconds.  I
think a bug report would definitely not be wrong.

Here is the result of running the profiler (using my current session).
I don't see anything obvious - no sit-for or so.  Maybe it depends on
completion-styles involved?  Let's try ... eh, no, with the default
styles enabled I still see 34 seconds.  Maybe this just scales with the
amount of loaded packages and "find-eev-quick-intro" is just very hard
to shorten, dunno.  Anyway, here is the profiler result:

Elapsed time: 35.878s (including 1.239s in 1 GCs and excluding 0.479s of idle time)
Conses: 511713
Vector-Cells: 42
Strings: 32135
String-Chars: 100
Symbols: 1.10411e+06
Floats: 606
Intervals: 138814

       34239 100% - ...
       33925  99%  - read-from-minibuffer
       33925  99%   - command-execute
       33925  99%    - call-interactively
       33925  99%     - funcall-interactively
       33886  98%      - my-profiler-profile-next-command
       33886  98%       - my-measuring-idle-time
       33886  98%        - #<compiled 0x2ec4e28c32523d9>
       33886  98%         - eval
       33886  98%          - benchmark-run
       33886  98%           - benchmark-call
       33886  98%            - #<lambda 0xfdda4d053>
       33886  98%             - progn
       33886  98%              - funcall-interactively
       33886  98%               - my-pp-eval-expression
       33800  98%                - pp-eval-expression
       33800  98%                 - eval
       33800  98%                  - progn
       33800  98%                   - progn
       33800  98%                    - execute-extended-command--shorter
       33760  98%                     - completion-try-completion
       33760  98%                      - completion--nth-completion
       33756  98%                       - completion--some
       33756  98%                        - #<compiled -0xd2c16e5a3854222>
       19670  57%                         - completion-pcm-try-completion
       19566  57%                          - completion-pcm--find-all-completions
       19562  57%                           - completion-pcm--all-completions
           4   0%                              completion-pcm--pattern->regex
         104   0%                          - completion-pcm--merge-try
          72   0%                             completion-pcm--merge-completions
       10354  30%                         - completion-substring-try-completion
       10354  30%                          - completion-substring--all-completions
       10350  30%                             completion-pcm--all-completions
        3732  10%                           completion-emacs22-try-completion
           4   0%                         completion--styles
           8   0%                     - execute-extended-command--shorter-1
                                        [...]


Michael

Re: Long delay after M-x commandname

[Michael Heerdegen]

Michael Heerdegen <michael_heerdegen@web.de> writes:

> >   (execute-extended-command--shorter "find-eev-quick-intro"
> > "find-eev-qui")
>
> Wow - takes 36 seconds for me.  In emacs -Q still 2 or 3 seconds.

FWIW, the 36 seconds happened when trying without having a command named
`find-eev-quick-intro' defined, so that was not really a fair test.

Michael.