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

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

Configura la app para recopilar 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);
}

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

Analiza el seguimiento

Debido a 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 se etiqueta según corresponda dentro de la IU.

Navegación de la IU de Perfetto al subproceso principal de la app.
Figura 1: Navegación al subproceso principal de la app

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

IU de Perfetto que muestra el final de un registro y destaca la ubicación del activador de ANR.
Figura 2: Ubicación del activador de ANR.

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

IU de Perfetto que muestra el tiempo de CPU que consumió la ejecución de handleNetworkResponse en el momento del error de ANR
Figura 3: Ejecución en el momento del error de ANR

Si solo confías en los seguimientos de pila en el momento del error de ANR para la depuración, es posible que atribuyas erróneamente el error de ANR por completo al código que se ejecuta dentro del segmento de seguimiento handleNetworkResponse, que no había finalizado cuando el perfil terminó de grabar. Sin embargo, 1.48 segundos no es suficiente para activar un error de ANR por sí solo, 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 que permita buscar la causa del error de ANR, comenzamos a buscar después del último fotograma que generó el subproceso de IU, que corresponde al segmento Choreographer#doFrame 551275, y no hay grandes fuentes de retraso antes de iniciar el segmento MyApp:SubmitButton que terminó en el error de ANR (figura 4).

IU de Perfetto que muestra el último fotograma renderizado por el subproceso de IU antes del error de ANR.
Figura 4: Es el último fotograma de la app que se generó antes del error de ANR.

Para comprender el bloqueo, aleja la imagen y, luego, inspecciona la porción completa de MyApp:SubmitButton. Notarás un detalle crítico en los estados de los subprocesos, 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.

La IU de Perfetto muestra los estados de los subprocesos durante una operación, con un 75% de tiempo de suspensión y un 24% de tiempo de ejecución.
Figura 5. Estados de los subprocesos durante la operación "MyApp:SubmitButton"

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

IU de Perfetto que muestra el primer intervalo de suspensión dentro de la porción de seguimiento de MyAppSubmitButton.
Figura 6. Primer tiempo de suspensión dentro de `MyAppSubmitButton`.
IU de Perfetto que muestra el segundo intervalo de suspensión dentro de la porción de seguimiento de MyAppSubmitButton.
Figura 7. Segundo tiempo de suspensión dentro de `MyAppSubmitButton`.
IU de Perfetto que muestra el tercer intervalo de suspensión dentro del segmento de seguimiento de MyAppSubmitButton.
Figura 8: Tercer tiempo de suspensión dentro de `MyAppSubmitButton`.
IU de Perfetto que muestra el cuarto intervalo de suspensión dentro de la porción de seguimiento de MyAppSubmitButton.
Figura 9: Cuarto tiempo de suspensión dentro de `MyAppSubmitButton`.

Los primeros tres intervalos de suspensión (figuras 6 a 8) son casi idénticos, de aproximadamente 2 segundos cada uno. Un cuarto estado de suspensión atípico (figura 9) es de 0.7 segundos. Una duración de exactamente 2 segundos rara vez es una coincidencia en un entorno de procesamiento. Esto sugiere con fuerza un tiempo de espera programado en lugar de una contención de recursos aleatoria. Es posible que la última suspensión se deba a que el subproceso finalizó su espera porque la operación que estaba esperando se realizó correctamente.

Esta hipótesis es que la app alcanzaba un tiempo de espera definido por el usuario de 2 segundos varias veces y, finalmente, se ejecutaba correctamente, lo que causaba un retraso suficiente para activar un error de ANR.

IU de Perfetto que muestra un resumen de los retrasos durante el segmento de seguimiento MyApp:SubmitButton, lo que indica varios intervalos de suspensión de 2 segundos.
Figura 10: Resumen de los retrasos durante la porción "MyApp:SubmitButton".

Para verificarlo, inspecciona el código asociado con la sección de seguimiento de 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();
}

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 de 2,000 ms codificado de forma rígida. Es fundamental que se ejecute dentro de un bucle while que reintente hasta 10 veces.

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

Para evitar este tipo 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.