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

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

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

Debido a que el 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 en consecuencia dentro de 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 ejecutaba la app cuando ocurrió el ANR. Específicamente, la app ejecutó código en el segmento de registro handleNetworkResponse. Este segmento estaba dentro del segmento 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 la depuración, es posible que atribuyas erróneamente el ANR por completo al código que se ejecuta dentro del segmento de registro handleNetworkResponse, que no había finalizado cuando el perfil terminó de grabar. Sin embargo, 1.48 segundos no son suficientes para activar un ANR por sí solos, aunque sea 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 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 terminó en el ANR (Figura 4).

Para comprender el bloqueo, aleja el zoom para inspeccionar el segmento MyApp:SubmitButton completo. Notará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 estado Sleeping y solo el 24% del tiempo en estado Running .

Esto indica que la causa principal del ANR fue la espera, no el cálculo. Examina las ocurrencias de inactividad individuales para encontrar un patrón.

Tercer tiempo de inactividad dentro de `MyAppSubmitButton`.

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

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

Para verificar esto, inspecciona el código asociado con la sección de registro 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();
}
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 2000 ms. Es fundamental que se ejecute dentro de un bucle while que vuelva 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 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 pasara a handleNetworkResponse. Sin embargo, el tiempo de espera acumulado ya activó el 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 ANRs.