Perfil do Trace de JSON

Nightly · 8.4 · 8.3 · 8.2 · 8.1 · 8.0 · 7.6

O perfil de rastreamento JSON pode ser muito útil para entender rapidamente em que o Bazel gastou tempo durante a invocação.

Por padrão, para todos os comandos e consultas semelhantes a build, o Bazel grava um perfil na base de saída chamada command-$INVOCATION_ID.profile.gz, em que $INVOCATION_ID é o identificador de invocação do comando. O Bazel também cria um link simbólico chamado command.profile.gz na base de saída que aponta para o perfil do último comando. É possível configurar se um perfil é gravado com a flag --generate_json_trace_profile e o local em que ele é gravado com a flag --profile. Os locais que terminam com .gz são compactados com GZIP. O Bazel mantém os últimos cinco perfis, configuráveis por --profiles_to_retain, na base de saída por padrão para análise pós-build. Transmitir explicitamente um caminho de perfil com --profile desativa a coleta automática de lixo.

Ferramentas

Você pode carregar esse perfil no chrome://tracing ou analisar e pós-processar com outras ferramentas.

`chrome://tracing`

Para visualizar o perfil, abra chrome://tracing em uma guia do navegador Chrome, clique em "Carregar" e escolha o arquivo de perfil (que pode estar compactado). Para resultados mais detalhados, clique nas caixas no canto inferior esquerdo.

Exemplo de perfil:

Figura 1. Exemplo de perfil.

Use estes controles do teclado para navegar:

Pressione 1 para o modo "selecionar". Nesse modo, é possível selecionar caixas específicas para inspecionar os detalhes do evento (veja no canto inferior esquerdo). Selecione vários eventos para receber um resumo e estatísticas agregadas.
Pressione 2 para o modo "panorâmica". Em seguida, arraste o mouse para mover a visualização. Também é possível usar a/d para mover para a esquerda/direita.
Pressione 3 para o modo "zoom". Em seguida, arraste o mouse para aplicar o zoom. Também é possível usar w/s para aumentar/diminuir o zoom.
Pressione 4 para o modo "tempo", em que é possível medir a distância entre dois eventos.
Pressione ? para conhecer todos os controles.

Analisador de invocação do Bazel

O Bazel Invocation Analyzer (link em inglês) de código aberto consome um formato de perfil e imprime sugestões sobre como melhorar o desempenho do build. Essa análise pode ser feita usando a CLI ou em https://analyzer.engflow.com.

`jq`

jq é como sed para dados JSON. Um exemplo de uso de jq para extrair todas as durações da etapa de criação da sandbox na execução de ações locais:

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

Informações do perfil

O perfil contém várias linhas. Normalmente, a maior parte das linhas representa threads do Bazel e os eventos correspondentes, mas algumas linhas especiais também são incluídas.

As linhas especiais incluídas dependem da versão do Bazel invocada quando o perfil foi criado e podem ser personalizadas por diferentes flags.

A Figura 1 mostra um perfil criado com o Bazel v5.3.1 e inclui estas linhas:

action count: mostra quantas ações simultâneas estavam em andamento. Clique nele para ver o valor real. Deve chegar ao valor de --jobs em builds limpos.
CPU usage (Bazel): para cada segundo do build, mostra a quantidade de CPU usada pelo Bazel (um valor de 1 equivale a um núcleo 100% ocupado).
Critical Path: mostra um bloco para cada ação no caminho crítico.
Main Thread: a linha de execução principal do Bazel. Útil para ter uma visão geral do que o Bazel está fazendo, por exemplo, "Launch Blaze", "evaluateTargetPatterns" e "runAnalysisPhase".
Garbage Collector: mostra pausas de coleta de lixo (GC) secundárias e principais.

Problemas comuns de desempenho

Ao analisar perfis de desempenho, procure:

Fase de análise mais lenta do que o esperado (runAnalysisPhase), principalmente em builds incrementais. Isso pode ser um sinal de uma implementação ruim da regra, por exemplo, uma que achata depsets. O carregamento de pacotes pode ser lento devido a uma quantidade excessiva de destinos, macros complexas ou globs recursivos.
Ações lentas individuais, principalmente aquelas no caminho crítico. É possível dividir ações grandes em várias menores ou reduzir o conjunto de dependências (transitivas) para acelerar o processo. Verifique também se há um número alto e incomum de não PROCESS_TIME (como REMOTE_SETUP ou FETCH).
Gargalos, ou seja, um pequeno número de linhas de execução está ocupado enquanto todas as outras estão ociosas / aguardando o resultado (veja por volta de 22s e 29s na Figura 1). Para otimizar isso, provavelmente será necessário alterar as implementações de regras ou o próprio Bazel para introduzir mais paralelismo. Isso também pode acontecer quando há uma quantidade incomum de GC.

Formato do arquivo de perfil

O objeto de nível superior contém metadados (otherData) e os dados de rastreamento reais (traceEvents). Os metadados contêm informações extras, por exemplo, o ID de invocação e a data da invocação do Bazel.

Exemplo:

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

Os carimbos de data/hora (ts) e as durações (dur) nos eventos de rastreamento são fornecidos em microssegundos. A categoria (cat) é um dos valores de enumeração de ProfilerTask. Alguns eventos são mesclados se forem muito curtos e próximos uns dos outros. Transmita --noslim_profile se quiser evitar a mesclagem de eventos.

Consulte também a especificação do formato de evento de rastreamento do Chrome.

Perfil do Trace de JSON Mantenha tudo organizado com as coleções Salve e categorize o conteúdo com base nas suas preferências.