Usa ftrace

ftrace es una herramienta de depuración para comprender lo que sucede dentro del kernel de Linux. En las siguientes secciones, se detallan la funcionalidad básica de ftrace, el uso de ftrace con atrace (que captura eventos del kernel) y ftrace dinámico.

Para obtener detalles sobre la funcionalidad avanzada de ftrace que no está disponible en systrace, consulta la documentación de ftrace en <kernel tree>/Documentation/trace/ftrace.txt.

Cómo capturar eventos del kernel con atrace

atrace (frameworks/native/cmds/atrace) usa ftrace para capturar eventos del kernel. A su vez, systrace.py (o run_systrace.py en versiones posteriores de Catapult) usa adb para ejecutar atrace en el dispositivo. atrace hace lo siguiente:

  • Configura el seguimiento en modo de usuario configurando una propiedad (debug.atrace.tags.enableflags).
  • Habilita la funcionalidad de ftrace deseada escribiendo en los nodos sysfs de ftrace adecuados. Sin embargo, como ftrace admite más funciones, puedes configurar algunos nodos sysfs por tu cuenta y, luego, usar atrace.

Con la excepción del seguimiento del tiempo de inicio, usa atrace para establecer la propiedad en el valor adecuado. La propiedad es una máscara de bits, y no hay una buena manera de determinar los valores correctos, además de mirar el encabezado adecuado (que podría cambiar entre las versiones de Android).

Habilita los eventos de ftrace

Los nodos sysfs de ftrace se encuentran en /sys/kernel/tracing y los eventos de seguimiento se dividen en categorías en /sys/kernel/tracing/events.

Para habilitar eventos por categoría, usa lo siguiente:

echo 1 > /sys/kernel/tracing/events/irq/enable

Para habilitar eventos por evento, usa lo siguiente:

echo 1 > /sys/kernel/tracing/events/sched/sched_wakeup/enable

Si se habilitaron eventos adicionales escribiendo en nodos sysfs, atrace no los restablecerá. Un patrón común para la activación de dispositivos Qualcomm es habilitar los puntos de seguimiento kgsl (GPU) y mdss (canalización de visualización) y, luego, usar atrace o systrace:

adb shell "echo 1 > /sys/kernel/tracing/events/mdss/enable"
adb shell "echo 1 > /sys/kernel/tracing/events/kgsl/enable"
./systrace.py sched freq idle am wm gfx view binder_driver irq workq ss sync -t 10 -b 96000 -o full_trace.html

También puedes usar ftrace sin atrace o systrace, lo que es útil cuando deseas obtener registros solo del kernel (o si te tomaste el tiempo de escribir la propiedad de registro en modo de usuario de forma manual). Para ejecutar solo ftrace, haz lo siguiente:

  1. Establece el tamaño del búfer en un valor lo suficientemente grande para tu seguimiento:
    echo 96000 > /sys/kernel/tracing/buffer_size_kb
    
  2. Habilita el seguimiento:
    echo 1 > /sys/kernel/tracing/tracing_on
    
  3. Ejecuta la prueba y, luego, inhabilita el seguimiento:
    echo 0 > /sys/kernel/tracing/tracing_on
    
  4. Volca el seguimiento:
    cat /sys/kernel/tracing/trace > /data/local/tmp/trace_output
    

trace_output proporciona el seguimiento en formato de texto. Para visualizarlo con Catapult, obtén el repositorio de Catapult de GitHub y ejecuta trace2html:

catapult/tracing/bin/trace2html ~/path/to/trace_file

De forma predeterminada, esto escribe trace_file.html en el mismo directorio.

Correlaciona eventos

A menudo, es útil observar la visualización de Catapult y el registro de ftrace simultáneamente. Por ejemplo, Catapult no visualiza algunos eventos de ftrace (en especial, los específicos del proveedor). Sin embargo, las marcas de tiempo de Catapult son relativas al primer evento del seguimiento o a una marca de tiempo específica que volcó atrace, mientras que las marcas de tiempo sin procesar de ftrace se basan en una fuente de reloj absoluta en particular en el kernel de Linux.

Para encontrar un evento ftrace determinado a partir de un evento de Catapult, haz lo siguiente:

  1. Abre el registro ftrace sin procesar. Los seguimientos en versiones recientes de systrace se comprimen de forma predeterminada:
    • Si capturaste tu systrace con --no-compress, este se encuentra en el archivo HTML, en la sección que comienza con BEGIN TRACE.
    • De lo contrario, ejecuta html2trace desde el árbol de Catapult (tracing/bin/html2trace) para descomprimir el registro.
  2. Busca la marca de tiempo relativa en la visualización de Catapult.
  3. Busca una línea al comienzo del seguimiento que contenga tracing_mark_sync. Debería ser similar a lo siguiente:
    <5134>-5134  (-----) [003] ...1    68.104349: tracing_mark_write: trace_event_clock_sync: parent_ts=68.104286
    

    Si esta línea no existe (o si usaste ftrace sin atrace), los tiempos serán relativos al primer evento del registro de ftrace.
    1. Agrega la marca de tiempo relativa (en milisegundos) al valor en parent_ts (en segundos).
    2. Busca la marca de tiempo nueva.

Estos pasos deberían llevarte al evento (o al menos muy cerca de él).

Usa ftrace dinámico

Cuando systrace y ftrace estándar no son suficientes, hay un último recurso disponible: ftrace dinámico. La ftrace dinámica implica la reescritura del código del kernel después del inicio y, como resultado, no está disponible en los kernels de producción por motivos de seguridad. Sin embargo, cada error de rendimiento difícil en 2015 y 2016 se debió, en última instancia, a la raíz con ftrace dinámico. Es especialmente útil para depurar suspensiones ininterrumpidas, ya que puedes obtener un seguimiento de pila en el kernel cada vez que presionas la función que activa la suspensión ininterrumpida. También puedes depurar secciones con interrupciones y preempciones inhabilitadas, lo que puede ser muy útil para probar problemas.

Para activar ftrace dinámico, edita el archivo defconfig del kernel:

  1. Quita CONFIG_STRICT_MEMORY_RWX (si está presente). Si tienes la versión 3.18 o una posterior y arm64, no está allí.
  2. Agrega lo siguiente: CONFIG_DYNAMIC_FTRACE=y, CONFIG_FUNCTION_TRACER=y, CONFIG_IRQSOFF_TRACER=y, CONFIG_FUNCTION_PROFILER=y y CONFIG_PREEMPT_TRACER=y.
  3. Vuelve a compilar y, luego, inicia el kernel nuevo.
  4. Ejecuta el siguiente comando para verificar si hay generadores de registros disponibles:
    cat /sys/kernel/tracing/available_tracers
    
  5. Confirma que el comando muestre function, irqsoff, preemptoff y preemptirqsoff.
  6. Ejecuta lo siguiente para asegurarte de que ftrace dinámico funcione:
    cat /sys/kernel/tracing/available_filter_functions | grep <a function you care about>
    

Después de completar estos pasos, tendrás disponible el ftrace dinámico, el generador de perfiles de funciones, el generador de perfiles de irqsoff y el generador de perfiles de preemptoff. Te recomendamos que leas la documentación de ftrace sobre estos temas antes de usarlos, ya que son potentes, pero complejos. irqsoff y preemptoff son útiles principalmente para confirmar que los controladores pueden dejar las interrupciones o la preempción desactivadas durante demasiado tiempo.

El generador de perfiles de funciones es la mejor opción para los problemas de rendimiento y, a menudo, se usa para averiguar dónde se llama a una función.


Si los datos del generador de perfiles de funciones no son lo suficientemente específicos, puedes combinar los puntos de seguimiento de ftrace con el generador de perfiles de funciones. Los eventos de ftrace se pueden habilitar de la misma manera que de costumbre y se intercalarán con tu seguimiento. Esto es muy útil si, de vez en cuando, se produce un tiempo de suspensión prolongado e ininterrumpido en una función específica que deseas depurar: establece el filtro ftrace en la función que deseas, habilita los puntos de seguimiento y toma un registro. Puedes analizar el seguimiento resultante con trace2html, encontrar el evento que deseas y, luego, obtener seguimientos de pila cercanos en el seguimiento sin procesar.

Cómo usar lockstat

A veces, ftrace no es suficiente y realmente necesitas depurar lo que parece ser una contención de bloqueo del kernel. Hay otra opción de kernel que vale la pena probar: CONFIG_LOCK_STAT. Esta es una opción de último recurso, ya que es muy difícil que funcione en dispositivos Android, ya que aumenta el tamaño del kernel más allá de lo que la mayoría de los dispositivos pueden manejar.

Sin embargo, lockstat usa la infraestructura de bloqueo de depuración, que es útil para muchas otras apps. Todas las personas que trabajan en la activación de dispositivos deben encontrar la manera de que esa opción funcione en todos los dispositivos, ya que habrá un momento en el que pienses: "Si pudiera activar LOCK_STAT, podría confirmar o refutar que este es el problema en cinco minutos en lugar de cinco días".


Si puedes iniciar un kernel con la opción de configuración, el seguimiento de bloqueo es similar a ftrace:

  1. Habilita el seguimiento:
    echo 1 > /proc/sys/kernel/lock_stat
    
  2. Ejecuta la prueba.
  3. Inhabilita el seguimiento:
    echo 0 > /proc/sys/kernel/lock_stat
    
  4. Vuelve a volcar el seguimiento:
    cat /proc/lock_stat > /data/local/tmp/lock_stat
    

Para obtener ayuda para interpretar el resultado, consulta la documentación de lockstat en <kernel>/Documentation/locking/lockstat.txt.

Usa puntos de seguimiento del proveedor

Primero, usa los puntos de seguimiento upstream, pero, a veces, deberás usar los puntos de seguimiento del proveedor:

  { "gfx",        "Graphics",         ATRACE_TAG_GRAPHICS, {
        { OPT,      "events/mdss/enable" },
        { OPT,      "events/sde/enable" },
        { OPT,      "events/mali_systrace/enable" },
    } },

Los puntos de seguimiento se pueden extender con el servicio de HAL, lo que te permite agregar puntos o categorías de seguimiento específicos del dispositivo. Los puntos de seguimiento se integran en Perfetto, atrace/systrace y la app de registro del sistema integrado en el dispositivo.

Las APIs para implementar puntos de seguimiento o categorías son las siguientes:

  • listCategories()genera (vec<TracingCategory> categories);
  • enableCategories(vec<string> categories) genera (Status status).
  • disableAllCategories() genera (estado de estado);
Para obtener más información, consulta la definición de HAL y la implementación predeterminada en AOSP: