Exemplo prático de depuração de performance: ANR

Esta seção mostra como depurar um erro "O app não está respondendo" (ANR) usando ProfilingManager com um exemplo de rastreamento.

Configurar o app para coletar ANRs

Comece configurando um acionador de ANR no app:

public void addANRTrigger() {
  ProfilingManager profilingManager = getApplicationContext().getSystemService(
      ProfilingManager.class);
  List<ProfilingTrigger> triggers = new ArrayList<>();
  ProfilingTrigger.Builder triggerBuilder = new ProfilingTrigger.Builder(
      ProfilingTrigger.TRIGGER_TYPE_ANR);
  triggers.add(triggerBuilder.build());
  Executor mainExecutor = Executors.newSingleThreadExecutor();
  Consumer<ProfilingResult> resultCallback =
      profilingResult -> {
        // Handle uploading trace to your back-end
      };
  profilingManager.registerForAllProfilingResults(mainExecutor, resultCallback);
  profilingManager.addProfilingTriggers(triggers);
}

Depois de capturar e fazer o upload de um rastreamento de ANR, abra-o na interface do Perfetto.

Analisar o rastreamento

Como o ANR acionou o rastreamento, você sabe que ele terminou quando o sistema detectou falta de resposta na linha de execução principal do app. A Figura 1 mostra como navegar até a linha de execução principal do app, que é marcada de acordo na interface.

Navegação da interface do Perfetto até a linha de execução principal do app.
Figura 1. Navegação até a linha de execução principal do app.

O final do rastreamento corresponde ao carimbo de data/hora do ANR, conforme mostrado na Figura 2.

A interface do Perfetto mostrando o fim de um rastreamento, destacando o local do gatilho de ANR.
Figura 2. Local do acionador de ANR.

O rastreamento também mostra as operações que o app estava executando quando o ANR ocorreu. Especificamente, o app executou o código na divisão de rastreamento handleNetworkResponse. Essa divisão estava dentro da divisão MyApp:SubmitButton. Ela usou 1,48 segundo de tempo de CPU (Figura 3).

A interface do Perfetto mostrando o tempo de CPU consumido pela execução de handleNetworkResponse no momento do ANR.
Figura 3. Execução no momento do ANR.

Se você confiar apenas em stack traces no momento do ANR para depuração, poderá atribuir o ANR incorretamente ao código em execução na divisão de rastreamento handleNetworkResponse, que não havia terminado quando o perfil terminou a gravação. No entanto, 1,48 segundo é insuficiente para acionar um ANR por conta própria, mesmo que seja uma operação cara. É necessário voltar mais no tempo para entender o que bloqueou a linha de execução principal antes desse método.

Para ter um ponto de partida para procurar a causa do ANR, começamos a procurar após o último frame gerado pela linha de execução da interface, que corresponde à Slice Choreographer#doFrame 551275, e não há grandes fontes de atraso antes de iniciar a Slice MyApp:SubmitButton que terminou no ANR (Figura 4).

A interface do Perfetto mostrando o último frame renderizado pela linha de execução da interface do usuário antes do ANR.
Figura 4. Último frame do app gerado antes do ANR.

Para entender o bloqueio, diminua o zoom para inspecionar a divisão MyApp:SubmitButton completa. Você vai notar um detalhe importante nos estados da linha de execução, conforme mostrado na Figura 4: a linha de execução passou 75% do tempo (6,7 segundos) no estado Sleeping e apenas 24% do tempo no estado Running .

Interface do Perfetto mostrando estados de linhas de execução durante uma operação, destacando 75% de tempo em suspensão e 24% de tempo de execução.
Figura 5. Estados da linha de execução durante a operação `MyApp:SubmitButton`.

Isso indica que a causa principal do ANR foi a espera, não a computação. Examine as ocorrências de suspensão individuais para encontrar um padrão.

A interface do Perfetto mostrando o primeiro intervalo de inatividade na fração de rastreamento MyAppSubmitButton.
Figura 6. Primeiro tempo de suspensão em `MyAppSubmitButton`.
A interface do Perfetto mostrando o segundo intervalo de sono na fração de rastreamento MyAppSubmitButton.
Figura 7. Segundo tempo de suspensão em `MyAppSubmitButton`.
A interface do Perfetto mostrando o terceiro intervalo de suspensão na fração de rastreamento MyAppSubmitButton.
Figura 8. Terceiro tempo de suspensão em `MyAppSubmitButton`.
A interface do Perfetto mostrando o quarto intervalo de inatividade na fração de rastreamento MyAppSubmitButton.
Figura 9. Quarto tempo de suspensão em `MyAppSubmitButton`.

Os três primeiros intervalos de suspensão (Figuras 6 a 8) são quase idênticos, aproximadamente 2 segundos cada. Um quarto tempo de suspensão atípico (Figura 9) é de 0,7 segundo. Uma duração de exatamente 2 segundos raramente é uma coincidência em um ambiente de computação. Isso sugere fortemente um tempo limite programado em vez de uma contenção de recursos aleatória. A última suspensão pode ser causada pela linha de execução que termina a espera porque a operação que ela estava aguardando foi bem-sucedida.

A hipótese é que o app estava atingindo um tempo limite definido pelo usuário de 2 segundos várias vezes e, por fim, sendo bem-sucedido, causando atraso suficiente para acionar um ANR.

A interface do Perfetto mostrando um resumo dos atrasos durante a fração de rastreamento MyApp:SubmitButton, indicando vários intervalos de espera de dois segundos.
Figura 10. Resumo dos atrasos durante a divisão `MyApp:SubmitButton`.

Para verificar isso, inspecione o código associado à seção de rastreamento MyApp:SubmitButton:

private static final int NETWORK_TIMEOUT_MILLISECS = 2000;
public void setupButtonCallback() {
  findViewById(R.id.submit).setOnClickListener(submitButtonView -> {
    Trace.beginSection("MyApp:SubmitButton");
    onClickSubmit();
    Trace.endSection();
  });
}

public void onClickSubmit() {
  prepareNetworkRequest();

  boolean networkRequestSuccess = false;
  int maxAttempts = 10;
  while (!networkRequestSuccess && maxAttempts > 0) {
    networkRequestSuccess = performNetworkRequest(NETWORK_TIMEOUT_MILLISECS);
    maxAttempts--;
  }

  if (networkRequestSuccess) {
    handleNetworkResponse();
  }
}

boolean performNetworkRequest(int timeoutMiliseconds) {
  // ...
}


void prepareNetworkRequest() {
  // ...
}

public void handleNetworkResponse() {
  Trace.beginSection("handleNetworkResponse");
  // ...
  Trace.endSection();
}

O código confirma essa hipótese. O método onClickSubmit executa uma solicitação de rede na linha de execução da interface do usuário com um NETWORK_TIMEOUT_MILLISECS fixado no código de 2.000 ms. É importante ressaltar que ele é executado dentro de um loop while que tenta novamente até 10 vezes.

Nesse rastreamento específico, o usuário provavelmente tinha uma conectividade de rede ruim. As três primeiras tentativas falharam, causando três tempos limite de 2 segundos (um total de 6 segundos). A quarta tentativa foi bem-sucedida após 0,7 segundo, permitindo que o código prosseguisse para handleNetworkResponse. No entanto, o tempo de espera acumulado já acionou o ANR.

Evite esse tipo de ANR colocando operações relacionadas à rede que têm latências variáveis em uma linha de execução em segundo plano, em vez de executá-las na linha de execução principal. Isso permite que a interface permaneça responsiva mesmo com conectividade ruim, eliminando completamente essa classe de ANRs.