Perfil de registro de JSON

Informar un problema Ver fuente Por la noche · 7.2 · 7.1 · 7.0 · 6.5 · 6.4

El perfil de seguimiento JSON puede ser muy útil para comprender rápidamente cuánto gastó Bazel tiempo durante la invocación.

De forma predeterminada, para todos los comandos similares a la compilación y las consultas, Bazel escribe ese perfil en command.profile.gz Puedes configurar si un perfil se escribe con el --generate_json_trace_profile marca y la ubicación en la que se escribe con el --profile. Las ubicaciones que terminan en .gz son las siguientes: comprimido con GZIP. Cómo usar la bandera --experimental_announce_profile_path para imprimir la ruta de acceso a este archivo en el registro.

Herramientas

Puedes cargar este perfil en chrome://tracing o analizar y procesarlos posteriormente con otras herramientas.

`chrome://tracing`

Para visualizar el perfil, abre chrome://tracing en una pestaña del navegador Chrome. haz clic en "Cargar". y elige el archivo de perfil (potencialmente comprimido). Para ver más los resultados detallados, haz clic en las casillas de la esquina inferior izquierda.

Perfil de ejemplo:

Figura 1: Perfil de ejemplo.

Puedes usar estos controles del teclado para navegar:

Presiona 1 para seleccionar . En este modo, puedes seleccionar casillas específicas para inspeccionar los detalles del evento (consulta la esquina inferior izquierda). Selecciona varios eventos para obtener un resumen y estadísticas agregadas.
Presiona 2 para "desplazar" . Luego, arrastra el mouse para mover la vista. Tú también puedes usar a/d para moverte hacia la izquierda o la derecha.
Presiona 3 para “acercar” . Luego, arrastra el mouse para hacer zoom. Puedes también utiliza w/s para acercar y alejar.
Presiona 4 para "temporizar" en el que puedes medir la distancia entre dos eventos.
Presiona ? para conocer todos los controles.

`bazel analyze-profile`

El subcomando analyze-profile de Bazel consume un formato de perfil e imprime estadísticas acumulativas para diferentes tipos de tareas para cada fase de compilación y un análisis de la ruta crítica.

Por ejemplo, los comandos

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

puede generar un resultado con el siguiente formato:

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

Analizador de invocación de Bazel

El modelo de código abierto Analizador de invocación de Bazel consume un formato de perfil e imprime sugerencias sobre cómo mejorar el rendimiento de la compilación. Este análisis se puede realizar con su CLI o en https://analyzer.engflow.com.

`jq`

jq es como sed para los datos JSON. Un ejemplo de uso de jq para extraer todo Duraciones del paso de creación de la zona de pruebas en la ejecución de la acción local:

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

Información del perfil

El perfil contiene varias filas. Por lo general, la mayor parte de las filas representan a Bazel subprocesos y sus eventos correspondientes, pero también se incluyen algunas filas especiales.

Las filas especiales incluidas dependen de la versión de Bazel invocada cuando se se creó y puede personalizarse con diferentes marcas.

En la Figura 1, se muestra un perfil creado con Bazel v5.3.1 e incluye estas filas:

action count: Muestra cuántas acciones simultáneas estaban en tránsito. Haz clic en para ver el valor real. Debería subir al valor de --jobs en limpio compilaciones.
CPU usage (Bazel): Por cada segundo de la compilación, muestra la cantidad de CPU que usó Bazel (un valor de 1 equivale a que un núcleo está 100% ocupado).
Critical Path: Muestra un bloque por cada acción en la ruta crítica.
Main Thread: Subproceso principal de Bazel. Es útil para obtener un panorama general de lo que hace Bazel, por ejemplo, “Launch Blaze”, “evaluateTargetPatterns”, y “runAnalysisphase”.
Garbage Collector: Muestra la recolección de elementos no utilizados (GC) secundaria y principal. se hace una pausa.

Problemas comunes de rendimiento

Cuando analices los perfiles de rendimiento, ten en cuenta lo siguiente:

Fase de análisis más lenta de lo esperado (runAnalysisPhase), especialmente en compilaciones incrementales. Esto puede ser una señal de una mala implementación de reglas, en uno que aplana los dependencias. La carga de paquetes puede ser lenta debido a un una cantidad excesiva de objetivos, macros complejas o globs recursivos.
Acciones individuales lentas, especialmente aquellas en la ruta crítica. Podría ser dividir acciones grandes en varias más pequeñas o reducir el de dependencias (transitivas) para acelerarlas. También comprueba si hay una puntuación alta que no sea PROCESS_TIME (como REMOTE_SETUP o FETCH).
Cuellos de botella, es decir, un pequeño número de hilos están ocupados, mientras que los demás están inactividad o espera del resultado (consulta los valores aproximados de 22 s y 29 s en la Figura 1). Lo más probable es que para optimizar esto requiera tocar las implementaciones de reglas o Bazel para introducir más paralelismo. Esto también puede ocurrir cuando hay una cantidad inusual de GC.

Formato de archivo de perfil

El objeto de nivel superior contiene metadatos (otherData) y los datos de seguimiento reales (traceEvents). Los metadatos contienen información adicional, por ejemplo, el ID de invocación y la fecha de la invocación de Bazel.

Ejemplo:

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

Las marcas de tiempo (ts) y las duraciones (dur) de los eventos de seguimiento se presentan en microsegundos. La categoría (cat) es uno de los valores de enumeración de ProfilerTask. Ten en cuenta que algunos eventos se fusionan si son muy cortos y están entre sí; pase --noslim_json_profile para que no se combinen los eventos.

Consulta también la Especificación de formato de eventos de registro de Chrome.