JSON トレースプロファイル

Nightly · 8.4 · 8.3 · 8.2 · 8.1 · 8.0 · 7.6

JSON トレースプロファイルは、呼び出し中に Bazel が何に時間を費やしたかをすばやく把握するのに非常に役立ちます。

デフォルトでは、ビルドのようなコマンドとクエリの場合、Bazel は command-$INVOCATION_ID.profile.gz という名前の出力ベースにプロファイルを書き込みます。ここで、$INVOCATION_ID はコマンドの呼び出し識別子です。Bazel は、出力ベースに command.profile.gz というシンボリックリンクも作成します。これは、最新のコマンドのプロファイルを指します。--generate_json_trace_profile フラグでプロファイルが書き込まれるかどうか、--profile フラグで書き込み先を指定できます。.gz で終わるロケーションは GZIP で圧縮されます。Bazel は、ビルド後の分析用に、デフォルトで出力ベースに最後の 5 つのプロファイルを保持します。これは --profiles_to_retain で構成できます。--profile でプロファイルパスを明示的に渡すと、自動ガベージコレクションが無効になります。

ツール

このプロファイルを chrome://tracing に読み込むか、他のツールで分析して後処理できます。

`chrome://tracing`

プロファイルを可視化するには、Chrome ブラウザのタブで chrome://tracing を開き、[読み込み] をクリックして（圧縮されている可能性のある）プロファイルファイルを選択します。より詳細な結果を表示するには、左下のボックスをクリックします。

プロファイル例:

図 1. プロファイルの例。

これらのキーボード操作を使用して移動できます。

1 を押して「選択」モードにします。このモードでは、特定のボックスを選択してイベントの詳細を調べることができます（左下隅を参照）。複数のイベントを選択して、概要と集計された統計情報を取得します。
2 を押して「パン」モードにします。マウスをドラッグしてビューを移動します。a / d を使用して左右に移動することもできます。
3 を押して「ズーム」モードにします。マウスをドラッグしてズームします。w/s を使用して拡大/縮小することもできます。
4 を押して「タイミング」モードにすると、2 つのイベント間の距離を測定できます。
すべてのコントロールについて詳しくは、? を押してください。

Bazel 呼び出しアナライザ

オープンソースの 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 のメインスレッド。Bazel が何をしているのか（「Launch Blaze」、「evaluateTargetPatterns」、「runAnalysisPhase」など）を大まかに把握するのに役立ちます。
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 を渡します。

Chrome トレースイベント形式の仕様もご覧ください。

JSON トレース プロファイル コレクションでコンテンツを整理 必要に応じて、コンテンツの保存と分類を行います。

ツール

chrome://tracing