JSON 트레이스 프로필

문제 신고하기 소스 보기

JSON 트레이스 프로필은 호출 중에 Bazel이 시간을 소비한 부분을 빠르게 파악하는 데 매우 유용할 수 있습니다.

기본적으로 모든 빌드와 유사한 명령어와 쿼리에 대해 Bazel은 이러한 프로필을 command.profile.gz에 씁니다. --generate_json_trace_profile 플래그로 프로필을 작성할지 여부를 구성하고 --profile 플래그를 사용하여 프로필을 쓸 위치를 구성할 수 있습니다. .gz로 끝나는 위치는 GZIP으로 압축됩니다. --experimental_announce_profile_path 플래그를 사용하여 이 파일의 경로를 로그에 출력합니다.

도구

이 프로필을 chrome://tracing에 로드하거나 다른 도구로 분석 및 후처리할 수 있습니다.

chrome://tracing

프로필을 시각화하려면 Chrome 브라우저 탭에서 chrome://tracing를 열고 '로드'를 클릭한 후 (압축되었을 가능성이 있는) 프로필 파일을 선택합니다. 더 자세한 결과를 보려면 왼쪽 하단의 상자를 클릭하세요.

예시 프로필:

프로필 예

그림 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): 빌드의 1초마다 Bazel에서 사용한 CPU 양을 표시합니다 (값 1은 100% 사용 중인 코어 1개와 같음).
  • Critical Path: 주요 경로의 각 작업에 하나의 블록을 표시합니다.
  • Main Thread: Bazel의 기본 스레드 Bazel이 수행하는 작업을 대략적으로 파악하는 데 유용합니다(예: 'Launch Blaze', 'evaluateTargetPatterns', 'runAnalysisPhase').
  • Garbage Collector: 소규모 및 주요 가비지 컬렉션 (GC) 일시중지를 표시합니다.

일반적인 성능 문제

실적 프로필을 분석할 때 다음을 확인하세요.

  • 특히 증분 빌드에서 예상보다 분석 단계 (runAnalysisPhase)가 느립니다. 이는 예를 들어 depset을 평면화하는 규칙 구현과 같이 잘못 구현되었다는 신호일 수 있습니다. 대상, 복잡한 매크로 또는 재귀 glob의 양이 많으면 패키지 로드가 느려질 수 있습니다.
  • 개별 느린 작업(특히 중요한 경로에 있는 작업) 큰 작업을 여러 개의 작은 작업으로 분할하거나 (전이) 종속 항목 집합을 줄여 작업 속도를 높일 수 있습니다. 또한 PROCESS_TIME이 아닌 값이 비정상적으로 높은지 확인합니다 (예: REMOTE_SETUP 또는 FETCH).
  • 소수의 스레드인 병목 현상은 다른 모든 스레드가 유휴 상태이거나 결과를 기다리는 동안 사용 중입니다 (그림 1의 약 22초 및 29초 참고). 이를 최적화하려면 더 많은 동시 로드를 가져오기 위해 규칙 구현이나 Bazel 자체를 수정해야 할 가능성이 높습니다. 이 문제는 GC 양이 비정상적일 때도 발생할 수 있습니다.

프로필 파일 형식

최상위 객체에는 메타데이터 (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_profile를 전달합니다.

Chrome 트레이스 이벤트 형식 사양도 참고하세요.