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

Nesta seção, mostramos como depurar um erro O app não está respondendo (ANR) usando ProfilingManager com um exemplo de trace.

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 upload de um rastro de ANR, abra-o na interface do Perfetto.

Analisar o trace

Como o ANR acionou o rastro, 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 para a linha de execução principal do app.
Figura 1. Navegação para a linha de execução principal do app.

O fim do rastro corresponde ao carimbo de data/hora do ANR, como mostrado na Figura 2.

Interface do Perfetto mostrando o fim de um rastro, destacando o local do acionador de ANR.
Figura 2. Local do gatilho de ANR.

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

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ê depender apenas de stack traces no momento do ANR para depuração, poderá atribuir o ANR inteiramente ao código em execução na fração de trace handleNetworkResponse, que não havia terminado quando o perfil concluiu a gravação. No entanto, 1,48 segundo não é suficiente para acionar um ANR por conta própria, mesmo que seja uma operação cara. É preciso analisar mais para trás no tempo para entender o que bloqueou a linha de execução principal antes desse método.

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

Interface do Perfetto mostrando o último frame renderizado pela linha de execução de interface antes do ANR.
Figura 4. Último frame do app gerado antes do ANR.

Para entender o bloqueio, diminua o zoom para inspecionar toda a fração MyApp:SubmitButton. Você vai notar um detalhe crítico 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 linha de execução durante uma operação, destacando 75% de tempo de 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. Analise as ocorrências de sono individuais para encontrar um padrão.

Interface do Perfetto mostrando o primeiro intervalo de suspensão na fração de rastreamento MyAppSubmitButton.
Figura 6. Primeiro tempo de suspensão em `MyAppSubmitButton`.
Interface do Perfetto mostrando o segundo intervalo de suspensão na fração de rastro MyAppSubmitButton.
Figura 7. Segundo tempo de suspensão em `MyAppSubmitButton`.
Interface do Perfetto mostrando o terceiro intervalo de suspensão na fração de rastro MyAppSubmitButton.
Figura 8. Terceiro tempo de suspensão em `MyAppSubmitButton`.
Interface do Perfetto mostrando o quarto intervalo de suspensão na fração de rastro 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, com aproximadamente 2 segundos cada. Um quarto sono atípico (Figura 9) é de 0,7 segundo. Uma duração de exatamente dois 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 encerra a espera porque a operação que ela estava aguardando foi concluída.

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

Interface do Perfetto mostrando um resumo dos atrasos durante a fração de rastro MyApp:SubmitButton, indicando vários intervalos de suspensão de 2 segundos.
Figura 10. Resumo dos atrasos durante a fração `MyApp:SubmitButton`.

Para verificar isso, inspecione o código associado à seção de trace 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 de interface com um NETWORK_TIMEOUT_MILLISECS fixado no código de 2.000 ms. O mais importante é que ele é executado em um loop while que tenta novamente até 10 vezes.

Nesse trace específico, é provável que o usuário tenha tido 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 prossiga 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 variadas em uma linha de execução em segundo plano, em vez de executá-las na linha de execução principal. Isso permite que a IU permaneça responsiva mesmo com conectividade ruim, eliminando completamente essa classe de ANRs.