JSON 追蹤記錄設定檔

7.3 · 7.2 · 7.1 · 7.0 · 6.5

JSON 追蹤設定檔非常實用，可快速瞭解 Bazel 在叫用期間花費的時間。

根據預設，對於所有類似建構的指令和查詢，Bazel 會將這類設定檔寫入 command.profile.gz。您可以設定是否要使用 --generate_json_trace_profile 標記寫入設定檔，以及使用 --profile 標記寫入的位置。結尾為 .gz 的位置會使用 GZIP 壓縮。使用 --experimental_announce_profile_path 旗標，將此檔案的路徑列印到記錄中。

工具

您可以將這個設定檔載入 chrome://tracing，或使用其他工具分析及後處理。

`chrome://tracing`

如要將設定檔視覺化，請在 Chrome 瀏覽器分頁中開啟 chrome://tracing，按一下「Load」，然後選取 (可能已壓縮) 的設定檔。如要查看更詳細的結果，請按一下左下角的方塊。

設定檔範例：

圖 1. 範例設定檔。

您可以使用下列鍵盤控制項進行瀏覽：

按下 1 即可進入「選取」模式。在這個模式下，您可以勾選特定方塊來查看事件詳細資料 (請見左下角)。選取多個事件，即可取得摘要和匯總統計資料。
按下 2 可切換至「平移」模式。然後拖曳滑鼠來移動檢視畫面。您也可以使用 a/d 鍵向左/右移動。
按下 3 可切換至「縮放」模式。然後拖曳滑鼠來縮放。您也可以使用 w/s 放大/縮小畫面。
按下 4 可進入「計時」模式，用於測量兩個事件之間的距離。
按下 ? 即可瞭解所有控制項。

`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)：顯示建構的每一秒，其中顯示 Bazel 使用的 CPU 數量 (值為 1 表示一個核心等於 100% 忙碌中)。
Critical Path：針對重要路徑中的每個動作顯示一個區塊。
Main Thread：Bazel 的主執行緒。很適合用來概略瞭解 Bazel 的運作情形，例如「Launch Blaze」、「業務評估模式」和「runAnalysisPhase」。
Garbage Collector：顯示次要和主要垃圾收集 (GC) 暫停。

常見效能問題

分析效能設定檔時，請留意以下事項：

分析階段 (runAnalysisPhase) 的速度比預期慢，尤其是在增量建構作業中。這可能是實作規則不佳的徵兆，例如會將 depset 扁平化。目標過多、巨集複雜或迴圈 glob 會導致套件載入速度變慢。
個別緩慢的動作，尤其是在重要路徑上。您可以將大型動作拆分成多個較小的動作，或是減少 (傳遞) 依附元件組合，以便加快動作速度。另外，請檢查是否有異常高的非 PROCESS_TIME (例如 REMOTE_SETUP 或 FETCH)。
瓶頸，只有少量執行緒處於忙碌狀態，其他執行緒則都在閒置 / 等待結果 (請參閱圖 1 約 22 和 29 的說明)。如要最佳化這項作業，最有可能需改變規則實作項目或 Bazel 本身，以產生更多平行處理。當垃圾收集次數異常時，也可能會發生這種情況。

設定檔檔案格式

頂層物件包含中繼資料 (otherData) 和實際的追蹤資料 (traceEvents)。中繼資料包含額外資訊，例如 Bazel 叫用 ID 和叫用日期。

範例：

{
  "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_json_profile。

另請參閱 Chrome 追蹤事件格式規格。