Perfil do Trace de JSON

Informar um problema Ver código-fonte Nightly · 7.4 . 7.3 · 7.2 · 7.1 · 7.0 · 6.5

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 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. 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 visualizar o perfil, abra chrome://tracing em uma guia do navegador Chrome, clique em "Load" e selecione o arquivo de perfil (possivelmente compactado). Para mais resultados detalhados, clique nas caixas no canto inferior esquerdo.

Exemplo de perfil:

Exemplo de perfil

Figura 1. Exemplo de perfil.

Use estes controles de teclado para navegar:

  • Pressione 1 para o modo "selecionar". Neste modo, você pode selecionar caixas específicas para inspecionar os detalhes do evento (consulte o canto inferior esquerdo). Selecione vários eventos para receber um resumo e estatísticas agregadas.
  • Pressione 2 para o modo "Movimentar". Em seguida, arraste o mouse para mover a visualização. Você também pode usar a/d para mover para a esquerda/direita.
  • Pressione 3 para "zoom" modo Em seguida, arraste o mouse para aplicar o zoom. Também é possível usar 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 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 biblioteca 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. 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 podem ser personalizadas por flags 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. Precisa aumentar até o valor de --jobs em builds limpos.
  • CPU usage (Bazel): para cada segundo do build, mostra a quantidade de CPU usada pelo Bazel (um valor de 1 equivale a um núcleo com 100% de uso).
  • 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 de coleta de lixo (GC) menores e maiores.

Problemas de desempenho comuns

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 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. 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 PROCESS_TIME alto incomum (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 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 há uma quantidade incomum de GC.

Formato do arquivo de perfil

O objeto de nível superior contém metadados (otherData) e os dados reais de rastreamento (traceEvents). Os metadados contêm informações extras, por exemplo, 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. 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 a especificação do formato de evento de trace do Chrome.