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

[jdelStrother]

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?

[lastquestion]

I'm sure it is. There is code that is "supposed" to handle this: https://github.com/lastquestion/explain-pause-mode/blob/master/explain-pause-mode.el#L1264-L1270

So, to summarize what happens, I think it's something like this:

1. You run git commit from command line
2. You have GIT_EDITOR set to emacs
3. This opens emacs, and then magit notices that you're opening a commit file, and runs a BUNCH of code to do magit stuff
4. Somewhere in this stack of code, either multiple commands are being nested, or multiple pipe-process-io, or timers are nesting
5. Command A was in the middle of being profiled and then command B profiled

Right?

I think what ought to occur is that the profiling flag needs to be set globally and checked from either process, timer, or command paths, and it should assume nesting is possible.

I remember reading the docs on this area, but I didn't read carefully enough: https://www.gnu.org/software/emacs/manual/html_node/elisp/Filter-Functions.html says

Emacs will only call the filter function during certain function calls. See Output from Processes. Note that if any of those functions are called by the filter, the filter may be called recursively.

This links further to

Output from a subprocess can arrive only while Emacs is waiting: when reading terminal input (see the function waiting-for-user-input-p), in sit-for and sleep-for (see Waiting), in accept-process-output (see Accepting Output), and in functions which send data to processes (see Input to Processes).

I think I can guess at a minimal repro case; I don't think you need to do anything. However, if this is annoying you right now a lot, set explain-pause-profile-enabled to nil until I fix this 💯

[lastquestion]

I thought about this problem a bit tonight and I realized my initial impressions are "right", but something is wrong, because I realized that code really does handle recursion already. Somehow a command must be attempting to profile while someone is already profiling. WTF?

So then I more closely read what you wrote, which is my fault for assuming that I knew what was wrong. My bad 😢. So then I grepped the magit sources. And I learned things.

When you do c c to ask magit to create a commit, magit does spawn a subprocess for git as an async process, which I expected. But, it sets GIT_EDITOR using this package with-editor to running emacs itself using a socket ? https://github.com/magit/with-editor. Then git will ask that editor, a emacsclient to ourselves, the original running emacs process, to open a file, which then magit (or with-editor I'm not sure which yet) opens as COMMIT_EDITMSG. Which is actually a kind of cute and nice way of dealing with it, as then the buffer you actually edit really is visiting the file that git expects the commit message to be written in, and no shenanigans needs to occur to pass the commit message you write back to git.

This is unexpected, in the sense that I surveyed the docs and knew that server-start and emacs as a server existed but didn't think it would be important to cover in v0.1. I need to read the docs and sources and understand how emacsclient works, and exactly what happens when multiple clients are connected to a emacs server.

All this is to say, sorry, this isn't as trivial a fix as I thought it would be. I still probably won't need a repro, but I need to think & survey the code for server-start to get to grips on how to fix this.

[jdelStrother]

No worries, I didn't expect it to be easy 🙂

[lastquestion]

Notes from investigation so far:

server.el is the ONLY built in elisp code in emacs that calls run-hook + pre-command-hooks and post-command-hooks, based on grep of emacs sources. It does so inside of server-visit-files, which is called from server-execute, which has the scary text:

;; This is run from timers and process-filters, i.e. "asynchronously".
;; But w.r.t the user, this is not really asynchronous since the timer
;; is run after 0s and the process-filter is run in response to the
;; user running emacsclient. So it is OK to override the
;; inhibit-quit flag, which is good since `commands' (as well as
;; find-file-noselect via the major-mode) can run arbitrary code,
;; including code that needs to wait.

(https://github.com/emacs-mirror/emacs/blob/master/lisp/server.el#L1296-L1302) Great.....

server-execute can either be directly called from a process filter OR from a timer. In either case, it may ultimately call server-visit-files. At that point, this-command is nil, because we are not in a command loop, yet server.el. has decided to call pre-command-hook without setting that value. And, we're starting a "command loop" in the middle of a timer or process filter.

Further, server-visit-files calls find-file-noselect when not executing random arbitrary elisp commands from the emacsclient. That ultimately does a bunch of stuff but calls y-or-n-p, which ultimately calls read-string (C code). read-string reads from minibuffer input (C code), which ultimately calls minibuffer-hooks. So it's possible to end up in minibuffer loop by calling y-or-no-p, which apparently it's OK to call from timer or process filter code!

sit-for is also called within process filter / timer loops; I separately discovered this in #31 unrelatedly.

So, mulling more about what to do here:

1. Cannot assume that people are correctly setting real-this-command and nesting pre/post-command-hooks. Need to be defensive, it's elisp, anyone can do anything. The actual C code in the command loop is only one representative good citizen. Must assume:

• command loops could be incomplete (someone called pre without post, in a random order, in a bad order, with nil as command). We must survive but maybe not actually record the data, maybe we take a stack backtrace so we can shame people, etc.
• command loops could be nested (command calls precommand, postcommand pretending to be a command loop)
• command loops could be called from timers or process filters

2. Must assume timer/process could call back into any family of read input / wait functions - similar to Handle sit-for variants inside timers and process handlers #31. Similarly, must assume timer/process code could ultimately call into minibuffer and the minibuffer hooks.

3. Assuming we do 1 + 2 correctly, the profiling invariant will hold again and the bug will be fixed.

Technical solution probably involves a stack of "current execution context" that is pushed from any side of code, command loop OR minibuffer OR process / timer, and we need to pop and push as we go. We also need to track read-time as an local of the current execution context so we don't misattribute.

[lastquestion]

OK, repro case:

(defun evil-function ()
  (message "inside evil %s" real-this-command)
  (run-hooks 'pre-command-hook)
  (message "after pre-command-evil")
  (run-hooks 'post-command-hook))

(defun test-command ()
  (interactive)
  (message "inside test-command")
  (explain-pause-profiles-force-command '(test-command))
  (run-with-timer 0.5 nil 'evil-function)
  (sit-for 2)
  (message "exit test-command"))

(defun prepare ()
  (explain-pause-profiles-clear-candidates)
  (explain-pause-profiles-force-command '(evil-function
                                          timer
                                          ivy-done)))

Notes to self: requires running as m-x, that's why ivy-done is in the command-set. Need to change how the command-set matching works, also, should be repro even with call-interactively, I think...

I am going to squash some easier display bugs and then come back to this. I also may add a test suite before tackling this refactor.

[lastquestion]

Update: Been working on this the last couple of days. I have an idea to stop measuring the command loop. We really only want to track "interactive" calls, so now I'm advising call-interactively directly. This approach also resolves like 3 other issues and improves how minibuffer entries are counted.

I am going to write test cases to cover all the bugs I already fixed, so I don't break them again with this rewrite of the measurement code. But I'll push a branch once I think it's working even if not all the tests are written so you can test it out too.

Coming soon.

[lastquestion]

^- the above PR which I need to add tests on and manually test (for now) at least emacs + emacs windowed should fix this now. I have been using magit with it for the last couple of days and things are ok.