JSON トレース プロファイルは、呼び出し中に Bazel が時間を費やした内容をすばやく把握するのに非常に役立ちます。
デフォルトでは、ビルドのようなコマンドとクエリの場合、Bazel はプロファイルを
という名前の出力ベースに書き込みます。ここで
$INVOCATION_ID はコマンドの呼び出し ID です。command-$INVOCATION_ID.profile.gzBazel は、出力ベースに command.profile.gz という名前のシンボリック リンクも作成します。これは、最新のコマンドのプロファイルを指します。プロファイルが書き込まれるかどうかは
--generate_json_trace_profile
フラグで構成できます。書き込み先の場所は
--profileフラグで構成できます。.gz で終わるロケーションは GZIP で圧縮されます。Bazel は、ビルド後の分析のために、デフォルトで出力ベースに最新の 5 つのプロファイルを保持します。この数は
--profiles_to_retain,
で構成できます。--profile でプロファイル パスを明示的に渡すと、自動ガベージ コレクションが無効になります。
ツール
このプロファイルを chrome://tracing に読み込んだり、他のツールで分析して後処理したりできます。
chrome://tracing
プロファイルを可視化するには、Chrome ブラウザのタブで chrome://tracing を開き、[Load] をクリックして、（圧縮されている可能性のある）プロファイル ファイルを選択します。詳細な結果を表示するには、左下隅のボックスをクリックします。
プロファイルの例:
図 1.プロファイルの例。
次のキーボード操作を使用して移動できます。
1を押すと、[select] モードになります。このモードでは、特定のボックスを選択してイベントの詳細を確認できます（左下隅を参照）。 複数のイベントを選択して、概要と集計統計を取得します。2を押すと、[pan] モードになります。マウスをドラッグしてビューを移動します。 `a` / `d` を使用して左右に移動することもできます。ad3を押すと、[zoom] モードになります。マウスをドラッグしてズームします。 `w`/`s` を使用して拡大/縮小することもできます。ws4を押すと、2 つのイベント間の距離を測定できる [timing] モードになります。?を押すと、すべての操作を確認できます。
Bazel Invocation Analyzer
オープンソースの Bazel Invocation Analyzer は、プロファイル形式を使用し、 ビルドのパフォーマンスを改善する方法に関する提案を出力します。この分析は、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): ビルドの各秒について、Bazel が使用した CPU の量が表示されます（値 1 は 1 コアが 100% ビジー状態であることを示します）。Critical Path: クリティカル パス上のアクションごとに 1 つのブロックが表示されます。Main Thread: Bazel のメインスレッド。「Launch Blaze」、「evaluateTargetPatterns」、「runAnalysisPhase」など、Bazel が行っている処理の概要を把握するのに役立ちます。Garbage Collector: マイナーとメジャーのガベージ コレクション（GC）の一時停止が表示されます。
一般的なパフォーマンスの問題
パフォーマンス プロファイルを分析する際は、次の点に注目してください。
- 分析フェーズ（
runAnalysisPhase）が予想よりも遅い。特に増分ビルドの場合。これは、depsets をフラット化するような、ルールの実装が不適切な兆候である可能性があります。パッケージの読み込みが、ターゲットの数が多すぎる、複雑なマクロ、再帰的な glob によって遅くなることがあります。 - 個々のアクションが遅い。特にクリティカル パス上のアクション。大きなアクションを複数の小さなアクションに分割したり、（推移的な）依存関係のセットを減らして高速化したりできる場合があります。
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 の列挙値のいずれかです。
イベントが非常に短く、互いに近い場合は、イベントがマージされることがあります。イベントのマージを防ぐ場合は、
--noslim_profile
を渡します。