El perfil de seguimiento en formato JSON puede ser muy útil para comprender rápidamente en qué invirtió tiempo Bazel durante la invocación.
De forma predeterminada, para todos los comandos y consultas similares a la compilación, Bazel escribe un perfil en la base de salida llamada command-$INOVCATION_ID.profile.gz, donde $INOVCATION_ID es el identificador de invocación del comando. Bazel también crea un symlink llamado command.profile.gz en la base de salida que apunta al perfil del comando más reciente. Puedes configurar si se escribe un perfil con la marca --generate_json_trace_profile y la ubicación en la que se escribe con la marca --profile. Las ubicaciones que terminan con .gz se comprimen con GZIP. De forma predeterminada, Bazel conserva los últimos 5 perfiles, que se pueden configurar con --profiles_to_retain, en la base de salida para el análisis posterior a la compilación. Si pasas de forma explícita una ruta de perfil con --profile, se inhabilita la recolección automática de elementos no utilizados.
Herramientas
Puedes cargar este perfil en chrome://tracing o analizarlo y posprocesarlo con otras herramientas.
chrome://tracing
Para visualizar el perfil, abre chrome://tracing en una pestaña del navegador Chrome, haz clic en "Load" y elige el archivo de perfil (que puede estar comprimido). Para obtener resultados más detallados, haz clic en los cuadros de la esquina inferior izquierda.
Perfil de ejemplo:
Figura 1: Perfil de ejemplo.
Puedes usar estos controles del teclado para navegar:
- Presiona
1para activar el modo de "selección". 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
2para activar el modo de desplazamiento. Luego, arrastra el mouse para mover la vista. También puedes usara/dpara moverte hacia la izquierda o la derecha. - Presiona
3para activar el modo de “zoom”. Luego, arrastra el mouse para acercar la imagen. También puedes usarw/spara acercar o alejar la imagen. - Presiona
4para activar el modo "cronómetro", en el que puedes medir la distancia entre dos eventos. - Presiona
?para obtener información sobre todos los controles.
bazel analyze-profile
El subcomando analyze-profile de Bazel consume un formato de perfil y muestra estadísticas acumulativas para diferentes tipos de tareas en 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 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
Bazel Invocation Analyzer
El analizador de invocación de Bazel de código abierto consume un formato de perfil y muestra sugerencias para 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 similar a sed para los datos JSON. A continuación, se muestra un ejemplo del uso de jq para extraer todas las duraciones del paso de creación del entorno 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 que se invocó 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 estaban en curso. Haz clic en él para ver el valor real. Debe aumentar hasta el valor de--jobsen las compilaciones limpias.CPU usage (Bazel): Para cada segundo de la compilación, muestra la cantidad de CPU que usó Bazel (un valor de 1 equivale a un núcleo ocupado al 100%).Critical Path: Muestra un bloque para cada acción en la ruta crítica.Main Thread: Es el subproceso principal de Bazel. Es útil para obtener una idea general de lo que hace Bazel, por ejemplo, "Launch Blaze", "evaluateTargetPatterns" y "runAnalysisPhase".Garbage Collector: Muestra las pausas de recolección de basura (GC) menores y mayores.
Problemas de rendimiento comunes
Cuando analices los perfiles de rendimiento, busca lo siguiente:
- La fase de análisis (
runAnalysisPhase) es más lenta de lo esperado, en especial en las compilaciones incrementales. Esto puede ser un signo de una implementación deficiente de la regla, por ejemplo, una que aplana los depsets. La carga de paquetes puede ser lenta debido a una cantidad excesiva de destinos, macros complejas o comodines recursivos. - Acciones lentas individuales, en especial las que se encuentran en la ruta crítica Es posible que se puedan 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 un valor inusualmente alto de no
PROCESS_TIME(comoREMOTE_SETUPoFETCH). - Cuellos de botella, es decir, una pequeña cantidad de subprocesos están ocupados mientras que todos los demás están inactivos o esperando el resultado (consulta los segundos 22 y 29 en la Figura 1). Para optimizar esto, es probable que debas modificar las implementaciones de reglas o Bazel para introducir más paralelismo. Esto también puede ocurrir cuando hay una cantidad inusual de GC.
Formato del 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) en los eventos de seguimiento se indican 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 están cerca unos de otros. Pasa --noslim_profile si deseas evitar la combinación de eventos.
Consulta también la especificación del formato de eventos de Chrome Trace.