JSON トレース プロファイル

問題を報告する ソースを表示 ナイトリー 8.1 · 8.0 · 7.5 · 7.4 · 7.3 · 7.2

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

デフォルトでは、ビルドに似たすべてのコマンドとクエリに対して、Bazel は command-$INVOCATION_ID.profile.gz という名前の出力ベースにプロファイルを書き込みます。ここで、$INVOCATION_ID はコマンドの呼び出し 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 呼び出しアナライザは、プロファイル形式を使用し、ビルドのパフォーマンスを改善する方法に関する推奨事項を出力します。この分析は、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)とメジャー GC の停止を表示します。

一般的なパフォーマンスの問題

パフォーマンス プロファイルを分析する際には、以下のことに注目します。

  • 分析フェーズ(runAnalysisPhase)が想定よりも遅い(特に増分ビルドの場合)。これは、depset をフラット化するなど、ルールの実装が適切でないことを示す可能性があります。ターゲット数が過剰、マクロが複雑、グロブが再帰的である場合、パッケージの読み込みが遅くなることがあります。
  • 個々の遅いアクション(特にクリティカル パス上のもの)。大規模なアクションを複数の小さなアクションに分割したり、(推移的)依存関係のセットを減らしたりすることで、速度を上げることができます。また、PROCESS_TIME 以外の異常に高い値(REMOTE_SETUPFETCH など)がないかどうかも確認します。
  • ボトルネック。少数のスレッドがビジー状態になり、他のすべてのスレッドがアイドル状態または結果を待機している状態(図 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_profile を渡します。

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