Occasional hangs in Emacs 27.1, interruptible with SIGUSR2

[wasamasa]

Sorry for the useless backtrace. If you have a better idea how to debug a hang here, please let me know.

Debugger entered--entering a function:
* (#f(compiled-function () #<bytecode 0x158f13a2c585>))
  (explain-pause--wrap-call-interactively #<subr call-interactively> undo-tree-undo nil nil)
  (apply explain-pause--wrap-call-interactively #<subr call-interactively> (undo-tree-undo nil nil))
  (call-interactively undo-tree-undo nil nil)
  (command-execute undo-tree-undo)

[lastquestion]

@wasamasa the backtrace isn't that bad... we at least know it was undo-tree-undo that kicked things off 🤣

Hm. We need to know what #f is. If explain-pause--wrap-call-interactively did its job correctly, then #f here should be the culprit, e.g. some real code in undo-tree-undo maybe or another package.

How repeatable is this? If it's moderately repeatable, we can try streaming every command out (which exists undocumented in the package right now) and then at least you'll know what emacs was doing right when it hangs.

If it's not very repeatable, at least it's interruptible. Next time it occurs, walk up the backtrace one step. You should be here: https://github.com/lastquestion/explain-pause-mode/blob/master/explain-pause-mode.el#L2693, and evaluating target-function should give you the function that was executing the loop or whatnot that hung emacs.

This gives me the idea to add a function to the mode that can be run while broken in the debugger to print out the current state right before the debugger was invoked... that's a good idea 💯

[lastquestion]

If this doesn't work, don't byte-compile explain-pause-mode. this is a tad bit slower, but you will get much more accurate callstacks as almost all of the core instrumentation of explain-pause-mode is inlined so a lot of the call stack is missing in byte-compiled mode.

[wasamasa]

I run into the error regularly, but can't reproduce it at will. I'll try evaluating target-function in the debugger's scope next time.

[wasamasa]

target-function is void when I run into the issue again. However I've managed triggering this backtrace instead by hitting C-g a few times too many:

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: 27.1

not top level in wrap-native for #<subr recursive-edit>
current
#s(explain-pause-command-record root-emacs nil nil 69880 (24386 42191 766545 52000) nil nil nil nil ...)

Backtrace:
  (explain-pause-report-measuring-bug "not top level in wrap-native for #<subr recursive-..." "current" #s(explain-pause-command-record :command root-emacs :native nil :parent nil :executing-time 69880 :entry-snap (24386 42191 766545 52000) :too-slow nil :is-profiled nil :under-profile nil :profile nil :depth 0))
  (explain-pause--wrap-native #<subr recursive-edit>)
  (apply explain-pause--wrap-native #<subr recursive-edit> nil)
  (recursive-edit)
  (debug error (quit))
  (redisplay_internal\ \(C\ function\))

[lastquestion]

Ah, the debug bug is #83 which I am still fixing but got super busy moving right now and I haven't finished. In particular I wrote

This is a pretty important use case, and in general, SIGUSR2 causes debug to happen on the next call in eval.c, so basically anywhere. So I think (debug) needs some special handling. I will think more on this.

And I decided to handle debug specially but I didn't finish the PR yet. Sorry.

If you're running it this often, can you load explain-pause without byte-compiling and then ask for a regular backtrace when you SIGUSR2 next time. You will get a full stack frame which will be quite deep... but it will help a lot.

[wasamasa]

What do you mean with "ask for a regular backtrace"? Anything special beyond loading the non-compiled version of the library?

[lastquestion]

Oh, so sorry, yes, load the library uncompiled and get a regular backtrace when you interrupt and break. I meant don't bother trying to walk the stack frames up and evaluating target-function :_)

[wasamasa]

Like this?

Debugger entered--beginning evaluation of function call form:
* (let ((top-frame explain-pause--current-command-record)) (if extra-frame (cond ((and (eq (progn (or ... ...) (aref top-frame 1)) target-function) (eq (progn (or ... ...) (aref top-frame 3)) command-frame)) (explain-pause--command-record-and-store top-frame) (if (progn (or (and ... t) (signal ... ...)) (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 (memq ... cl-struct-explain-pause-command-record-tags) t) (signal 'wrong-type-argument (list ... command-frame))) (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))))
  (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> undo-tree-undo nil nil)
  (apply explain-pause--wrap-call-interactively #<subr call-interactively> (undo-tree-undo nil nil))
  (call-interactively undo-tree-undo nil nil)
  (command-execute undo-tree-undo)

[wasamasa]

Hm, I doubt the hang has anything to do with explain-pause-mode, but will leave this open due to the weird backtrace.

[wasamasa]

Yup, I managed having these hangs without it, seems to be an undo-tree issue. I've reverted to not using undo-tree at all and re-enabled explain-pause-mode. Feel free to close this.