Ignore time that emacs is waiting for input (root cause: read-key-sequence not advised)

[aaronjensen]

This is great and I can see this being super helpful, thank you!

I've noticed one issue so far that makes the log rather noisy:

If I'm using evil, for example, and I hit d, then wait before hitting d again, I'll see

Wed May 20 19:30:38 2020 - 1915 ms - evil-delete [*explain-pause-log* (fundamental-mode)]

Similarly if I'm using which-key and wait for which-key to appear, then I see:

Wed May 20 19:31:34 2020 - 65 ms - which-key--update, idle-timer

[lastquestion]

Hi, thanks for trying this out!

This **should ** already be accounted for because any times that you're waiting for input in that way, sit-for should have been called, and that should be subtracted and say something like this (I deliberately set the threshold to 0 to get this to print):

Wed May 20 21:27:02 2020 - 11 ms (sit-for 639 ms) - self-insert-command [cache.ts (typescript-mode)]

It's possible that those packages are using something different to delay for user input, in which case I need to advise and/or hook on those things.

If you can try to make/confirm repro case with just which-key that would be so awesome, but I'll pull which-key down as soon as I can (once I get initial work for #4 done).

[unhammer]

evil uses read-key-sequence:

- command-execute                                                  38  97%
 - call-interactively                                              38  97%
  - byte-code                                                      24  61%
   - evil-operator-range                                           24  61%
    - evil-read-motion                                             22  56%
     - evil-keypress-parser                                        22  56%
      - read-key-sequence                                          22  56%
       - apply                                                     22  56%
        - ad-Advice-read-key-sequence                              22  56%
         - #<subr read-key-sequence>                               18  46%
          - timer-event-handler                                     4  10%
           - apply                                                  4  10%
            - explain--measure-idle-timer-callback                  4  10%
             - explain--measure-function                            4  10%
              - if                                                  4  10%
               - let                                                4  10%
                + let                                               4  10%
    - evil-change-state                                             1   2%
     - evil-operator-state                                          1   2%
        evil-normalize-keymaps                                      1   2%
    - #<compiled 0x991d9d33dcb4251>                                 1   2%
     - evil-change-state                                            1   2%
      - evil-normal-state                                           1   2%
       - evil-normalize-keymaps                                     1   2%
        - evil-state-keymaps                                        1   2%
         - apply                                                    1   2%
          - evil-state-keymaps                                      1   2%
           - evil-state-overriding-keymaps                          1   2%
              evil-overriding-keymap-p                              1   2%
  - funcall-interactively                                          14  35%
   - evil-delete                                                   14  35%
    - apply                                                        14  35%
     - evil-goggles--generic-blocking-advice                       13  33%
      - evil-goggles--show-blocking-hint                           13  33%
       - sit-for                                                   12  30%
        - apply                                                    12  30%
         - explain--wrap-sit-for                                   12  30%
          - let                                                    12  30%
           - let                                                   12  30%
            - apply                                                12  30%
             - #<compiled -0x78bc3da3894956c>                      12  30%
              - redisplay                                          12  30%
               - redisplay_internal (C function)                    1   2%
                - eval                                              1   2%
                 - rm--mode-list-as-string-list                     1   2%
                  - mapcar                                          1   2%
                     rm-format-mode-line-entry                      1   2%
         #<compiled 0x16549650237112>                               1   2%
     + #<compiled -0x10d76ba752c2bc16>                              1   2%
- jit-lock--antiblink-post-command                                  1   2%
   syntax-ppss                                                      1   2%
- ...                                                               0   0%
   Automatic GC                                                     0   0%

[lastquestion]

Ahhhhah, OK. Thanks for jumping in with the callstack @unhammer. Did you get this from the profile that was generated? Very nice. 💯

This doesn't have anything to do with evil being super fancy, which I feared. Rather that I didn't handle read-key-sequence. I read the c code; read-key-sequence (ref: https://github.com/emacs-mirror/emacs/blob/master/src/keyboard.c#L9839) (which is a giant, hairy, and classic 20+ year old function) does a lot of things to eat keys until it can form a key sequence, but ultimately it calls read_char (ref: https://github.com/emacs-mirror/emacs/blob/master/src/keyboard.c#L2327) which:

• does redisplay
• runs timers, including idle timers
• redisplays if requested
• and has a time for when it should end, just like sit_for
• and sometimes calls sit_for itself.

And the callstack above shows that: there's an idle timer running inside read-key-sequence, which has been successfully advised by explain-pause-mode itself! haha.

So, the C level sit_fors will never be advised, but that's OK. We can advise at the read-key-sequence layer, and count the entire time it ran as non-blocking time. The C code allows the things to update, timers to run and the screen to redisplay, so I think that's appropriate.

I'm going to update the title of this issue and then add a checklist in the next comment.

[lastquestion]

• Advise read-key-sequence, read-key-sequence-vector. They act like non-blocking keyboard eat waits, so discount their entire execution time, same as sit-for.
• Check C code for all calls to read_key_sequence
• Check C code for parent calls to read_char, which ultimately is doing the nonblocking wait. Are there are other functions that need advising at the elisp layer?

[lastquestion]

Fri May 22 00:08:42 2020 - 2 ms (read-key* 1393ms) - from mini-buffer (`explain-pause-log-all-input-loop`), from mini-buffer (`customize-set-variable`), counsel-M-x [*scratch* (lisp-interaction-mode)]

Progress!

• read-key is also exposed, need to check on this.

The native C callstacks that could call read_key_sequence:

• menu_show_hook ~ tty_menu_show -> tty_menu_activate -> read_menu_input -> read_menu_command -> read_key_sequence
  It's only used only for TTY menus, which is menu-bar-open. Bound to [F10] normally. menu-bar-open in graphical systems opens a minibuffer driven text menu. I'm not quite sure what I want to do here, but I'll probably either exclude menu-bar-open from being tracked, or advise it.

• call-interactively -> k or K -> read_key_sequence
  This is important, but I will open a new issue to track it. Almost all real-life uses of call-interactively are going to open the minibuffer to request input from the user, which causes minibuffer hooks to fire. So in reality, this already isn't a problem. But it should be possible to deal with pathological cases. call-interactively is NOT called from C code so advising it is safe.

Found 3 more functions that need to be advised; none of them are called from C code (except for one use in call-interactively)

• read-char
• read-char-exclusive
• read-event

[lastquestion]

I've tested this with direct calls to read-key-sequence. Can either of you guys give this a shot @aaronjensen @unhammer and let me know if it fixes it in evil? Please reopen this issue if not. 🎉 THANK YOU!

[unhammer]

Fixes it for me, I can d[wait five seconds]d and it no longer says Emacs was blocked (but it still correctly says Gnus took five seconds of my life) :)

[lastquestion]

Fastest user feedback ever. <grin>

[aaronjensen]

Works for me too! Thank you for the quick fix.