O perfil de rastro 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 e consultas semelhantes a build, o Bazel grava esse perfil em
command.profile.gz. É possível configurar se um perfil será gravado com a sinalização
--generate_json_trace_profile
e o local em que ele será gravado com a
sinalização --profile. Os locais que terminam em .gz são compactados com GZIP. Use a flag
--experimental_announce_profile_path
para mostrar 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 "Load" 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 do 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 estatísticas agregadas. - Pressione
2para acessar o 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 usar o modo "zoom". Em seguida, arraste o mouse para aplicar zoom. Você também pode usarw/spara aumentar ou diminuir o zoom. - Pressione
4para usar o modo "tempo", 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 tarefa 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 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 toda
a duração 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 tem várias linhas. Normalmente, a maior parte das linhas representa 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 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 nele para ver o valor real. Precisa subir até o valor de--jobsem builds limpos.CPU usage (Bazel): para cada segundo da compilação, 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: 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 secundárias e principais da coleta de lixo (GC, na sigla em inglês).
Problemas comuns de desempenho
Ao analisar os perfis de performance, procure:
- Fase de análise mais lenta que o esperado (
runAnalysisPhase), especialmente em builds incrementais. Isso pode ser um sinal de uma implementação de regra ruim. Por exemplo, uma que nivela os depsets. O carregamento de pacotes pode ser lento por uma quantidade excessiva de destinos, macros complexas ou globs recursivos. - Ações lentas individuais, especialmente aquelas no caminho crítico. É possível
dividir ações grandes em várias menores ou reduzir o
conjunto de dependências (transitivas) para acelerá-las. Verifique também se há um valor
alto diferente de
PROCESS_TIMEincomum (comoREMOTE_SETUPouFETCH). - Os gargalos, ou seja, um pequeno número de linhas de execução está ocupado, enquanto todas as outras estão inativas / aguardando o resultado (confira cerca de 22 segundos e 29 segundos na Figura 1). Otimizar isso provavelmente exigirá tocar nas 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 do perfil
O objeto de nível superior contém metadados (otherData) e os dados de rastreamento reais
(traceEvents). Os metadados contêm mais informações, 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 vão ser mesclados se forem muito curtos e próximos
entre si. Transmita
--noslim_profile
se quiser evitar a mesclagem de eventos.
Consulte também a Especificação de formato de evento de rastreamento do Chrome.