# はじめに
弊社では複数ある web サービスのうち、Rust を採用しているサービスがあります。 これの開発時の cargo check が重いなあと以前から感じていたので、どこがボトルネックになっているのか調査したいと思い、パフォーマンスの計測の仕方について調べました。
# TL;DR
timings を使うと crate ごとのビルド時間がわかり、self-profile を使ったコンパイラのフェーズごとのボトルネックを調べることができます。
# スコープ
今回は cargo check のみを対象として測定することにしました。 rust-analyzer や cargo build などは対象とはしていません。
# 対象とするファイルの規模
対象となっているリポジトリに含まれる Rust コードは 600 ファイル、 80000 行程度です。
# timings による計測
cargo のビルド時間を見る方法でまず浮かぶのは timings を使った計測でしょう。
cargo check --timings で crate ごとのビルド(check)時間を見ることができます。
これを適用すると、以下のような結果が得られます。
| Unit | Total | Codegen |
|---|---|---|
| 弊社サービス | 28.0s | 0.4s (1%) |
| diesel | 4.6s | 0.0s (1%) |
| chrono-tz | 2.7s | 0.0s (1%) |
| google_maps | 2.1s | 0.0s (1%) |
ということで、素の状態でのビルドはほぼ弊社サービスが支配的となっていることがわかります。 また、開発時には依存ライブラリのビルドはほぼキャッシュされていることが予想できるため、やはり弊社サービスのビルド時間が開発者体験にダイレクトに影響を与えているのではないかという予想が立ちました。
そこで今度はより深ぼって、弊社サービスの cargo check 自体のパフォーマンスを計測する方法を調べました。
# self-profile による計測
Rust には self-profile というオプションがあり、これを使うとコンパイル時の trace を吐いてくれるようです。
https://doc.rust-lang.org/beta/unstable-book/compiler-flags/self-profile.html
self-profile の吐く結果はそのままだと読めないので、以下で提供されているツール群を使うと良いです。
self-profile を使った計測は以下のように行います。
RUSTFLAGS="-Zself-profile" cargo +nightly check
RUSTFLAGS="-Zself-profile" cargo +nightly clean -p my_crate
RUSTFLAGS="-Zself-profile" cargo +nightly check
内容としては、まず cargo check でビルドして、 cargo clean -p my_crate で当該 crate のキャッシュのみ削除し、再度 cargo check でビルドします。
これにより .mm_profdata なるファイルが作成されます。
これを上記の summarize で集計すると、以下のようなフェーズごとの結果が得られます。 (一部抜粋)
| Item | Self time | % of total time | Time | Item count | Incremental result hashing time |
|---|---|---|---|---|---|
| evaluate_obligation | 5.85s | 20.017 | 5.96s | 305275 | 35.86ms |
| typeck | 4.62s | 15.797 | 9.50s | 26677 | 78.19ms |
| type_op_prove_predicate | 3.70s | 12.645 | 4.22s | 159797 | 36.40ms |
| mir_borrowck | 2.42s | 8.283 | 14.60s | 26677 | 4.18ms |
| normalize_canonicalized_projection_ty | 1.06s | 3.639 | 1.38s | 30033 | 6.55ms |
| expand_proc_macro | 926.08ms | 3.167 | 926.08ms | 1403 | 0.00ns |
| compare_impl_item | 737.40ms | 2.522 | 966.19ms | 17081 | 1.83ms |
| mir_built | 629.82ms | 2.154 | 1.54s | 26677 | 144.08ms |
Self time のところがそのフェーズにかかっている時間を表しています。 一番大きな evalulate_obligation が 5.85s かかっていることがわかります。しかしこれでも全体の 20%なので、どこかがとても大きなボトルネックというわけではなさそうです。
また、Chrome の profiler に読み込ませることができるフォーマットで吐いてくれる crox というツールもあるようですが、私の環境では Chrome は読んでくれませんでした(残念)。 flamegraph を吐いてくれるツールもあるので、こちらも使ってみると以下のようになります。
これをみると、型チェックと借用チェックが支配的であることがわかります。 cargo check でこれらが重くなることは順当だなと思います。
# まとめ
以上のことから取れる対策としては、
- コードの中でコンパイルが重そうな箇所をコメントアウトするなどして、支配的な場所を探す
- crate を分割する
あたりかなと思います。 ただ、前者についてはどこかに強烈なボトルネックがあるようにも感じないので、そこまで効果があるかはわかりません。
対策については計測する前からうすうすわかっていたことではありますが、計測するツールについて知ることができたので良いことにします。