bug#50042: 26.3; Post-command hooks slow with M-x commands

bug#50042: 26.3; Post-command hooks slow with M-x commands

[Simon Katz]

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

Post-command hooks are slow to run for commands invoked using `M-x ...`.

I'm using Emacs 26.3 (which produced this bug report), but I've checked
with 27.2.2 and I get the same behaviour.


Here's a startup file that can be used to show this (also at
https://github.com/simon-katz/demo-post-command-hook-slow-with-m-x-commands.el/blob/8e7b96fc322f6372fb1531f04ab6008d59ab9b9e/demo-post-command-hook-slow-with-m-x-commands.el#L1
).

;;; demo-post-command-hook-slow-with-m-x-commands.el --- Demo that
post-sommand hooks are slow with M-x commands      -*- lexical-binding: t;
-*-

;; This demonstrates an issue with `(add-hook 'post-command-hook ...)`.

;; To reproduce the problem:
;; - Run `emacs -q -l demo-post-command-hook-slow-with-m-x-commands.el`
(that's
;;   this file).
;; - Enter `M-x next-line`.
;; - Observe that the message displayed by the `say-something` function
;;   takes a while to appear.
;; - Contrast with hitting the down-arrow key, when the message appears
;;   immediately.

;;; Code:

(require 'package)

(setq debug-on-error t
      no-byte-compile t
      package-archives '(("melpa" . "https://melpa.org/packages/")
                         ("gnu" . "https://elpa.gnu.org/packages/"))
      package-user-dir (expand-file-name (make-temp-name
"flycheck-tmp-elpa")
                                         user-emacs-directory)
      custom-file (expand-file-name "custom.el" package-user-dir))

(defun say-something ()
  (let ((inhibit-message t))
    (message
     "With `M-x next-line` (for example), this message is slow to appear")))

(add-hook 'post-command-hook 'say-something)

(display-buffer "*Messages*")

(provide 'demo-post-command-hook-slow-with-m-x-commands)
;;; demo-post-command-hook-slow-with-m-x-commands.el ends here






In GNU Emacs 26.3 (build 1, x86_64-apple-darwin18.2.0, NS appkit-1671.20
Version 10.14.3 (Build 18D109))
 of 2019-09-02 built on builder10-14.porkrind.org
Windowing system distributor 'Apple', version 10.3.1894
Recent messages:
For information about GNU Emacs and the GNU system, type C-h C-a.
With ‘M-x next-line‘ (for example), this message is slow to appear [13
times]
You can run the command ‘next-line’ with C-n
With ‘M-x next-line‘ (for example), this message is slow to appear [10
times]
Quit
With ‘M-x next-line‘ (for example), this message is slow to appear [7 times]
Making completion list...
With ‘M-x next-line‘ (for example), this message is slow to appear [6 times]

Configured using:
 'configure --with-ns '--enable-locallisppath=/Library/Application
 Support/Emacs/${version}/site-lisp:/Library/Application
 Support/Emacs/site-lisp' --with-modules'

Configured features:
NOTIFY ACL GNUTLS LIBXML2 ZLIB TOOLKIT_SCROLL_BARS NS MODULES THREADS

Important settings:
  value of $LANG: en_GB.UTF-8
  locale-coding-system: utf-8-unix

Major mode: Fundamental

Minor modes in effect:
  tooltip-mode: t
  global-eldoc-mode: t
  electric-indent-mode: t
  mouse-wheel-mode: t
  tool-bar-mode: t
  menu-bar-mode: t
  file-name-shadow-mode: t
  global-font-lock-mode: t
  blink-cursor-mode: t
  auto-composition-mode: t
  auto-encryption-mode: t
  auto-compression-mode: t
  buffer-read-only: t
  line-number-mode: t
  transient-mark-mode: t

Load-path shadows:
None found.

Features:
(shadow sort map mail-extr emacsbug message rmc puny dired
dired-loaddefs format-spec rfc822 mml mml-sec epa derived epg gnus-util
rmail rmail-loaddefs mm-decode mm-bodies mm-encode mail-parse rfc2231
mailabbrev gmm-utils mailheader sendmail rfc2047 rfc2045 ietf-drums
mm-util mail-prsvr mail-utils
demo-post-command-hook-slow-with-m-x-commands package easymenu
epg-config url-handlers url-parse auth-source cl-seq eieio eieio-core
cl-macs eieio-loaddefs password-cache url-vars seq byte-opt gv bytecomp
byte-compile cconv cl-loaddefs cl-lib elec-pair time-date tooltip eldoc
electric uniquify ediff-hook vc-hooks lisp-float-type mwheel term/ns-win
ns-win ucs-normalize mule-util term/common-win tool-bar dnd fontset
image regexp-opt fringe tabulated-list replace newcomment text-mode
elisp-mode lisp-mode prog-mode register page menu-bar rfn-eshadow
isearch timer select scroll-bar mouse jit-lock font-lock syntax facemenu
font-core term/tty-colors frame cl-generic cham georgian utf-8-lang
misc-lang vietnamese tibetan thai tai-viet lao korean japanese eucjp-ms
cp51932 hebrew greek romanian slovak czech european ethiopic indian
cyrillic chinese composite charscript charprop case-table epa-hook
jka-cmpr-hook help simple abbrev obarray minibuffer cl-preloaded nadvice
loaddefs button faces cus-face macroexp files text-properties overlay
sha1 md5 base64 format env code-pages mule custom widget
hashtable-print-readable backquote threads kqueue cocoa ns multi-tty
make-network-process emacs)

Memory information:
((conses 16 213714 7973)
 (symbols 48 21049 1)
 (miscs 40 83 191)
 (strings 32 31839 1672)
 (string-bytes 1 863206)
 (vectors 16 36747)
 (vector-slots 8 745240 8812)
 (floats 8 57 65)
 (intervals 56 214 0)
 (buffers 992 13))

[-- Attachment #2: Type: text/html, Size: 6001 bytes --]

bug#50042: 26.3; Post-command hooks slow with M-x commands

[Lars Ingebrigtsen]

Simon Katz <sk@nomistech.com> writes:

> Here's a startup file that can be used to show this (also at

Simpler repro:

(add-hook 'post-command-hook
	  (lambda ()
	    (let ((inhibit-message t))
	      (message "foo: %s" this-command))))
(display-buffer "*Messages*")

M-x previous-line

I think this has something to do with the

You can run the command ‘previous-line’ with C-p

stuff -- if the `M-x' command in question isn't bound to anything,
`post-command-hook' is run immediately instead of after a two-second
timeout.

Hm...  yup:

`execute-extended-command' ends with

        (when binding
          (with-temp-message
              (format-message "You can run the command `%s' with %s"
                              function
                              (if (stringp binding)
                                  (concat "M-x " binding " RET")
                                (key-description binding)))
            (sit-for (if (numberp suggest-key-bindings)
                         suggest-key-bindings
                       2))))))))

So presumably `post-command-hook' isn't run after that timeout has
completed.

Uhm...  anybody got any ideas how to fix this?  I mean, in one way it's
behaving as it's supposed to -- the command really isn't finished after
this sit-for has finished.

On the other hand, it's pretty awkward.

Could we yank this out of the flow and run it from a timer (fired
immediately) instead?

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

bug#50042: 26.3; Post-command hooks slow with M-x commands

[Simon Katz]

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

It's probably worth me giving a bit more context…

I'm using `lsp-ui`, and that's using post-command hooks to update the UI.

If I use `M-x flycheck-next-error` (for example), it takes time for the UI
to update.

See https://github.com/emacs-lsp/lsp-ui/issues/647

[-- Attachment #2: Type: text/html, Size: 468 bytes --]

bug#50042: 26.3; Post-command hooks slow with M-x commands

[Lars Ingebrigtsen]

Lars Ingebrigtsen <larsi@gnus.org> writes:

> Simpler repro:
>
> (add-hook 'post-command-hook
> 	  (lambda ()
> 	    (let ((inhibit-message t))
> 	      (message "foo: %s" this-command))))
> (display-buffer "*Messages*")
>
> M-x previous-line

[...]

> `execute-extended-command' ends with
>
>         (when binding
>           (with-temp-message
>               (format-message "You can run the command `%s' with %s"
>                               function
>                               (if (stringp binding)
>                                   (concat "M-x " binding " RET")
>                                 (key-description binding)))
>             (sit-for (if (numberp suggest-key-bindings)
>                          suggest-key-bindings
>                        2))))))))
>
> So presumably `post-command-hook' isn't run after that timeout has
> completed.

[...]

> Could we yank this out of the flow and run it from a timer (fired
> immediately) instead?

Stefan, I forgot to put you on the CCs here -- I wondered whether you
had any ideas here.  I think lifting this out of
`execute-extended-command' should be possible -- either by doing
something a la

(run-at-time 0 nil (lambda ()
                     (with-temp-message "The binding is foo"
		       (sit-for 1))))

or making `execute-extended-command' set a variable and do the messaging
from the "command loop" after running post-command-hook.

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

bug#50042: 26.3; Post-command hooks slow with M-x commands

[Stefan Monnier via Bug reports for GNU Emacs, the Swiss army knife of text editors]

>> `execute-extended-command' ends with
>>
>>         (when binding
>>           (with-temp-message
>>               (format-message "You can run the command `%s' with %s"
>>                               function
>>                               (if (stringp binding)
>>                                   (concat "M-x " binding " RET")
>>                                 (key-description binding)))
>>             (sit-for (if (numberp suggest-key-bindings)
>>                          suggest-key-bindings
>>                        2))))))))

Indeed this `sit-for` is a problem because it delays running the
`post-command-hook`.
[ We have a few other such problems, tho I sadly didn't bother to keep
  track of them.  ]

> Stefan, I forgot to put you on the CCs here -- I wondered whether you
> had any ideas here.  I think lifting this out of
> `execute-extended-command' should be possible -- either by doing
> something a la
>
> (run-at-time 0 nil (lambda ()
>                      (with-temp-message "The binding is foo"
> 		       (sit-for 1))))
>
> or making `execute-extended-command' set a variable and do the messaging
> from the "command loop" after running post-command-hook.

Using a timer might be a good option, indeed.


        Stefan

bug#50042: 26.3; Post-command hooks slow with M-x commands

[Lars Ingebrigtsen]

Stefan Monnier <monnier@iro.umontreal.ca> writes:

> Using a timer might be a good option, indeed.

OK; I've now implemented a solution based on `run-at-time', and after
using it for a bit, I'm not seeing any glitches usage-wise, so I'm
pushing it.  But I realise that there might be some peculiarities in
this area, so we'll see...

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

bug#50042: 26.3; Post-command hooks slow with M-x commands

[Dmitry Gutov]

On 15.08.2021 14:38, Lars Ingebrigtsen wrote:
> OK; I've now implemented a solution based on `run-at-time', and after
> using it for a bit, I'm not seeing any glitches usage-wise, so I'm
> pushing it.

Thanks for this change, it's been a long time coming.

bug#50042: acknowledged by developer (control message for bug #50042)

[Simon Katz]

Hi Lars,

Thanks for fixing the bug I reported.

You mentioned that there might be some peculiarities in this
area, and indeed that seems to be the case.

I still have a problem. If you are interested in what I am trying
to fix, see https://github.com/emacs-lsp/lsp-ui/issues/647

Note that everything is fine if I set `suggest-key-bindings` to
`nil`.

The problems seem to be with commands that both (a) write
messages to the echo area, and (b) have key bindings.

The code below reproduces the problem. See the comments at the
beginning for instructions.


--------------------------------------------------------------------------------

;;; demo-post-command-hook-slow-with-m-x-commands-v2.el --- Demo that
post-command hooks are slow with M-x commands      -*-
lexical-binding: t; -*-

;; This demonstrates an issue with:
;;   `(add-hook 'post-command-hook ...)`.
;; It's a follow-up to an already-reported and partially-fixed problem -- see
;; https://debbugs.gnu.org/cgi/bugreport.cgi?bug=50042

;; To reproduce the problem:
;;
;; - Run `emacs -q -l <this-file>`
;;
;; - Enter `M-x **-msg-cmd-without-key-binding`.
;; - Observe that it takes many seconds (~15 for me) to produce output to the
;;   "my-output" buffer, and that the "*Messages*" buffer has the message:
;;     You can run the command ‘**-msg-cmd-without-key-binding’ with
M-x -witho RET
;;
;; - Enter `M-x **-msg-cmd-without-key-binding` again.
;; - Observe that both the "*Messages*" buffer and the "my-output" buffer update
;;   immediately.
;; - Repeatedly enter `M-x **-msg-cmd-without-key-binding` and observe the same
;; - result.
;;
;; - Enter `M-x **-msg-cmd-with-key-binding`.
;; - Observe that it takes 2 seconds for output to appear in the "my-output"
;;   buffer.
;; - Observe that the behaviour is the same if the command is repeated.
;;
;; - Use the `C-c C-c` key binding, to invoke `**-msg-cmd-with-key-binding`.
;; - Observe that there are no delays.


;; Emacs displays the "*GNU Emacs*" buffer after loading this file, so use
;; `run-at-time` to delay setting up which buffers are displayed.
(run-at-time 1
             nil
             (lambda ()
               (switch-to-buffer "*Messages*" nil t)
               (display-buffer (generate-new-buffer "my-output"))
               ;; Arrange things so that we see the output as it appears:
               (select-window (get-buffer-window "my-output"))))

(defun date-time ()
  (format-time-string "%Y-%m-%d %H:%M:%S"))

(defun post-command-message ()
  (when (member this-command
                '(**-msg-cmd-with-key-binding
                  **-msg-cmd-without-key-binding))
    (with-current-buffer "my-output"
      (goto-char (point-max))
      (insert (date-time)
              " The command `"
              (format "%s" this-command)
              "` was executed\n")
      (goto-char (point-max)))))

(add-hook 'post-command-hook 'post-command-message)

(defun **-msg-cmd-without-key-binding ()
  (interactive)
  (message "%s Hello from `**-msg-cmd-without-key-binding`"
           (date-time)))

(defun **-msg-cmd-with-key-binding ()
  (interactive)
  (message "%s Hello from `**-msg-cmd-with-key-binding`"
           (date-time)))

(define-key global-map (kbd "C-c C-c") '**-msg-cmd-with-key-binding)

(setq suggest-key-bindings nil)

(when t ; Whether to load the changes in Emacs commit 42a98feb5b

  (defvar execute-extended-command--binding-timer nil)

  (defun execute-extended-command (prefixarg &optional command-name typed)
    ;; Based on Fexecute_extended_command in keyboard.c of Emacs.
    ;; Aaron S. Hawley <aaron.s.hawley(at)gmail.com> 2009-08-24
    "Read a command name, then read the arguments and call the command.
To pass a prefix argument to the command you are
invoking, give a prefix argument to `execute-extended-command'."
    (declare (interactive-only command-execute))
    ;; FIXME: Remember the actual text typed by the user before completion,
    ;; so that we don't later on suggest the same shortening.
    (interactive
     (let ((execute-extended-command--last-typed nil))
       (list current-prefix-arg
             (read-extended-command)
             execute-extended-command--last-typed)))
    ;; Emacs<24 calling-convention was with a single `prefixarg' argument.
    (unless command-name
      (let ((current-prefix-arg prefixarg) ; for prompt
            (execute-extended-command--last-typed nil))
        (setq command-name (read-extended-command))
        (setq typed execute-extended-command--last-typed)))
    (let* ((function (and (stringp command-name) (intern-soft command-name)))
           (binding (and suggest-key-bindings
                         (not executing-kbd-macro)
                         (where-is-internal function overriding-local-map t))))
      (unless (commandp function)
        (error "`%s' is not a valid command name" command-name))
      ;; Some features, such as novice.el, rely on this-command-keys
      ;; including M-x COMMAND-NAME RET.
      (set--this-command-keys (concat "\M-x" (symbol-name function) "\r"))
      (setq this-command function)
      ;; Normally `real-this-command' should never be changed, but
here we really
      ;; want to pretend that M-x <cmd> RET is nothing more than a "key
      ;; binding" for <cmd>, so the command the user really wanted to run is
      ;; `function' and not `execute-extended-command'.  The difference is
      ;; visible in cases such as M-x <cmd> RET and then C-x z (bug#11506).
      (setq real-this-command function)
      (let ((prefix-arg prefixarg))
        (command-execute function 'record))
      ;; If enabled, show which key runs this command.
      ;; But first wait, and skip the message if there is input.
      (let* ((waited
              ;; If this command displayed something in the echo area;
              ;; wait a few seconds, then display our suggestion message.
              ;; FIXME: Wait *after* running post-command-hook!
              ;; FIXME: If execute-extended-command--shorter were
              ;; faster, we could compute the result here first too.
              (when (and suggest-key-bindings
                         (or binding
                             (and extended-command-suggest-shorter typed)))
                (sit-for (cond
                          ((zerop (length (current-message))) 0)
                          ((numberp suggest-key-bindings) suggest-key-bindings)
                          (t 2))))))
        (when (and waited (not (consp unread-command-events)))
          (unless (or (not extended-command-suggest-shorter)
                      binding executing-kbd-macro (not (symbolp function))
                      (<= (length (symbol-name function)) 2))
            ;; There's no binding for CMD.  Let's try and find the shortest
            ;; string to use in M-x.
            ;; FIXME: Can be slow.  Cache it maybe?
            (while-no-input
              (setq binding (execute-extended-command--shorter
                             (symbol-name function) typed))))
          (when binding
            ;; This is normally not necessary -- the timer should run
            ;; immediately, but be defensive and ensure that we never
            ;; have two of these timers in flight.
            (when execute-extended-command--binding-timer
              (cancel-timer execute-extended-command--binding-timer))
            (setq execute-extended-command--binding-timer
                  (run-at-time
                   0 nil
                   (lambda ()
                     (with-temp-message
                         (format-message "You can run the command `%s' with %s"
                                         function
                                         (if (stringp binding)
                                             (concat "M-x " binding " RET")
                                           (key-description binding)))
                       (sit-for (if (numberp suggest-key-bindings)
                                    suggest-key-bindings
                                  2))))))))))))

(provide 'demo-post-command-hook-slow-with-m-x-commands-v2)
;;; demo-post-command-hook-slow-with-m-x-commands-v2.el ends here

--------------------------------------------------------------------------------

bug#50042: acknowledged by developer (control message for bug #50042)

[Simon Katz]

Oh, I'm really sorry…

I was playing around and I accidentally left in the `(setq
suggest-key-bindings nil)` form.

Please remove that in order to reproduce the problem!

On Wed, 18 Aug 2021 at 16:27, Simon Katz <sk@nomistech.com> wrote:
>
> Hi Lars,
>
> Thanks for fixing the bug I reported.
>
> You mentioned that there might be some peculiarities in this
> area, and indeed that seems to be the case.
>
> I still have a problem. If you are interested in what I am trying
> to fix, see https://github.com/emacs-lsp/lsp-ui/issues/647
>
> Note that everything is fine if I set `suggest-key-bindings` to
> `nil`.
>
> The problems seem to be with commands that both (a) write
> messages to the echo area, and (b) have key bindings.
>
> The code below reproduces the problem. See the comments at the
> beginning for instructions.
>
>
> --------------------------------------------------------------------------------
>
> ;;; demo-post-command-hook-slow-with-m-x-commands-v2.el --- Demo that
> post-command hooks are slow with M-x commands      -*-
> lexical-binding: t; -*-
>
> ;; This demonstrates an issue with:
> ;;   `(add-hook 'post-command-hook ...)`.
> ;; It's a follow-up to an already-reported and partially-fixed problem -- see
> ;; https://debbugs.gnu.org/cgi/bugreport.cgi?bug=50042
>
> ;; To reproduce the problem:
> ;;
> ;; - Run `emacs -q -l <this-file>`
> ;;
> ;; - Enter `M-x **-msg-cmd-without-key-binding`.
> ;; - Observe that it takes many seconds (~15 for me) to produce output to the
> ;;   "my-output" buffer, and that the "*Messages*" buffer has the message:
> ;;     You can run the command ‘**-msg-cmd-without-key-binding’ with
> M-x -witho RET
> ;;
> ;; - Enter `M-x **-msg-cmd-without-key-binding` again.
> ;; - Observe that both the "*Messages*" buffer and the "my-output" buffer update
> ;;   immediately.
> ;; - Repeatedly enter `M-x **-msg-cmd-without-key-binding` and observe the same
> ;; - result.
> ;;
> ;; - Enter `M-x **-msg-cmd-with-key-binding`.
> ;; - Observe that it takes 2 seconds for output to appear in the "my-output"
> ;;   buffer.
> ;; - Observe that the behaviour is the same if the command is repeated.
> ;;
> ;; - Use the `C-c C-c` key binding, to invoke `**-msg-cmd-with-key-binding`.
> ;; - Observe that there are no delays.
>
>
> ;; Emacs displays the "*GNU Emacs*" buffer after loading this file, so use
> ;; `run-at-time` to delay setting up which buffers are displayed.
> (run-at-time 1
>              nil
>              (lambda ()
>                (switch-to-buffer "*Messages*" nil t)
>                (display-buffer (generate-new-buffer "my-output"))
>                ;; Arrange things so that we see the output as it appears:
>                (select-window (get-buffer-window "my-output"))))
>
> (defun date-time ()
>   (format-time-string "%Y-%m-%d %H:%M:%S"))
>
> (defun post-command-message ()
>   (when (member this-command
>                 '(**-msg-cmd-with-key-binding
>                   **-msg-cmd-without-key-binding))
>     (with-current-buffer "my-output"
>       (goto-char (point-max))
>       (insert (date-time)
>               " The command `"
>               (format "%s" this-command)
>               "` was executed\n")
>       (goto-char (point-max)))))
>
> (add-hook 'post-command-hook 'post-command-message)
>
> (defun **-msg-cmd-without-key-binding ()
>   (interactive)
>   (message "%s Hello from `**-msg-cmd-without-key-binding`"
>            (date-time)))
>
> (defun **-msg-cmd-with-key-binding ()
>   (interactive)
>   (message "%s Hello from `**-msg-cmd-with-key-binding`"
>            (date-time)))
>
> (define-key global-map (kbd "C-c C-c") '**-msg-cmd-with-key-binding)
>
> (setq suggest-key-bindings nil)
>
> (when t ; Whether to load the changes in Emacs commit 42a98feb5b
>
>   (defvar execute-extended-command--binding-timer nil)
>
>   (defun execute-extended-command (prefixarg &optional command-name typed)
>     ;; Based on Fexecute_extended_command in keyboard.c of Emacs.
>     ;; Aaron S. Hawley <aaron.s.hawley(at)gmail.com> 2009-08-24
>     "Read a command name, then read the arguments and call the command.
> To pass a prefix argument to the command you are
> invoking, give a prefix argument to `execute-extended-command'."
>     (declare (interactive-only command-execute))
>     ;; FIXME: Remember the actual text typed by the user before completion,
>     ;; so that we don't later on suggest the same shortening.
>     (interactive
>      (let ((execute-extended-command--last-typed nil))
>        (list current-prefix-arg
>              (read-extended-command)
>              execute-extended-command--last-typed)))
>     ;; Emacs<24 calling-convention was with a single `prefixarg' argument.
>     (unless command-name
>       (let ((current-prefix-arg prefixarg) ; for prompt
>             (execute-extended-command--last-typed nil))
>         (setq command-name (read-extended-command))
>         (setq typed execute-extended-command--last-typed)))
>     (let* ((function (and (stringp command-name) (intern-soft command-name)))
>            (binding (and suggest-key-bindings
>                          (not executing-kbd-macro)
>                          (where-is-internal function overriding-local-map t))))
>       (unless (commandp function)
>         (error "`%s' is not a valid command name" command-name))
>       ;; Some features, such as novice.el, rely on this-command-keys
>       ;; including M-x COMMAND-NAME RET.
>       (set--this-command-keys (concat "\M-x" (symbol-name function) "\r"))
>       (setq this-command function)
>       ;; Normally `real-this-command' should never be changed, but
> here we really
>       ;; want to pretend that M-x <cmd> RET is nothing more than a "key
>       ;; binding" for <cmd>, so the command the user really wanted to run is
>       ;; `function' and not `execute-extended-command'.  The difference is
>       ;; visible in cases such as M-x <cmd> RET and then C-x z (bug#11506).
>       (setq real-this-command function)
>       (let ((prefix-arg prefixarg))
>         (command-execute function 'record))
>       ;; If enabled, show which key runs this command.
>       ;; But first wait, and skip the message if there is input.
>       (let* ((waited
>               ;; If this command displayed something in the echo area;
>               ;; wait a few seconds, then display our suggestion message.
>               ;; FIXME: Wait *after* running post-command-hook!
>               ;; FIXME: If execute-extended-command--shorter were
>               ;; faster, we could compute the result here first too.
>               (when (and suggest-key-bindings
>                          (or binding
>                              (and extended-command-suggest-shorter typed)))
>                 (sit-for (cond
>                           ((zerop (length (current-message))) 0)
>                           ((numberp suggest-key-bindings) suggest-key-bindings)
>                           (t 2))))))
>         (when (and waited (not (consp unread-command-events)))
>           (unless (or (not extended-command-suggest-shorter)
>                       binding executing-kbd-macro (not (symbolp function))
>                       (<= (length (symbol-name function)) 2))
>             ;; There's no binding for CMD.  Let's try and find the shortest
>             ;; string to use in M-x.
>             ;; FIXME: Can be slow.  Cache it maybe?
>             (while-no-input
>               (setq binding (execute-extended-command--shorter
>                              (symbol-name function) typed))))
>           (when binding
>             ;; This is normally not necessary -- the timer should run
>             ;; immediately, but be defensive and ensure that we never
>             ;; have two of these timers in flight.
>             (when execute-extended-command--binding-timer
>               (cancel-timer execute-extended-command--binding-timer))
>             (setq execute-extended-command--binding-timer
>                   (run-at-time
>                    0 nil
>                    (lambda ()
>                      (with-temp-message
>                          (format-message "You can run the command `%s' with %s"
>                                          function
>                                          (if (stringp binding)
>                                              (concat "M-x " binding " RET")
>                                            (key-description binding)))
>                        (sit-for (if (numberp suggest-key-bindings)
>                                     suggest-key-bindings
>                                   2))))))))))))
>
> (provide 'demo-post-command-hook-slow-with-m-x-commands-v2)
> ;;; demo-post-command-hook-slow-with-m-x-commands-v2.el ends here
>
> --------------------------------------------------------------------------------

bug#50042: acknowledged by developer (control message for bug #50042)

[Simon Katz]

(Just so that you see the new part of the previous
message -- apologies for my cack-handedness at
driving Gmail with plain text!)

Oh, I'm really sorry…

I was playing around and I accidentally left in the
`(setq suggest-key-bindings nil)` form.

Please remove that in order to reproduce the problem!

bug#50042: acknowledged by developer (control message for bug #50042)

[Lars Ingebrigtsen]

Simon Katz <sk@nomistech.com> writes:

> (Just so that you see the new part of the previous
> message -- apologies for my cack-handedness at
> driving Gmail with plain text!)
>
> Oh, I'm really sorry…
>
> I was playing around and I accidentally left in the
> `(setq suggest-key-bindings nil)` form.
>
> Please remove that in order to reproduce the problem!

The file for reproducing the problem was apparently mangled during
transmission, too.  Can you re-send the file as an attachment?

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

bug#50042: acknowledged by developer (control message for bug #50042)

[Simon Katz]

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

> The file for reproducing the problem was apparently mangled during
> transmission, too.  Can you re-send the file as an attachment?

Sure. Please find it attached.

[-- Attachment #2: demo-post-command-hook-slow-with-m-x-commands-v2.el --]
[-- Type: application/octet-stream, Size: 7514 bytes --]

;;; demo-post-command-hook-slow-with-m-x-commands-v2.el --- Demo that post-command hooks are slow with M-x commands      -*- lexical-binding: t; -*-

;; This demonstrates an issue with:
;;   `(add-hook 'post-command-hook ...)`.
;; It's a follow-up to an already-reported and partially-fixed problem -- see
;; https://debbugs.gnu.org/cgi/bugreport.cgi?bug=50042

;; To reproduce the problem:
;;
;; - Run `emacs -q -l <this-file>`
;;
;; - Enter `M-x **-msg-cmd-without-key-binding`.
;; - Observe that it takes many seconds (~15 for me) to produce output to the
;;   "my-output" buffer, and that the "*Messages*" buffer has the message:
;;     You can run the command ‘**-msg-cmd-without-key-binding’ with M-x -witho RET
;;
;; - Enter `M-x **-msg-cmd-without-key-binding` again.
;; - Observe that both the "*Messages*" buffer and the "my-output" buffer update
;;   immediately.
;; - Repeatedly enter `M-x **-msg-cmd-without-key-binding` and observe the same
;; - result.
;;
;; - Enter `M-x **-msg-cmd-with-key-binding`.
;; - Observe that it takes 2 seconds for output to appear in the "my-output"
;;   buffer.
;; - Observe that the behaviour is the same if the command is repeated.
;;
;; - Use the `C-c C-c` key binding, to invoke `**-msg-cmd-with-key-binding`.
;; - Observe that there are no delays.


;; Emacs displays the "*GNU Emacs*" buffer after loading this file, so use
;; `run-at-time` to delay setting up which buffers are displayed.
(run-at-time 1
             nil
             (lambda ()
               (switch-to-buffer "*Messages*" nil t)
               (display-buffer (generate-new-buffer "my-output"))
               ;; Arrange things so that we see the output as it appears:
               (select-window (get-buffer-window "my-output"))))

(defun date-time ()
  (format-time-string "%Y-%m-%d %H:%M:%S"))

(defun post-command-message ()
  (when (member this-command
                '(**-msg-cmd-with-key-binding
                  **-msg-cmd-without-key-binding))
    (with-current-buffer "my-output"
      (goto-char (point-max))
      (insert (date-time)
              " The command `"
              (format "%s" this-command)
              "` was executed\n")
      (goto-char (point-max)))))

(add-hook 'post-command-hook 'post-command-message)

(defun **-msg-cmd-without-key-binding ()
  (interactive)
  (message "%s Hello from `**-msg-cmd-without-key-binding`"
           (date-time)))

(defun **-msg-cmd-with-key-binding ()
  (interactive)
  (message "%s Hello from `**-msg-cmd-with-key-binding`"
           (date-time)))

(define-key global-map (kbd "C-c C-c") '**-msg-cmd-with-key-binding)

(when t ; Whether to load the changes in Emacs commit 42a98feb5b

  (defvar execute-extended-command--binding-timer nil)

  (defun execute-extended-command (prefixarg &optional command-name typed)
    ;; Based on Fexecute_extended_command in keyboard.c of Emacs.
    ;; Aaron S. Hawley <aaron.s.hawley(at)gmail.com> 2009-08-24
    "Read a command name, then read the arguments and call the command.
To pass a prefix argument to the command you are
invoking, give a prefix argument to `execute-extended-command'."
    (declare (interactive-only command-execute))
    ;; FIXME: Remember the actual text typed by the user before completion,
    ;; so that we don't later on suggest the same shortening.
    (interactive
     (let ((execute-extended-command--last-typed nil))
       (list current-prefix-arg
             (read-extended-command)
             execute-extended-command--last-typed)))
    ;; Emacs<24 calling-convention was with a single `prefixarg' argument.
    (unless command-name
      (let ((current-prefix-arg prefixarg) ; for prompt
            (execute-extended-command--last-typed nil))
        (setq command-name (read-extended-command))
        (setq typed execute-extended-command--last-typed)))
    (let* ((function (and (stringp command-name) (intern-soft command-name)))
           (binding (and suggest-key-bindings
                         (not executing-kbd-macro)
                         (where-is-internal function overriding-local-map t))))
      (unless (commandp function)
        (error "`%s' is not a valid command name" command-name))
      ;; Some features, such as novice.el, rely on this-command-keys
      ;; including M-x COMMAND-NAME RET.
      (set--this-command-keys (concat "\M-x" (symbol-name function) "\r"))
      (setq this-command function)
      ;; Normally `real-this-command' should never be changed, but here we really
      ;; want to pretend that M-x <cmd> RET is nothing more than a "key
      ;; binding" for <cmd>, so the command the user really wanted to run is
      ;; `function' and not `execute-extended-command'.  The difference is
      ;; visible in cases such as M-x <cmd> RET and then C-x z (bug#11506).
      (setq real-this-command function)
      (let ((prefix-arg prefixarg))
        (command-execute function 'record))
      ;; If enabled, show which key runs this command.
      ;; But first wait, and skip the message if there is input.
      (let* ((waited
              ;; If this command displayed something in the echo area;
              ;; wait a few seconds, then display our suggestion message.
              ;; FIXME: Wait *after* running post-command-hook!
              ;; FIXME: If execute-extended-command--shorter were
              ;; faster, we could compute the result here first too.
              (when (and suggest-key-bindings
                         (or binding
                             (and extended-command-suggest-shorter typed)))
                (sit-for (cond
                          ((zerop (length (current-message))) 0)
                          ((numberp suggest-key-bindings) suggest-key-bindings)
                          (t 2))))))
        (when (and waited (not (consp unread-command-events)))
          (unless (or (not extended-command-suggest-shorter)
                      binding executing-kbd-macro (not (symbolp function))
                      (<= (length (symbol-name function)) 2))
            ;; There's no binding for CMD.  Let's try and find the shortest
            ;; string to use in M-x.
            ;; FIXME: Can be slow.  Cache it maybe?
            (while-no-input
              (setq binding (execute-extended-command--shorter
                             (symbol-name function) typed))))
          (when binding
            ;; This is normally not necessary -- the timer should run
            ;; immediately, but be defensive and ensure that we never
            ;; have two of these timers in flight.
            (when execute-extended-command--binding-timer
              (cancel-timer execute-extended-command--binding-timer))
            (setq execute-extended-command--binding-timer
                  (run-at-time
                   0 nil
                   (lambda ()
                     (with-temp-message
                         (format-message "You can run the command `%s' with %s"
                                         function
                                         (if (stringp binding)
                                             (concat "M-x " binding " RET")
                                           (key-description binding)))
                       (sit-for (if (numberp suggest-key-bindings)
                                    suggest-key-bindings
                                  2))))))))))))

(provide 'demo-post-command-hook-slow-with-m-x-commands-v2)
;;; demo-post-command-hook-slow-with-m-x-commands-v2.el ends here

bug#50042: acknowledged by developer (control message for bug #50042)

[Lars Ingebrigtsen]

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

Simon Katz <sk@nomistech.com> writes:

>> The file for reproducing the problem was apparently mangled during
>> transmission, too.  Can you re-send the file as an attachment?
>
> Sure. Please find it attached.

Thanks.

When I hoisted the final waiting from the command, I totally didn't
notice that there was even more waiting there (in the case of a command
that had displayed a message).

I've now tweaked this further, and it now seems to work correctly in
all the message/no keybinding/keybinding cases, I think...

Can you test this, too, to see if I got all the cases right?  That is,
it shouldn't display anything if you do anything else before the
suggestion triggers, and it shouldn't inhibit entering other commands,
and...  er...  no other peculiarities.

One thing that is peculiar, but no more than before, is this bit:

                       ;; FIXME: Can be slow.  Cache it maybe?
                       (setq binding (execute-extended-command--shorter
                                      (symbol-name function) typed))))

It takes five seconds on my laptop, which means that these suggestion
arrive five seconds after I did the `M-x'.  But that hasn't changed
since before these patches.  

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

[-- Attachment #2: demo-post-command-hook-slow-with-m-x-commands-v2.el --]
[-- Type: application/emacs-lisp, Size: 1439 bytes --]

bug#50042: acknowledged by developer (control message for bug #50042)

[Simon Katz]

Lars Ingebrigtsen <larsi <at> gnus.org> writes:

> Can you test this, too, to see if I got all the cases right?  That is,
> it shouldn't display anything if you do anything else before the
> suggestion triggers, and it shouldn't inhibit entering other commands,
> and...  er...  no other peculiarities.

I'm using the version of `execute-extended-command` in commit
00a9c50ad7, and everything is behaving as I would expect.

Thanks!

> One thing that is peculiar, but no more than before, is this bit:
>
>                        ;; FIXME: Can be slow.  Cache it maybe?
>                        (setq binding (execute-extended-command--shorter
>                                       (symbol-name function) typed))))
>
> It takes five seconds on my laptop, which means that these suggestion
> arrive five seconds after I did the `M-x'.  But that hasn't changed
> since before these patches.

FWIW, I haven't looked at this -- I'm not sure when it comes into play.
But I guess it's a separate issue.

Thanks again.

bug#50042: acknowledged by developer (control message for bug #50042)

[Lars Ingebrigtsen]

Simon Katz <sk@nomistech.com> writes:

> Lars Ingebrigtsen <larsi <at> gnus.org> writes:
>
>> Can you test this, too, to see if I got all the cases right?  That is,
>> it shouldn't display anything if you do anything else before the
>> suggestion triggers, and it shouldn't inhibit entering other commands,
>> and...  er...  no other peculiarities.
>
> I'm using the version of `execute-extended-command` in commit
> 00a9c50ad7, and everything is behaving as I would expect.

Thanks for checking.

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