Hồ sơ theo dõi JSON

Báo cáo vấn đề Xem nguồn Nightly · 7.4 .

Hồ sơ theo dõi JSON có thể rất hữu ích trong việc nhanh chóng hiểu được Bazel đã dành thời gian để làm gì trong lệnh gọi.

Theo mặc định, đối với tất cả các lệnh và truy vấn giống như bản dựng, Bazel sẽ ghi hồ sơ như vậy vào command.profile.gz. Bạn có thể định cấu hình xem một hồ sơ có được ghi bằng cờ --generate_json_trace_profile hay không và vị trí hồ sơ được ghi bằng cờ --profile. Các vị trí kết thúc bằng .gz được nén bằng GZIP. Sử dụng cờ --experimental_announce_profile_path để in đường dẫn đến tệp này vào nhật ký.

Công cụ

Bạn có thể tải hồ sơ này vào chrome://tracing hoặc phân tích và xử lý hồ sơ bằng các công cụ khác.

chrome://tracing

Để trực quan hoá hồ sơ, hãy mở chrome://tracing trong thẻ trình duyệt Chrome, nhấp vào "Tải" rồi chọn tệp hồ sơ (có thể được nén). Để xem kết quả chi tiết hơn, hãy nhấp vào các hộp ở góc dưới bên trái.

Hồ sơ mẫu:

Hồ sơ mẫu

Hình 1. Hồ sơ mẫu.

Bạn có thể sử dụng các phím điều khiển sau để di chuyển:

  • Nhấn 1 để chuyển sang chế độ "chọn". Ở chế độ này, bạn có thể chọn các hộp cụ thể để kiểm tra thông tin chi tiết về sự kiện (xem góc dưới bên trái). Chọn nhiều sự kiện để xem thông tin tóm tắt và số liệu thống kê tổng hợp.
  • Nhấn 2 để chuyển sang chế độ "quét". Sau đó, kéo chuột để di chuyển khung hiển thị. Bạn cũng có thể dùng a/d để di chuyển sang trái/sang phải.
  • Nhấn 3 để chuyển sang chế độ "thu phóng". Sau đó, hãy kéo chuột để thu phóng. Bạn cũng có thể sử dụng w/s để phóng to/thu nhỏ.
  • Nhấn 4 để chuyển sang chế độ "timing" (đo thời gian), trong đó bạn có thể đo khoảng cách giữa hai sự kiện.
  • Nhấn ? để tìm hiểu về mọi chế độ điều khiển.

bazel analyze-profile

Lệnh con Bazel analyze-profile sử dụng định dạng hồ sơ và in số liệu thống kê tích luỹ cho các loại tác vụ khác nhau cho mỗi giai đoạn xây dựng và phân tích đường dẫn quan trọng.

Ví dụ: các lệnh

$ bazel build --profile=/tmp/profile.gz //path/to:target
...
$ bazel analyze-profile /tmp/profile.gz

có thể tạo ra kết quả ở dạng này:

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

Trình phân tích lệnh gọi Bazel

Trình phân tích lệnh gọi Bazel nguồn mở sử dụng định dạng hồ sơ và in các đề xuất về cách cải thiện hiệu suất của bản dựng. Bạn có thể thực hiện phân tích này bằng cách sử dụng CLI hoặc trên https://analyzer.engflow.com.

jq

jq giống như sed đối với dữ liệu JSON. Ví dụ về cách sử dụng jq để trích xuất tất cả thời lượng của bước tạo hộp cát trong quá trình thực thi hành động cục bộ:

$ 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
[...]

Thông tin hồ sơ

Hồ sơ chứa nhiều hàng. Thông thường, hàng loạt hàng đại diện cho các luồng Bazel và các sự kiện tương ứng, nhưng cũng có một số hàng đặc biệt.

Các hàng đặc biệt được đưa vào tuỳ thuộc vào phiên bản Bazel được gọi khi tạo hồ sơ và có thể được tuỳ chỉnh theo các cờ khác nhau.

Hình 1 cho thấy một cấu hình được tạo bằng Bazel v5.3.1 và bao gồm các hàng sau:

  • action count: Cho biết số lượng hành động đồng thời đang diễn ra. Hãy nhấp vào đó để xem giá trị thực tế. Phải tăng lên giá trị của --jobs trong các bản dựng sạch.
  • CPU usage (Bazel): Đối với mỗi giây của bản dựng, hiển thị lượng CPU mà Bazel đã sử dụng (giá trị 1 tương đương với một lõi đang bận 100%).
  • Critical Path: Hiển thị một khối cho mỗi hành động trên đường dẫn quan trọng.
  • Main Thread: Luồng chính của Bazel. Hữu ích để có được thông tin tổng quan về những gì Bazel đang làm, ví dụ: "Launch Blaze" (Khởi chạy Blaze), "evaluateTargetPatterns" (đánh giá TargetPatterns) và "runAnalysisPhase" (chạy AnalysisPhase).
  • Garbage Collector: Hiển thị các điểm tạm dừng thu gom rác (GC) nhỏ và lớn.

Các vấn đề thường gặp về hiệu suất

Khi phân tích hồ sơ hiệu suất, hãy tìm:

  • Giai đoạn phân tích chậm hơn dự kiến (runAnalysisPhase), đặc biệt là trên các bản dựng gia tăng. Đây có thể là dấu hiệu của việc triển khai quy tắc không hiệu quả, ví dụ: một quy tắc làm phẳng các nhóm phần phụ thuộc. Quá nhiều mục tiêu, macro phức tạp hoặc glob đệ quy có thể khiến quá trình tải gói bị chậm.
  • Từng hành động chậm, đặc biệt là những hành động trên lộ trình quan trọng. Bạn có thể chia các thao tác lớn thành nhiều thao tác nhỏ hơn hoặc giảm tập hợp các phần phụ thuộc (có tính chất bắc cầu) để tăng tốc độ của các thao tác đó. Ngoài ra, hãy kiểm tra xem có giá trị cao bất thường không phải PROCESS_TIME (chẳng hạn như REMOTE_SETUP hoặc FETCH) hay không.
  • Điểm tắc nghẽn, tức là một số ít luồng đang bận trong khi tất cả các luồng khác đang ở trạng thái rảnh / chờ kết quả (xem khoảng 22 giây và 29 giây trong Hình 1). Để tối ưu hoá quá trình này, rất có thể bạn sẽ phải chạm vào các hoạt động triển khai quy tắc hoặc chính Bazel để tăng cường tính song song. Điều này cũng có thể xảy ra khi có một lượng GC bất thường.

Định dạng tệp hồ sơ

Đối tượng cấp cao nhất chứa siêu dữ liệu (otherData) và dữ liệu theo dõi thực tế (traceEvents). Siêu dữ liệu chứa thêm thông tin, chẳng hạn như mã gọi và ngày gọi Bazel.

Ví dụ:

{
  "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},
 ]
}

Dấu thời gian (ts) và thời lượng (dur) trong các sự kiện theo dõi được cung cấp bằng micrô giây. Danh mục (cat) là một trong các giá trị enum của ProfilerTask. Xin lưu ý rằng một số sự kiện sẽ được hợp nhất với nhau nếu chúng rất ngắn và gần nhau; hãy truyền --noslim_json_profile nếu bạn muốn ngăn việc hợp nhất sự kiện.

Xem thêm Thông số kỹ thuật về định dạng sự kiện theo dõi của Chrome.