Perfil de registro de JSON

El perfil de seguimiento de 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-$INVOCATION_ID.profile.gz, en la que $INVOCATION_ID es el identificador de invocación del comando. Bazel también crea un vínculo simbólico 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 --generate_json_trace_profile marca, y la ubicación en la que se escribe con la --profile marca. Las ubicaciones que terminan con .gz se comprimen con GZIP. Bazel conserva los últimos 5 perfiles, que se pueden configurar con --profiles_to_retain, en la base de salida de forma predeterminada para el análisis posterior a la compilación. Si pasas explícitamente 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 procesarlo 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 (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 1 para el modo "seleccionar". En este modo, puedes seleccionar cuadros específicos 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 el modo "paneo". Luego, arrastra el mouse para mover la vista. También puedes usar a/d para moverte hacia la izquierda o la derecha.
• Presiona 3 para el modo "zoom". Luego, arrastra el mouse para hacer zoom. También puedes usar w/s para acercar o alejar la imagen.
• Presiona 4 para el modo "tiempo", en el que puedes medir la distancia entre dos eventos.
• Presiona ? para obtener información sobre todos los controles.

Bazel Invocation Analyzer

El Bazel Invocation Analyzer 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 como sed para datos JSON. El siguiente es un ejemplo de uso de jq para extraer todas las duraciones del paso de creación de sandbox en la ejecución de acciones locales:

$ 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 los 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 y se incluyen estas filas:

• action count: Muestra cuántas acciones simultáneas estaban en curso. Haz clic en él para ver el valor real. Debe subir al valor de --jobs en 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 que un núcleo esté 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 imagen de alto nivel de lo que hace Bazel, por ejemplo, "Launch Blaze", "evaluateTargetPatterns" y "runAnalysisPhase".
• Garbage Collector: Muestra pausas menores y mayores de recolección de elementos no utilizados (GC).

Problemas de rendimiento comunes

Cuando analices los perfiles de rendimiento, busca lo siguiente:

• Fase de análisis más lenta de lo esperado (runAnalysisPhase), en especial en compilaciones incrementales. Esto puede ser un signo de una implementación de reglas deficiente, por ejemplo, una que aplana los conjuntos de dependencias. La carga de paquetes puede ser lenta debido a una cantidad excesiva de objetivos, macros complejas o comodines recursivos.
• Acciones individuales lentas, en especial las que están 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 un valor no PROCESS_TIME inusualmente alto (como REMOTE_SETUP o FETCH).
• Cuellos de botella, es decir, una pequeña cantidad de subprocesos está ocupada mientras que todos los demás están inactivos o esperando el resultado (consulta alrededor de 22 s y 29 s en la Figura 1). Para optimizar esto, es probable que debas 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) en los eventos de seguimiento se indican en microsegundos. La categoría (cat) es uno de los valores de enum de ProfilerTask. Ten en cuenta que algunos eventos se combinan si son muy cortos y están cerca uno del otro. Pasa --noslim_profile si deseas evitar la combinación de eventos.

Consulta también la especificación del formato de eventos de seguimiento de Chrome.