JSON トレース プロファイルは、呼び出し中に Bazel がどの処理に時間を費やしたかをすばやく把握するのに非常に役立ちます。
デフォルトでは、ビルドに似たすべてのコマンドとクエリに対して、Bazel はこのようなプロファイルを command.profile.gz に書き込みます。プロファイルを書き込むかどうかは --generate_json_trace_profile フラグで、書き込む場所は --profile フラグで構成できます。.gz で終わるロケーションは GZIP で圧縮されます。フラグ --experimental_announce_profile_path を使用して、このファイルのパスをログに出力します。
ツール
このプロファイルを chrome://tracing に読み込むか、他のツールで分析してポストプロセスできます。
chrome://tracing
プロファイルを可視化するには、Chrome ブラウザのタブで chrome://tracing を開き、[読み込み] をクリックして、（圧縮されている可能性のある）プロファイル ファイルを選択します。より詳細な結果を確認するには、左下にあるボックスをクリックします。
プロファイルの例:
図 1. プロファイルの例。
次のキーボード コントロールを使用して移動できます。
1キーを押して「選択」モードにします。このモードでは、特定のボックスを選択してイベントの詳細を調べることができます（左下を参照）。複数のイベントを選択すると、概要と集計された統計情報が表示されます。2を押して「パン」モードにします。マウスをドラッグしてビューを移動します。a/dを使用して左右に移動することもできます。3キーを押すと「ズーム」モードになります。マウスをドラッグしてズームします。w/sを使用してズームイン/ズームアウトすることもできます。4を押すと「タイミング」モードになり、2 つのイベント間の距離を測定できます。- すべてのコントロールについて詳しくは、
?を押してください。
bazel analyze-profile
Bazel サブコマンド analyze-profile は、プロファイル形式を使用し、各ビルドフェーズで異なるタスクタイプの累積統計情報とクリティカル パスの分析結果を出力します。
たとえば、次のコマンドを使用します。
$ bazel build --profile=/tmp/profile.gz //path/to:target
...
$ bazel analyze-profile /tmp/profile.gz
次のような出力になります。
INFO: Profile created on Tue Jun 16 08:59:40 CEST 2020, build ID: 0589419c-738b-4676-a374-18f7bbc7ac23, output base: /home/johndoe/.cache/bazel/_bazel_johndoe/d8eb7a85967b22409442664d380222c0
=== PHASE SUMMARY INFORMATION ===
Total launch phase time 1.070 s 12.95%
Total init phase time 0.299 s 3.62%
Total loading phase time 0.878 s 10.64%
Total analysis phase time 1.319 s 15.98%
Total preparation phase time 0.047 s 0.57%
Total execution phase time 4.629 s 56.05%
Total finish phase time 0.014 s 0.18%
------------------------------------------------
Total run time 8.260 s 100.00%
Critical path (4.245 s):
Time Percentage Description
8.85 ms 0.21% _Ccompiler_Udeps for @local_config_cc// compiler_deps
3.839 s 90.44% action 'Compiling external/com_google_protobuf/src/google/protobuf/compiler/php/php_generator.cc [for host]'
270 ms 6.36% action 'Linking external/com_google_protobuf/protoc [for host]'
0.25 ms 0.01% runfiles for @com_google_protobuf// protoc
126 ms 2.97% action 'ProtoCompile external/com_google_protobuf/python/google/protobuf/compiler/plugin_pb2.py'
0.96 ms 0.02% runfiles for //tools/aquery_differ aquery_differ
Bazel 呼び出しアナライザ
オープンソースの Bazel 呼び出しアナライザは、プロファイル形式を使用し、ビルドのパフォーマンスを改善する方法に関する推奨事項を出力します。この分析は、CLI または https://analyzer.engflow.com で実行できます。
jq
jq は、JSON データの sed に似ています。jq を使用して、ローカル アクションの実行でサンドボックス作成ステップのすべての時間を抽出する例:
$ zcat $(../bazel-6.0.0rc1-linux-x86_64 info output_base)/command.profile.gz | jq '.traceEvents | .[] | select(.name == "sandbox.createFileSystem") | .dur'
6378
7247
11850
13756
6555
7445
8487
15520
[...]
プロフィール情報
プロファイルに複数の行が含まれています。通常、行の大部分は Bazel スレッドとそれに対応するイベントを表しますが、特別な行も含まれています。
含まれる特別な行は、プロファイルの作成時に呼び出された Bazel のバージョンに依存し、さまざまなフラグでカスタマイズできます。
図 1 は、Bazel v5.3.1 で作成されたプロファイルで、次の行が含まれています。
action count: 処理中の同時アクションの数を表示します。クリックすると、実際の値が表示されます。クリーンビルドでは、--jobsまでの値にする必要があります。CPU usage (Bazel): ビルドの 1 秒ごとに、Bazel が使用した CPU の量を表示します（値 1 は、1 つのコアが 100% ビジー状態になることを意味します）。Critical Path: クリティカル パス上のアクションごとに 1 つのブロックを表示します。Main Thread: Bazel のメインスレッド。「Launch Blaze」、「evaluateTargetPatterns」、「runAnalysisPhase」など、Bazel が行っている処理の概要を把握するのに役立ちます。Garbage Collector: マイナーとメジャーのガベージ コレクション（GC）の一時停止を表示します。
パフォーマンスに関する一般的な問題
パフォーマンス プロファイルを分析する際には、以下のことに注目します。
- 分析フェーズ（
runAnalysisPhase）が想定よりも遅い（特に増分ビルドの場合）。これは、depset をフラット化するなど、ルールの実装が適切でないことを示す可能性があります。ターゲット数が過剰、マクロが複雑、グロブが再帰的である場合、パッケージの読み込みが遅くなることがあります。 - 個々の遅いアクション（特にクリティカル パス上のもの）。大規模なアクションを複数の小さなアクションに分割したり、（推移的な）依存関係のセットを減らして高速化できる場合があります。また、
PROCESS_TIME以外の異常に高い値（REMOTE_SETUPやFETCHなど）がないか確認します。 - ボトルネック（少数のスレッド）は、ビジー状態で、他のすべてのスレッドがアイドル状態または結果を待機している状態です（図 1 の 22 秒と 29 秒前後を参照）。これを最適化するには、ルールの実装または Bazel 自体に変更を加えて、より多くの並列処理を導入する必要があります。これは、GC の量が異常に多い場合にも発生することがあります。
プロファイル ファイル形式
最上位のオブジェクトにはメタデータ（otherData）と実際のトレースデータ（traceEvents）が含まれます。メタデータには、呼び出し ID や Bazel 呼び出しの日付などの追加情報が含まれます。
例:
{
"otherData": {
"build_id": "101bff9a-7243-4c1a-8503-9dc6ae4c3b05",
"date": "Wed Oct 26 08:22:35 CEST 2022",
"profile_finish_ts": "1677666095162000",
"output_base": "/usr/local/google/_bazel_johndoe/573d4be77eaa72b91a3dfaa497bf8cd0"
},
"traceEvents": [
{"name":"thread_name","ph":"M","pid":1,"tid":0,"args":{"name":"Critical Path"}},
...
{"cat":"build phase marker","name":"Launch Blaze","ph":"X","ts":-1306000,"dur":1306000,"pid":1,"tid":21},
...
{"cat":"package creation","name":"foo","ph":"X","ts":2685358,"dur":784,"pid":1,"tid":246},
...
{"name":"thread_name","ph":"M","pid":1,"tid":11,"args":{"name":"Garbage Collector"}},
{"cat":"gc notification","name":"minor GC","ph":"X","ts":825986,"dur":11000,"pid":1,"tid":11},
...
{"cat":"action processing","name":"Compiling foo/bar.c","ph":"X","ts":54413389,"dur":357594,"pid":1,"args":{"mnemonic":"CppCompile"},"tid":341},
]
}
トレース イベントのタイムスタンプ（ts）と時間（dur）はマイクロ秒単位で指定されます。カテゴリ（cat）は、ProfilerTask の列挙値の 1 つです。イベントが非常に短く、互いに近接している場合、イベントが統合されることがあります。イベントの統合を防ぐには、--noslim_json_profile を渡します。
Chrome トレース イベント形式の仕様もご覧ください。