Profiling shell commands in Emacs

Question

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.

Answer 1

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)