O perfil de trace JSON pode ser muito útil para entender rapidamente o que o Bazel gastou. 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 será criado com o
--generate_json_trace_profile
e o local no qual ela foi gravada com o
--profile
. Os locais que terminam com .gz
são
compactado com GZIP. Usar a sinalização
--experimental_announce_profile_path
para imprimir o caminho desse arquivo para o registro.
Ferramentas
Você pode carregar esse perfil no chrome://tracing
ou analisar e
depois do processamento com outras ferramentas.
chrome://tracing
Para acessar o perfil, abra o app chrome://tracing
em uma guia do Chrome.
clique em "Carregar" e escolha o arquivo de perfil (possivelmente compactado). Para mais
resultados detalhados, clique nas caixas no canto inferior esquerdo.
Exemplo de perfil:
Figura 1. Exemplo de perfil.
Use estes controles de teclado para navegar:
- Pressione
1
para "selecionar" modo Neste modo, você pode selecionar caixas específicas para inspecionar os detalhes do evento (consulte o canto inferior esquerdo). Selecione vários eventos para ver um resumo e as estatísticas agregadas. - Pressione
2
para "pan" modo Em seguida, arraste o mouse para mover a visualização. Você também pode usara
/d
para mover para a esquerda/direita. - Pressione
3
para "zoom" modo Em seguida, arraste o mouse para aplicar o zoom. Você pode usew
/s
para aumentar/diminuir o zoom. - Pressione
4
para "tempo" em que é possível 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 produzir uma saída desta forma:
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
A Analisador de invocação do Bazel usa um formato de perfil e imprime sugestões sobre como melhorar o desempenho do build. Essa análise pode ser realizada usando a CLI ou https://analyzer.engflow.com.
jq
jq
é como sed
para dados JSON. Um exemplo de uso de jq
para extrair todos
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 o Bazel linhas de execução e seus 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 pode ser personalizado por sinalizações diferentes.
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 em para conferir o valor real. Deve subir até o valor de--jobs
em limpeza builds.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 100% ocupado).Critical Path
: mostra um bloco para cada ação no caminho crítico.Main Thread
: linha de execução principal do Bazel. Útil para ter uma visão geral da o que o Bazel está fazendo, por exemplo, "Launch Blaze", "evaluateTargetPatterns", e "runAnalysisFase".Garbage Collector
: exibe coleta de lixo (GC, na sigla em inglês) pequena e grande. pausa.
Problemas comuns de desempenho
Ao analisar os 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 má implementação da regra, um exemplo que nivela dependências. O carregamento do pacote pode demorar quantidade excessiva de alvos, macros complexas ou globs recursivos. - Ações lentas individuais, especialmente as que estão no caminho crítico. Pode ser
possível dividir grandes ações em várias ações menores ou reduzir a
de dependências (transitivas) para acelerá-las. Verifique também se há um erro incomum
alto diferente de
PROCESS_TIME
(comoREMOTE_SETUP
ouFETCH
). - Gargalos, ou seja, um pequeno número de tópicos ocupados, enquanto todos os outros estão inatividade / espera pelo resultado (veja cerca de 22 e 29s na figura 1). Para otimizar essa opção, provavelmente você vai precisar tocar nas implementações das regras ou o próprio Bazel para incluir mais paralelismo. Isso também pode acontecer quando uma quantidade incomum de GC.
Formato do arquivo do 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, como 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 tipo enumerado de ProfilerTask
.
Observe que alguns eventos serão mesclados se forem muito curtos e próximos de
uns aos outros; passar
--noslim_json_profile
se quiser evitar a mesclagem de eventos.
Consulte também Especificação de formato de eventos de rastreamento do Chrome.