- 環境
- 改善前
- 改善前計測
- untrackedcacheを使った高速化
- file system monitorを使った高速化
- サブモジュールをオフにして高速化
- Appendix: Gitバージョンアップ実験結果
- まとめ
- We are hiring!
こんにちは。バックエンドエンジニアのshirakawaxです。
Mirrativのバックエンドリポジトリのgit statusが遅かったので1.941秒 → 0.173秒に改善した話を書きます。
環境
Apple M1 Max メモリ 64 GB macOS Sonoma 14.4
$ git -v git version 2.39.3 (Apple Git-146)
改善前
私の環境では改善前のgit statusは1.941秒かかっていました。 頻繁に実行するコマンドではないですが、若干ストレスになっていました。
$ time git status On branch master Your branch is up to date with 'origin/master'. nothing to commit, working tree clean git status 0.25s user 2.18s system 124% cpu 1.941 total
改善前計測
gitのパフォーマンス計測にはGIT_TRACE_PERFORMANCE環境変数(Trace1)やTrace2を使った計測方法があります。
GIT_TRACE_PERFORMANCE環境変数(Trace1)は、有効にしてgitコマンドを実行すると、パフォーマンス用のログが標準出力に出ます。 Trace2はGit 2.22で導入されたログ フレームワークで、GIT_TRACE_PERFORMANCE環境変数(Trace1)の後継として導入されました。 今回は詳細が分かりやすいTrace2を使って計測しています。
Trace2を使う場合は、以下のように機能フラグとログ出力先を指定してgitコマンドを実行します。ログはgitコマンドを実行するたびに追記されるので必要に応じてリセットしてください。
# 機能フラグを有効にする $ export GIT_TRACE2_PERF_BRIEF=true # ログ出力先を指定する $ export GIT_TRACE2_PERF=$(pwd)/local/trace2.log # サブモジュールがあるとログが見辛いのでオフにしてます $ git status --ignore-submodules=all On branch master Your branch is up to date with 'origin/master'. nothing to commit, working tree clean
ログはPERF 形式で出力されます。
以下が実際のログになります。
ログを見ると、大抵の項目は0.001秒 ~ 0.01秒ですが、後半にあるlabel:untracked (gitでバージョン管理されていないファイルの確認)処理だけで1.81秒かかっておりボトルネックになっていました。
cat local/trace2.log | 絶対時間 | 経過時間 | カテゴリ | メッセージ | | | | 2.39.3 (Apple Git-146) | 0.003200 | | | /Applications/Xcode.app/Contents/Developer/usr/bin/git status --ignore-submodules=all | | | | worktree:/Users/hogefuga/Documents/projects/backend | | | | status (status) | 0.006748 | | index | label:do_read_index .git/index | 0.014735 | | cache_tree | ..label:read | 0.024203 | 0.009468 | cache_tree | ..label:read | 0.024255 | 0.017507 | index | ..read/version:2 | 0.024266 | 0.017518 | index | ..read/cache_nr:90500 | 0.024276 | 0.017528 | index | label:do_read_index .git/index | 0.024294 | | progress | label:Refresh index | 0.024301 | | index | ..label:preload | 0.131155 | 0.106854 | index | ....preload/sum_lstat:90498 | 0.131213 | 0.106912 | index | ..label:preload | 0.131220 | | index | ..label:refresh | | | | ....worktree:/Users/hogefuga/Documents/projects/backend/embed/submodule_1 | | | | ....worktree:/Users/hogefuga/Documents/projects/backend/embed/submodule_2 | 0.135313 | 0.004093 | index | ....refresh/sum_lstat:2 | 0.135322 | 0.004102 | index | ....refresh/sum_scan:0 | 0.135326 | 0.004106 | index | ..label:refresh | 0.135332 | 0.111038 | progress | ..total_objects:90500 # ↓後ろの節で見ますがlabel:Refresh indexも後で改善します。 | 0.135336 | 0.111042 | progress | label:Refresh index | 0.135687 | | status | label:worktrees | 0.137517 | | diff | ..label:setup | 0.137539 | 0.000022 | diff | ..label:setup | 0.137543 | | diff | ..label:write back to queue | 0.137548 | 0.000005 | diff | ..label:write back to queue | 0.137555 | 0.001868 | status | label:worktrees | 0.137560 | | status | label:index | 0.145312 | | unpack_trees | ..label:unpack_trees | 0.146151 | | unpack_trees | ....label:traverse_trees | 0.146195 | 0.000044 | unpack_trees | ....label:traverse_trees | 0.146424 | 0.001112 | unpack_trees | ..label:unpack_trees | 0.146439 | | diff | ..label:setup | 0.146445 | 0.000006 | diff | ..label:setup | 0.146460 | | diff | ..label:write back to queue | 0.146464 | 0.000004 | diff | ..label:write back to queue | 0.146469 | 0.008909 | status | label:index | 0.146473 | | status | label:untracked | 0.146693 | | dir | ..label:read_directory | 0.146802 | | index | ....label:name-hash-init | 0.158578 | 0.011776 | index | ....label:name-hash-init | 1.965044 | 1.818351 | read_directo | ....path: | 1.965074 | 1.818381 | read_directo | ....directories-visited:38175 | 1.965079 | 1.818386 | read_directo | ....paths-visited:130156 | 1.965083 | 1.818390 | dir | ..label:read_directory # ↓label:untrackedで1.81秒かかっている | 1.965091 | 1.818618 | status | label:untracked | 1.965586 | 1.965586 | status | count/changed:0 | 1.965609 | 1.965609 | status | count/untracked:0 | 1.965614 | 1.965614 | status | count/ignored:0 | 1.965618 | | status | label:print | 1.966125 | 0.000507 | status | label:print | 1.966142 | | | code:0 | 1.966151 | 1.966151 | traverse_tre | statistics:{"traverse_trees_count":1,"traverse_trees_max_depth":1} | 1.966160 | | | code:0
untrackedcacheを使った高速化
untrackedの確認を高速化するためにuntrackedcacheが使用できます。
untrackedcacheを有効にすると、ディレクトリの更新時刻（mtime）が変わらない場合は再度のディレクトリ読み込みや stat 呼び出しを省略し高速化できます。
untrackedcacheを使うにはmtimeが正しく機能する必要があり、以下のコマンドでテストできます。
$ git update-index --test-untracked-cache Testing mtime in '/Users/testdayo/Documents/projects/backend' ...... OK
untrackedcacheを有効にして計測してみます。
$ git config core.untrackedcache true $ rm local/trace2.log $ git status --ignore-submodules=all
ログを見るとlabel:untracked処理が1.81秒 → 0.106秒に短くなっています。だいぶ改善されました。
| 絶対時間 | 経過時間 | カテゴリ | メッセージ # 略 | 0.175419 | | status | label:untracked | 0.175713 | | dir | ..label:read_directory | 0.281987 | 0.106274 | read_directo | ....path: | 0.282015 | 0.106302 | read_directo | ....directories-visited:38175 | 0.282019 | 0.106306 | read_directo | ....paths-visited:38174 | 0.282023 | 0.106310 | read_directo | ....node-creation:0 | 0.282026 | 0.106313 | read_directo | ....gitignore-invalidation:0 | 0.282029 | 0.106316 | read_directo | ....directory-invalidation:0 | 0.282033 | 0.106320 | read_directo | ....opendir:0 | 0.282036 | 0.106323 | dir | ..label:read_directory # ↓改善された | 0.282047 | 0.106628 | status | label:untracked | 0.282607 | 0.282607 | status | count/changed:0 | 0.282629 | 0.282629 | status | count/untracked:0 | 0.282632 | 0.282632 | status | count/ignored:0 | 0.282636 | | status | label:print | 0.283293 | 0.000657 | status | label:print | 0.283307 | | | code:0 | 0.283315 | 0.283315 | traverse_tre | statistics:{"traverse_trees_count":1,"traverse_trees_max_depth":1} | 0.283319 | | | code:0
Trace2をオフにして計測すると、git statusコマンド全体の処理時間は改善前と比べると1.941秒 → 0.399秒と改善されていることがわかります
$ export GIT_TRACE2_PERF_BRIEF=false $ time git status On branch master Your branch is up to date with 'origin/master'. nothing to commit, working tree clean git status 0.16s user 1.08s system 312% cpu 0.399 total
file system monitorを使った高速化
Mirrativのバックエンドリポジトリはモノレポで管理されており、2025年2月現在はファイル数が9万ほどあります。
$ git ls-files ./ | wc -l 90187
gitが差分を算出する際はワークツリー全体を検索する必要があるため、ファイル数に応じて処理が遅くなりやすいです。 これを解決するためにgit 2.37.0から導入されたfile system monitorが使えます。 file system monitorは、ファイルの変更を検知するデーモンを常駐させることで、全ファイルではなく変更されたファイルだけ差分チェックできるようにする仕組みです。
configを書き換えるだけで有効になります。(現在はmacOSとwindowsのみ使用可能です)
$ git config core.fsmonitor true
git fsmonitor--daemon status コマンドでdaemonが起動していることがわかります。
$ git fsmonitor--daemon status fsmonitor-daemon is watching '/Users/testdayo/Documents/projects/backend'
$ export GIT_TRACE2_PERF_BRIEF=true $ rm local/trace2.log $ git status --ignore-submodules=all
fsmonitorを有効にしたことでlabel:Refresh indexの処理時間が0.111042秒 → 0.007714秒に短くなりました。
| 絶対時間 | 経過時間 | カテゴリ | メッセージ # 略 | | | | 2.39.3 (Apple Git-146) | 0.002192 | | | /Applications/Xcode.app/Contents/Developer/usr/bin/git status --ignore-submodules=all | | | | worktree:/Users/hogefuga/Documents/projects/backend | | | | status (status) | 0.006329 | | index | label:do_read_index .git/index | 0.013220 | | cache_tree | ..label:read | 0.023909 | 0.010689 | cache_tree | ..label:read | 0.027429 | 0.021100 | index | ..extension/fsmn/read/token:builtin:0.2084.20250210T150900.201203Z:970 | 0.027503 | 0.021174 | index | ..read/version:2 | 0.027512 | 0.021183 | index | ..read/cache_nr:90500 | 0.027520 | 0.021191 | index | label:do_read_index .git/index | 0.028038 | | fsm_client | label:query | 0.028066 | 0.000028 | fsm_client | ..query/command:builtin:0.2084.20250210T150900.201203Z:970 | 0.028080 | | ipc-client | ..label:try-connect | 0.028088 | 0.000008 | ipc-client | ....try-connect/path:.git/fsmonitor--daemon.ipc | 0.028130 | 0.000050 | ipc-client | ....try-connect/state:0 | 0.028142 | 0.000062 | ipc-client | ..label:try-connect | 0.028149 | | ipc-client | ..label:send-command | 0.040667 | 0.012518 | ipc-client | ..label:send-command | 0.040712 | 0.012674 | fsm_client | ..query/response-length:101 | 0.040720 | 0.012682 | fsm_client | label:query | 0.040727 | | fsmonitor | label:apply_results | 0.040745 | 0.000018 | fsmonitor | ..apply_count:3 | 0.040752 | 0.000025 | fsmonitor | label:apply_results | 0.040770 | | progress | label:Refresh index | 0.040777 | | index | ..label:preload | 0.041161 | 0.000384 | index | ....preload/sum_lstat:0 | 0.041178 | 0.000401 | index | ..label:preload | 0.041184 | | index | ..label:refresh | | | | ....worktree:/Users/hogefuga/Documents/projects/backend/embed/submodule_1 | | | | ....worktree:/Users/hogefuga/Documents/projects/backend/embed/submodule_2 | 0.048434 | 0.007250 | index | ....refresh/sum_lstat:2 | 0.048445 | 0.007261 | index | ....refresh/sum_scan:0 | 0.048451 | 0.007267 | index | ..label:refresh | 0.048479 | 0.007709 | progress | ..total_objects:90500 # ↓改善された | 0.048484 | 0.007714 | progress | label:Refresh index
Trace2をオフにして計測すると、git statusコマンド全体の処理時間は前回の改善から0.399秒 → 0.271秒と改善できました。
$ export GIT_TRACE2_PERF_BRIEF=false $ time git status On branch master Your branch is up to date with 'origin/master'. nothing to commit, working tree clean git status 0.14s user 0.09s system 81% cpu 0.271 total
サブモジュールをオフにして高速化
Mirrativのバックエンドリポジトリには2つのサブモジュールがあります。 --ignore-submodules=allをつけずにgit statusを実行してtrace2ログをみると、サブモジュールごとに差分を算出して微妙に時間がかかっていることがわかります。
$ cat local/trace2.log | 絶対時間 | 経過時間 | カテゴリ | メッセージ # 略 # ↓サブモジュール1つ目の処理 | 0.049440 | | status | label:worktrees | 0.051284 | | | ..[ch0] class:? cd:embed/submodule_1 argv:[git status --porcelain=2] | | | | 2.39.3 (Apple Git-146) | 0.002519 | | | /Applications/Xcode.app/Contents/Developer/usr/libexec/git-core/git status --porcelain=2 | | | | worktree:/Users/hogefuga/Documents/projects/backend/embed/submodule_1 | | | | status (status/status) | 0.004297 | | index | label:do_read_index /Users/hogefuga/Documents/projects/backend/.git/modules/embed/submodule_1/index | 0.004709 | | cache_tree | ..label:read | 0.004718 | 0.000009 | cache_tree | ..label:read | 0.004731 | 0.000434 | index | ..read/version:2 | 0.004737 | 0.000440 | index | ..read/cache_nr:56 | 0.004742 | 0.000445 | index | label:do_read_index /Users/hogefuga/Documents/projects/backend/.git/modules/embed/submodule_1/index | 0.004773 | | index | label:refresh | 0.004921 | 0.000148 | index | ..refresh/sum_lstat:56 | 0.004926 | 0.000153 | index | ..refresh/sum_scan:0 | 0.004930 | 0.000157 | index | label:refresh | 0.005200 | | status | label:worktrees | 0.005223 | | diff | ..label:setup | 0.005228 | 0.000005 | diff | ..label:setup | 0.005232 | | diff | ..label:write back to queue | 0.005236 | 0.000004 | diff | ..label:write back to queue | 0.005245 | 0.000045 | status | label:worktrees | 0.005249 | | status | label:index | 0.011865 | | unpack_trees | ..label:unpack_trees | 0.012040 | | unpack_trees | ....label:traverse_trees | 0.012055 | 0.000015 | unpack_trees | ....label:traverse_trees | 0.012063 | 0.000198 | unpack_trees | ..label:unpack_trees | 0.012069 | | diff | ..label:setup | 0.012073 | 0.000004 | diff | ..label:setup | 0.012077 | | diff | ..label:write back to queue | 0.012081 | 0.000004 | diff | ..label:write back to queue | 0.012086 | 0.006837 | status | label:index | 0.012091 | | status | label:untracked | 0.012190 | | dir | ..label:read_directory | 0.012311 | | index | ....label:name-hash-init | 0.012332 | 0.000021 | index | ....label:name-hash-init | 0.013435 | 0.001245 | read_directo | ....path: | 0.013458 | 0.001268 | read_directo | ....directories-visited:12 | 0.013474 | 0.001284 | read_directo | ....paths-visited:68 | 0.013478 | 0.001288 | dir | ..label:read_directory | 0.013485 | 0.001394 | status | label:untracked | 0.016834 | 0.016834 | status | count/changed:0 | 0.016858 | 0.016858 | status | count/untracked:0 | 0.016863 | 0.016863 | status | count/ignored:0 | 0.016868 | | status | label:print | 0.016874 | 0.000006 | status | label:print | 0.016882 | | | code:0 | 0.016890 | 0.016890 | traverse_tre | statistics:{"traverse_trees_count":1,"traverse_trees_max_depth":1} | 0.016897 | | | code:0 | 0.081167 | 0.029883 | | ..[ch0] pid:21177 code:0 # ↑ここまでサブモジュール1つ目の処理 # ↓サブモジュール2つ目の処理 | 0.081708 | | | ..[ch1] class:? cd:embed/submodule_2 argv:[git status --porcelain=2] | | | | 2.39.3 (Apple Git-146) | 0.002707 | | | /Applications/Xcode.app/Contents/Developer/usr/libexec/git-core/git status --porcelain=2 | | | | worktree:/Users/hogefuga/Documents/projects/backend/embed/submodule_2 | | | | status (status/status) | 0.003825 | | index | label:do_read_index /Users/hogefuga/Documents/projects/backend/.git/modules/embed/submodule_2/index | 0.004109 | | cache_tree | ..label:read | 0.004118 | 0.000009 | cache_tree | ..label:read | 0.004126 | 0.000301 | index | ..read/version:2 | 0.004132 | 0.000307 | index | ..read/cache_nr:57 | 0.004137 | 0.000312 | index | label:do_read_index /Users/hogefuga/Documents/projects/backend/.git/modules/embed/submodule_2/index | 0.004160 | | index | label:refresh | 0.004293 | 0.000133 | index | ..refresh/sum_lstat:57 | 0.004297 | 0.000137 | index | ..refresh/sum_scan:0 | 0.004301 | 0.000141 | index | label:refresh | 0.004469 | | status | label:worktrees | 0.004489 | | diff | ..label:setup | 0.004493 | 0.000004 | diff | ..label:setup | 0.004497 | | diff | ..label:write back to queue | 0.004500 | 0.000003 | diff | ..label:write back to queue | 0.004510 | 0.000041 | status | label:worktrees | 0.004514 | | status | label:index | 0.007851 | | unpack_trees | ..label:unpack_trees | 0.007997 | | unpack_trees | ....label:traverse_trees | 0.008010 | 0.000013 | unpack_trees | ....label:traverse_trees | 0.008018 | 0.000167 | unpack_trees | ..label:unpack_trees | 0.008023 | | diff | ..label:setup | 0.008027 | 0.000004 | diff | ..label:setup | 0.008030 | | diff | ..label:write back to queue | 0.008034 | 0.000004 | diff | ..label:write back to queue | 0.008039 | 0.003525 | status | label:index | 0.008043 | | status | label:untracked | 0.008144 | | dir | ..label:read_directory | 0.008254 | | index | ....label:name-hash-init | 0.008274 | 0.000020 | index | ....label:name-hash-init | 0.009887 | 0.001743 | read_directo | ....path: | 0.009910 | 0.001766 | read_directo | ....directories-visited:12 | 0.009922 | 0.001778 | read_directo | ....paths-visited:69 | 0.009927 | 0.001783 | dir | ..label:read_directory | 0.009934 | 0.001891 | status | label:untracked | 0.010457 | 0.010457 | status | count/changed:0 | 0.010466 | 0.010466 | status | count/untracked:0 | 0.010471 | 0.010471 | status | count/ignored:0 | 0.010475 | | status | label:print | 0.010479 | 0.000004 | status | label:print | 0.010485 | | | code:0 | 0.010492 | 0.010492 | traverse_tre | statistics:{"traverse_trees_count":1,"traverse_trees_max_depth":1} # ↑ここまでサブモジュール2つ目の処理 # あとはリポジトリの差分処理などが続く
普段サブモジュールに依存する作業がない方は、サブモジュールを無視して高速化することを検討できそうです。 今回はgit statusのaliasとしてgit stコマンドを.gitconfigに追加して自動で--ignore-submodules=allがつくようにしました。
[alias] st = status --ignore-submodules=all
trace2をオフにして計測すると、git statusコマンド全体の処理時間は前回の改善から0.271秒 → 0.173秒まで高速化できました。
$ export GIT_TRACE2_PERF_BRIEF=false $ time git st On branch master Your branch is up to date with 'origin/master'. nothing to commit, working tree clean git st 0.07s user 0.03s system 58% cpu 0.173 total
Appendix: Gitバージョンアップ実験結果
今回のgit status高速化検証の一環として、Git自体を最新バージョンにアップデートして試してみました。しかし、最新バージョンに更新してもgit statusの実行時間に変化は見られませんでした。
$ brew install git $ git -v git version 2.48.1 $ time git st On branch master Your branch is up to date with 'origin/master'. nothing to commit, working tree clean git st 0.08s user 0.03s system 60% cpu 0.178 total
まとめ
Trace2を使って計測し、untracked cache と fsmonitor とサブモジュールの無視でgit statusを高速化しました。地味な改善ですが何かの参考になれば幸いです。
$ git config core.untrackedcache true $ git config core.fsmonitor true $ git status --ignore-submodules=all
We are hiring!
こういう改善楽しいですね。 ミラティブでは計測 & 改善が大好きなエンジニアを募集しています！！
