โปรไฟล์การติดตาม JSON

โปรไฟล์การติดตาม JSON มีประโยชน์อย่างยิ่งในการทำความเข้าใจสิ่งที่ Bazel ใช้เวลาไปกับการดำเนินการเรียกใช้

โดยค่าเริ่มต้น สำหรับคำสั่งและคำค้นหาที่คล้ายกับการสร้างทั้งหมด Bazel จะเขียนโปรไฟล์ดังกล่าวลงใน command.profile.gz คุณสามารถกำหนดค่าได้ว่าจะให้เขียนโปรไฟล์ด้วย Flag --generate_json_trace_profile หรือไม่ และตำแหน่งที่จะเขียนด้วย Flag --profile ระบบจะบีบอัดสถานที่ที่ลงท้ายด้วย .gz ด้วย GZIP ใช้ Flag --experimental_announce_profile_path เพื่อพิมพ์เส้นทางไปยังไฟล์นี้ลงในบันทึก

เครื่องมือ

คุณสามารถโหลดโปรไฟล์นี้ลงใน chrome://tracing หรือวิเคราะห์และประมวลผลหลังด้วยเครื่องมืออื่นๆ

chrome://tracing

หากต้องการดูโปรไฟล์เป็นภาพ ให้เปิด chrome://tracing ในแท็บเบราว์เซอร์ Chrome แล้วคลิก "โหลด" แล้วเลือกไฟล์โปรไฟล์ (อาจมีการบีบอัด) หากต้องการดูผลลัพธ์ที่ละเอียดยิ่งขึ้น ให้คลิกช่องที่มุมล่างซ้าย

ตัวอย่างโปรไฟล์

รูปที่ 1 ตัวอย่างโปรไฟล์

คุณใช้การควบคุมด้วยแป้นพิมพ์ต่อไปนี้เพื่อไปยังส่วนต่างๆ ได้

• กด 1 สำหรับโหมด "เลือก" ในโหมดนี้ คุณสามารถเลือกช่องทำเครื่องหมายเพื่อตรวจสอบรายละเอียดกิจกรรมได้ (ดูมุมซ้ายล่าง) เลือกหลายกิจกรรมเพื่อดูข้อมูลสรุปและสถิติแบบรวม
• กด 2 สำหรับโหมด "เลื่อน" จากนั้นลากเมาส์เพื่อย้ายมุมมอง หรือจะใช้ a/d เพื่อเลื่อนไปทางซ้าย/ขวาก็ได้
• กด 3 สำหรับโหมด "ซูม" จากนั้นลากเมาส์เพื่อซูม คุณยังใช้ w/s เพื่อซูมเข้า/ออกได้ด้วย
• กด 4 เพื่อดูโหมด "ระยะเวลา" ซึ่งคุณจะวัดระยะทางระหว่าง 2 เหตุการณ์ได้
• กด ? เพื่อดูข้อมูลเกี่ยวกับการควบคุมทั้งหมด

bazel analyze-profile

คำสั่งย่อย analyze-profile ของ Bazel ใช้รูปแบบโปรไฟล์และพิมพ์สถิติสะสมสำหรับงานประเภทต่างๆ ในแต่ละระยะการสร้าง รวมถึงการวิเคราะห์เส้นทางที่สำคัญ

เช่น คำสั่ง

$ 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 เปรียบเสมือน sed สำหรับข้อมูล JSON ตัวอย่างการใช้ 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 ที่เรียกใช้เมื่อสร้างโปรไฟล์ และอาจปรับแต่งด้วย Flag ต่างๆ

รูปที่ 1 แสดงโปรไฟล์ที่สร้างด้วย Bazel v5.3.1 และมีแถวต่อไปนี้

• action count: แสดงจำนวนการกระทำที่เกิดขึ้นพร้อมกันในระหว่างแสดงโฆษณา คลิกเพื่อดูค่าจริง ควรเพิ่มขึ้นเป็นค่าของ --jobs ในบิลด์ที่สะอาด
• CPU usage (Bazel): ในแต่ละวินาทีของบิลด์ จะแสดงจำนวน CPU ที่ Bazel ใช้ (ค่า 1 เท่ากับ 1 แกนที่ไม่ว่าง 100%)
• Critical Path: แสดงบล็อก 1 บล็อกสําหรับการดําเนินการแต่ละรายการในเส้นทางสําคัญ
• Main Thread: ด้ายหลักของ Bazel มีประโยชน์ในการดูภาพรวมเกี่ยวกับสิ่งที่ Bazel กำลังทำ เช่น "Launch Blaze", "evaluateTargetPatterns" และ "runAnalysisPhase"
• Garbage Collector: แสดงการหยุดชั่วคราวของการเก็บขยะ (GC) เล็กน้อยและที่สำคัญ

ปัญหาด้านประสิทธิภาพที่พบบ่อย

เมื่อวิเคราะห์โปรไฟล์ประสิทธิภาพ ให้มองหาสิ่งต่อไปนี้

• ช้ากว่าช่วงการวิเคราะห์ที่คาดไว้ (runAnalysisPhase) โดยเฉพาะในบิลด์ที่เพิ่มขึ้น ซึ่งอาจเป็นสัญญาณของการใช้กฎที่ไม่มีประสิทธิภาพ เช่น กฎที่แยกการตั้งค่าเป็นเดี่ยว การโหลดแพ็กเกจอาจช้าเนื่องจากมีเป้าหมายมากเกินไป มาโครที่ซับซ้อน หรือนิพจน์ทั่วไปแบบซ้ำซ้อน
• การดำเนินการแต่ละรายการที่ช้า โดยเฉพาะการดำเนินการในเส้นทางที่สำคัญ อาจเป็นไปได้ที่จะแบ่งการดำเนินการขนาดใหญ่ออกเป็นการดำเนินการขนาดเล็กหลายรายการ หรือลดชุดทรัพยากร Dependency (แบบสโลป) เพื่อเร่งการทำงานให้เร็วขึ้น นอกจากนี้ ให้ตรวจสอบจำนวนที่ไม่ใช่ PROCESS_TIME สูงผิดปกติ (เช่น REMOTE_SETUP หรือ FETCH)
• จุดคอขวดซึ่งเป็นชุดข้อความจำนวนเล็กน้อยที่ไม่ว่างในขณะที่ชุดข้อความอื่นๆ ทั้งหมด ไม่มีการใช้งาน / กำลังรอผลลัพธ์ (ดูประมาณ 22 และ 29 ในรูปที่ 1) การเพิ่มประสิทธิภาพนี้อาจต้องเกี่ยวข้องกับการใช้งานกฎหรือ Bazel เองเพื่อเพิ่มการทำงานแบบขนาน กรณีนี้อาจเกิดขึ้นได้เช่นกัน เมื่อมีปริมาณ GC มากผิดปกติ

รูปแบบไฟล์โปรไฟล์

ออบเจ็กต์ระดับบนสุดมีข้อมูลเมตา (otherData) และข้อมูลการติดตามจริง (traceEvents) ข้อมูลเมตามีข้อมูลเพิ่มเติม เช่น รหัสการเรียกใช้และวันที่เรียกใช้ 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) คือค่า enum ค่าหนึ่งของ ProfilerTask โปรดทราบว่าระบบจะผสานเหตุการณ์บางรายการเข้าด้วยกันหากเหตุการณ์เหล่านั้นสั้นมากและอยู่ใกล้กัน ให้ส่ง --noslim_json_profile หากต้องการป้องกันการผสานเหตุการณ์

โปรดดูหัวข้อข้อกําหนดเฉพาะรูปแบบเหตุการณ์การติดตามของ Chrome ด้วย