lastquestion / explain-pause-mode Goto Github PK

View Code? Open in Web Editor NEW

234.0 11.0 5.0 1.66 MB

top, but for Emacs.

License: GNU General Public License v3.0

Emacs Lisp 99.01% Makefile 0.99%

emacs performance melpa elisp

explain-pause-mode's Introduction

explain-pause-mode

See what's in development in the project board | Feature requests, bug reports, issues | Changelog

v0.2 is the current development release. See vNext for more details on what's coming next.

How to use

explain-pause-mode is very lightweight; you can leave it running all the time. Turn it on after requiring it:

(explain-pause-mode)

explain-pause-top shows a top-like view of the things Emacs has been doing:

Installing

There are 2 ways right now to install. (Melpa coming soon!)

Straight.el

If you are using straight.el, then you can use a normal receipe to install:

(straight-use-package
 '(explain-pause-mode :type git :host github :repo "lastquestion/explain-pause-mode"))
(explain-pause-mode)

You might be using use-package with straight.el, then you can install and enable at the same time:

(use-package explain-pause-mode
  :straight (explain-pause-mode :type git :host github :repo "lastquestion/explain-pause-mode")
  :config
  (explain-pause-mode))

From sources

If you are interested in contributing, you might want to directly install from sources. Just git clone and then make install. make install will bytecompile and install the sources to a path you specify, which should be on your emacs load path. It is important to bytecompile and optimize explain-pause-mode for normal use, as the package hooks into many operations that happen on every command or keypress.

vNext

v0.3 major features roadmap:

Contribute

Feel free to take a look at the issues board, development is tracked openly on it and the the project board.

explain-pause-mode's People

Contributors

Stargazers

Watchers

Forkers

bbigras biffhero alphapapa emacsmirror lwiechec

explain-pause-mode's Issues

Enabling explain-pause-mode causes committing via magit/with-editor over TRAMP to stop working (Root cause: `with-editor` checks for itself with `process-filter`, which fails because we wrapped it)

Steps to reproduce

explain-pause-mode: version 318dace
magit: magit-20200108.532
emacs: 26.3
NixOS 20.03

Set up a git repo on a remote machine:

SERVER=srv
ssh $SERVER "mkdir tmp-git && cd tmp-git && git init

Now try to commit to that repo via magit over TRAMP, when explain-pause-mode is called.

(add-to-list 'load-path "~/.emacs.d/lisp/")

(require 'package)
(require 'explain-pause-mode)
(explain-pause-mode t)
(require 'magit)

(magit-status "/ssh:$SERVER:tmp-git")

To commit, switch to the "magit: tmp-git" buffer, and hit "c c"

Expected

magit's mode for writing commit message is displayed.

Actual

magit's mode for writing commit message is not displayed. The current buffer is still "magit: tmp-git". There is a buffer named "magit-process: git-tmp" which is typically read by with-editor's process filter (which doesn't get executed, when explain-pause-mode is enabled).

Some diagnosis

If I don't execute explain-pause-mode, then I get the expected behaviour.

Attempt at figuring root cause

Using edebug-defun I set edebug to trace calls to explain--wrap-set-process-filter-callback and with-editor-process-filter .

When explain-pause-mode is enabled, I observe only is executed explain--wrap-set-process-filter-callback (notably, with-editor-process-filter is not executed). I expect with-editor-process-filter to also execute, however.

When explain-pause-mode is disabled, I observe with-editor-process-filter is executed, as expected.

More context

#44 (comment)
https://github.com/tomfitzhenry/dotfiles/commit/09d05c4d16a9421b9cb8b9efde550f4549fec4e0

explain-pause-top breaks notmuch thread view (root cause: `:stderr` option of `make-process` when given a BUFFER does not work)

With explain-pause-top the threads in notmuch are not accessible.

This is the error in Messages
or: Wrong type argument: explain-pause-command-record, nil

Verify that the timing for opening pure text files is around 100ms

I tested in my regular conf.
It's possible there is special magic around here which is confusing the package.

Verify in emacs -Q that it still opens that slow
Verify the command-loop for open really is 100ms. Instrument or bind against native code in emacs. Maybe use dtrace to verify what's going on.

verify `run_hooks_with_args` native use

Advise any in the same was as safe_run_hooks as in #56 .

Frames do not match in 'not top level in wrap-native for #<subr read-from-minibuffer>' (root-cause: native-comp branch doesn't respect advices yet... I think)

Hi, I decided to give this cool package a try.

Once the package is enabled, any time I try to access M-x with ivy I get the following error message. For reference, I am using the native-compile branch of Emacs on a linux machine with Spacemacs.

frames do not match in 'not top level in wrap-native for #<subr read-from-minibuffer>'
current:
#s(explain-pause-command-record root-emacs nil nil 63056 (24323 4741 255931 522000) nil nil nil nil 0)
test:
#s(explain-pause-command-record root-emacs nil nil 63056 (24323 4741 255931 522000) nil nil nil nil 0)


Backtrace:
  backtrace()
  explain-pause-report-measuring-bug("not top level in wrap-native for #<subr read-from-..." #s(explain-pause-command-record :command root-emacs :native nil :parent nil :executing-time 63056 :entry-snap (24323 4741 255931 522000) :too-slow nil :is-profiled nil :under-profile nil :profile nil :depth 0) #s(explain-pause-command-record :command root-emacs :native nil :parent nil :executing-time 63056 :entry-snap (24323 4741 255931 522000) :too-slow nil :is-profiled nil :under-profile nil :profile nil :depth 0))
  explain-pause--wrap-native(#<subr read-from-minibuffer> "M-x " "^" (keymap (keymap (67108908 . counsel--info-lookup-symbol) (67108910 . counsel-find-symbol)) keymap (escape . minibuffer-keyboard-quit) (12 . ivy-alt-done) (33554440 keymap (113 . help-quit) (118 . describe-variable) (119 . where-is) (116 . help-with-tutorial) (115 . describe-syntax) (114 . info-emacs-manual) (80 . describe-package) (112 . finder-by-keyword) (110 . view-emacs-news) (111 . describe-symbol) (109 . describe-mode) (108 . view-lossage) (107 . describe-key) (52 keymap (105 . info-other-window)) (105 . info) (104 . view-hello-file) (103 . describe-gnu-project) (102 . describe-function) (101 . view-echo-area-messages) (100 . apropos-documentation) (99 . describe-key-briefly) (98 . describe-bindings) (97 . apropos-command) (83 . info-lookup-symbol) (76 . describe-language-environment) (75 . Info-goto-emacs-key-command-node) (73 . describe-input-method) (70 . Info-goto-emacs-command-node) (67 . describe-coding-system) (28 . describe-input-method) (23 . describe-no-warranty) (20 . view-emacs-todo) (19 . search-forward-help-for-help) (16 . view-emacs-problems) (15 . describe-distribution) (14 . view-emacs-news) (13 . view-order-manuals) (6 . view-emacs-FAQ) (5 . view-external-packages) (4 . view-emacs-debugging) (3 . describe-copying) (1 . about-emacs) (63 . help-for-help) (46 . display-local-help) (f1 . help-for-help) (help . help-for-help) (8 . help-for-help)) (8 . "\177") (11 . ivy-previous-line) (36 . ivy-magic-read-file-env) (3 keymap (19 . ivy-rotate-sort) (1 . ivy-toggle-ignore) (15 . ivy-occur)) (33554464 . ivy-restrict-to-matches) (15 . hydra-ivy/body) (22 . ivy-scroll-up-command) (prior . ivy-scroll-down-command) (next . ivy-scroll-up-command) (7 . minibuffer-keyboard-quit) (right . ivy-forward-char) (32 . self-insert-command) (18 . ivy-reverse-i-search) (remap keymap (describe-mode . ivy-help) (kill-ring-save . ivy-kill-ring-save) (kill-whole-line . ivy-kill-whole-line) (kill-line . ivy-kill-line) (scroll-down-command . ivy-scroll-down-command) (scroll-up-command . ivy-scroll-up-command) (end-of-buffer . ivy-end-of-buffer) (beginning-of-buffer . ivy-beginning-of-buffer) (kill-word . ivy-kill-word) (forward-char . ivy-forward-char) (delete-char . ivy-delete-char) (backward-kill-word . ivy-backward-kill-word) (backward-delete-char-untabify . ivy-backward-delete-char) (delete-backward-char . ivy-backward-delete-char) (previous-line . ivy-previous-line) (next-line . ivy-next-line)) (9 . ivy-partial-or-done) (10 . ivy-next-line) (27 keymap (32 . hydra-ivy/body) (1 . ivy-read-action) (15 . ivy-dispatching-call) (111 . ivy-dispatching-done) (25 . ivy-insert-current-full) (105 . ivy-insert-current) (106 . ivy-yank-word) (114 . ivy-toggle-regexp-quote) (97 . ivy-toggle-marks) (16 . ivy-previous-line-and-call) (14 . ivy-next-line-and-call) (118 . ivy-scroll-down-command) (112 . ivy-previous-history-element) (110 . ivy-next-history-element) (10 . ivy-immediate-done) (13 . ivy-call)) (mouse-3 . ivy-mouse-dispatching-done) (mouse-1 . ivy-mouse-done) (down-mouse-1 . ignore) (13 . ivy-done)) nil counsel-M-x-history)
  apply(explain-pause--wrap-native #<subr read-from-minibuffer> ("M-x " "^" (keymap (keymap (67108908 . counsel--info-lookup-symbol) (67108910 . counsel-find-symbol)) keymap (escape . minibuffer-keyboard-quit) (12 . ivy-alt-done) (33554440 keymap (113 . help-quit) (118 . describe-variable) (119 . where-is) (116 . help-with-tutorial) (115 . describe-syntax) (114 . info-emacs-manual) (80 . describe-package) (112 . finder-by-keyword) (110 . view-emacs-news) (111 . describe-symbol) (109 . describe-mode) (108 . view-lossage) (107 . describe-key) (52 keymap (105 . info-other-window)) (105 . info) (104 . view-hello-file) (103 . describe-gnu-project) (102 . describe-function) (101 . view-echo-area-messages) (100 . apropos-documentation) (99 . describe-key-briefly) (98 . describe-bindings) (97 . apropos-command) (83 . info-lookup-symbol) (76 . describe-language-environment) (75 . Info-goto-emacs-key-command-node) (73 . describe-input-method) (70 . Info-goto-emacs-command-node) (67 . describe-coding-system) (28 . describe-input-method) (23 . describe-no-warranty) (20 . view-emacs-todo) (19 . search-forward-help-for-help) (16 . view-emacs-problems) (15 . describe-distribution) (14 . view-emacs-news) (13 . view-order-manuals) (6 . view-emacs-FAQ) (5 . view-external-packages) (4 . view-emacs-debugging) (3 . describe-copying) (1 . about-emacs) (63 . help-for-help) (46 . display-local-help) (f1 . help-for-help) (help . help-for-help) (8 . help-for-help)) (8 . "\177") (11 . ivy-previous-line) (36 . ivy-magic-read-file-env) (3 keymap (19 . ivy-rotate-sort) (1 . ivy-toggle-ignore) (15 . ivy-occur)) (33554464 . ivy-restrict-to-matches) (15 . hydra-ivy/body) (22 . ivy-scroll-up-command) (prior . ivy-scroll-down-command) (next . ivy-scroll-up-command) (7 . minibuffer-keyboard-quit) (right . ivy-forward-char) (32 . self-insert-command) (18 . ivy-reverse-i-search) (remap keymap (describe-mode . ivy-help) (kill-ring-save . ivy-kill-ring-save) (kill-whole-line . ivy-kill-whole-line) (kill-line . ivy-kill-line) (scroll-down-command . ivy-scroll-down-command) (scroll-up-command . ivy-scroll-up-command) (end-of-buffer . ivy-end-of-buffer) (beginning-of-buffer . ivy-beginning-of-buffer) (kill-word . ivy-kill-word) (forward-char . ivy-forward-char) (delete-char . ivy-delete-char) (backward-kill-word . ivy-backward-kill-word) (backward-delete-char-untabify . ivy-backward-delete-char) (delete-backward-char . ivy-backward-delete-char) (previous-line . ivy-previous-line) (next-line . ivy-next-line)) (9 . ivy-partial-or-done) (10 . ivy-next-line) (27 keymap (32 . hydra-ivy/body) (1 . ivy-read-action) (15 . ivy-dispatching-call) (111 . ivy-dispatching-done) (25 . ivy-insert-current-full) (105 . ivy-insert-current) (106 . ivy-yank-word) (114 . ivy-toggle-regexp-quote) (97 . ivy-toggle-marks) (16 . ivy-previous-line-and-call) (14 . ivy-next-line-and-call) (118 . ivy-scroll-down-command) (112 . ivy-previous-history-element) (110 . ivy-next-history-element) (10 . ivy-immediate-done) (13 . ivy-call)) (mouse-3 . ivy-mouse-dispatching-done) (mouse-1 . ivy-mouse-done) (down-mouse-1 . ignore) (13 . ivy-done)) nil counsel-M-x-history))
  read-from-minibuffer("M-x " "^" (keymap (keymap (67108908 . counsel--info-lookup-symbol) (67108910 . counsel-find-symbol)) keymap (escape . minibuffer-keyboard-quit) (12 . ivy-alt-done) (33554440 keymap (113 . help-quit) (118 . describe-variable) (119 . where-is) (116 . help-with-tutorial) (115 . describe-syntax) (114 . info-emacs-manual) (80 . describe-package) (112 . finder-by-keyword) (110 . view-emacs-news) (111 . describe-symbol) (109 . describe-mode) (108 . view-lossage) (107 . describe-key) (52 keymap (105 . info-other-window)) (105 . info) (104 . view-hello-file) (103 . describe-gnu-project) (102 . describe-function) (101 . view-echo-area-messages) (100 . apropos-documentation) (99 . describe-key-briefly) (98 . describe-bindings) (97 . apropos-command) (83 . info-lookup-symbol) (76 . describe-language-environment) (75 . Info-goto-emacs-key-command-node) (73 . describe-input-method) (70 . Info-goto-emacs-command-node) (67 . describe-coding-system) (28 . describe-input-method) (23 . describe-no-warranty) (20 . view-emacs-todo) (19 . search-forward-help-for-help) (16 . view-emacs-problems) (15 . describe-distribution) (14 . view-emacs-news) (13 . view-order-manuals) (6 . view-emacs-FAQ) (5 . view-external-packages) (4 . view-emacs-debugging) (3 . describe-copying) (1 . about-emacs) (63 . help-for-help) (46 . display-local-help) (f1 . help-for-help) (help . help-for-help) (8 . help-for-help)) (8 . "\177") (11 . ivy-previous-line) (36 . ivy-magic-read-file-env) (3 keymap (19 . ivy-rotate-sort) (1 . ivy-toggle-ignore) (15 . ivy-occur)) (33554464 . ivy-restrict-to-matches) (15 . hydra-ivy/body) (22 . ivy-scroll-up-command) (prior . ivy-scroll-down-command) (next . ivy-scroll-up-command) (7 . minibuffer-keyboard-quit) (right . ivy-forward-char) (32 . self-insert-command) (18 . ivy-reverse-i-search) (remap keymap (describe-mode . ivy-help) (kill-ring-save . ivy-kill-ring-save) (kill-whole-line . ivy-kill-whole-line) (kill-line . ivy-kill-line) (scroll-down-command . ivy-scroll-down-command) (scroll-up-command . ivy-scroll-up-command) (end-of-buffer . ivy-end-of-buffer) (beginning-of-buffer . ivy-beginning-of-buffer) (kill-word . ivy-kill-word) (forward-char . ivy-forward-char) (delete-char . ivy-delete-char) (backward-kill-word . ivy-backward-kill-word) (backward-delete-char-untabify . ivy-backward-delete-char) (delete-backward-char . ivy-backward-delete-char) (previous-line . ivy-previous-line) (next-line . ivy-next-line)) (9 . ivy-partial-or-done) (10 . ivy-next-line) (27 keymap (32 . hydra-ivy/body) (1 . ivy-read-action) (15 . ivy-dispatching-call) (111 . ivy-dispatching-done) (25 . ivy-insert-current-full) (105 . ivy-insert-current) (106 . ivy-yank-word) (114 . ivy-toggle-regexp-quote) (97 . ivy-toggle-marks) (16 . ivy-previous-line-and-call) (14 . ivy-next-line-and-call) (118 . ivy-scroll-down-command) (112 . ivy-previous-history-element) (110 . ivy-next-history-element) (10 . ivy-immediate-done) (13 . ivy-call)) (mouse-3 . ivy-mouse-dispatching-done) (mouse-1 . ivy-mouse-done) (down-mouse-1 . ignore) (13 . ivy-done)) nil counsel-M-x-history)
  ivy-read("M-x " ("explain-pause-mode" "org-mode" "package-install" "visual-fill-column-mode" "visual-line-mode" "prettier-js" "make-directory" "lsp" "emacs-lisp-mode" "typescript-mode" "rename-file" "revert-buffer" "package-delete" "macrostep-expand" "intero-mode" "haskell-mode" "counsel-fonts" "lsp-treemacs-errors-list" "vterm" "all-the-icons-install-fonts" "s" "ca" "cd" "5x5" "arp" "dbx" "dig" "erc" "ert" "eww" "ftp" "gdb" "irc" "jdb" "man" "mpc" "mvn" "pdb" "pwd" "rsh" "sdb" "xdb" "calc" "diff" "dirs" "ffap" "gnus" "grep" "help" "ielm" ...) :predicate #<subr F616e6f6e796d6f75732d6c616d626461_anonymous_lambda_31> :require-match t :history counsel-M-x-history :action counsel-M-x-action :keymap (keymap (67108908 . counsel--info-lookup-symbol) (67108910 . counsel-find-symbol)) :initial-input nil :caller counsel-M-x)
  counsel-M-x()
  #<subr funcall-interactively>(counsel-M-x)
  apply(#<subr funcall-interactively> counsel-M-x)
  funcall-interactively(counsel-M-x)
  command-execute(counsel-M-x)

Let me know how I can help to debug this issue, thanks!

Top should support total time executed, and show native frames

Unclear what the UI would be to make this viable, but sometimes pauses will not show because they are waiting in native code and we are hiding native frames and also subtracting native time out of command execution time. This made #57 more difficult to debug.

Handle sit-for variants inside timers and process handlers

You're "not suppposed to do that", according to the emacs docs, but for example a timer can write a message to the minibuffer via minibuffer-message which calls sit-for internally.

Don't trust anyone, and discount sit-for times inside timers and process handlers, too.

Example repro:

(run-with-timer 1 nil (lambda ()
                        (minibuffer-message "a long message")))

will give

Wed May 27 22:38:11 2020 - 2004 ms - (lambda nil (minibuffer-message a long message)), timer

only because the default wait inside minibuffer-message is 2 seconds.

key-chord broken

Hi,

First of all, thanks for your package 👍

I am trying to use this package with key-chord (https://github.com/emacsorphanage/key-chord).

I noticed that may key-chord bindings do not work anymore when your package is active. I also notice that it only happens when the operation behind the chord takes a long time (maybe more that your default 40ms setting?).

There's goes a minimal test.el file you use to test this. It uses straight.el to install both your package and key chord

(defvar bootstrap-version)
(let ((bootstrap-file
       (expand-file-name "straight/repos/straight.el/bootstrap.el" user-emacs-directory))
      (bootstrap-version 5))
  (unless (file-exists-p bootstrap-file)
    (with-current-buffer
        (url-retrieve-synchronously
         "https://raw.githubusercontent.com/raxod502/straight.el/develop/install.el"
         'silent 'inhibit-cookies)
      (goto-char (point-max))
      (eval-print-last-sexp)))
  (load bootstrap-file nil 'nomessage))

(straight-use-package 'key-chord)

(defun slow-operation ()
  (interactive)
  (sleep-for 2)
  (message "Done!"))

(require 'key-chord)
(key-chord-mode 1)
(key-chord-define-global "ab" 'slow-operation)


(when load-explain
  (message "Loading explain...")
  (straight-use-package '(explain-pause-mode
			  :host github
			  :repo "lastquestion/explain-pause-mode"
			  :branch "master"))
  (require 'explain-pause-mode)
  (explain-pause-mode 1))

You can test two scenarios:

emacs -Q --eval "(setq load-explain nil)" --load test.el: baseline: key chord without explain: you can type both keys ab and it will run the slow-operation and display Done
emacs -Q --eval "(setq load-explain tl)" --load test.el: bug: key chord with explain: you can type both keys ab and it will never run the slow-operation.

I tried increasing explain-pause-blocking-too-long-ms but it doesn't seem to help.

Handle recursive-edit (fixes debugger, and other things)

in #42 we started recording time via call-interactively and making a call stack, versus attempting to measure via pre-/post-command hooks. This is way more accurate, but recursive-edit breaks it. This is used by debug which can confuse the call stack tracking.

Fix and add a test by advising recursive-edit in some way, if possible.

Pass bytecompile

Lots of warnings.

frames do not match in 'not top level in wrap-native for #<subr read-event>' (root cause: flyspell runs `sit-for` in `post-command-hook`)

Reported by @condy0919 in #50, splitting it into a separate bug:

Explain-pause-mode: please report this bug by creating a Github
issue at https://github.com/lastquestion/explain-pause-mode. Explain-pause-mode
is now _disabled_ so you can continue to hopefully use Emacs. Info follows:


frames do not match in 'not top level in wrap-native for #<subr read-event>'
current:
#s(explain-pause-command-record root-emacs nil nil 1146334 (24320 27529 114676 750000) nil nil nil nil 0)
test:
#s(explain-pause-command-record root-emacs nil nil 1146334 (24320 27529 114676 750000) nil nil nil nil 0)


Backtrace:
  backtrace()
  explain-pause-report-measuring-bug("not top level in wrap-native for #<subr read-event..." #s(explain-pause-command-record :command root-emacs :native nil :parent nil :executing-time 1146334 :entry-snap (24320 27529 114676 750000) :too-slow nil :is-profiled nil :under-profile nil :profile nil :depth 0) #s(explain-pause-command-record :command root-emacs :native nil :parent nil :executing-time 1146334 :entry-snap (24320 27529 114676 750000) :too-slow nil :is-profiled nil :under-profile nil :profile nil :depth 0))
  explain-pause--wrap-native(#<subr read-event> nil t 3)
  apply(explain-pause--wrap-native #<subr read-event> (nil t 3))
  read-event(nil t 3)
  sit-for(3)
  flyspell-check-word-p()
  flyspell-post-command-hook()

Process-filter format exception on Emacs 28 + LSP + magit (root cause: `explain--function-as-string` does not escape format specifiers)

error in process filter: explain--alert-profile: Not enough arguments for format string
error in process filter: Not enough arguments for format string

This should never happen, the line is https://github.com/lastquestion/explain-pause-mode/blob/master/explain-pause-mode.el#L156m even nil counts as a valid argument.

This bug was filed from Reddit, there isn't more repro steps than this yet. Will try to get more details from reddit user.

Not sure how this could happen unless there's something changed way process filters work in 28.

87b0478 breaks emacs if started during init

Prior to this, it worked fine on Emacs 27 with my config. With the latest master, I see this or something like it after every command and nothing works at all. I have to kill emacs.

*ERROR*: Symbol’s function definition is void: explain-pause--seq-contains

As far as I can tell, if I start emacs and then evaluate explain-pause-mode, it works out.

"wrong-type-argument hash-table-p nil" when opening a buffer to write a commit message in magit (duplicate with #26)

Was on a magit-status committing some changes and when opening the COMMIT_EDITMSG buffer I experience that error, there is the backtrace:

Debugger entered--Lisp error: (wrong-type-argument hash-table-p nil)
  profiler-cpu-log()
  (profiler-make-profile :type 'cpu :timestamp (current-time) :log (profiler-cpu-log))
  explain--save-and-stop-profiling()
  (let ((profile (explain--save-and-stop-profiling))) (if too-long (progn (explain--store-profile now-snap diff command-set profile))))
  (progn (let ((profile (explain--save-and-stop-profiling))) (if too-long (progn (explain--store-profile now-snap diff command-set profile)))))
  (if was-profiled (progn (let ((profile (explain--save-and-stop-profiling))) (if too-long (progn (explain--store-profile now-snap diff command-set profile))))))
  (let* ((now-snap (current-time)) (diff (explain--as-ms-exact (time-subtract now-snap before-snap))) (too-long (> diff explain-pause-slow-too-long-ms))) (if was-profiled (progn (let ((profile (explain--save-and-stop-profiling))) (if too-long (progn (explain--store-profile now-snap diff command-set profile)))))) (setq executing-command original-execution-command) (run-hook-with-args 'explain-pause-measured-command-hook diff 0 command-set (and was-profiled too-long)) (if (or too-long (symbol-value diff-override)) (progn (explain--log-pause diff 0 command-set nil nil) (if too-long (progn (explain--increment-profile command-set))))))
  (let ((before-snap (current-time))) (apply measure-func args) (let* ((now-snap (current-time)) (diff (explain--as-ms-exact (time-subtract now-snap before-snap))) (too-long (> diff explain-pause-slow-too-long-ms))) (if was-profiled (progn (let ((profile (explain--save-and-stop-profiling))) (if too-long (progn (explain--store-profile now-snap diff command-set profile)))))) (setq executing-command original-execution-command) (run-hook-with-args 'explain-pause-measured-command-hook diff 0 command-set (and was-profiled too-long)) (if (or too-long (symbol-value diff-override)) (progn (explain--log-pause diff 0 command-set nil nil) (if too-long (progn (explain--increment-profile command-set)))))))
  (let ((original-execution-command executing-command) (was-profiled (and (not profiling-command) (explain--profile-p command-set)))) (setq executing-command command-set) (if was-profiled (progn (explain--start-profiling))) (let ((before-snap (current-time))) (apply measure-func args) (let* ((now-snap (current-time)) (diff (explain--as-ms-exact (time-subtract now-snap before-snap))) (too-long (> diff explain-pause-slow-too-long-ms))) (if was-profiled (progn (let ((profile ...)) (if too-long (progn ...))))) (setq executing-command original-execution-command) (run-hook-with-args 'explain-pause-measured-command-hook diff 0 command-set (and was-profiled too-long)) (if (or too-long (symbol-value diff-override)) (progn (explain--log-pause diff 0 command-set nil nil) (if too-long (progn (explain--increment-profile command-set))))))))
  (if (not explain-pause-mode) (apply measure-func args) (let ((original-execution-command executing-command) (was-profiled (and (not profiling-command) (explain--profile-p command-set)))) (setq executing-command command-set) (if was-profiled (progn (explain--start-profiling))) (let ((before-snap (current-time))) (apply measure-func args) (let* ((now-snap (current-time)) (diff (explain--as-ms-exact (time-subtract now-snap before-snap))) (too-long (> diff explain-pause-slow-too-long-ms))) (if was-profiled (progn (let (...) (if too-long ...)))) (setq executing-command original-execution-command) (run-hook-with-args 'explain-pause-measured-command-hook diff 0 command-set (and was-profiled too-long)) (if (or too-long (symbol-value diff-override)) (progn (explain--log-pause diff 0 command-set nil nil) (if too-long (progn ...))))))))
  explain--measure-function(server-process-filter (#<process server <5>> "-dir /home/jorge/Documentos/straubinger-digital/jn...") (server-process-filter process-filter) explain-pause-log-all-process-io)
  (closure ((final-command-set server-process-filter process-filter) (original-callback . server-process-filter) (command-set process-filter) explain-pause-top-mode-abbrev-table explain-pause-top-mode-syntax-table cl-struct-explain-pause-top--command-entry-tags cl-struct-explain-pause-top--table-display-entry-tags cl-struct-explain-pause-top--table-tags t) (&rest callback-args) (explain--measure-function original-callback callback-args final-command-set 'explain-pause-log-all-process-io))(#<process server <5>> "-dir /home/jorge/Documentos/straubinger-digital/jn...")

this error does not pop always, just from time to time. My Emacs version is GNU Emacs 28.0.50 (build 3, x86_64-pc-linux-gnu, GTK+ Version 3.24.14, cairo version 1.17.3) of 2020-02-18

Expose event stream in Emacs in some form

Document the event stream
Add some kind of way to consume it in another Emacs process

Maybe have it show in a new top window?
Maybe have it directly just stream the output in a buffer?

This would have made it easier for user to debug in #57

Long Emacs session statistics

Apart from some commands taking a lot of time/memory to run, there is another common problem of Emacs being slower when running for a long time. The same command running on fresh Emacs and Emacs running for several days may take several times more time to finish.

The slowdown can be caused by many reasons, like overall memory leakage or just changing the environment (e.g. changing buffer text or buffer-local variables). Tracking down this kind of problems is extremely difficult without a right toolset. There were some attempts to make a toolset in the past [1,2], but they are often troublesome to use.

If would be useful to track how cpu time/memory consumption changes through Emacs session for various commands.

[1] https://www.emacswiki.org/emacs/EmacsMemoryDebugging
[2] http://notes.secretsauce.net/notes/2015/10/05_memory-leak-debugging-tools.html

"CPU profiler is already running" in magit (root cause: `server-start` aka server.el is not handled)

Every so often I get an error when trying to commit something in magit. I hit cc and get a "There was a problem with the editor" error. Pressing $ shows full output:

hint: Waiting for your editor to close the file... Waiting for Emacs...
*ERROR*: CPU profiler is already running
error: There was a problem with the editor '/Applications/Emacs.app/Contents/MacOS/bin/emacsclient --socket-name=/var/folders/tw/w2zffvln1xj2gn5rr26dw4gw0000gn/T/emacs501/server'.
Please supply the message using either -m or -F option.

If I try to commit again, it works fine.

I'm not able to reproduce this at-will, so I'm not entirely sure if it's due to explain-pause-mode or not. I've only started seeing it in the last week or so, which does correspond with when I started using explain-pause-mode though...

Does it sound like explain-pause-mode might be to blame here? Anything I can do to narrow it down?

not top level in wrap-native for #<subr read-event> (root cause: dgram socket full causes read-event, but if the dgram is full before command-entry, the current-command can be root)

@bqv, I've moved out your comment into a new issue. It's unrelated. :)

Explain-pause-mode: please report this bug by creating a Github
issue at https://github.com/lastquestion/explain-pause-mode. Explain-pause-mode
is now _disabled_ so you can continue to hopefully use Emacs. Info follows:

explain-pause version: 0.1
emacs version: 28.0.50

not top level in wrap-native for #<subr read-event>
current
#s(explain-pause-command-record root-emacs nil nil 13403357 (24336 4785 995038 705000) nil nil nil nil 0)

Backtrace:
  explain-pause-report-measuring-bug("not top level in wrap-native for #<subr read-event..." "current" #s(explain-pause-command-record :command root-emacs :native nil :parent nil :executing-time 13403357 :entry-snap (24336 4785 995038 705000) :too-slow nil :is-profiled nil :under-profile nil :profile nil :depth 0))
  (if (eq explain-pause--current-command-record explain-pause-root-command-loop) (explain-pause-report-measuring-bug (format "not top level in %s" (format "wrap-native for %s" original-func)) "current" explain-pause--current-command-record) (let ((current-record explain-pause--current-command-record)) (explain-pause--command-record-and-store current-record) (let ((new-frame (explain-pause--command-record-from-parent current-record current-record original-func t))) (progn (explain-pause-log--send-command-entry explain-pause--current-command-record new-frame) (setq explain-pause--current-command-record new-frame) (let ((should-profile (explain-pause--command-record-profile-p new-frame))) (if should-profile (progn (explain-pause--command-record-start-profiling new-frame))) (progn (or (and ... t) (signal ... ...)) (let* (...) (aset v 5 ...))) (unwind-protect (apply original-func args) (explain-pause--command-record-and-store new-frame) (if should-profile (progn ...)) (explain-pause-log--send-command-exit new-frame) (if (not ...) (explain-pause-report-measuring-bug ... "current" explain-pause--current-command-record "should be equal" new-frame) (explain-pause--run-measure-hook new-frame) (progn ... ...) (setq explain-pause--current-command-record current-record))))))))
  explain-pause--wrap-native(#<subr read-event> nil t 2)
  apply(explain-pause--wrap-native #<subr read-event> (nil t 2))
  read-event(nil t 2)
  sit-for(2)
  explain-pause-log--missing-socket-disable()
  (if (eq (aref explain-pause-log--dgram-buffer 0) next) (explain-pause-log--missing-socket-disable) (let* ((v explain-pause-log--dgram-buffer) (v (+ (aref explain-pause-log--dgram-buffer 1) 2))) (aset v v str)) (let* ((v explain-pause-log--dgram-buffer)) (aset v 1 next)))
  (let ((next (% (1+ (aref explain-pause-log--dgram-buffer 1)) explain-pause-log--dgram-buffer-size))) (if (eq (aref explain-pause-log--dgram-buffer 0) next) (explain-pause-log--missing-socket-disable) (let* ((v explain-pause-log--dgram-buffer) (v (+ (aref explain-pause-log--dgram-buffer 1) 2))) (aset v v str)) (let* ((v explain-pause-log--dgram-buffer)) (aset v 1 next))))
  (cond ((eq (car err) 'file-missing) (explain-pause-log--missing-socket-disable)) ((eq (car err) 'file-error) (let ((next (% (1+ (aref explain-pause-log--dgram-buffer 1)) explain-pause-log--dgram-buffer-size))) (if (eq (aref explain-pause-log--dgram-buffer 0) next) (explain-pause-log--missing-socket-disable) (let* ((v explain-pause-log--dgram-buffer) (v (+ ... 2))) (aset v v str)) (let* ((v explain-pause-log--dgram-buffer)) (aset v 1 next))))))
  (condition-case err (progn (while (not (eq (aref explain-pause-log--dgram-buffer 0) (aref explain-pause-log--dgram-buffer 1))) (process-send-string explain-pause-log--send-process (aref explain-pause-log--dgram-buffer (+ (aref explain-pause-log--dgram-buffer 0) 2))) (let* ((v explain-pause-log--dgram-buffer)) (aset v 0 (% (1+ (aref explain-pause-log--dgram-buffer 0)) explain-pause-log--dgram-buffer-size)))) (process-send-string explain-pause-log--send-process str)) (file-error (cond ((eq (car err) 'file-missing) (explain-pause-log--missing-socket-disable)) ((eq (car err) 'file-error) (let ((next (% ... explain-pause-log--dgram-buffer-size))) (if (eq (aref explain-pause-log--dgram-buffer 0) next) (explain-pause-log--missing-socket-disable) (let* (... ...) (aset v v str)) (let* (...) (aset v 1 next))))))))
  explain-pause-log--send-dgram("(\"enter\" \"weechat--relay-process-filter\" \"root-ema...")
  (progn (explain-pause-log--send-dgram (format "(\"enter\" \"%s\" \"%s\" \"%s\" %s %s %s %s %s %d)\n" (explain-pause--command-as-string (progn (or (and (memq ... cl-struct-explain-pause-command-record-tags) t) (signal 'wrong-type-argument (list ... record))) (aref record 1))) (explain-pause--command-as-string (progn (or (and (memq ... cl-struct-explain-pause-command-record-tags) t) (signal 'wrong-type-argument (list ... entry))) (aref entry 1))) (explain-pause--command-as-string (progn (or (and (memq ... cl-struct-explain-pause-command-record-tags) t) (signal 'wrong-type-argument (list ... ...))) (aref (progn (or ... ...) (aref record 3)) 1))) (progn (or (and (memq (type-of record) cl-struct-explain-pause-command-record-tags) t) (signal 'wrong-type-argument (list 'explain-pause-command-record record))) (aref record 2)) (progn (or (and (memq (type-of record) cl-struct-explain-pause-command-record-tags) t) (signal 'wrong-type-argument (list 'explain-pause-command-record record))) (aref record 4)) (progn (or (and (memq (type-of record) cl-struct-explain-pause-command-record-tags) t) (signal 'wrong-type-argument (list 'explain-pause-command-record record))) (aref record 6)) (progn (or (and (memq (type-of record) cl-struct-explain-pause-command-record-tags) t) (signal 'wrong-type-argument (list 'explain-pause-command-record record))) (aref record 7)) (progn (or (and (memq (type-of record) cl-struct-explain-pause-command-record-tags) t) (signal 'wrong-type-argument (list 'explain-pause-command-record record))) (aref record 8)) (progn (or (and (memq (type-of record) cl-struct-explain-pause-command-record-tags) t) (signal 'wrong-type-argument (list 'explain-pause-command-record record))) (aref record 10)))))
  (if explain-pause-log--send-process (progn (explain-pause-log--send-dgram (format "(\"enter\" \"%s\" \"%s\" \"%s\" %s %s %s %s %s %d)\n" (explain-pause--command-as-string (progn (or (and ... t) (signal ... ...)) (aref record 1))) (explain-pause--command-as-string (progn (or (and ... t) (signal ... ...)) (aref entry 1))) (explain-pause--command-as-string (progn (or (and ... t) (signal ... ...)) (aref (progn ... ...) 1))) (progn (or (and (memq ... cl-struct-explain-pause-command-record-tags) t) (signal 'wrong-type-argument (list ... record))) (aref record 2)) (progn (or (and (memq ... cl-struct-explain-pause-command-record-tags) t) (signal 'wrong-type-argument (list ... record))) (aref record 4)) (progn (or (and (memq ... cl-struct-explain-pause-command-record-tags) t) (signal 'wrong-type-argument (list ... record))) (aref record 6)) (progn (or (and (memq ... cl-struct-explain-pause-command-record-tags) t) (signal 'wrong-type-argument (list ... record))) (aref record 7)) (progn (or (and (memq ... cl-struct-explain-pause-command-record-tags) t) (signal 'wrong-type-argument (list ... record))) (aref record 8)) (progn (or (and (memq ... cl-struct-explain-pause-command-record-tags) t) (signal 'wrong-type-argument (list ... record))) (aref record 10))))))
  explain-pause-log--send-command-entry(#s(explain-pause-command-record :command root-emacs :native nil :parent nil :executing-time 13403357 :entry-snap (24336 4785 995038 705000) :too-slow nil :is-profiled nil :under-profile nil :profile nil :depth 0) #s(explain-pause-command-record :command weechat--relay-process-filter :native nil :parent #s(explain-pause-command-record :command process-filter :native nil :parent #s(explain-pause-command-record :command "weechat-relay-tls" :native nil :parent #s(explain-pause-command-record :command root-emacs :native nil :parent nil :executing-time 13403357 :entry-snap (24336 4785 995038 705000) :too-slow nil :is-profiled nil :under-profile nil :profile nil :depth 0) :executing-time 0 :entry-snap nil :too-slow nil :is-profiled nil :under-profile nil :profile nil :depth 1) :executing-time 0 :entry-snap nil :too-slow nil :is-profiled nil :under-profile nil :profile nil :depth 2) :executing-time 0 :entry-snap nil :too-slow nil :is-profiled nil :under-profile nil :profile nil :depth 3))
  (progn (explain-pause-log--send-command-entry explain-pause--current-command-record new-frame) (setq explain-pause--current-command-record new-frame) (let ((should-profile (explain-pause--command-record-profile-p new-frame))) (if should-profile (progn (explain-pause--command-record-start-profiling new-frame))) (progn (or (and (memq (type-of new-frame) cl-struct-explain-pause-command-record-tags) t) (signal 'wrong-type-argument (list 'explain-pause-command-record new-frame))) (let* ((v new-frame)) (aset v 5 (current-time)))) (unwind-protect (apply original-cb args) (explain-pause--command-record-and-store new-frame) (if should-profile (progn (explain-pause--command-record--save-and-stop-profiling new-frame))) (explain-pause-log--send-command-exit new-frame) (if (not (eq explain-pause--current-command-record new-frame)) (explain-pause-report-measuring-bug (format "wrap callback for %s" original-cb) "current" explain-pause--current-command-record "should be equal" new-frame) (explain-pause--run-measure-hook new-frame) (progn (or (and (memq ... cl-struct-explain-pause-command-record-tags) t) (signal 'wrong-type-argument (list ... current-record))) (let* ((v current-record)) (aset v 5 (current-time)))) (setq explain-pause--current-command-record current-record)))))
  (let ((new-frame (explain-pause--command-record-from-parent current-record parent-command-record original-cb))) (progn (explain-pause-log--send-command-entry explain-pause--current-command-record new-frame) (setq explain-pause--current-command-record new-frame) (let ((should-profile (explain-pause--command-record-profile-p new-frame))) (if should-profile (progn (explain-pause--command-record-start-profiling new-frame))) (progn (or (and (memq (type-of new-frame) cl-struct-explain-pause-command-record-tags) t) (signal 'wrong-type-argument (list 'explain-pause-command-record new-frame))) (let* ((v new-frame)) (aset v 5 (current-time)))) (unwind-protect (apply original-cb args) (explain-pause--command-record-and-store new-frame) (if should-profile (progn (explain-pause--command-record--save-and-stop-profiling new-frame))) (explain-pause-log--send-command-exit new-frame) (if (not (eq explain-pause--current-command-record new-frame)) (explain-pause-report-measuring-bug (format "wrap callback for %s" original-cb) "current" explain-pause--current-command-record "should be equal" new-frame) (explain-pause--run-measure-hook new-frame) (progn (or (and ... t) (signal ... ...)) (let* (...) (aset v 5 ...))) (setq explain-pause--current-command-record current-record))))))
  (let ((current-record explain-pause--current-command-record)) (explain-pause--command-record-and-store current-record) (let ((new-frame (explain-pause--command-record-from-parent current-record parent-command-record original-cb))) (progn (explain-pause-log--send-command-entry explain-pause--current-command-record new-frame) (setq explain-pause--current-command-record new-frame) (let ((should-profile (explain-pause--command-record-profile-p new-frame))) (if should-profile (progn (explain-pause--command-record-start-profiling new-frame))) (progn (or (and (memq ... cl-struct-explain-pause-command-record-tags) t) (signal 'wrong-type-argument (list ... new-frame))) (let* ((v new-frame)) (aset v 5 (current-time)))) (unwind-protect (apply original-cb args) (explain-pause--command-record-and-store new-frame) (if should-profile (progn (explain-pause--command-record--save-and-stop-profiling new-frame))) (explain-pause-log--send-command-exit new-frame) (if (not (eq explain-pause--current-command-record new-frame)) (explain-pause-report-measuring-bug (format "wrap callback for %s" original-cb) "current" explain-pause--current-command-record "should be equal" new-frame) (explain-pause--run-measure-hook new-frame) (progn (or ... ...) (let* ... ...)) (setq explain-pause--current-command-record current-record)))))))
  (if (not explain-pause-mode) (apply original-cb args) (let ((current-record explain-pause--current-command-record)) (explain-pause--command-record-and-store current-record) (let ((new-frame (explain-pause--command-record-from-parent current-record parent-command-record original-cb))) (progn (explain-pause-log--send-command-entry explain-pause--current-command-record new-frame) (setq explain-pause--current-command-record new-frame) (let ((should-profile (explain-pause--command-record-profile-p new-frame))) (if should-profile (progn (explain-pause--command-record-start-profiling new-frame))) (progn (or (and ... t) (signal ... ...)) (let* (...) (aset v 5 ...))) (unwind-protect (apply original-cb args) (explain-pause--command-record-and-store new-frame) (if should-profile (progn ...)) (explain-pause-log--send-command-exit new-frame) (if (not ...) (explain-pause-report-measuring-bug ... "current" explain-pause--current-command-record "should be equal" new-frame) (explain-pause--run-measure-hook new-frame) (progn ... ...) (setq explain-pause--current-command-record current-record))))))))
  explain-pause--wrap-callback(#s(explain-pause-command-record :command process-filter :native nil :parent #s(explain-pause-command-record :command "weechat-relay-tls" :native nil :parent #s(explain-pause-command-record :command root-emacs :native nil :parent nil :executing-time 13403357 :entry-snap (24336 4785 995038 705000) :too-slow nil :is-profiled nil :under-profile nil :profile nil :depth 0) :executing-time 0 :entry-snap nil :too-slow nil :is-profiled nil :under-profile nil :profile nil :depth 1) :executing-time 0 :entry-snap nil :too-slow nil :is-profiled nil :under-profile nil :profile nil :depth 2) weechat--relay-process-filter #<process weechat-relay-tls> "\0\0\1}\0\0\0\0\22_buffer_line_addedhda\0\0\0\11line_data\0\0\0fbuf...")
  apply(explain-pause--wrap-callback #s(explain-pause-command-record :command process-filter :native nil :parent #s(explain-pause-command-record :command "weechat-relay-tls" :native nil :parent #s(explain-pause-command-record :command root-emacs :native nil :parent nil :executing-time 13403357 :entry-snap (24336 4785 995038 705000) :too-slow nil :is-profiled nil :under-profile nil :profile nil :depth 0) :executing-time 0 :entry-snap nil :too-slow nil :is-profiled nil :under-profile nil :profile nil :depth 1) :executing-time 0 :entry-snap nil :too-slow nil :is-profiled nil :under-profile nil :profile nil :depth 2) weechat--relay-process-filter (#<process weechat-relay-tls> "\0\0\1}\0\0\0\0\22_buffer_line_addedhda\0\0\0\11line_data\0\0\0fbuf..."))
  (closure ((original-callback . weechat--relay-process-filter) (parent-command-record . #s(explain-pause-command-record :command process-filter :native nil :parent #s(explain-pause-command-record :command "weechat-relay-tls" :native nil :parent #s(explain-pause-command-record :command root-emacs :native nil :parent nil :executing-time 13403357 :entry-snap (24336 4785 995038 705000) :too-slow nil :is-profiled nil :under-profile nil :profile nil :depth 0) :executing-time 0 :entry-snap nil :too-slow nil :is-profiled nil :under-profile nil :profile nil :depth 1) :executing-time 0 :entry-snap nil :too-slow nil :is-profiled nil :under-profile nil :profile nil :depth 2)) explain-pause-top-mode-abbrev-table explain-pause-top-mode-syntax-table cl-struct-explain-pause-top--command-entry-tags cl-struct-explain-pause-top--table-display-entry-tags cl-struct-explain-pause-top--table-tags cl-struct-explain-pause-command-record-tags explain-pause-mode t) (&rest callback-args) (apply 'explain-pause--wrap-callback parent-command-record original-callback callback-args))(#<process weechat-relay-tls> "\0\0\1}\0\0\0\0\22_buffer_line_addedhda\0\0\0\11line_data\0\0\0fbuf...")

Originally posted by @bqv in #65 (comment)

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

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

explain-pause-top doesn't handle closures well (root cause: closure context includes newlines)

Regular functions are printed fine, closures aren't. Maybe it's better to abbreviate the display of a function to the max width of a column and add some sign of truncation...

Configurable profile-opening function

Hi @lastquestion,

Thanks for this package! It is a great idea, and a much more convenient workflow than manually profiling Emacs.

Do you think it makes sense to make the profile-opening function configurable? Right now, it is hard coded to profiler-report-profile-other-frame.

If it's made configurable, I'd personally configure it to just profiler-report-profile or profiler-report-profile-other-window so that new frames aren't being created. I've found that this could be a source of slowness on my setup.

Get testing working

Also, write a test suite.

After some investigation

Let's use buttercup
Try to find some kind full integration test driver that actually drives a full emacs?
Let's just handle write a makefile.

Track `menu-bar-open` in TTY only

This is elisp, which calls different kinds of menus. Need to test the various cases and decide what to do.

In TTY, the TTY menu eventually calls read_key_sequence in C land, and that time is not tracked, showing up as a slow call.

~~- [ ] test graphical mouse and non mouse~~ TTY only

test tmm-menubar
test popup-menu (F10 when menubar is visible)
figure out what both call down into to find the best place to advise

Optimally, we should treat menu like minibuffer, splitting up the execution time and restarting the tracking when the command begins execution, if possible.

Error running timer ‘explain--measure-timer-callback’: (args-out-of-range [] 0) Root cause: `explain-pause-top--table-refresh` called on first load with one entry already

I run into the following error when running explain-pause-top.
I am not that experienced with debugging emacs so I hope this is sufficient. If not please tell me how I can further assist.
I am running the latest Spacemacs develop on emacs 28.0.50 an using explain-pause-mode d18eea7

Error during redisplay: ((closure ((this-buffer . #<buffer *explain-pause-top*>) explain-pause-top-mode-abbrev-table explain-pause-top-mode-syntax-table cl-struct-explain-pause-top--command-entry-tags cl-struct-explain-pause-top--table-display-entry-tags cl-struct-explain-pause-top--table-tags t) (_) (explain-pause-top--buffer-update-width-from-windows this-buffer)) #<frame emacs@PC16-176 0x55b7451d0190>) signaled (args-out-of-range [] 0) [2 times]
Error running timer ‘explain--measure-timer-callback’: (args-out-of-range [] 0)
Emacs was slow 6 times recently. Run ‘explain-pause-top’ or check ‘*explain-pause-log*’ to learn more.
Error running timer ‘explain--measure-timer-callback’: (args-out-of-range [] 0) [20 times]

Why does `xterm--report-background-handler` and `version-handler` take 2 seconds to return on at least iterm2 and alacritty? Investigate emacs-bug. (was Doesn't detect pause when starting "emacsclient -nw")

I'm trying to track down a 2 second pause where running "emacsclient -nw SOMEFILE" shows emacs immediately (either on the scratch buffer or whatever buffer I was last interacting with in another window/tty) before it shows SOMEFILE.

I start explain-pause-mode in init.el at "emacs --daemon" start time. I tried to open a file 6 times in a row, but explain-pause-top just showed some normal ~70ms GC pauses, nothing close to 2000ms.

Dunno if this use-case is intended or even possible...

not top level in wrap-native for #<subr read-event> (root cause: disabled-command-function hook is called inside command-execute)

hello!

Explain-pause-mode: please report this bug by creating a Github
issue at https://github.com/lastquestion/explain-pause-mode. Explain-pause-mode
is now _disabled_ so you can continue to hopefully use Emacs. Info follows:

explain-pause version: 0.1
emacs version: 28.0.50

not top level in wrap-native for #<subr read-event>
current
#s(explain-pause-command-record root-emacs nil nil 4449444 (24332 37011 940679 239000) nil nil nil nil 0)

Backtrace:
  explain-pause-report-measuring-bug("not top level in wrap-native for #<subr read-event..." "current" #s(explain-pause-command-record :command root-emacs :native nil :parent nil :executing-time 4449444 :entry-snap (24332 37011 940679 239000) :too-slow nil :is-profiled nil :under-profile nil :profile nil :depth 0))
  (if (eq explain-pause--current-command-record explain-pause-root-command-loop) (explain-pause-report-measuring-bug (format "not top level in %s" (format "wrap-native for %s" original-func)) "current" explain-pause--current-command-record) (let ((current-record explain-pause--current-command-record)) (explain-pause--command-record-and-store current-record) (let ((new-frame (explain-pause--command-record-from-parent current-record current-record original-func t))) (progn (explain-pause-log--send-command-entry explain-pause--current-command-record new-frame) (setq explain-pause--current-command-record new-frame) (let ((should-profile (explain-pause--command-record-profile-p new-frame))) (if should-profile (progn (explain-pause--command-record-start-profiling new-frame))) (progn (or (and ... t) (signal ... ...)) (let* (...) (aset v 5 ...))) (unwind-protect (apply original-func args) (explain-pause--command-record-and-store new-frame) (if should-profile (progn ...)) (explain-pause-log--send-command-exit new-frame) (if (not ...) (explain-pause-report-measuring-bug ... "current" explain-pause--current-command-record "should be equal" new-frame) (explain-pause--run-measure-hook new-frame) (progn ... ...) (setq explain-pause--current-command-record current-record))))))))
  explain-pause--wrap-native(#<subr read-event>)
  apply(explain-pause--wrap-native #<subr read-event> nil)
  read-event()
  disabled-command-function()
  run-hooks(disabled-command-function)
  command-execute(dired-find-alternate-file)

nil deref error in treemacs when explain-pause-mode is active (root cause: process-filter wrap nil callback)

Opening a treemacs buffer, and calling treemacs-toggle-node on one of the folders triggers a (void-function nil) error

Debugger entered--Lisp error: (void-function nil)
  nil(#<process Process Future<1>> "finished\n")
  apply(nil (#<process Process Future<1>> "finished\n"))
  explain--measure-function(nil (#<process Process Future<1>> "finished\n") (nil sentinel-filter treemacs-TAB-action) explain-pause-log-all-process-io)
  #f(compiled-function (&rest callback-args) #<bytecode -0x1bdc34496122d242>)(#<process Process Future<1>> "finished\n")
  accept-process-output(#<process Process Future<1>>)
  pfuture-await-to-finish(#<process Process Future<1>>)
  treemacs--parse-collapsed-dirs(#<process Process Future<1>>)
  treemacs--expand-dir-node(#<marker (moves after insertion) at 48 in  *Treemacs-Scoped-Buffer-#<frame emacs (main frame) 0x7f97a8063a30>*> :recursive nil)
  treemacs-toggle-node(nil)
  treemacs-TAB-action(nil)
  funcall-interactively(treemacs-TAB-action nil)
  call-interactively(treemacs-TAB-action nil nil)
  command-execute(treemacs-TAB-action)

disabling explain-pause-mode eliminates the error.

I haven't dived much deeper into this so far (need to finish unrelated work) - but figured I'd post this here to see if there is any immediate insight. Thanks for taking a look!

Remove `explain-pause-profiles` and integrate into `explain-pause-top`

Add the buttons for slow runs into the rows in explain-pause-top. Remove the explain-pause-profiles hard-coded machinery; add a new hook similar to explain-pause-measured-command-hook, probably explain-pause-profiled-command-hook, that fires when a profile is saved. Thus, separate the core measurement engine with the display layer.

This should clear the way to fix #16, too.

Drop `dash.el` dependency

dash.el - It's really only used for -let and a few other things, and depending only on emacs builtins would make packaging and testing this easier.

~~- [ ] Check https://github.com/alphapapa/emacs-package-dev-handbook for other useful things~~ I'll open new issues as I explore more and keep this one simple

Wrong documentation

The README (https://github.com/lastquestion/explain-pause-mode/blob/master/README.md#L5-L5) reads to use (require-pause-mode t), but that command doesn't exist. Instead, it should read: (explain-pause-mode t).

Adjust profiling call stack depth

Apparently the default is 16, that's way too low. I was looking at profiles and the depth often already was 10-12 for relatively simple commands.

Double check my guess why that is in the native code in profiler.c

Hat tip to reddit user /u/cpitclaudel for pointing this out.

Cannot follow links with mouse click with the mode on

Hello,

Great mode idea, it should prove very useful !

Just one bug so far: when explain-pause-mode is on, clicking on links (be it emacs links such as the ones in help nodes, org links, etc.) does not do anything.

It can be reproduced with emacs -Q and loading only dash and the mode.

(tested on Emacs 26.3 on Linux)

frames do not match in 'not top level in wrap-native for #<subr read-event>' (root case: TTY terminal init happens in each new TTY emacsclient (emacsclient -nw), which does `readkey`)

Ran "emacsclient -nw" and got a "explain-pause-mode-report-bug" buffer containing:

Explain-pause-mode: please report this bug by creating a Github
issue at https://github.com/lastquestion/explain-pause-mode. Explain-pause-mode
is now _disabled_ so you can continue to hopefully use Emacs. Info follows:


frames do not match in 'not top level in wrap-native for #<subr read-event>'
current:
#s(explain-pause-command-record root-emacs nil nil -1 (24319 39098 109174 270000) nil nil nil nil 0)
test:
#s(explain-pause-command-record root-emacs nil nil -1 (24319 39098 109174 270000) nil nil nil nil 0)


Backtrace:
  backtrace()
  (progn (princ "Explain-pause-mode: please report this bug by creating a Github\012issue at https://github.com/lastquestion/explain-pause\
-mode. Explain-pause-mode\012is now _disabled_ so you can continue to hopefully use Emacs. Info follows:\012\012\012") (princ (format "fra\
mes do not match in '%s'\012current:\012%s\012test:\012%s\012\012\012" where current-command test-command)) (princ "Backtrace:\012") (back\
trace))
  (prog1 (progn (princ "Explain-pause-mode: please report this bug by creating a Github\012issue at https://github.com/lastquestion/explai\
n-pause-mode. Explain-pause-mode\012is now _disabled_ so you can continue to hopefully use Emacs. Info follows:\012\012\012") (princ (form\
at "frames do not match in '%s'\012current:\012%s\012test:\012%s\012\012\012" where current-command test-command)) (princ "Backtrace:\012"\
) (backtrace)) (internal-temp-output-buffer-show buf))
  (let* ((old-dir default-directory) (buf (save-current-buffer (set-buffer (get-buffer-create "explain-pause-mode-report-bug")) (prog1 (cu\
rrent-buffer) (kill-all-local-variables) (setq default-directory old-dir) (setq buffer-read-only nil) (setq buffer-file-name nil) (setq bu\
ffer-undo-list t) (let ((inhibit-read-only t) (inhibit-modification-hooks t)) (erase-buffer) (run-hooks (quote temp-buffer-setup-hook)))))\
) (standard-output buf)) (prog1 (progn (princ "Explain-pause-mode: please report this bug by creating a Github\012issue at https://github.\
com/lastquestion/explain-pause-mode. Explain-pause-mode\012is now _disabled_ so you can continue to hopefully use Emacs. Info follows:\012\
\012\012") (princ (format "frames do not match in '%s'\012current:\012%s\012test:\012%s\012\012\012" where current-command test-command)) \
(princ "Backtrace:\012") (backtrace)) (internal-temp-output-buffer-show buf)))
  explain-pause-report-measuring-bug("not top level in wrap-native for #<subr read-event>" #s(explain-pause-command-record root-emacs nil \
nil -1 (24319 39098 109174 270000) nil nil nil nil 0) #s(explain-pause-command-record root-emacs nil nil -1 (24319 39098 109174 270000) ni\
l nil nil nil 0))
  (if (eq explain-pause--current-command-record explain-pause-root-command-loop) (explain-pause-report-measuring-bug (format "not top leve\
l in %s" (format "wrap-native for %s" original-func)) explain-pause--current-command-record explain-pause-root-command-loop) (let ((curren\
t-record explain-pause--current-command-record)) (explain-pause--command-record-and-store current-record) (let ((new-frame (explain-pause-\
-command-record-from-parent current-record current-record original-func t))) (progn (explain-pause-log--send-command-entry explain-pause--\
current-command-record new-frame) (setq explain-pause--current-command-record new-frame) (let ((should-profile (explain-pause--command-rec\
ord-profile-p new-frame))) (if should-profile (progn (explain-pause--command-record-start-profiling new-frame))) (progn (or (and ... t) (s\
ignal ... ...)) (let* (...) (aset v 5 ...))) (unwind-protect (apply original-func args) (explain-pause--command-record-and-store new-frame\
) (if should-profile (progn ...)) (explain-pause-log--send-command-exit new-frame) (if (not ...) (explain-pause-report-measuring-bug ... e\
xplain-pause--current-command-record new-frame) (explain-pause--run-measure-hook new-frame) (progn ... ...) (setq explain-pause--current-c\
ommand-record current-record))))))))
  explain-pause--wrap-native(#<subr read-event> nil nil 2)
  apply(explain-pause--wrap-native #<subr read-event> (nil nil 2))
  read-event(nil nil 2)
  xterm--query("\033[>0c" (("\033[?" . xterm--version-handler) ("\033[>" . xterm--version-handler)))
  terminal-init-xterm()
  tty-run-terminal-initialization(#<frame F3 0x580f530> nil t)
  tty-create-frame-with-faces(((right-fringe . 12) (left-fringe . 12) (vertical-scroll-bars) (font . "Monospace-9") (horizontal-scroll-bar\
s) (window-system) (tty . "/dev/pts/0") (tty-type . "xterm-256color") (client . #<process server <2>>) (environment "OLDPWD=/home/nolan/.e\
macs.d/elisp" "_=/usr/bin/emacsclient" "DBUS_SESSION_BUS_ADDRESS=unix:path=/run/user/1000/bus" "GDMSESSION=lightdm-xsession" "ALACRITTY_LO\
G=/tmp/Alacritty-1803.log" "PATH=/home/nolan/.cargo/bin:/home/nolan/bin:/home/nolan/.cargo/bin:/home/nolan/bin:/home/nolan/.cargo/bin:/hom\
e/nolan/bin:/usr/local/bin:/usr/bin:/bin:/usr/local/games:/usr/games:/sbin:/usr/sbin:/usr/local/sbin:/sbin:/usr/sbin:/usr/local/sbin" "XDG\
_DATA_DIRS=/home/nolan/.local/share/flatpak/exports/share:/var/lib/flatpak/exports/share:/usr/local/share:/usr/share" "GCC_COLORS=error=01\
;31:warning=01;35:note=01;36:caret=01;32:locus=01:quote=01" "XDG_RUNTIME_DIR=/run/user/1000" "XDG_SESSION_ID=1" "XDG_VTNR=7" "SHLVL=2" "DI\
SPLAY=:0" "AUTOJUMP_SOURCED=1" "USER=nolan" "TERM=xterm-256color" "XDG_SESSION_CLASS=user" "XDG_SEAT_PATH=/org/freedesktop/DisplayManager/\
Seat0" "PYTHONSTARTUP=/home/nolan/.pythonrc" "LS_COLORS=rs=0:di=01;34:ln=01;36:mh=00:pi=40;33:so=01;35:do=01;35:bd=40;33;01:cd=40;33;01:or\
=40;31;01:mi=00:su=37;41:sg=30;43:ca=30;41:tw=30;42:ow=34;42:st=37;44:ex=01;32:*.tar=01;31:*.tgz=01;31:*.arc=01;31:*.arj=01;31:*.taz=01;31\
:*.lha=01;31:*.lz4=01;31:*.lzh=01;31:*.lzma=01;31:*.tlz=01;31:*.txz=01;31:*.tzo=01;31:*.t7z=01;31:*.zip=01;31:*.z=01;31:*.dz=01;31:*.gz=01\
;31:*.lrz=01;31:*.lz=01;31:*.lzo=01;31:*.xz=01;31:*.zst=01;31:*.tzst=01;31:*.bz2=01;31:*.bz=01;31:*.tbz=01;31:*.tbz2=01;31:*.tz=01;31:*.de\
b=01;31:*.rpm=01;31:*.jar=01;31:*.war=01;31:*.ear=01;31:*.sar=01;31:*.rar=01;31:*.alz=01;31:*.ace=01;31:*.zoo=01;31:*.cpio=01;31:*.7z=01;3\
1:*.rz=01;31:*.cab=01;31:*.wim=01;31:*.swm=01;31:*.dwm=01;31:*.esd=01;31:*.jpg=01;35:*.jpeg=01;35:*.mjpg=01;35:*.mjpeg=01;35:*.gif=01;35:*\
.bmp=01;35:*.pbm=01;35:*.pgm=01;35:*.ppm=01;35:*.tga=01;35:*.xbm=01;35:*.xpm=01;35:*.tif=01;35:*.tiff=01;35:*.png=01;35:*.svg=01;35:*.svgz\
=01;35:*.mng=01;35:*.pcx=01;35:*.mov=01;35:*.mpg=01;35:*.mpeg=01;35:*.m2v=01;35:*.mkv=01;35:*.webm=01;35:*.ogm=01;35:*.mp4=01;35:*.m4v=01;\
35:*.mp4v=01;35:*.vob=01;35:*.qt=01;35:*.nuv=01;35:*.wmv=01;35:*.asf=01;35:*.rm=01;35:*.rmvb=01;35:*.flc=01;35:*.avi=01;35:*.fli=01;35:*.f\
lv=01;35:*.gl=01;35:*.dl=01;35:*.xcf=01;35:*.xwd=01;35:*.yuv=01;35:*.cgm=01;35:*.emf=01;35:*.ogv=01;35:*.ogx=01;35:*.aac=00;36:*.au=00;36:\
*.flac=00;36:*.m4a=00;36:*.mid=00;36:*.midi=00;36:*.mka=00;36:*.mp3=00;36:*.mpc=00;36:*.ogg=00;36:*.ra=00;36:*.wav=00;36:*.oga=00;36:*.opu\
s=00;36:*.spx=00;36:*.xspf=00;36:" "LANG=en_US.UTF-8" "AUTOJUMP_ERROR_PATH=/home/nolan/.local/share/autojump/errors.log" "HOME=/home/nolan\
" "GDM_LANG=en_US.utf8" "XDG_GREETER_DATA_DIR=/var/lib/lightdm/data/nolan" "XAUTHORITY=/home/nolan/.Xauthority" "GPG_AGENT_INFO=/run/user/\
1000/gnupg/S.gpg-agent:0:1" "XDG_SESSION_TYPE=x11" "QT_QPA_PLATFORMTHEME=qt5ct" "LOGNAME=nolan" "XDG_SESSION_DESKTOP=lightdm-xsession" "PW\
D=/home/nolan/.emacs.d" "XDG_SEAT=seat0" "SSH_AGENT_PID=1717" "DESKTOP_SESSION=lightdm-xsession" "SSH_AUTH_SOCK=/run/user/1000/keyring/ssh\
" "XDG_SESSION_PATH=/org/freedesktop/DisplayManager/Session0" "COLORTERM=truecolor" "QT_ACCESSIBILITY=1" "WINDOWID=33554434" "SHELL=/bin/b\
ash")))
  #[257 "\300\001!\207" [tty-create-frame-with-faces] 3 "\012\012(fn PARAMS)"](((right-fringe . 12) (left-fringe . 12) (vertical-scroll-ba\
rs) (font . "Monospace-9") (horizontal-scroll-bars) (window-system) (tty . "/dev/pts/0") (tty-type . "xterm-256color") (client . #<process\
 server <2>>) (environment "OLDPWD=/home/nolan/.emacs.d/elisp" "_=/usr/bin/emacsclient" "DBUS_SESSION_BUS_ADDRESS=unix:path=/run/user/1000\
/bus" "GDMSESSION=lightdm-xsession" "ALACRITTY_LOG=/tmp/Alacritty-1803.log" "PATH=/home/nolan/.cargo/bin:/home/nolan/bin:/home/nolan/.carg\
o/bin:/home/nolan/bin:/home/nolan/.cargo/bin:/home/nolan/bin:/usr/local/bin:/usr/bin:/bin:/usr/local/games:/usr/games:/sbin:/usr/sbin:/usr\
/local/sbin:/sbin:/usr/sbin:/usr/local/sbin" "XDG_DATA_DIRS=/home/nolan/.local/share/flatpak/exports/share:/var/lib/flatpak/exports/share:\
/usr/local/share:/usr/share" "GCC_COLORS=error=01;31:warning=01;35:note=01;36:caret=01;32:locus=01:quote=01" "XDG_RUNTIME_DIR=/run/user/10\
00" "XDG_SESSION_ID=1" "XDG_VTNR=7" "SHLVL=2" "DISPLAY=:0" "AUTOJUMP_SOURCED=1" "USER=nolan" "TERM=xterm-256color" "XDG_SESSION_CLASS=user\
" "XDG_SEAT_PATH=/org/freedesktop/DisplayManager/Seat0" "PYTHONSTARTUP=/home/nolan/.pythonrc" "LS_COLORS=rs=0:di=01;34:ln=01;36:mh=00:pi=4\
0;33:so=01;35:do=01;35:bd=40;33;01:cd=40;33;01:or=40;31;01:mi=00:su=37;41:sg=30;43:ca=30;41:tw=30;42:ow=34;42:st=37;44:ex=01;32:*.tar=01;3\
1:*.tgz=01;31:*.arc=01;31:*.arj=01;31:*.taz=01;31:*.lha=01;31:*.lz4=01;31:*.lzh=01;31:*.lzma=01;31:*.tlz=01;31:*.txz=01;31:*.tzo=01;31:*.t\
7z=01;31:*.zip=01;31:*.z=01;31:*.dz=01;31:*.gz=01;31:*.lrz=01;31:*.lz=01;31:*.lzo=01;31:*.xz=01;31:*.zst=01;31:*.tzst=01;31:*.bz2=01;31:*.\
bz=01;31:*.tbz=01;31:*.tbz2=01;31:*.tz=01;31:*.deb=01;31:*.rpm=01;31:*.jar=01;31:*.war=01;31:*.ear=01;31:*.sar=01;31:*.rar=01;31:*.alz=01;\
31:*.ace=01;31:*.zoo=01;31:*.cpio=01;31:*.7z=01;31:*.rz=01;31:*.cab=01;31:*.wim=01;31:*.swm=01;31:*.dwm=01;31:*.esd=01;31:*.jpg=01;35:*.jp\
eg=01;35:*.mjpg=01;35:*.mjpeg=01;35:*.gif=01;35:*.bmp=01;35:*.pbm=01;35:*.pgm=01;35:*.ppm=01;35:*.tga=01;35:*.xbm=01;35:*.xpm=01;35:*.tif=\
01;35:*.tiff=01;35:*.png=01;35:*.svg=01;35:*.svgz=01;35:*.mng=01;35:*.pcx=01;35:*.mov=01;35:*.mpg=01;35:*.mpeg=01;35:*.m2v=01;35:*.mkv=01;\
35:*.webm=01;35:*.ogm=01;35:*.mp4=01;35:*.m4v=01;35:*.mp4v=01;35:*.vob=01;35:*.qt=01;35:*.nuv=01;35:*.wmv=01;35:*.asf=01;35:*.rm=01;35:*.r\
mvb=01;35:*.flc=01;35:*.avi=01;35:*.fli=01;35:*.flv=01;35:*.gl=01;35:*.dl=01;35:*.xcf=01;35:*.xwd=01;35:*.yuv=01;35:*.cgm=01;35:*.emf=01;3\
5:*.ogv=01;35:*.ogx=01;35:*.aac=00;36:*.au=00;36:*.flac=00;36:*.m4a=00;36:*.mid=00;36:*.midi=00;36:*.mka=00;36:*.mp3=00;36:*.mpc=00;36:*.o\
gg=00;36:*.ra=00;36:*.wav=00;36:*.oga=00;36:*.opus=00;36:*.spx=00;36:*.xspf=00;36:" "LANG=en_US.UTF-8" "AUTOJUMP_ERROR_PATH=/home/nolan/.l\
ocal/share/autojump/errors.log" "HOME=/home/nolan" "GDM_LANG=en_US.utf8" "XDG_GREETER_DATA_DIR=/var/lib/lightdm/data/nolan" "XAUTHORITY=/h\
ome/nolan/.Xauthority" "GPG_AGENT_INFO=/run/user/1000/gnupg/S.gpg-agent:0:1" "XDG_SESSION_TYPE=x11" "QT_QPA_PLATFORMTHEME=qt5ct" "LOGNAME=\
nolan" "XDG_SESSION_DESKTOP=lightdm-xsession" "PWD=/home/nolan/.emacs.d" "XDG_SEAT=seat0" "SSH_AGENT_PID=1717" "DESKTOP_SESSION=lightdm-xs\
ession" "SSH_AUTH_SOCK=/run/user/1000/keyring/ssh" "XDG_SESSION_PATH=/org/freedesktop/DisplayManager/Session0" "COLORTERM=truecolor" "QT_A\
CCESSIBILITY=1" "WINDOWID=33554434" "SHELL=/bin/bash")))
  apply(#[257 "\300\001!\207" [tty-create-frame-with-faces] 3 "\012\012(fn PARAMS)"] ((right-fringe . 12) (left-fringe . 12) (vertical-scr\
oll-bars) (font . "Monospace-9") (horizontal-scroll-bars) (window-system) (tty . "/dev/pts/0") (tty-type . "xterm-256color") (client . #<p\
rocess server <2>>) (environment "OLDPWD=/home/nolan/.emacs.d/elisp" "_=/usr/bin/emacsclient" "DBUS_SESSION_BUS_ADDRESS=unix:path=/run/use\
r/1000/bus" "GDMSESSION=lightdm-xsession" "ALACRITTY_LOG=/tmp/Alacritty-1803.log" "PATH=/home/nolan/.cargo/bin:/home/nolan/bin:/home/nolan\
/.cargo/bin:/home/nolan/bin:/home/nolan/.cargo/bin:/home/nolan/bin:/usr/local/bin:/usr/bin:/bin:/usr/local/games:/usr/games:/sbin:/usr/sbi\
n:/usr/local/sbin:/sbin:/usr/sbin:/usr/local/sbin" "XDG_DATA_DIRS=/home/nolan/.local/share/flatpak/exports/share:/var/lib/flatpak/exports/\
share:/usr/local/share:/usr/share" "GCC_COLORS=error=01;31:warning=01;35:note=01;36:caret=01;32:locus=01:quote=01" "XDG_RUNTIME_DIR=/run/u\
ser/1000" "XDG_SESSION_ID=1" "XDG_VTNR=7" "SHLVL=2" "DISPLAY=:0" "AUTOJUMP_SOURCED=1" "USER=nolan" "TERM=xterm-256color" "XDG_SESSION_CLAS\
S=user" "XDG_SEAT_PATH=/org/freedesktop/DisplayManager/Seat0" "PYTHONSTARTUP=/home/nolan/.pythonrc" "LS_COLORS=rs=0:di=01;34:ln=01;36:mh=0\
0:pi=40;33:so=01;35:do=01;35:bd=40;33;01:cd=40;33;01:or=40;31;01:mi=00:su=37;41:sg=30;43:ca=30;41:tw=30;42:ow=34;42:st=37;44:ex=01;32:*.ta\
r=01;31:*.tgz=01;31:*.arc=01;31:*.arj=01;31:*.taz=01;31:*.lha=01;31:*.lz4=01;31:*.lzh=01;31:*.lzma=01;31:*.tlz=01;31:*.txz=01;31:*.tzo=01;\
31:*.t7z=01;31:*.zip=01;31:*.z=01;31:*.dz=01;31:*.gz=01;31:*.lrz=01;31:*.lz=01;31:*.lzo=01;31:*.xz=01;31:*.zst=01;31:*.tzst=01;31:*.bz2=01\
;31:*.bz=01;31:*.tbz=01;31:*.tbz2=01;31:*.tz=01;31:*.deb=01;31:*.rpm=01;31:*.jar=01;31:*.war=01;31:*.ear=01;31:*.sar=01;31:*.rar=01;31:*.a\
lz=01;31:*.ace=01;31:*.zoo=01;31:*.cpio=01;31:*.7z=01;31:*.rz=01;31:*.cab=01;31:*.wim=01;31:*.swm=01;31:*.dwm=01;31:*.esd=01;31:*.jpg=01;3\
5:*.jpeg=01;35:*.mjpg=01;35:*.mjpeg=01;35:*.gif=01;35:*.bmp=01;35:*.pbm=01;35:*.pgm=01;35:*.ppm=01;35:*.tga=01;35:*.xbm=01;35:*.xpm=01;35:\
*.tif=01;35:*.tiff=01;35:*.png=01;35:*.svg=01;35:*.svgz=01;35:*.mng=01;35:*.pcx=01;35:*.mov=01;35:*.mpg=01;35:*.mpeg=01;35:*.m2v=01;35:*.m\
kv=01;35:*.webm=01;35:*.ogm=01;35:*.mp4=01;35:*.m4v=01;35:*.mp4v=01;35:*.vob=01;35:*.qt=01;35:*.nuv=01;35:*.wmv=01;35:*.asf=01;35:*.rm=01;\
35:*.rmvb=01;35:*.flc=01;35:*.avi=01;35:*.fli=01;35:*.flv=01;35:*.gl=01;35:*.dl=01;35:*.xcf=01;35:*.xwd=01;35:*.yuv=01;35:*.cgm=01;35:*.em\
f=01;35:*.ogv=01;35:*.ogx=01;35:*.aac=00;36:*.au=00;36:*.flac=00;36:*.m4a=00;36:*.mid=00;36:*.midi=00;36:*.mka=00;36:*.mp3=00;36:*.mpc=00;\
36:*.ogg=00;36:*.ra=00;36:*.wav=00;36:*.oga=00;36:*.opus=00;36:*.spx=00;36:*.xspf=00;36:" "LANG=en_US.UTF-8" "AUTOJUMP_ERROR_PATH=/home/no\
lan/.local/share/autojump/errors.log" "HOME=/home/nolan" "GDM_LANG=en_US.utf8" "XDG_GREETER_DATA_DIR=/var/lib/lightdm/data/nolan" "XAUTHOR\
ITY=/home/nolan/.Xauthority" "GPG_AGENT_INFO=/run/user/1000/gnupg/S.gpg-agent:0:1" "XDG_SESSION_TYPE=x11" "QT_QPA_PLATFORMTHEME=qt5ct" "LO\
GNAME=nolan" "XDG_SESSION_DESKTOP=lightdm-xsession" "PWD=/home/nolan/.emacs.d" "XDG_SEAT=seat0" "SSH_AGENT_PID=1717" "DESKTOP_SESSION=ligh\
tdm-xsession" "SSH_AUTH_SOCK=/run/user/1000/keyring/ssh" "XDG_SESSION_PATH=/org/freedesktop/DisplayManager/Session0" "COLORTERM=truecolor"\
 "QT_ACCESSIBILITY=1" "WINDOWID=33554434" "SHELL=/bin/bash")))
  frame-creation-function(((right-fringe . 12) (left-fringe . 12) (vertical-scroll-bars) (font . "Monospace-9") (horizontal-scroll-bars) (\
window-system) (tty . "/dev/pts/0") (tty-type . "xterm-256color") (client . #<process server <2>>) (environment "OLDPWD=/home/nolan/.emacs\
.d/elisp" "_=/usr/bin/emacsclient" "DBUS_SESSION_BUS_ADDRESS=unix:path=/run/user/1000/bus" "GDMSESSION=lightdm-xsession" "ALACRITTY_LOG=/t\
mp/Alacritty-1803.log" "PATH=/home/nolan/.cargo/bin:/home/nolan/bin:/home/nolan/.cargo/bin:/home/nolan/bin:/home/nolan/.cargo/bin:/home/no\
lan/bin:/usr/local/bin:/usr/bin:/bin:/usr/local/games:/usr/games:/sbin:/usr/sbin:/usr/local/sbin:/sbin:/usr/sbin:/usr/local/sbin" "XDG_DAT\
A_DIRS=/home/nolan/.local/share/flatpak/exports/share:/var/lib/flatpak/exports/share:/usr/local/share:/usr/share" "GCC_COLORS=error=01;31:\
warning=01;35:note=01;36:caret=01;32:locus=01:quote=01" "XDG_RUNTIME_DIR=/run/user/1000" "XDG_SESSION_ID=1" "XDG_VTNR=7" "SHLVL=2" "DISPLA\
Y=:0" "AUTOJUMP_SOURCED=1" "USER=nolan" "TERM=xterm-256color" "XDG_SESSION_CLASS=user" "XDG_SEAT_PATH=/org/freedesktop/DisplayManager/Seat\
0" "PYTHONSTARTUP=/home/nolan/.pythonrc" "LS_COLORS=rs=0:di=01;34:ln=01;36:mh=00:pi=40;33:so=01;35:do=01;35:bd=40;33;01:cd=40;33;01:or=40;\
31;01:mi=00:su=37;41:sg=30;43:ca=30;41:tw=30;42:ow=34;42:st=37;44:ex=01;32:*.tar=01;31:*.tgz=01;31:*.arc=01;31:*.arj=01;31:*.taz=01;31:*.l\
ha=01;31:*.lz4=01;31:*.lzh=01;31:*.lzma=01;31:*.tlz=01;31:*.txz=01;31:*.tzo=01;31:*.t7z=01;31:*.zip=01;31:*.z=01;31:*.dz=01;31:*.gz=01;31:\
*.lrz=01;31:*.lz=01;31:*.lzo=01;31:*.xz=01;31:*.zst=01;31:*.tzst=01;31:*.bz2=01;31:*.bz=01;31:*.tbz=01;31:*.tbz2=01;31:*.tz=01;31:*.deb=01\
;31:*.rpm=01;31:*.jar=01;31:*.war=01;31:*.ear=01;31:*.sar=01;31:*.rar=01;31:*.alz=01;31:*.ace=01;31:*.zoo=01;31:*.cpio=01;31:*.7z=01;31:*.\
rz=01;31:*.cab=01;31:*.wim=01;31:*.swm=01;31:*.dwm=01;31:*.esd=01;31:*.jpg=01;35:*.jpeg=01;35:*.mjpg=01;35:*.mjpeg=01;35:*.gif=01;35:*.bmp\
=01;35:*.pbm=01;35:*.pgm=01;35:*.ppm=01;35:*.tga=01;35:*.xbm=01;35:*.xpm=01;35:*.tif=01;35:*.tiff=01;35:*.png=01;35:*.svg=01;35:*.svgz=01;\
35:*.mng=01;35:*.pcx=01;35:*.mov=01;35:*.mpg=01;35:*.mpeg=01;35:*.m2v=01;35:*.mkv=01;35:*.webm=01;35:*.ogm=01;35:*.mp4=01;35:*.m4v=01;35:*\
.mp4v=01;35:*.vob=01;35:*.qt=01;35:*.nuv=01;35:*.wmv=01;35:*.asf=01;35:*.rm=01;35:*.rmvb=01;35:*.flc=01;35:*.avi=01;35:*.fli=01;35:*.flv=0\
1;35:*.gl=01;35:*.dl=01;35:*.xcf=01;35:*.xwd=01;35:*.yuv=01;35:*.cgm=01;35:*.emf=01;35:*.ogv=01;35:*.ogx=01;35:*.aac=00;36:*.au=00;36:*.fl\
ac=00;36:*.m4a=00;36:*.mid=00;36:*.midi=00;36:*.mka=00;36:*.mp3=00;36:*.mpc=00;36:*.ogg=00;36:*.ra=00;36:*.wav=00;36:*.oga=00;36:*.opus=00\
;36:*.spx=00;36:*.xspf=00;36:" "LANG=en_US.UTF-8" "AUTOJUMP_ERROR_PATH=/home/nolan/.local/share/autojump/errors.log" "HOME=/home/nolan" "G\
DM_LANG=en_US.utf8" "XDG_GREETER_DATA_DIR=/var/lib/lightdm/data/nolan" "XAUTHORITY=/home/nolan/.Xauthority" "GPG_AGENT_INFO=/run/user/1000\
/gnupg/S.gpg-agent:0:1" "XDG_SESSION_TYPE=x11" "QT_QPA_PLATFORMTHEME=qt5ct" "LOGNAME=nolan" "XDG_SESSION_DESKTOP=lightdm-xsession" "PWD=/h\
ome/nolan/.emacs.d" "XDG_SEAT=seat0" "SSH_AGENT_PID=1717" "DESKTOP_SESSION=lightdm-xsession" "SSH_AUTH_SOCK=/run/user/1000/keyring/ssh" "X\
DG_SESSION_PATH=/org/freedesktop/DisplayManager/Session0" "COLORTERM=truecolor" "QT_ACCESSIBILITY=1" "WINDOWID=33554434" "SHELL=/bin/bash"\
)))
  make-frame(((window-system) (tty . "/dev/pts/0") (tty-type . "xterm-256color") (client . #<process server <2>>) (environment "OLDPWD=/ho\
me/nolan/.emacs.d/elisp" "_=/usr/bin/emacsclient" "DBUS_SESSION_BUS_ADDRESS=unix:path=/run/user/1000/bus" "GDMSESSION=lightdm-xsession" "A\
LACRITTY_LOG=/tmp/Alacritty-1803.log" "PATH=/home/nolan/.cargo/bin:/home/nolan/bin:/home/nolan/.cargo/bin:/home/nolan/bin:/home/nolan/.car\
go/bin:/home/nolan/bin:/usr/local/bin:/usr/bin:/bin:/usr/local/games:/usr/games:/sbin:/usr/sbin:/usr/local/sbin:/sbin:/usr/sbin:/usr/local\
/sbin" "XDG_DATA_DIRS=/home/nolan/.local/share/flatpak/exports/share:/var/lib/flatpak/exports/share:/usr/local/share:/usr/share" "GCC_COLO\
RS=error=01;31:warning=01;35:note=01;36:caret=01;32:locus=01:quote=01" "XDG_RUNTIME_DIR=/run/user/1000" "XDG_SESSION_ID=1" "XDG_VTNR=7" "S\
HLVL=2" "DISPLAY=:0" "AUTOJUMP_SOURCED=1" "USER=nolan" "TERM=xterm-256color" "XDG_SESSION_CLASS=user" "XDG_SEAT_PATH=/org/freedesktop/Disp\
layManager/Seat0" "PYTHONSTARTUP=/home/nolan/.pythonrc" "LS_COLORS=rs=0:di=01;34:ln=01;36:mh=00:pi=40;33:so=01;35:do=01;35:bd=40;33;01:cd=\
40;33;01:or=40;31;01:mi=00:su=37;41:sg=30;43:ca=30;41:tw=30;42:ow=34;42:st=37;44:ex=01;32:*.tar=01;31:*.tgz=01;31:*.arc=01;31:*.arj=01;31:\
*.taz=01;31:*.lha=01;31:*.lz4=01;31:*.lzh=01;31:*.lzma=01;31:*.tlz=01;31:*.txz=01;31:*.tzo=01;31:*.t7z=01;31:*.zip=01;31:*.z=01;31:*.dz=01\
;31:*.gz=01;31:*.lrz=01;31:*.lz=01;31:*.lzo=01;31:*.xz=01;31:*.zst=01;31:*.tzst=01;31:*.bz2=01;31:*.bz=01;31:*.tbz=01;31:*.tbz2=01;31:*.tz\
=01;31:*.deb=01;31:*.rpm=01;31:*.jar=01;31:*.war=01;31:*.ear=01;31:*.sar=01;31:*.rar=01;31:*.alz=01;31:*.ace=01;31:*.zoo=01;31:*.cpio=01;3\
1:*.7z=01;31:*.rz=01;31:*.cab=01;31:*.wim=01;31:*.swm=01;31:*.dwm=01;31:*.esd=01;31:*.jpg=01;35:*.jpeg=01;35:*.mjpg=01;35:*.mjpeg=01;35:*.\
gif=01;35:*.bmp=01;35:*.pbm=01;35:*.pgm=01;35:*.ppm=01;35:*.tga=01;35:*.xbm=01;35:*.xpm=01;35:*.tif=01;35:*.tiff=01;35:*.png=01;35:*.svg=0\
1;35:*.svgz=01;35:*.mng=01;35:*.pcx=01;35:*.mov=01;35:*.mpg=01;35:*.mpeg=01;35:*.m2v=01;35:*.mkv=01;35:*.webm=01;35:*.ogm=01;35:*.mp4=01;3\
5:*.m4v=01;35:*.mp4v=01;35:*.vob=01;35:*.qt=01;35:*.nuv=01;35:*.wmv=01;35:*.asf=01;35:*.rm=01;35:*.rmvb=01;35:*.flc=01;35:*.avi=01;35:*.fl\
i=01;35:*.flv=01;35:*.gl=01;35:*.dl=01;35:*.xcf=01;35:*.xwd=01;35:*.yuv=01;35:*.cgm=01;35:*.emf=01;35:*.ogv=01;35:*.ogx=01;35:*.aac=00;36:\
*.au=00;36:*.flac=00;36:*.m4a=00;36:*.mid=00;36:*.midi=00;36:*.mka=00;36:*.mp3=00;36:*.mpc=00;36:*.ogg=00;36:*.ra=00;36:*.wav=00;36:*.oga=\
00;36:*.opus=00;36:*.spx=00;36:*.xspf=00;36:" "LANG=en_US.UTF-8" "AUTOJUMP_ERROR_PATH=/home/nolan/.local/share/autojump/errors.log" "HOME=\
/home/nolan" "GDM_LANG=en_US.utf8" "XDG_GREETER_DATA_DIR=/var/lib/lightdm/data/nolan" "XAUTHORITY=/home/nolan/.Xauthority" "GPG_AGENT_INFO\
=/run/user/1000/gnupg/S.gpg-agent:0:1" "XDG_SESSION_TYPE=x11" "QT_QPA_PLATFORMTHEME=qt5ct" "LOGNAME=nolan" "XDG_SESSION_DESKTOP=lightdm-xs\
ession" "PWD=/home/nolan/.emacs.d" "XDG_SEAT=seat0" "SSH_AGENT_PID=1717" "DESKTOP_SESSION=lightdm-xsession" "SSH_AUTH_SOCK=/run/user/1000/\
keyring/ssh" "XDG_SESSION_PATH=/org/freedesktop/DisplayManager/Session0" "COLORTERM=truecolor" "QT_ACCESSIBILITY=1" "WINDOWID=33554434" "S\
HELL=/bin/bash")))
  server-create-tty-frame("/dev/pts/0" "xterm-256color" #<process server <2>>)
  server-process-filter(#<process server <2>> "-env SHELL=/bin/bash -env WINDOWID=33554434 -env QT_ACCESSIBILITY=1 -env COLORTERM=truecolo\
r -env XDG_SESSION_PATH=/org/freedesktop/DisplayManager/Session0 -env SSH_AUTH_SOCK=/run/user/1000/keyring/ssh -env DESKTOP_SESSION=lightd\
m-xsession -env SSH_AGENT_PID=1717 -env XDG_SEAT=seat0 -env PWD=/home/nolan/.emacs.d -env XDG_SESSION_DESKTOP=lightdm-xsession -env LOGNAM\
E=nolan -env QT_QPA_PLATFORMTHEME=qt5ct -env XDG_SESSION_TYPE=x11 -env GPG_AGENT_INFO=/run/user/1000/gnupg/S.gpg-agent:0:1 -env XAUTHORITY\
=/home/nolan/.Xauthority -env XDG_GREETER_DATA_DIR=/var/lib/lightdm/data/nolan -env GDM_LANG=en_US.utf8 -env HOME=/home/nolan -env AUTOJUM\
P_ERROR_PATH=/home/nolan/.local/share/autojump/errors.log -env LANG=en_US.UTF-8 -env LS_COLORS=rs=0:di=01;34:ln=01;36:mh=00:pi=40;33:so=01\
;35:do=01;35:bd=40;33;01:cd=40;33;01:or=40;31;01:mi=00:su=37;41:sg=30;43:ca=30;41:tw=30;42:ow=34;42:st=37;44:ex=01;32:*.tar=01;31:*.tgz=01\
;31:*.arc=01;31:*.arj=01;31:*.taz=01;31:*.lha=01;31:*.lz4=01;31:*.lzh=01;31:*.lzma=01;31:*.tlz=01;31:*.txz=01;31:*.tzo=01;31:*.t7z=01;31:*\
.zip=01;31:*.z=01;31:*.dz=01;31:*.gz=01;31:*.lrz=01;31:*.lz=01;31:*.lzo=01;31:*.xz=01;31:*.zst=01;31:*.tzst=01;31:*.bz2=01;31:*.bz=01;31:*\
.tbz=01;31:*.tbz2=01;31:*.tz=01;31:*.deb=01;31:*.rpm=01;31:*.jar=01;31:*.war=01;31:*.ear=01;31:*.sar=01;31:*.rar=01;31:*.alz=01;31:*.ace=0\
1;31:*.zoo=01;31:*.cpio=01;31:*.7z=01;31:*.rz=01;31:*.cab=01;31:*.wim=01;31:*.swm=01;31:*.dwm=01;31:*.esd=01;31:*.jpg=01;35:*.jpeg=01;35:*\
.mjpg=01;35:*.mjpeg=01;35:*.gif=01;35:*.bmp=01;35:*.pbm=01;35:*.pgm=01;35:*.ppm=01;35:*.tga=01;35:*.xbm=01;35:*.xpm=01;35:*.tif=01;35:*.ti\
ff=01;35:*.png=01;35:*.svg=01;35:*.svgz=01;35:*.mng=01;35:*.pcx=01;35:*.mov=01;35:*.mpg=01;35:*.mpeg=01;35:*.m2v=01;35:*.mkv=01;35:*.webm=\
01;35:*.ogm=01;35:*.mp4=01;35:*.m4v=01;35:*.mp4v=01;35:*.vob=01;35:*.qt=01;35:*.nuv=01;35:*.wmv=01;35:*.asf=01;35:*.rm=01;35:*.rmvb=01;35:\
*.flc=01;35:*.avi=01;35:*.fli=01;35:*.flv=01;35:*.gl=01;35:*.dl=01;35:*.xcf=01;35:*.xwd=01;35:*.yuv=01;35:*.cgm=01;35:*.emf=01;35:*.ogv=01\
;35:*.ogx=01;35:*.aac=00;36:*.au=00;36:*.flac=00;36:*.m4a=00;36:*.mid=00;36:*.midi=00;36:*.mka=00;36:*.mp3=00;36:*.mpc=00;36:*.ogg=00;36:*\
.ra=00;36:*.wav=00;36:*.oga=00;36:*.opus=00;36:*.spx=00;36:*.xspf=00;36: -env PYTHONSTARTUP=/home/nolan/.pythonrc -env XDG_SEAT_PATH=/org/\
freedesktop/DisplayManager/Seat0 -env XDG_SESSION_CLASS=user -env TERM=xterm-256color -env USER=nolan -env AUTOJUMP_SOURCED=1 -env DISPLAY\
=:0 -env SHLVL=2 -env XDG_VTNR=7 -env XDG_SESSION_ID=1 -env XDG_RUNTIME_DIR=/run/user/1000 -env GCC_COLORS=error=01;31:warning=01;35:note=\
01;36:caret=01;32:locus=01:quote=01 -env XDG_DATA_DIRS=/home/nolan/.local/share/flatpak/exports/share:/var/lib/flatpak/exports/share:/usr/\
local/share:/usr/share -env PATH=/home/nolan/.cargo/bin:/home/nolan/bin:/home/nolan/.cargo/bin:/home/nolan/bin:/home/nolan/.cargo/bin:/hom\
e/nolan/bin:/usr/local/bin:/usr/bin:/bin:/usr/local/games:/usr/games:/sbin:/usr/sbin:/usr/local/sbin:/sbin:/usr/sbin:/usr/local/sbin -env \
ALACRITTY_LOG=/tmp/Alacritty-1803.log -env GDMSESSION=lightdm-xsession -env DBUS_SESSION_BUS_ADDRESS=unix:path=/run/user/1000/bus -env _=/\
usr/bin/emacsclient -env OLDPWD=/home/nolan/.emacs.d/elisp -dir /home/nolan/.emacs.d/ -tty /dev/pts/0 xterm-256color -file init.el \012")

Record the buffer that the command ran in and display

In #46 , we dropped the command stack display code and started showing only the command that ran. This buckets all commands in all buffers and all situations into one. Often times things are slow only in one buffer, etc.

Record the buffer that the action came from
Expand explain-pause-top to support trees and allow expansion of nodes.

Note that this basically implements classic "bottom up" call tree view of a profiler view.
Obvious expansions then are reversed, so "top down" from a buffer, process, etc.

While doing this, clean up the command stringification logic as well.
Before attempting this, implement unit tests for the display code.

Support emacs 27+ early init

Currently, when we notice we are in init, we install during emacs-startup-hook, which is extremely late.

The reason why is because someone could run advised-code in init.el or as a -f command arg, and because explain-pause-mode itself was also called during that same phase, we cannot guarentee we have a clean state to install all hooks and setup the command stack.

Document that early init would allow you to see what happens during init.el
Update the init detection code to handle early init and install anyway.
Perhaps set a flag during all init phase so that if report-bug fires, we know it was during init.

Separate out into multiple .el files

I can't handle this giant .el file even though it seems it's common in elisp land. Find out how to make it work so there can be multiple files.

Will it be a problem for straight, etc.?
Do I need to build some packaging?
Maybe wait until I can distribute thru MELPA, then people don't have to manually download
I probably need a build system at this point

Make profiling alert message soft (and configurable)

Currently the profiling alert message prints out to minibuffer no matter what is going on. If profiling happens this can interrupt the user while they are using the minibuffer for input. I had originally thought this was a good idea - because profiling should be relatively rare.

However, if we want people to use this thing nonstop, continuously, in the background, it needs to be really unobtrusive.

Make the profiling messages just like the alert messages. The "alert messages" already implement "soft alerting" where it only prints stuff if the minibuffer isn't in use, do the same thing.

Abort-quit out of recursive edit in a minibuffer (e.g. in `b` interactive forms) confuses call-interactively tracking

EG. quit out of kill-buffer or even a elisp command. Probably broken after implementing recursive edit tracking #47

Handle file-notify callbacks

hat-tip to @yyoncho

file-notify-add-watch is a compiled Lisp function in ‘filenotify.el’.

(file-notify-add-watch FILE FLAGS CALLBACK)
....
When any event happens, Emacs will call the CALLBACK function passing
it a single argument EVENT, which is of the form

  (DESCRIPTOR ACTION FILE [FILE1])

Verify how filenotify calls the callback. I suspect it's from C code.
Figure out what to advise to wrap the callback, handle similarly to timers or process filters

lsp might be a good test case for this.

Provide memory profiling

Some hangs in Emacs can be caused by garbage collections. explain-pause-profiles is not exatly useful in such cases:

Slow profile report
  Time: Wed May 27 03:37:35 2020
  Command: gcmh-idle-garbage-collect, idle-timer
  Duration: 1231 ms

[ View profile ]

Slow profile report
  Time: Wed May 27 03:19:07 2020
  Command: gcmh-idle-garbage-collect, idle-timer
  Duration: 4305 ms

[ View profile ]

- ...                                                             408 100%
   Automatic GC                                                   408 100%

It would be helpful if memory profiling was also done (with configurable threshold). similar to time profiling.

Handle recursive timers so their command stacks do not grow infinitely

If a timer runs another timer within it, the command stack will obviously include each timer, and if this continues indefinitely, in order to approximate repeat, then the stack - a list - will grow indefinitely. Furthermore, none of the objects will be GC'able as they are still pointed to by the current live set. This will eventually lead to memory exhaustion and certainly high GC pressure.

Repro:

(defun recursive-timer ()
  (message "call")
  (run-with-timer 2 0 #'recursive-timer))

This ultimately runs into cycle and tail recursion problem space. It's not super valuable to hold the entire call stack chain in memory. We should cut the length of the command set when it grows beyond say 10. Additionally we should special case the timer that calls itself and collapse the command so it never grows beyond 2 in that case.

Long Emacs session statistics

If would be useful to track how cpu time/memory consumption changes through Emacs session for various commands.

[1] https://www.emacswiki.org/emacs/EmacsMemoryDebugging
[2] http://notes.secretsauce.net/notes/2015/10/05_memory-leak-debugging-tools.html

Better track `call-interactively` time

In #14, I discovered the read* family of functions, which read and wait on input. One of the C functions that call those is call-interactively, which is currently not advised.

So, in reality, most cases require actual parameters, which means the minibuffer is activated or the echo area is, which means the command loop runs. So, everything works OK in normal use cases.

However, consider this case:

(defun a-blocking-guy ()
  (interactive)
  (sleep-for 5))

(call-interactively 'a-blocking-guy)

This causes explain-pause-mode to think that call-interactively (or rather, it's parent, in scratch that would be eval-print-last-sexp) to take 5 seconds, but it's really actually a-blocking-guy. call-interactively is implemented in C code, and depending on the interactive spec may or may not call out to minibuffer, read functions, etc.

It's not called from C code, so it can be straightforwardly advised. I'm leaning towards advising it, and wrapping the function to be called in a wrapper timer.

`top` for commands

note: edited with spec from original ideas when first opened (hit edited for a dropdown of change history in github)

Make a table of the top N commands, that works like top

columns:
- command
- avg-ms
- total ms
- invocations
sortable

Call it explain-pause-top. Should be a major mode.

make it fast enough to refresh automatically. Controllable refresh interval.
Data is collected for lifetime of emacs, can be user cleared

First PR should do the above. Next new issues:

Handle actions and remove explain-top-report (profile, select for profile, ignore for profile, etc.)
Add keymaps, faces
clean up the internal routing and use same system for logging
Support trees for command-sets, original buffer

Improve bug report buffer backtrace by skipping over known code

Don't use backtrace but mapbacktrace and generate the lines ourselves so we can skip over the giant closures inside explain-pause-mode itself.

ref: https://github.com/lastquestion/explain-pause-mode/blob/master/explain-pause-mode.el#L2405

handle thread yield

Need to handle thread yields.

Can advise thread-yield
Check C code for calls to thread-yield, e.g. not from elisp. Any?
Verify entry into a thread must be from exit of the existing transition set - accept-process-output, sit-for, command-loop. (Assumption based on documentation)
Verify there is no elisp we can advise for thread entry - I don't think so.

Possible design that can still measure thread execution time:

on exit of existing transition, mark a time.
advise thread-yield and calculate the time from the mark, store it into thread-execution-time
on next entry (command-loop, process-filter, timer, etc.) check to see thread-execution-time is non-nil, if so, we know that we must have executed a thread when we transitioned out. If it's nil, we transitioned into some other code.

Works by process of elimination.

wrong-type-argument symbolp #f(compiled-function () #<bytecode 0x4c7a0e9800c1d76>) when saving file

Well. After updating to ef0ce46 turns out that I now experience this bug when saving a file to disk (C-x C-s):

Debugger entered--Lisp error: (wrong-type-argument symbolp #f(compiled-function () #<bytecode 0x4c7a0e9800c1d76>))
  advice-add(#f(compiled-function () #<bytecode 0x4c7a0e9800c1d76>) :around (closure ((hook-list . post-command-hook) (hook-func . #f(compiled-function () #<bytecode 0x4c7a0e9800c1d76>)) explain-pause-top-mode-abbrev-table explain-pause-top-mode-syntax-table cl-struct-explain-pause-top--command-entry-tags cl-struct-explain-pause-top--table-display-entry-tags cl-struct-explain-pause-top--table-tags cl-struct-explain-pause-command-record-tags t) (orig-func &rest args) (if (not explain-pause-mode) (apply orig-func args) (let ((current-record explain-pause--current-command-record)) (explain-pause--command-record-and-store current-record) (let ((new-frame (let ... ...))) (progn (explain-pause-log--send-command-entry explain-pause--current-command-record new-frame) (setq explain-pause--current-command-record new-frame) (let (...) (if should-profile ...) (progn ... ...) (unwind-protect ... ... ... ... ...))))))) ((name . "explain-pause-wrap-hook-post-command-hook")))
  (cond ((or (symbolp hook-func) (byte-code-function-p hook-func)) (advice-add hook-func :around (explain-pause--generate-hook-wrapper hook-func hook-list) (cons (cons 'name (format "explain-pause-wrap-hook-%s" hook-list)) nil)) hook-func) (t (if (and (listp hook-func) (listp (nth 3 hook-func)) (equal (nth 1 (nth 3 hook-func)) '#'explain-pause--lambda-hook-wrapper)) hook-func #'(lambda (&rest args) (apply #'explain-pause--lambda-hook-wrapper hook-func hook-list args)))))
  explain-pause--advice-add-hook(#f(compiled-function () #<bytecode 0x4c7a0e9800c1d76>) post-command-hook)
  (setcar c (explain-pause--advice-add-hook hook-func hook-list))
  (let* ((c (nthcdr 1 args))) (setcar c (explain-pause--advice-add-hook hook-func hook-list)))
  (progn (let* ((c (nthcdr 1 args))) (setcar c (explain-pause--advice-add-hook hook-func hook-list))))
  (if (and (seq-contains explain-pause--native-called-hooks hook-list) (functionp hook-func)) (progn (let* ((c (nthcdr 1 args))) (setcar c (explain-pause--advice-add-hook hook-func hook-list)))))
  (let ((hook-list (nth 0 args)) (hook-func (nth 1 args))) (if (and (seq-contains explain-pause--native-called-hooks hook-list) (functionp hook-func)) (progn (let* ((c (nthcdr 1 args))) (setcar c (explain-pause--advice-add-hook hook-func hook-list))))))
  explain-pause--wrap-add-hook((post-command-hook #f(compiled-function () #<bytecode 0x4c7a0e9800c1d76>) append nil))
  add-hook(post-command-hook #f(compiled-function () #<bytecode 0x4c7a0e9800c1d76>) append nil)
  flymake-start(t)
  flymake-after-save-hook()
  run-hooks(after-save-hook)
  basic-save-buffer(t)
  save-buffer(1)
  #<subr funcall-interactively>(save-buffer 1)
  apply(#<subr funcall-interactively> (save-buffer 1))
  funcall-interactively(save-buffer 1)
  #<subr call-interactively>(save-buffer nil nil)
  apply(#<subr call-interactively> (save-buffer nil nil))
  (unwind-protect (apply original-func args) (let ((top-frame explain-pause--current-command-record)) (if extra-frame (cond ((and (eq (progn ... ...) target-function) (eq (progn ... ...) command-frame)) (explain-pause--command-record-and-store top-frame) (if (progn (or ... ...) (aref top-frame 7)) (progn (explain-pause--command-record--save-and-stop-profiling top-frame))) (explain-pause-log--send-command-exit top-frame) (explain-pause--run-measure-hook top-frame) (explain-pause-log--send-command-exit command-frame) (explain-pause--run-measure-hook command-frame)) ((eq top-frame command-frame) (explain-pause--command-record-and-store top-frame) (explain-pause-log--send-command-exit top-frame) (explain-pause--run-measure-hook top-frame)) (t (explain-pause-report-measuring-bug "call-interactively has extra-frame" "top-frame" top-frame "target-function" target-function))) (if (not (eq top-frame command-frame)) (explain-pause-report-measuring-bug "call interactively frame does not match" "command-frame" command-frame "should be equal" top-frame) (explain-pause--command-record-and-store command-frame) (if (progn (or (and ... t) (signal ... ...)) (aref command-frame 7)) (progn (explain-pause--command-record--save-and-stop-profiling command-frame))) (explain-pause-log--send-command-exit command-frame) (explain-pause--run-measure-hook command-frame)))) (if (eq parent explain-pause-root-command-loop) nil (progn (or (and (memq (type-of parent) cl-struct-explain-pause-command-record-tags) t) (signal 'wrong-type-argument (list 'explain-pause-command-record parent))) (let* ((v parent)) (aset v 5 (current-time))))) (setq explain-pause--current-command-record parent))
  (let ((parent explain-pause--current-command-record) (target-function (car args)) (command-frame nil) (extra-frame nil)) (if (eq parent explain-pause-root-command-loop) nil (explain-pause--command-record-and-store parent)) (if (or (eq target-function #'self-insert-command) (eq target-function #'newline) (eq target-function #'next-line) (eq target-function #'previous-line) (eq target-function #'delete-forward-char)) nil (let ((i-spec (car (cdr (interactive-form target-function))))) (if (and (stringp i-spec) (explain-pause--interactive-form-needs-frame-p i-spec)) (progn (setq command-frame (explain-pause--command-record-from-parent parent parent 'call-interactively-interactive t)) (setq extra-frame t))))) (if extra-frame nil (setq command-frame (explain-pause--command-record-from-parent parent parent target-function))) (explain-pause-log--send-command-entry parent command-frame) (setq explain-pause--current-command-record command-frame) (progn (or (and (memq (type-of command-frame) cl-struct-explain-pause-command-record-tags) t) (signal 'wrong-type-argument (list 'explain-pause-command-record command-frame))) (let* ((v command-frame)) (aset v 5 (current-time)))) (if (and (not extra-frame) (explain-pause--command-record-profile-p command-frame)) (progn (explain-pause--command-record-start-profiling command-frame))) (unwind-protect (apply original-func args) (let ((top-frame explain-pause--current-command-record)) (if extra-frame (cond ((and (eq ... target-function) (eq ... command-frame)) (explain-pause--command-record-and-store top-frame) (if (progn ... ...) (progn ...)) (explain-pause-log--send-command-exit top-frame) (explain-pause--run-measure-hook top-frame) (explain-pause-log--send-command-exit command-frame) (explain-pause--run-measure-hook command-frame)) ((eq top-frame command-frame) (explain-pause--command-record-and-store top-frame) (explain-pause-log--send-command-exit top-frame) (explain-pause--run-measure-hook top-frame)) (t (explain-pause-report-measuring-bug "call-interactively has extra-frame" "top-frame" top-frame "target-function" target-function))) (if (not (eq top-frame command-frame)) (explain-pause-report-measuring-bug "call interactively frame does not match" "command-frame" command-frame "should be equal" top-frame) (explain-pause--command-record-and-store command-frame) (if (progn (or ... ...) (aref command-frame 7)) (progn (explain-pause--command-record--save-and-stop-profiling command-frame))) (explain-pause-log--send-command-exit command-frame) (explain-pause--run-measure-hook command-frame)))) (if (eq parent explain-pause-root-command-loop) nil (progn (or (and (memq (type-of parent) cl-struct-explain-pause-command-record-tags) t) (signal 'wrong-type-argument (list 'explain-pause-command-record parent))) (let* ((v parent)) (aset v 5 (current-time))))) (setq explain-pause--current-command-record parent)))
  explain-pause--wrap-call-interactively(#<subr call-interactively> save-buffer nil nil)
  apply(explain-pause--wrap-call-interactively #<subr call-interactively> (save-buffer nil nil))
  call-interactively(save-buffer nil nil)
  command-execute(save-buffer)

this error happens 100% of the time there is something to be written to disk. My Emacs version is GNU Emacs 28.0.50 (build 3, x86_64-pc-linux-gnu, GTK+ Version 3.24.14, cairo version 1.17.3) of 2020-02-18

Adjust exclusion list for profiling and reporting

They probably ought to be separate. If the profiler itself is profiled while generating profiles, then the list of profiles will just get filled up with profiles of the profiler. (Read that sentence back again fast!)

Support profile exclusion list, somewhere around https://github.com/lastquestion/explain-pause-mode/blob/master/explain-pause-mode.el#L310
Support reporting exclusion list, somewhere around https://github.com/lastquestion/explain-pause-mode/blob/master/explain-pause-mode.el#L336

`top` missing features (sort, clear, keymaps, faces)

Add

Sort. Should work by under point.
Clear. Clear all the data stored so far. Clear should also happen when quitting the last top buffer.
Keymaps. Derive from special mode already.
- 'c' - clear
- 's' - sort under point?
faces
"slow" column

Get on MELPA; update docs for straight and MELPA

Update docs for Straight
Update docs for MELPA
Pass MELPA's lint checks and add them to the makefile