O perfil de trace JSON pode ser muito útil para entender rapidamente em que o Bazel gastou tempo durante a invocação.
Por padrão, em 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 ele é 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 resultados mais detalhados, clique nas caixas no canto inferior esquerdo.
Exemplo de perfil:
Figura 1. Exemplo de perfil.
Use estes controles de teclado para navegar:
- Pressione
1para o modo "selecionar". Nesse 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
2para entrar no modo "movimentar". 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 o zoom. Também é possível usarw/spara aumentar ou diminuir o zoom. - Pressione
4para acessar o modo de 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 build 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
O Bazel Invocation Analyzer (em inglês) consome 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 (em inglês).
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 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 conferir o valor real. Precisa subir até o 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: 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 do que o Bazel está fazendo. Por exemplo, "Launch Blaze", "evaluateTargetPatterns" e "runAnalysisPhase".Garbage Collector: exibe pausas de coleta de lixo (GC, na sigla em inglês) secundária e principal.
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 uma implementação de regra ruim, como uma que nivela as dependências. O carregamento de pacotes pode ser lento devido a uma quantidade excessiva de destinos, macros complexas ou globs recursivos. - Ações lentas individuais, especialmente as que estão no caminho crítico. Pode ser
possível dividir ações grandes em várias ações menores ou reduzir o
conjunto de dependências (transitivas) para acelerá-las. Verifique também se há um valor alto
incomum que não seja
PROCESS_TIME(comoREMOTE_SETUPouFETCH). - Gargalos, ou seja, um pequeno número de linhas de execução estão ocupadas, enquanto todas as outras estão inativas / aguardando o resultado (veja cerca de 22 e 29 segundos na Figura 1). Otimizar isso provavelmente exigirá tocar nas implementações de regras ou no próprio Bazel para introduzir mais paralelismo. Isso também pode acontecer quando há 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
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.
Alguns eventos serão mesclados se forem muito curtos e próximos
uns dos outros. Transmita
--noslim_json_profile
se quiser evitar a mesclagem de eventos.
Consulte também a Especificação de formato de eventos do Chrome Trace.