El perfil de seguimiento JSON puede ser muy útil para comprender rápidamente en qué tiempo Bazel pasó el tiempo durante la invocación.
De forma predeterminada, para todos los comandos similares a compilaciones y la consulta, Bazel escribe ese perfil en
command.profile.gz. Puedes configurar si un perfil se escribe con la marca --generate_json_trace_profile y la ubicación en la que se escribe con la marca --profile. Las ubicaciones que terminan en .gz se comprimen con GZIP. Usa la marca --experimental_announce_profile_path para imprimir la ruta de acceso de este archivo al registro.
Herramientas
Puedes cargar este perfil en chrome://tracing o analizarlo y procesarlo con otras herramientas.
chrome://tracing
Para visualizar el perfil, abre chrome://tracing en una pestaña del navegador Chrome, haz clic en "Cargar" y selecciona el archivo de perfil (que puede estar comprimido). Para obtener resultados más detallados, haz clic en las casillas de la esquina inferior izquierda.
Perfil de ejemplo:
Figura 1: Perfil de ejemplo.
Puedes usar estos controles de teclado para navegar:
- Presiona
1para seleccionar el modo. En este modo, puedes seleccionar determinadas casillas para inspeccionar los detalles del evento (consulta la esquina inferior izquierda). Seleccione varios eventos para obtener un resumen y estadísticas agregadas. - Presiona
2para el modo de desplazamiento lateral. Luego, arrastra el mouse para mover la vista. También puedes usaraodpara moverte a la izquierda o a la derecha. - Presiona
3para acceder al modo de "zoom". Luego, arrastra el mouse para hacer zoom. También puedes usarwospara acercar o alejar la imagen. - Presiona
4para el modo "sincronización", en el que puedes medir la distancia entre dos eventos. - Presiona
?para ver todos los controles.
bazel analyze-profile
El subcomando analyze-profile de Bazel consume un formato de perfil y, luego, imprime estadísticas acumulativas para diferentes tipos de tareas de cada fase de compilación y un análisis de la ruta de acceso crítica.
Por ejemplo, los comandos
$ bazel build --profile=/tmp/profile.gz //path/to:target
...
$ bazel analyze-profile /tmp/profile.gz
puede producir un resultado con este 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 Analizador de invocaciones de Bazel de código abierto consume un formato de perfil y, luego, imprime sugerencias para mejorar el rendimiento de la compilación. Este análisis se puede realizar a través de su CLI o en https://analyzer.engflow.com.
jq
jq es como sed para datos JSON. Un ejemplo de uso de jq para extraer todas las 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ía de las filas representan subprocesos de Bazel 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 creó el perfil y se pueden personalizar con diferentes marcas.
En la Figura 1, se muestra un perfil creado con Bazel v5.3.1 que incluye las siguientes filas:
action count: Muestra cuántas acciones simultáneas estuvieron en tránsito. Haz clic en él para ver el valor real. Debe subir al valor de--jobsen compilaciones limpias.CPU usage (Bazel): por cada segundo de la compilación, se muestra la cantidad de CPU que usó Bazel (un valor de 1 equivale a un núcleo que está 100% ocupado).Critical Path: Muestra un bloque por cada acción en la ruta crítica.Main Thread: La conversación principal de Bazel. Es útil para obtener una visión general de lo que hace Bazel, por ejemplo, "Iniciar Blaze", "evaluateTargetPatterns" y "runAnalysisPhase".Garbage Collector: Muestra pausas importantes y menores en la recolección de elementos no utilizados (GC).
Problemas comunes de rendimiento
Cuando analices los perfiles de rendimiento, busca lo siguiente:
- Fase de análisis más lenta que la esperada (
runAnalysisPhase), especialmente en compilaciones incrementales. Esto puede ser un indicador de una implementación de reglas deficiente, por ejemplo, que aplana los repositorios. La carga de paquetes puede ser lenta por una cantidad excesiva de objetivos, macros complejas o globs recursivos. - Acciones lentas individuales, especialmente aquellas en la ruta crítica. Es posible dividir
las acciones grandes en varias acciones más pequeñas o reducir el
conjunto de dependencias (transitivas) para acelerarlas. También verifica si hay una alta inusual que no sea
PROCESS_TIME(comoREMOTE_SETUPoFETCH). - Cuellos de botella, es decir, una pequeña cantidad de subprocesos, cuando todos los demás están inactivos o esperando el resultado (consulta alrededor de 22 y 29 s en la Figura 1) Es probable que, al optimizar esto, sea necesario tocar las implementaciones de reglas o Bazel para ingresar 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, como 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) en los eventos de seguimiento se proporcionan en microsegundos. La categoría (cat) es uno de los valores de enumeración de ProfilerTask.
Ten en cuenta que algunos eventos se combinan si son muy cortos y cercanos entre sí. Pasa --noslim_json_profile si deseas evitar la combinación de eventos.
Consulta también la Especificación de formato de eventos de Chrome Trace.