Is there a way to profile the amount of time blocking on shell commands in emacs? Consider the following program:
(profiler-start 'cpu)
(shell-command "sleep 3")
(profiler-report)
(profiler-stop)
The profiler report will look something like this:
- command-execute 371 95%
- call-interactively 371 95%
- funcall-interactively 329 84%
- execute-extended-command 175 44%
- execute-extended-command--shorter 157 40%
- completion-try-completion 149 38%
- completion--nth-completion 149 38%
- completion--some 143 36%
- #<compiled 0x438307f1> 143 36%
- completion-pcm-try-completion 102 26%
- completion-pcm--find-all-completions 98 25%
completion-pcm--all-completions 98 25%
+ completion-pcm--merge-try 4 1%
completion-basic-try-completion 41 10%
+ sit-for 16 4%
- eval-expression 154 39%
- eval 154 39%
- profiler-start 154 39%
- debug 154 39%
- recursive-edit 141 36%
- command-execute 114 29%
- call-interactively 114 29%
- byte-code 107 27%
+ read--expression 64 16%
+ read-extended-command 43 11%
+ funcall-interactively 7 1%
+ byte-code 42 10%
+ ... 19 4%
As you can see the time spent is more or less evenly distributed. I'm interested in seeing output that tells me that I'm spending the significant part of the program blocking on the shell-command sleep 3, is this possible somehow? I am aware that sleep 3 is not heavy on my CPU - but I'm trying to figure out which shell commands are called from magit that is taking such a long time - so I'll also be interested in stuff that's IO-bound.
Note that profiler.el is a sampling profiler. You might want to try an instrumenting profiler such as elp.el if you are interested in the wall time.
In your case you may want to instrument magit by using M-x elp-instrument-package RET magit RET. After running your magit commands you can then take a look at the results using M-x elp-results RET.
For magit you would probably find that the function magit-process-file is taking up a lot of time. To further investigate the specific function calls you could then simply instrument that or any other function by adding an advice function logging the runtime together with the function's arguments to the messages buffer for each individual function call as follows.
(defun log-function-time (f &rest args)
(let ((time-start (current-time)))
(prog1
(apply f args)
(message "%s seconds used in (magit-process-file %s)"
(time-to-seconds (time-subtract (current-time) time-start))
args))))
(advice-add 'magit-process-file :around 'log-function-time)