JSON トレースプロファイル

Nightly · 9.0 · 8.6 · 8.5 · 8.4 · 8.3 · 8.2 · 7.7

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

デフォルトでは、ビルドのようなコマンドとクエリの場合、Bazel は出力ベースにcommand-$INOVCATION_ID.profile.gzという名前のプロファイルを書き込みます。ここで、 $INOVCATION_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 を開き、 [Load] をクリックして、（圧縮されている可能性のある）プロファイルファイルを選択します。詳細な結果を表示するには、左下隅のボックスをクリックします。

プロファイルの例:

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

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

1 を押すと、[select] モードになります。このモードでは、特定のボックスを選択してイベントの詳細を確認できます（左下隅を参照）。複数のイベントを選択して、概要と集計統計を取得します。
2 を押すと、[pan] モードになります。マウスをドラッグしてビューを移動します。 `a` / `d` を使用して左右に移動することもできます。ad
3 を押すと、[zoom] モードになります。マウスをドラッグしてズームします。 `w`/`s` を使用して拡大/縮小することもできます。ws
4 を押すと、[timing] モードになります。このモードでは、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 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): ビルドの 1 秒ごとに、Bazel が使用した CPU の量が表示されます（値 1 は 1 コアが 100% ビジー状態であることを意味します）。
Critical Path: クリティカルパス上のアクションごとに 1 つのブロックが表示されます。
Main Thread: Bazel のメインスレッド。「Launch Blaze」、「evaluateTargetPatterns」、「runAnalysisPhase」など、Bazel が行っていることの概要を把握するのに役立ちます。
Garbage Collector: マイナーとメジャーのガベージコレクション（GC）の一時停止が表示されます。

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

パフォーマンスプロファイルを分析するときは、次の点に注意してください。

分析フェーズ（runAnalysisPhase）が予想よりも遅い。特にインクリメンタルビルドの場合。これは、depsets をフラット化するルール実装が不適切な兆候である可能性があります。パッケージの読み込みが遅くなる原因としては、ターゲットの数が多すぎる、マクロが複雑すぎる、再帰的な glob などが考えられます。
個々のアクションが遅い。特にクリティカルパス上のアクションの場合。大きなアクションを複数の小さなアクションに分割したり、（推移的な）依存関係のセットを減らしたりすることで、処理を高速化できる可能性があります。また、以外の値（REMOTE_SETUP や FETCH など）が異常に高くなっていないかどうかも確認してください。PROCESS_TIME
ボトルネック。つまり、他のすべてのスレッドがアイドル状態または結果を待機している間に、少数のスレッドがビジー状態になっている（図 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 Trace Event Format Specificationもご覧ください。

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

ツール

chrome://tracing

bazel analyze-profile