Keyboard shortcuts

Press ← or → to navigate between chapters

Press S or / to search in the book

Press ? to show this help

Press Esc to hide this help

perf を使ったプロファイリング

これは、perf を使って rustc をプロファイリングする方法のガイドです。

初期手順

  • rust-lang/rust のクリーンなチェックアウトを取得する
  • bootstrap.toml に次の設定を行う:
    • rust.debuginfo-level = 1 - 行デバッグ情報を有効にする
    • rust.jemalloc = false - valgrind を使ったメモリ使用量のプロファイリングを可能にする
    • それ以外はすべてデフォルトのままにする
  • ./x build を実行して完全なビルドを取得する
  • その結果を指す rustup ツールチェーンを作成する

perf プロファイルの収集

perf は Linux 上の優れたツールであり、あらゆる種類の情報を収集して 分析するために使用できます。主に、プログラムがどこで時間を費やしているかを 把握するために使われます。ただし、キャッシュミスなど、他の種類のイベントにも 使用できます。

基本

基本的な perf コマンドは次のとおりです:

perf record -F99 --call-graph dwarf XXX

-F99 は、perf に 99 Hz でサンプリングするよう指示します。これにより、 長い実行で大量のデータが生成されるのを避けられます（なぜ 99 Hz なのか、ですか？ 他の周期的な活動と同期しにくいため、よく選ばれます）。--call-graph dwarf は、 正確なデバッグ情報からコールグラフ情報を取得するよう perf に指示します。XXX は プロファイリングしたいコマンドです。したがって、たとえば次のようにできます:

perf record -F99 --call-graph dwarf cargo +<toolchain> rustc

これは cargo を実行します – ここで <toolchain> は、最初に作成したツールチェーンの 名前である必要があります。ただし、注意すべき点がいくつかあります:

  • 依存関係のビルドに費やされる時間は、おそらくプロファイリングしたくないでしょう。 そのため、cargo build; cargo clean -p $C のようなものが役立つ場合があります （ここで $C は crate 名です）
    • ただし、通常は代わりに touch src/lib.rs して再ビルドするだけです。=)
  • インクリメンタルビルドがプロファイルに干渉するのは、おそらく望ましくないでしょう。 そのため、CARGO_INCREMENTAL=0 のようなものが役立ちます。

cargo から収集したデータを読み取るときに addr2line xxx/elf: could not read first record の問題を回避するには、 最新版の addr2line を使用する必要があるかもしれません:

cargo install addr2line --features="bin"

perf.rust-lang.org のテストから perf プロファイルを収集する

多くの場合、perf.rust-lang.org の特定のテストを分析したいことがあります。 それを行う最も簡単な方法は、rustc-perf ベンチマークスイートを 使用することです。この方法はこちらで説明されています。

ベンチマークスイートの CLI を使用する代わりに、ベンチマークを手動でプロファイリングすることもできます。まず、 rustc-perf リポジトリをクローンする必要があります:

$ git clone https://github.com/rust-lang/rustc-perf

次に、プロファイリングしたいテストのソースコードを見つけます。テストのソースは collector/compile-benchmarks ディレクトリと collector/runtime-benchmarks ディレクトリにあります。それでは、 特定のテストのディレクトリに移動しましょう。ここでは clap-rs を例として使用します:

cd collector/compile-benchmarks/clap-3.1.6

この場合、cargo check のパフォーマンスをプロファイリングしたいとします。 その場合、私はまず依存関係をビルドするためにいくつかの基本的なコマンドを実行します:

# セットアップ: まず古い結果をすべて削除し、依存関係をビルドします:
cargo +<toolchain> clean
CARGO_INCREMENTAL=0 cargo +<toolchain> check

（繰り返しになりますが、<toolchain> は最初の手順で作成したツールチェーンの名前に 置き換える必要があります。）

次に、cargo check を実行して、ちょうど clap-rs crate の実行時間を記録したいとします。 私はこれに cargo rustc を使うことが多いです。後で行うように、明示的なフラグを追加することも できるためです。

touch src/lib.rs
CARGO_INCREMENTAL=0 perf record -F99 --call-graph dwarf cargo rustc --profile check --lib

最後のコマンドに注意してください。これはかなり大がかりです！これは cargo rustc コマンドを使用しており、追加のオプションを付けて（可能性として）rustc を実行します。 --profile check と --lib オプションは、cargo check の実行を行っていること、 そしてこれがライブラリ（バイナリではない）であることを指定します。

この時点で、perf ツールを使用して結果を分析できます。たとえば:

perf report

これは対話型の TUI プログラムを開きます。単純なケースでは、これが役立つことがあります。 より詳細な調査には、perf-focus ツールが役立つ場合があります。これについては後述します。

注意事項。 rustc-perf の各テストは、それぞれ独自の特殊ケースです。 特に、その一部はライブラリではありません。その場合は touch src/main.rs を行い、 --lib を渡さないようにする必要があります。正直なところ、どのテストがどちらなのかを 見分ける最善の方法はよく分かりません。

NLL データの収集

NLL の実行をプロファイリングしたい場合は、次のように cargo rustc コマンドに 追加のオプションを渡すだけです:

touch src/lib.rs
CARGO_INCREMENTAL=0 perf record -F99 --call-graph dwarf cargo rustc --profile check --lib -- -Z borrowck=mir

perf focus による perf プロファイルの分析

perf プロファイルを収集したら、それに関する情報を取得したいところです。 このために、私は個人的に perf focus を使用しています。これはシンプルながら便利な ツールの一種で、次のようなクエリに答えることができます:

  • 「関数 F でどれだけの時間が費やされたか」（どこから呼び出されたかに関係なく）
  • 「関数 G から呼び出されたとき、関数 F でどれだけの時間が費やされたか」
  • 「関数 G で費やされた時間を除外して、関数 F でどれだけの時間が費やされたか」
  • 「F はどの関数を呼び出し、それらでどれだけの時間を費やしているか」

これがどのように機能するかを理解するには、perf について少しだけ知っておく必要があります。 基本的に、perf は定期的に（または何らかのイベントが発生したときに）プロセスを サンプリングすることで動作します。各サンプルについて、perf はバックトレースを収集します。 perf focus を使うと、そのバックトレースにどの関数が現れるかをテストする正規表現を 書くことができ、その正規表現に一致するバックトレースを持つサンプルが何パーセントあったかを 教えてくれます。おそらく、私が NLL パフォーマンスをどのように分析するかを順を追って説明するのが 最も分かりやすいでしょう。

perf-focus のインストール

cargo install を使って perf-focus をインストールできます:

cargo install perf-focus

例: MIR borrowck ではどれだけの時間が費やされているか？

あるテストについて NLL データを収集したとします。MIR 借用チェッカーで どれだけの時間が費やされているかを知りたいとします。MIR borrowck の「メイン」 関数は do_mir_borrowck と呼ばれているため、次のコマンドを実行できます:

$ perf focus '{do_mir_borrowck}'
Matcher    : {do_mir_borrowck}
Matches    : 228
Not Matches: 542
Percentage : 29%

'{do_mir_borrowck}' 引数は matcher と呼ばれます。これは、バックトレースに適用されるテストを指定します。この場合、{X} は、正規表現 X を満たす関数がバックトレース上に 何らか 存在しなければならないことを示します。この場合、その正規表現は、欲しい関数の名前そのものです（実際には、名前の一部です。完全な名前には、モジュールパスなど、ほかにも多くのものが含まれます）。このモードでは、perf-focus は、do_mir_borrowck がスタック上にあったサンプルの割合だけを出力します。この場合は 29% です。

c++filt に関する注意。 perf からデータを取得するために、perf focus は現在 perf script を実行しています（もっと良い方法があるかもしれません…）。ときどき、perf script が C++ のマングルされた名前を出力することがあります。これは厄介です。自分で perf script | head を実行すれば分かります。rustc::middle ではなく 5rustc6middle のような名前が見える場合、同じ問題が起きています。これは次のようにして解決できます。

perf script | c++filt | perf focus --from-stdin ...

これにより、perf script からの出力が c++filt にパイプされ、それらの名前の大半がより扱いやすい形式に変換されるはずです。perf focus の --from-stdin フラグは、perf focus を実行するのではなく、stdin からデータを取得するように指示します。これはもっと便利にすべきです（最悪の場合でも、perf focus に c++filt オプションを追加するか、単に常にそれを使うようにするかもしれません。かなり無害です）。

例: MIR borrowck は trait の解決にどれくらいの時間を費やしているか？

MIR borrowck が trait checker でどれくらいの時間を費やしているかを知りたいかもしれません。より複雑な正規表現を使って、これを問い合わせることができます。

$ perf focus '{do_mir_borrowck}..{^rustc::traits}'
Matcher    : {do_mir_borrowck},..{^rustc::traits}
Matches    : 12
Not Matches: 1311
Percentage : 0%

ここでは、.. 演算子を使って「スタック上に do_mir_borrowck があり、その後ろに、名前が rustc::traits で始まる何らかの関数がある頻度はどれくらいか？」を尋ねています（基本的には、そのモジュール内のコードです）。結果として、答えは「ほとんどない」です。その記述に当てはまるサンプルは 12 個だけです（サンプルが まったく 見つからない場合、多くの場合、クエリがおかしくなっていることを示します）。

興味があれば、--print-match オプションを使うことで、どのサンプルなのかを正確に調べることができます。これにより、各サンプルの完全なバックトレースが出力されます。行の先頭にある | は、正規表現がマッチした部分を示します。

例: MIR borrowck はどこで時間を費やしているか？

多くの場合、より「探索的」なクエリを実行したくなります。たとえば、MIR borrowck が時間の 29% を占めていることは分かっていますが、その時間はどこで費やされているのでしょうか？そのためには、--tree-callees オプションが最適なツールであることが多いです。通常は --tree-min-percent または --tree-max-depth も指定したくなります。結果は次のようになります。

$ perf focus '{do_mir_borrowck}' --tree-callees --tree-min-percent 3
Matcher    : {do_mir_borrowck}
Matches    : 577
Not Matches: 746
Percentage : 43%

Tree
| matched `{do_mir_borrowck}` (43% total, 0% self)
: | rustc_borrowck::nll::compute_regions (20% total, 0% self)
: : | rustc_borrowck::nll::type_check::type_check_internal (13% total, 0% self)
: : : | core::ops::function::FnOnce::call_once (5% total, 0% self)
: : : : | rustc_borrowck::nll::type_check::liveness::generate (5% total, 3% self)
: : : | <rustc_borrowck::nll::type_check::TypeVerifier<'a, 'b, 'tcx> as rustc::mir::visit::Visitor<'tcx>>::visit_mir (3% total, 0% self)
: | rustc::mir::visit::Visitor::visit_mir (8% total, 6% self)
: | <rustc_borrowck::MirBorrowckCtxt<'cx, 'tcx> as rustc_mir_dataflow::DataflowResultsConsumer<'cx, 'tcx>>::visit_statement_entry (5% total, 0% self)
: | rustc_mir_dataflow::do_dataflow (3% total, 0% self)

--tree-callees で起きることは次のとおりです。

  • 正規表現にマッチする各サンプルを見つける
  • 正規表現のマッチの 後 に現れるコードを見て、コールツリーを構築しようとする

--tree-min-percent 3 オプションは、「時間の 3% より多くを占めるものだけを表示してほしい」という意味です。これがないと、ツリーはしばしば非常にノイズが多くなり、malloc の内部のようなランダムなものが含まれます。--tree-max-depth も便利な場合があります。これは、出力する階層数を制限するだけです。

各行について、その関数全体での時間の割合（“total”）と、その関数だけに費やされ、その関数の何らかの callee には費やされていない時間の割合（self）を表示します。通常は “total” のほうが興味深い数値ですが、常にそうとは限りません。

相対的な割合

デフォルトでは、perf-focus におけるすべての割合は プログラム全体の実行 に対する相対値です。これは視点を保つのに役立ちます。多くの場合、ホットスポットを見つけるために掘り下げていくと、プログラム全体の実行という観点では、この「ホットスポット」は実際には重要ではないという事実を見失うことがあります。また、異なるクエリ間の割合を互いに簡単に比較できることも保証されます。

とはいえ、相対的な割合を取得すると便利な場合もあるため、perf focus は --relative オプションを提供しています。この場合、割合は、すべてのサンプルではなく、マッチしたサンプルだけについて表示されます。したがって、たとえば次のようにして、borrowck 自体に対する相対的な割合を取得できます。

$ perf focus '{do_mir_borrowck}' --tree-callees --relative --tree-max-depth 1 --tree-min-percent 5
Matcher    : {do_mir_borrowck}
Matches    : 577
Not Matches: 746
Percentage : 100%

Tree
| matched `{do_mir_borrowck}` (100% total, 0% self)
: | rustc_borrowck::nll::compute_regions (47% total, 0% self) [...]
: | rustc::mir::visit::Visitor::visit_mir (19% total, 15% self) [...]
: | <rustc_borrowck::MirBorrowckCtxt<'cx, 'tcx> as rustc_mir_dataflow::DataflowResultsConsumer<'cx, 'tcx>>::visit_statement_entry (13% total, 0% self) [...]
: | rustc_mir_dataflow::do_dataflow (8% total, 1% self) [...]

ここでは、compute_regions が “47% total” として現れていることが分かります。これは、do_mir_borrowck の 47% がその関数で費やされていることを意味します。以前は 20% でした。これは、do_mir_borrowck 自体が合計時間の 43% にすぎないためです（そして .47 * .43 = .20）。