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

Esta seção mostra como depurar um Application Not Responding (ANR) usando ProfilingManager com um exemplo de rastreamento.

Configurar o app para coletar ANRs

Comece configurando um acionador de ANR no seu 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);
}
ProfilingManagerJavaSnippets.java

Depois de capturar e fazer 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.

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

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 fração de rastreamento handleNetworkResponse. Essa fatia estava dentro da fatia MyApp:SubmitButton. Ele usou 1,48 segundo de tempo de CPU (Figura 3).

Se você confiar apenas nos stack traces no momento do ANR para depuração, poderá atribuir erroneamente o ANR inteiramente ao código em execução no intervalo de rastreamento 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 si só, mesmo que seja uma operação cara. É preciso 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 na busca pela causa do ANR, começamos a procurar após o último frame gerado pela linha de execução da interface, que corresponde à fatia Choreographer#doFrame 551275, e não há grandes fontes de atraso antes de iniciar a fatia MyApp:SubmitButton que terminou no ANR (Figura 4).

Para entender o bloqueio, diminua o zoom e inspecione a fatia completa de MyApp:SubmitButton. 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.

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.

Os três primeiros intervalos de sono (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 2 segundos raramente é uma coincidência em um ambiente de computação. Isso sugere fortemente um tempo limite programado em vez de uma disputa aleatória de recursos. A última suspensão pode ser causada pela conclusão da espera da linha de execução porque a operação que ela estava aguardando foi concluída.

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

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) {
  // ...
}

  // ...
}

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

O código confirma essa hipótese. O método onClickSubmit executa uma solicitação de rede na linha de execução de IU com um NETWORK_TIMEOUT_MILLISECS codificado de 2.000 ms. É importante ressaltar que ele é executado em um loop while que tenta até 10 vezes.

Neste 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 dois segundos (total de seis 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.

Para evitar esse tipo de ANR, coloque 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.