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)

[lastquestion]

@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 https://github.com/lastquestion/explain-pause-mode/issues/65#issuecomment-659666850

[lastquestion]

@bqv, how did you find out about explain-pause-log-to-socket?! 😀 it's undocumented!

Did you happen to actually call explain-pause-log-to-socket with a real DGRAM UNIX file socket?

There is also a bug here that explain-pause-log--send-command-entry needs to be called after entering the command frame so that the read-event has a root, but... I don't think you kew about this feature, did you? In which case, I don't know how the dgram code fired...

But if you did know about this feature, you have to use a DGRAM socket accept that is fast enough to process all the DGRAM packets or else eventually the buffer will get full and then explain-pause-mode will give up on the socket - which is what it was trying to do.

[bqv]

Whoops :D yes, I was digging around and set it to log to systemd's /dev/log. Clearly it can't keep up, that's a shame, I was liking that feature

[lastquestion]

Oh, is it! Haha, well, well @bqv ! Yes, then that explains why this bug happened. I will do an audit and make sure any time packets are written we've entered a frame and then at least you'll just a message "Sorry the buffer is full, stopping logging" instead of crashing out.

As for some hints about what to log it to, you can change the size of the buffer with explain-pause-log--dgram-buffer-size, it's set to 256. But it can easily be much bigger; it's just a circular buffer implemented in a vector. So far, when I've been using it, I've found that when you're typing, it's usually pretty OK, but if you're accepting packets from HTTP etc, it can be a problem. You may want to try using socat and then using it to buffer the input and have it then send the output to systemd. Another option is to write a little program that can accept and buffer?

I really want to make it so that a separate emacs process can stream the socket input and then build a proper visualization in buffer and explain-pause-top, but I'm dreading it because I think emacs won't be able to accept input fast enough, so I was already thinking about either using a existing *nix utility (preferable) or building something in python/go/something-not-C to buffer.

Another option I'm thinking about is to switching to TCP sockets, but the emacs C code for TCP send will yield to other code, which is of course bad when you're trying to instrument everything-emacs-runs :D So, to do TCP I would implement a producer-consumer using the same circular buffer. That would help with accept and backpressure, but he tradeoff there unfortunately though would be that sometimes emacs could lock up or do GC and you wouldn't be guaranteed to stream the command entry before it starts, whereas right now, if the DGRAM socket is fast enough, we're sure to send the record.

I might make it an option.

But yes, the stream is actually super useful, and it's really scary/interesting how much stuff executes in emacs to just accept one key press sometimes :O

If you have ideas about how you'd use the feature, where you'd like to log to , if you would find TCP much more useful, etc. let me know your thoughts.

The original intent of the socket was to finally be able to "See what emacs is doing when it pauses!", which is why I originally chose the UDP DGRAM socket, but it's been a real pain so far...

[bqv]

That all sounds worthwhile! I've personally attempting to use it to narrow down what might be causing a recurring crash, and it seems very useful theoretically to just have "more logs" in systemd, but you're right, it's probably a good idea to buffer it out with socat or similar.

Alternatively, if your solution demotes it to a warning which carries on logging after, I'm happy to have small silent spots at least for this purpose :)

Either way, definitely a neat feature