トレースと計測のためにmy-profiler.elを作りました。
まずは全体的な流れを把握。
(require 'my-profiler)
(my-profiler-instrument-all
'((magit-commit-create . start)
(server-execute . stop)
magit-commit-diff
git-commit-setup
(git-commit-setup-font-lock-in-buffer . short)
(magit-auto-revert-mode-enable-in-buffers . short)
normal-mode))
(progn
(switch-to-buffer "magit: my-test-git-repository")
(magit-commit-create))
TM startからの経過時間 前計測点からの経過時間 関数内の滞在時間
TM 0.014 + 0.014 Enter #<subr magit-commit-create>
TM 806.706 + 806.692 806.641 Leave #<subr magit-commit-create>
TM 988.713 + 182.007 Enter #<subr server-execute>
TM 996.355 + 7.642 Enter #<subr normal-mode>
TM 1209.287 + 212.932 212.859 Eval #<subr git-commit-setup-font-lock-in-buffer>
TM 1675.698 + 466.411 466.354 Eval #<subr magit-auto-revert-mode-enable-in-buffers>
TM 1896.232 + 220.534 217.599 Eval #<subr git-commit-setup-font-lock-in-buffer>
TM 2364.570 + 468.338 468.274 Eval #<subr magit-auto-revert-mode-enable-in-buffers>
TM 2365.017 + 0.447 1368.649 Leave #<subr normal-mode>
TM 2365.066 + 0.049 Enter #<subr git-commit-setup>
TM 2365.100 + 0.034 Enter #<subr normal-mode>
TM 2587.760 + 222.660 222.564 Eval #<subr git-commit-setup-font-lock-in-buffer>
TM 3060.027 + 472.267 472.190 Eval #<subr magit-auto-revert-mode-enable-in-buffers>
TM 3325.810 + 265.783 262.448 Eval #<subr git-commit-setup-font-lock-in-buffer>
TM 3782.673 + 456.863 456.770 Eval #<subr magit-auto-revert-mode-enable-in-buffers>
TM 3783.060 + 0.387 1417.947 Leave #<subr normal-mode>
TM 4899.085 + 1116.025 2533.975 Leave #<subr git-commit-setup>
TM 4899.128 + 0.043 0.001 Eval #<subr magit-auto-revert-mode-enable-in-buffers>
TM 5122.180 + 223.052 Enter #<subr magit-commit-diff>
TM 7588.585 + 2466.405 0.001 Eval #<subr git-commit-setup-font-lock-in-buffer>
TM 7588.614 + 0.029 0.003 Eval #<subr magit-auto-revert-mode-enable-in-buffers>
TM 7821.368 + 232.754 2699.136 Leave #<subr magit-commit-diff>
TM 7822.309 + 0.941 6833.551 Leave #<subr server-execute>
- まずmagit-commit-createが終わるまでに800msかかります。
- serverがemacsclientからの要求を受けてserver-executeを実行するのが約1s経過時点。以下server-executeの中で6.8sかかります。
- ファイルを開いてメジャーモードが切り替わるので、normal-mode関数によってafter-change-major-mode-hookが実行されます。フックに設定されているgit-commit-setup-font-lock-in-bufferとmagit-auto-revert-mode-enable-in-buffersが呼ばれます。一回のnormal-modeで二回も。
- git-commit-setupに入る時点で既に2.3s経過。
- git-commit-major-modeの設定に従ってメジャーモードを変更するのでまたafter-change-major-mode-hookが実行されます。
- そしてgit-commit-diffでdiffを出力し、終わるのが開始から7.8s後。
どの関数でも数百msもの時間がかかっています。
また、計上されていない時間もあり状況がよく分かりません。なのでそれらの関数の中身を読んで詳しく調べました。
すると多数のgitコマンドの実行が見つかりました。例えばgit-commit-setup-font-lock関数内には次のようなコードがあります。
(setq-local comment-start
(or (with-temp-buffer
(and (zerop
(call-process
(git-commit-executable) nil (list t nil) nil
"config" "core.commentchar"))
(not (bobp))
(progn
(goto-char (point-min))
(buffer-substring (point) (line-end-position)))))
"#"))
このコードは git config core.commentchar
を実行してコメントに使う文字をgitから取得しています。
また、git-commit-setup関数内には次のようなコードがあります。
(let ((default-directory
(or (and (not (file-exists-p ".dir-locals.el"))
(fboundp 'magit-toplevel)
(magit-toplevel))
default-directory)))
ここでは(magit-toplevel)という関数が使われています。この関数はリポジトリの最上位のディレクトリを返しますが、内部で git rev-parse --show-toplevel
というコマンドを実行しています。
このようにあちこちから気軽にgitコマンドが実行されているので全てを把握するのが困難です。
そこで次のような計測を行ってcall-processの呼び出し状況を調べてみました。
(require 'my-profiler)
(my-profiler-instrument-all
'((magit-commit-create . start)
(server-execute . stop)
magit-commit-diff
git-commit-setup
git-commit-setup-font-lock-in-buffer
magit-auto-revert-mode-enable-in-buffers
normal-mode
(call-process . short)))
(progn
(switch-to-buffer "magit: my-test-git-repository")
(magit-commit-create))
TM 0.067 + 0.067 Enter magit-commit-create
TM 165.595 + 165.528 128.970 Eval call-process
TM 276.355 + 110.760 110.152 Eval call-process
TM 383.838 + 107.483 106.953 Eval call-process
TM 492.492 + 108.654 108.011 Eval call-process
TM 597.941 + 105.449 103.835 Eval call-process
TM 702.018 + 104.077 103.379 Eval call-process
TM 806.025 + 104.007 103.550 Eval call-process
TM 818.413 + 12.388 818.277 Leave magit-commit-create
TM 998.803 + 180.390 Enter server-execute
TM 1006.222 + 7.419 Enter normal-mode
TM 1006.265 + 0.043 Enter git-commit-setup-font-lock-in-buffer
TM 1116.712 + 110.447 110.347 Eval call-process
TM 1225.767 + 109.055 108.696 Eval call-process
TM 1226.047 + 0.280 219.770 Leave git-commit-setup-font-lock-in-buffer
TM 1226.065 + 0.018 Enter magit-auto-revert-mode-enable-in-buffers
TM 1350.425 + 124.360 114.586 Eval call-process
TM 1457.264 + 106.839 106.571 Eval call-process
TM 1569.336 + 112.072 111.709 Eval call-process
TM 1683.220 + 113.884 113.402 Eval call-process
TM 1683.250 + 0.030 457.178 Leave magit-auto-revert-mode-enable-in-buffers
TM 1686.554 + 3.304 Enter git-commit-setup-font-lock-in-buffer
TM 1794.665 + 108.111 107.975 Eval call-process
TM 1910.274 + 115.609 115.262 Eval call-process
TM 1910.601 + 0.327 224.034 Leave git-commit-setup-font-lock-in-buffer
TM 1910.632 + 0.031 Enter magit-auto-revert-mode-enable-in-buffers
TM 2039.771 + 129.139 119.084 Eval call-process
TM 2154.799 + 115.028 114.813 Eval call-process
TM 2263.058 + 108.259 107.883 Eval call-process
TM 2374.596 + 111.538 111.138 Eval call-process
TM 2374.652 + 0.056 464.004 Leave magit-auto-revert-mode-enable-in-buffers
TM 2375.022 + 0.370 1368.786 Leave normal-mode
TM 2375.053 + 0.031 Enter git-commit-setup
TM 2375.080 + 0.027 Enter normal-mode
TM 2375.131 + 0.051 Enter git-commit-setup-font-lock-in-buffer
TM 2481.555 + 106.424 106.317 Eval call-process
TM 2590.186 + 108.631 108.101 Eval call-process
TM 2590.481 + 0.295 215.338 Leave git-commit-setup-font-lock-in-buffer
TM 2590.498 + 0.017 Enter magit-auto-revert-mode-enable-in-buffers
TM 2714.161 + 123.663 113.784 Eval call-process
TM 2825.484 + 111.323 111.140 Eval call-process
TM 2931.823 + 106.339 105.959 Eval call-process
TM 3046.016 + 114.193 113.908 Eval call-process
TM 3046.080 + 0.064 455.567 Leave magit-auto-revert-mode-enable-in-buffers
TM 3048.839 + 2.759 Enter git-commit-setup-font-lock-in-buffer
TM 3159.395 + 110.556 110.437 Eval call-process
TM 3269.152 + 109.757 109.407 Eval call-process
TM 3269.528 + 0.376 220.675 Leave git-commit-setup-font-lock-in-buffer
TM 3269.548 + 0.020 Enter magit-auto-revert-mode-enable-in-buffers
TM 3398.770 + 129.222 119.693 Eval call-process
TM 3504.807 + 106.037 105.769 Eval call-process
TM 3615.480 + 110.673 110.212 Eval call-process
TM 3727.668 + 112.188 111.808 Eval call-process
TM 3727.712 + 0.044 458.142 Leave magit-auto-revert-mode-enable-in-buffers
TM 3728.222 + 0.510 1353.118 Leave normal-mode
TM 3843.396 + 115.174 114.663 Eval call-process
TM 3954.347 + 110.951 110.736 Eval call-process
TM 4063.458 + 109.111 108.434 Eval call-process
TM 4173.732 + 110.274 109.117 Eval call-process
TM 4277.008 + 103.276 101.671 Eval call-process
TM 4386.951 + 109.943 109.613 Eval call-process
TM 4496.227 + 109.276 102.939 Eval call-process
TM 4607.267 + 111.040 110.903 Eval call-process
TM 4735.445 + 128.178 123.408 Eval call-process
TM 4846.907 + 111.462 110.492 Eval call-process
TM 4847.823 + 0.916 2472.720 Leave git-commit-setup
TM 4847.862 + 0.039 Enter magit-auto-revert-mode-enable-in-buffers
TM 4847.882 + 0.020 0.012 Leave magit-auto-revert-mode-enable-in-buffers
TM 4957.249 + 109.367 105.964 Eval call-process
TM 5071.761 + 114.512 114.348 Eval call-process
TM 5075.277 + 3.516 Enter magit-commit-diff
TM 5190.165 + 114.888 114.456 Eval call-process
TM 5299.389 + 109.224 108.968 Eval call-process
TM 5406.564 + 107.175 106.868 Eval call-process
TM 5523.598 + 117.034 116.481 Eval call-process
TM 5628.045 + 104.447 104.183 Eval call-process
TM 5733.773 + 105.728 105.326 Eval call-process
TM 5854.707 + 120.934 118.859 Eval call-process
TM 5961.210 + 106.503 106.278 Eval call-process
TM 6074.760 + 113.550 112.966 Eval call-process
TM 6204.416 + 129.656 129.186 Eval call-process
TM 6320.894 + 116.478 116.091 Eval call-process
TM 6426.537 + 105.643 105.306 Eval call-process
TM 6531.705 + 105.168 104.829 Eval call-process
TM 6653.648 + 121.943 121.594 Eval call-process
TM 6766.164 + 112.516 112.064 Eval call-process
TM 6883.633 + 117.469 116.855 Eval call-process
TM 6996.202 + 112.569 112.346 Eval call-process
TM 7105.460 + 109.258 108.693 Eval call-process
TM 7223.988 + 118.528 117.887 Eval call-process
TM 7330.973 + 106.985 106.761 Eval call-process
TM 7475.212 + 144.239 143.927 Eval call-process
TM 7595.205 + 119.993 118.270 Eval call-process
TM 7595.306 + 0.101 Enter git-commit-setup-font-lock-in-buffer
TM 7595.332 + 0.026 0.019 Leave git-commit-setup-font-lock-in-buffer
TM 7595.346 + 0.014 Enter magit-auto-revert-mode-enable-in-buffers
TM 7595.362 + 0.016 0.010 Leave magit-auto-revert-mode-enable-in-buffers
TM 7701.903 + 106.541 106.110 Eval call-process
TM 7825.783 + 123.880 123.021 Eval call-process
TM 7827.148 + 1.365 2751.850 Leave magit-commit-diff
TM 7828.413 + 1.265 6829.588 Leave server-execute
非常に多くのcall-processが呼ばれていることが分かります。その数なんと67回(この数は現在開いているファイルなどEmacs全体の状態によって多少変わります)。
1回につきだいたい100msは持って行かれています。それが67回ですから、そりゃ遅いわけです。