Ejemplo práctico de depuración del rendimiento: ANR

En esta sección, se muestra cómo depurar un error de Aplicación que no responde (ANR) con ProfilingManager y un ejemplo de registro.

Configura la app para recopilar errores de ANR

Para comenzar, configura un activador de ANR en tu 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

Después de capturar y subir un registro de ANR, ábrelo en la IU de Perfetto.

Analiza el registro

Dado que el error de ANR activó el registro, sabes que este finalizó cuando el sistema detectó que el subproceso principal de tu app no respondía. En la figura 1, se muestra cómo navegar al subproceso principal de tu app, que está etiquetado de forma adecuada en la IU.

El final del registro coincide con la marca de tiempo del ANR, como se muestra en la Figura 2.

El registro también muestra las operaciones que la app estaba ejecutando cuando ocurrió el error de ANR. Específicamente, la app ejecutó código en el segmento de registro handleNetworkResponse. Esta división estaba dentro de la división MyApp:SubmitButton. Usó 1.48 segundos de tiempo de CPU (figura 3).

Si solo confías en los seguimientos de pila en el momento del ANR para depurar, es posible que atribuyas erróneamente el ANR por completo al código que se ejecuta dentro del segmento de seguimiento de handleNetworkResponse que no había finalizado cuando el perfil terminó de registrarse. Sin embargo, 1.48 segundos no son suficientes para activar un error de ANR por sí solos, aunque se trate de una operación costosa. Debes mirar más atrás en el tiempo para comprender qué bloqueó el subproceso principal antes de este método.

Para obtener un punto de partida para buscar la causa del error de ANR, comenzamos a buscar después del último fotograma generado por el subproceso de IU, que corresponde al segmento Choreographer#doFrame 551275, y no hay grandes fuentes de demora antes de iniciar el segmento MyApp:SubmitButton que finalizó en el error de ANR (figura 4).

Para comprender el bloqueo, aleja el zoom y examina el segmento MyApp:SubmitButton completo. Observarás un detalle fundamental en los estados del subproceso, como se muestra en la figura 4: el subproceso pasó el 75% del tiempo (6.7 segundos) en el estado Sleeping y solo el 24% del tiempo en el estado Running.

Esto indica que la causa principal del ANR fue la espera, no el procesamiento. Examina los episodios de sueño individuales para encontrar un patrón.

Los primeros tres intervalos de sueño (figuras 6 a 8) son casi idénticos, de aproximadamente 2 segundos cada uno. Un cuarto sueño atípico (figura 9) dura 0.7 segundos. En un entorno de procesamiento, una duración de exactamente 2 segundos rara vez es una coincidencia. Esto sugiere un tiempo de espera programado en lugar de una contención de recursos aleatoria. El último período de inactividad puede deberse a que el subproceso finalizó su espera porque la operación que esperaba se completó correctamente.

La hipótesis es que la app alcanzó un tiempo de espera definido por el usuario de 2 segundos varias veces y, finalmente, tuvo éxito, lo que provocó una demora suficiente para activar un ANR.

Para verificar esto, inspecciona el código asociado con la sección de seguimiento 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

El código confirma esta hipótesis. El método onClickSubmit ejecuta una solicitud de red en el subproceso de IU con un NETWORK_TIMEOUT_MILLISECS codificado de 2,000 ms. Es fundamental que se ejecute dentro de un bucle while que vuelve a intentarlo hasta 10 veces.

En este registro específico, es probable que el usuario haya tenido una conectividad de red deficiente. Los primeros tres intentos fallaron, lo que provocó tres tiempos de espera de 2 segundos (un total de 6 segundos). El cuarto intento se realizó correctamente después de 0.7 s, lo que permitió que el código continuara con handleNetworkResponse. Sin embargo, el tiempo de espera acumulado ya activó el ANR.

Para evitar este tipo de error de ANR, coloca las operaciones relacionadas con la red que tienen latencias variables en un subproceso en segundo plano en lugar de ejecutarlas en el subproceso principal. Esto permite que la IU siga respondiendo incluso con una conectividad deficiente, lo que elimina por completo esta clase de ANR.