Cómo leer informes de errores

Los errores son una realidad en cualquier tipo de desarrollo, y los informes de errores son muy importantes para identificar y resolver problemas. Todas las versiones de Android admiten la captura de informes de errores con Android Debug Bridge (adb); las versiones 4.2 y posteriores de Android admiten las Opciones para desarrolladores, que permiten generar informes de errores y compartirlos por correo electrónico, Drive, etc.

Los informes de errores de Android contienen datos dumpsys, dumpstate y logcat en formato de texto (.txt), lo que te permite buscar fácilmente contenido específico. En las siguientes secciones, se detallan los componentes de los informes de errores, se describen problemas comunes y se brindan sugerencias útiles y comandos grep para encontrar registros asociados con esos errores. En la mayoría de las secciones, también se incluyen ejemplos para el comando y la salida grep, o la salida dumpsys.

Logcat

El registro logcat es un volcado basado en strings de toda la información de logcat. La parte de system está reservada para el marco de trabajo y tiene un historial más largo que main, que contiene todo lo demás. Cada línea suele comenzar con timestamp UID PID TID log-level, aunque es posible que el UID no aparezca en versiones anteriores de Android.

Cómo ver el registro de acontecimientos

Este registro contiene representaciones de strings de mensajes de registro con formato binario. Es más relevante que el registro logcat, pero también un poco más difícil de leer. Al visualizar registros de acontecimientos, puedes buscar en esta sección un ID de proceso (PID) específico para ver lo que realizó un proceso. El formato básico es timestamp PID TID log-level log-tag tag-values.

Los niveles de registro incluyen lo siguiente:

  • V: Detallado
  • D: Depuración
  • I: Información
  • W: Advertencia
  • E: Error

 

Para ver otras etiquetas de registros de acontecimientos útiles, consulta /services/core/java/com/android/server/EventLogTags.logtags.

Interbloqueos y ANR

Los informes de errores pueden ayudarte a identificar qué causa los errores de Aplicación no responde (ANR) y eventos de interbloqueo.

Cómo identificar apps que no responden

Cuando una aplicación no responde dentro de un tiempo determinado, generalmente debido a que un subproceso principal está ocupado o bloqueado, el sistema detiene el proceso y vuelca la pila en /data/anr. Para descubrir la causa de un ANR, realiza una búsqueda grep de am_anr en el registro de acontecimientos binarios.

También puedes realizar una búsqueda grep de ANR in en el registro logcat, que contiene más información sobre lo que estaba usando la CPU en el momento del ANR.

Cómo encontrar seguimientos de pila

A menudo, puedes encontrar seguimientos de pila que corresponden a un ANR. Asegúrate de que la marca de tiempo y el PID de los registros de VM coincidan con el ANR que estés investigando. Luego, verifica el subproceso principal del proceso. Ten en cuenta lo siguiente:

  • El subproceso principal solo te dice qué estaba haciendo el subproceso al momento del ANR, lo que puede corresponder o no a la verdadera causa de este. (La pila del informe de errores puede ser inocente; es posible que otro proceso se haya bloqueado por demorarse mucho tiempo, pero no lo suficiente como para generar un error ANR, antes de reanudarse).
  • Puede existir más de un conjunto de seguimiento de pila (VM TRACES JUST NOW y VM TRACES AT LAST ANR). Asegúrate de estar viendo la sección correcta.

Cómo buscar interbloqueos

Los interbloqueos suelen aparecer en principio como ANR cuando se atascan los subprocesos. Si el interbloqueo afecta al servidor del sistema, eventualmente, el perro guardián finalizará el proceso, lo que generará una entrada en el registro similar a WATCHDOG KILLING SYSTEM PROCESS. Desde la perspectiva del usuario, se reinicia el dispositivo, aunque técnicamente es un reinicio del tiempo de ejecución en lugar de un verdadero reinicio.

  • En un reinicio de tiempo de ejecución, el servidor del sistema se apaga y se reinicia; el usuario ve que el dispositivo regresa a la animación de inicio.
  • En un reinicio, falla el kernel; el usuario ve que el dispositivo regresa al logotipo de inicio de Google.

Para encontrar interbloqueos, revisa las secciones de seguimiento de la VM, a fin de encontrar un patrón donde el subproceso A espera un objeto retenido por el subproceso B, que a su vez está esperando un objeto retenido por el subproceso A.

Actividades

Un objeto Activity es un componente de la aplicación que proporciona una pantalla con la que interactúan los usuarios para marcar un número, tomar una foto, enviar un correo electrónico, etc. Desde la perspectiva del informe de errores, un objeto Activity es una actividad única y específica que puede realizar un usuario. Durante una falla, es muy importante poder ubicar a la actividad que estaba en foco. Dado que los objetos Activity ejecutan procesos (mediante ActivityManager), ubicar todos los inicios y detenciones de procesos de una actividad determinada también puede ayudar a solucionar problemas.

Cómo ver las actividades enfocadas

Para ver un historial de actividades enfocadas, busca am_focused_activity.

Cómo ver los inicios de procesos

Para ver un historial de inicios de procesos, busca Start proc.

¿El dispositivo realiza una hiperpaginación?

Para determinar si el dispositivo realiza una hiperpaginación, verifica si hay un aumento anormal de la actividad alrededor de am_proc_died y am_proc_start en un período corto.

Memoria

Debido a que los dispositivos Android suelen tener una memoria física limitada, es fundamental administrar la memoria de acceso aleatorio (RAM). Los informes de errores contienen varios indicadores de memoria baja, así como un dumpstate que proporciona una instantánea de la memoria.

Cómo identificar memoria baja

La memoria baja puede causar la hiperpaginación del sistema, ya que elimina algunos procesos para liberar memoria, pero continúa iniciando otros. Para comprobar que la memoria está baja, verifica las concentraciones de las entradas am_proc_died y am_proc_start en el registro de acontecimientos binario.

La memoria baja también puede ralentizar el cambio entre tareas y frustrar los intentos de volver a una tarea (porque se finalizó la tarea a la que el usuario intentaba regresar). Si se cerró el selector, se reinicia cuando el usuario toca el botón de inicio, y los registros muestran que el selector vuelve a cargar el contenido.

Cómo ver indicadores históricos

La entrada am_low_memory del registro de acontecimientos binarios indica que finalizó el último proceso almacenado en caché. Después de esto, el sistema comienza a cerrar servicios.

Cómo ver indicadores de hiperpaginación

Los ciclos de consumo kswapd, kworker y mmcqd son otros indicadores de hiperpaginación del sistema (paginación, recuperación directa, etc.). (Ten en cuenta que el informe de errores recopilado puede influir en los indicadores de hiperpaginación).

Los registros de ANR pueden proporcionar una instantánea de memoria similar.

Cómo obtener una instantánea de memoria

La instantánea de memoria es un dumpstate que enumera los procesos nativos y de Java en ejecución (para obtener más información, consulta Cómo visualizar las asignaciones de memoria en general). Ten en cuenta que la instantánea solo muestra el estado en un momento específico; es posible que el sistema estuviera en mejor (o peor) estado antes de que se generara la instantánea.

Transmisiones

Las aplicaciones generan transmisiones con el objetivo de enviar eventos dentro de la aplicación actual o en otra aplicación. Los receptores de transmisión se suscriben a mensajes específicos (mediante filtros), lo que les permite escuchar y responder una transmisión. Los informes de errores contienen información sobre transmisiones enviadas y no enviadas, además de un dumpsys de todos los receptores que escuchan una transmisión específica.

Cómo ver transmisiones históricas

Las transmisiones históricas son aquellas que ya se enviaron, enumeradas en orden cronológico inverso.

La sección summary es una descripción general de las últimas 300 transmisiones en primer plano y las últimas 300 en segundo plano.

La sección detail contiene información completa de las últimas 50 transmisiones en primer plano y las últimas 50 en segundo plano, así como los receptores de cada transmisión. Los receptores que tienen:

  • Una entrada BroadcastFilter se registran en el tiempo de ejecución y se envían solo a los procesos que ya están en ejecución.
  • Una entrada ResolveInfo se registran mediante entradas de manifiesto. ActivityManager inicia el proceso para cada ResolveInfo si aún está en ejecución.

Cómo ver transmisiones activas

Las transmisiones activas son aquellas que todavía no se enviaron. Un número alto en la cola significa que el sistema no puede despachar las transmisiones lo suficientemente rápido como para mantenerse al día.

Cómo ver objetos de escucha de transmisión

Para ver una lista de receptores que son objetos de escucha de una transmisión, revisa la tabla Agente de resolución del receptor en las dumpsys activity broadcasts. En el siguiente ejemplo, se muestran todos los receptores que actúan como objetos de escucha para USER_PRESENT.

Contención de supervisión

El registro de contención de supervisión a veces puede indicar la contención real de supervisión, pero suele indicar que el sistema está tan cargado, que todo se ejecuta más lento. Es posible que veas eventos de supervisión de larga duración registrados por ART en el sistema o en el registro de acontecimientos.

En el registro del sistema:

10-01 18:12:44.343 29761 29914 W art     : Long monitor contention event with owner method=void android.database.sqlite.SQLiteClosable.acquireReference() from SQLiteClosable.java:52 waiters=0 for 3.914s

En el registro de acontecimientos:

10-01 18:12:44.364 29761 29914 I dvm_lock_sample: [com.google.android.youtube,0,pool-3-thread-9,3914,ScheduledTaskMaster.java,138,SQLiteClosable.java,52,100]

Compilación en segundo plano

La compilación puede consumir muchos recursos y ralentizar el dispositivo.

La compilación puede producirse en segundo plano cuando se descargan actualizaciones de Google Play Store. En este caso, los mensajes de la app de Google Play Store (finsky) e installd aparecen antes que los mensajes de dex2oat.

La compilación también puede producirse en segundo plano cuando una aplicación está cargando un archivo dex que todavía no se compiló. En ese caso, no verás la creación de registros finsky ni installd.

Narración

Establecer la narración de un problema (cómo comenzó, qué sucedió y cómo reaccionó el sistema) requiere una línea de tiempo de eventos sólida. Puedes usar los datos del informe de errores para sincronizar las líneas de tiempo de varios registros y determinar la marca de tiempo exacta del informe de errores.

Cómo sincronizar líneas de tiempo

Un informe de errores refleja múltiples líneas de tiempo paralelas: registro del sistema, registro de acontecimientos, registro del núcleo y múltiples líneas de tiempo especializadas para transmisiones, estadísticas de batería, etc. Desafortunadamente, las líneas de tiempo a menudo se informan con diferentes bases de tiempo.

Las marcas de tiempo del registro de acontecimientos y del sistema están en la misma zona horaria que el usuario (como la mayoría de las otras marcas de tiempo). Por ejemplo, cuando el usuario presiona el botón de inicio, el registro del sistema informa lo siguiente:

10-03 17:19:52.939  1963  2071 I ActivityManager: START u0 {act=android.intent.action.MAIN cat=[android.intent.category.HOME] flg=0x10200000 cmp=com.google.android.googlequicksearchbox/com.google.android.launcher.GEL (has extras)} from uid 1000 on display 0

Para la misma acción, el registro de acontecimientos informa lo siguiente:

10-03 17:19:54.279  1963  2071 I am_focused_activity: [0,com.google.android.googlequicksearchbox/com.google.android.launcher.GEL]

Los registros de kernel (dmesg) usan una base de tiempo diferente y etiquetan los elementos del registro con los segundos transcurridos desde que se completa el bootloader. Para registrar esta escala de tiempo en otras escalas, busca los mensajes suspend exit y suspended entry:

<6>[201640.779997] PM: suspend exit 2015-10-03 19:11:06.646094058 UTC
…
<6>[201644.854315] PM: suspend entry 2015-10-03 19:11:10.720416452 UTC

Debido a que es posible que los registros kernel no incluyan el tiempo mientras están en suspensión, deberías crear entradas de a partes en el registro entre los mensajes de suspensión y de salida. Además, los registros de kernel usan la zona horaria UTC y deben ajustarse a la del usuario.

Cómo identificar el tiempo de los informes de errores

Para determinar cuándo se generó un informe de errores, primero revisa el registro del sistema (Logcat) para el dumpstate: begin:

10-03 17:19:54.322 19398 19398 I dumpstate: begin

Luego, verifica las marcas de tiempo del registro de kernel (dmesg) para el mensaje Starting service 'bugreport':

<5>[207064.285315] init: Starting service 'bugreport'...

Trabaja hacia atrás para correlacionar los dos eventos, pero ten en cuenta las advertencias mencionadas en la sección Cómo sincronizar líneas de tiempo. Si bien suceden muchas cosas después de iniciar el informe de errores, la mayoría de las actividades no son muy útiles, ya que genera el informe carga el sistema considerablemente.

Encendido/apagado

El registro de acontecimientos incluye el estado de encendido/apagado de la pantalla, donde 0 es apagado, 1 es encendido y 2 es para el bloqueo del teclado.

Los informes de errores también contienen estadísticas sobre el bloqueo de activación, un mecanismo que usan los desarrolladores de aplicaciones para indicar que su aplicación necesita que el dispositivo permanezca encendido. (Para más información sobre los bloqueos de activación, consulta PowerManager.WakeLock y Cómo mantener la CPU encendida).

Las estadísticas acumuladas sobre la duración del bloqueo de activación solo hacen un seguimiento del tiempo en el que un bloqueo de activación es responsable de mantener el dispositivo activo y no incluyen el tiempo con la pantalla encendida. Además, si se producen varios bloqueos de activación simultáneos, el tiempo de duración del bloqueo de activación se distribuirá entre esos bloqueos de activación.

Para obtener más ayuda sobre cómo visualizar el estado de encendido/apagado, usa Battery Historian, una herramienta de código abierto de Google que sirve para analizar qué elementos consumen la batería mediante archivos de informes de errores de Android.

Paquetes

La sección DUMP OF SERVICE package contiene versiones de la aplicación (y demás información útil).

Procesos

Los informes de errores contienen una gran cantidad de datos para procesos, incluidos el tiempo de inicio y detención, la duración del tiempo de ejecución, los servicios asociados, la puntuación de oom_adj, etc. Si quieres obtener información detallada sobre cómo Android gestiona los procesos, consulta la sección Procesos y subprocesos.

Cómo determinar el tiempo de ejecución de un proceso

En la sección procstats, encontrarás estadísticas completas sobre el tiempo de ejecución de los procesos y los servicios asociados. Para obtener un resumen rápido y legible, busca AGGREGATED OVER y verás los datos de las últimas 3 o 24 horas. Luego, busca Summary: para ver la lista de procesos, cuánto tiempo se ejecutaron esos procesos con diversas prioridades y su uso de RAM con el formato min-average-max PSS/min-average-max USS.

¿Por qué se está ejecutando un proceso?

En la sección dumpsys activity processes, se enumeran todos los procesos en ejecución en ese momento, ordenados por la puntuación de oom_adj (Android indica la importancia del proceso asignándole un valor oom_adj, que ActivityManager puede actualizar de forma dinámica). El resultado es similar al de una instantánea de memoria, pero incluye información adicional sobre qué está causando la ejecución del proceso. En el siguiente ejemplo, las entradas en negrita indican que el proceso gms.persistent se ejecuta con prioridad vis (visible) porque el proceso del sistema está vinculado a su NetworkLocationService.

Análisis

Sigue estos pasos para identificar las aplicaciones que realizan análisis excesivos de Bluetooth de bajo consumo (BLE):

  • Busca mensajes de registro de BluetoothLeScanner:
    $ grep 'BluetoothLeScanner' ~/downloads/bugreport.txt
    07-28 15:55:19.090 24840 24851 D BluetoothLeScanner: onClientRegistered() - status=0 clientIf=5
    
  • Encuentra el PID en los mensajes de registro. En este ejemplo, "24840" y "24851" son PID (ID de proceso) y TID (ID de subproceso).
  • Encuentra la aplicación asociada con el PID:
    PID #24840: ProcessRecord{4fe996a 24840:com.badapp/u0a105}
    

    En este ejemplo, el nombre del paquete es com.badapp.

  • Busca el nombre del paquete en Google Play para identificar la aplicación responsable: https://play.google.com/store/apps/details?id=com.badapp.

Nota: En los dispositivos que ejecutan Android 7.0, el sistema recopila datos para análisis de BLE y los asocia a la aplicación de inicio. Para obtener más información, consulta la sección Análisis de bajo consumo (LE) y Bluetooth.