O perfil de rastreamento JSON pode ser muito útil para entender rapidamente em que o Bazel passou tempo durante a invocação.
Por padrão, para todos os comandos semelhantes a build e consulta, o Bazel grava esse perfil em command.profile.gz. É possível configurar se um perfil é gravado com a sinalização
--generate_json_trace_profile
e o local em que é gravado com a sinalização
--profile. Os locais que terminam com .gz são
compactados com GZIP. Use a sinalização
--experimental_announce_profile_path
para imprimir o caminho para esse arquivo no registro.
Ferramentas
É possível carregar esse perfil em chrome://tracing ou analisá-lo e
pós-processá-lo 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 (possivelmente compactado). Para ver resultados mais detalhados, clique nas caixas no canto inferior esquerdo.
Exemplo de perfil:
Figura 1. Perfil de exemplo.
Use estes controles de teclado para navegar:
- Pressione
1para selecionar o modo. Nesse modo, é possível selecionar caixas específicas para inspecionar os detalhes do evento (veja o canto esquerdo de baixo). Selecione vários eventos para ver um resumo e as estatísticas agregadas. - Pressione
2para o modo "mover". Em seguida, arraste o mouse para mover a visualização. Também é possível usara/dpara mover para a esquerda/direita. - Pressione
3para o modo "zoom". Em seguida, arraste o mouse para aplicar zoom. Também é possível usarw/spara aumentar/diminuir o zoom. - Pressione
4para o modo "Velocidade", em que você pode medir a distância entre dois eventos. - Pressione
?para saber mais sobre todos os controles.
bazel analyze-profile
O subcomando analyze-profile do Bazel consome um formato de perfil e imprime estatísticas cumulativas para diferentes tipos de tarefas para cada fase de compilação e uma análise do caminho crítico.
Por exemplo, os comandos
$ bazel build --profile=/tmp/profile.gz //path/to:target
...
$ bazel analyze-profile /tmp/profile.gz
pode gerar saída deste 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
Analisador de invocação do Bazel
O Bazel Invocation Analyzer de código aberto consome um formato de perfil e imprime sugestões sobre como melhorar o desempenho do build. É possível realizar essa análise 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 do sandbox na execução da ação 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
[...]
Informações do perfil
O perfil contém várias linhas. Normalmente, a maior parte das linhas representa as linhas de execução do Bazel e os eventos correspondentes, mas algumas linhas especiais também estã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 sinalizações.
A Figura 1 mostra um perfil criado com o Bazel v5.3.1 e inclui estas linhas:
action count: exibe quantas ações simultâneas estavam em andamento. Clique nele para ver o valor real. Precisa chegar ao valor de--jobsem builds limpos.CPU usage (Bazel): para cada segundo do build, exibe a quantidade de CPU usada pelo Bazel (um valor de 1 equivale a um núcleo sendo 100% ocupado).Critical Path: exibe 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, "Iniciar Blaze", "evaluateTargetPatterns" e "runAnalysisPhase".Garbage Collector: exibe pausas de coleta de lixo (GC, na sigla em inglês) pequena e importante.
Problemas comuns de desempenho
Ao analisar perfis de performance, procure:
- Fase de análise mais lenta do que o esperado (
runAnalysisPhase), especialmente em builds incrementais. Isso pode ser um sinal de uma implementação incorreta de regra, por exemplo, uma implementação que nivela depsets. O carregamento do pacote pode ser lento por uma excesso de destinos, macros complexas ou globs recursivos. - Ações individuais lentas, especialmente aquelas no caminho crítico. Pode ser
possível dividir grandes ações em várias ações menores ou reduzir o
conjunto de dependências (transitivas) para acelerá-las. Confira também se há um
alto
PROCESS_TIMEnão alto (comoREMOTE_SETUPouFETCH). - Os gargalos, que são um número pequeno de linhas de execução, estão ocupados enquanto todos os outros estão interrompidos / esperando o resultado. Veja cerca de 22s e 29s na Figura 1. Otimizar isso provavelmente vai exigir o contato com 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 adicionais, como o ID 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 trace são fornecidos em
microssegundos. A categoria (cat) é um dos valores de enumeração de ProfilerTask.
Alguns eventos serão mesclados se forem muito curtos e próximos uns aos outros. Transmita --noslim_json_profile se quiser evitar a mesclagem de eventos.
Consulte também a Especificação de formato de evento do Chrome Trace.