Perfil do Trace de JSON

Informar um problema Ver a fonte Nightly · 7.3 · 7.2 · 7.1 · 7.0 · 6.5

O perfil de rastro 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 em a base de saída chamada command-$INOVCATION_ID.profile.gz, em que $INOVCATION_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 o perfil; do comando mais recente. É possível configurar se um perfil será criado com a --generate_json_trace_profile e o local no qual ela foi gravada com o --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

É possível carregar esse perfil no chrome://tracing ou analisá-lo e pós-processá-lo 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 resultados mais detalhados, clique nas caixas no canto inferior esquerdo.

Exemplo de perfil:

Perfil de exemplo

Figura 1. Exemplo de perfil.

Use estes controles de teclado para navegar:

  • Pressione 1 para "selecionar" modo Nesse modo, é possível 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. 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. Você pode use w/s para aumentar/diminuir o zoom.
  • Pressione 4 para o modo "timing", 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 usa um formato de perfil e imprime estatísticas cumulativas para diferentes tipos de tarefas em 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 de código aberto consome um formato de perfil e mostra 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. Exemplo de uso de jq para extrair todas as durações da etapa de criação do sandbox na execução de 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 para conferir o valor real. Precisa aumentar até o valor de --jobs em 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 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: mostra pausas de coleta de lixo (GC) menores e maiores.

Problemas de desempenho comuns

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, por exemplo, uma que simplifica os depsets. O carregamento do pacote pode ser lento devido a uma quantidade excessiva de destinos, macros complexas ou globais recursivos.
  • Ações lentas individuais, especialmente aquelas no caminho crítico. Talvez seja possível dividir ações grandes em várias ações menores ou reduzir o conjunto de dependências (transitivo) para acelerar. Verifique também se há um erro incomum alto diferente de PROCESS_TIME (como REMOTE_SETUP ou FETCH).
  • 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 isso, provavelmente será necessário 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 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, 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 durações (dur) nos eventos de rastreamento são fornecidos em microssegundos. A categoria (cat) é um dos valores de enumeração de ProfilerTask. Observe que alguns eventos serão mesclados se forem muito curtos e próximos de uns aos outros; passar --noslim_profile se quiser evitar a mesclagem de eventos.

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