在 Emacs 中分析 shell 命令

Question

有没有办法分析 emacs 中 shell 命令的阻塞时间？考虑以下程序：

(profiler-start 'cpu)
(shell-command "sleep 3")
(profiler-report)
(profiler-stop)

分析器报告将如下所示：

- 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%

如您所见，所花费的时间或多或少是均匀分布的。我有兴趣看到输出告诉我我将程序的重要部分花费在 shell 命令sleep 3 上，这可能吗？我知道sleep 3 在我的 CPU 上并不重 - 但我试图弄清楚从 magit 调用哪些 shell 命令需要很长时间 - 所以我也会对 IO 的东西感兴趣-绑定。

Answer 1

请注意，profiler.el 是一个采样分析器。如果您对挂墙时间感兴趣，您可能想尝试使用诸如elp.el 之类的检测分析器。

在您的情况下，您可能希望使用 M-x elp-instrument-package RET magit RET 来检测 magit。运行 magit 命令后，您可以使用 M-x elp-results RET 查看结果。

对于magit，您可能会发现函数magit-process-file 占用了大量时间。为了进一步调查特定的函数调用，您可以简单地检测该函数或任何其他函数，方法是添加一个建议函数，将运行时连同函数的参数一起记录到每个单独函数调用的消息缓冲区中，如下所示。

(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)