usando ftrace

ftrace es una herramienta de depuración para comprender lo que sucede dentro del kernel de Linux. Las siguientes secciones 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, consulte la documentación de ftrace en <kernel tree>/Documentation/trace/ftrace.txt .

Capturando 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 estableciendo una propiedad ( debug.atrace.tags.enableflags ).
  • Habilita la funcionalidad ftrace deseada escribiendo en los nodos ftrace sysfs apropiados. Sin embargo, como ftrace admite más funciones, puede configurar algunos nodos sysfs usted mismo y luego usar atrace.

Con la excepción del seguimiento en el momento del arranque, utilice 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 aparte de mirar el encabezado apropiado (que podría cambiar entre versiones de Android).

Habilitación de eventos ftrace

Los nodos ftrace sysfs están 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, utilice:

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

Para habilitar eventos por evento, use:

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

Si se han habilitado eventos adicionales escribiendo en nodos sysfs, atrace no los restablecerá. Un patrón común para activar dispositivos Qualcomm es habilitar los puntos de seguimiento kgsl (GPU) y mdss (display pipeline) 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 puede usar ftrace sin atrace o systrace, lo cual es útil cuando desea realizar seguimientos solo del kernel (o si se ha tomado el tiempo de escribir a mano la propiedad de seguimiento en modo de usuario). Para ejecutar simplemente ftrace:

  1. Establezca el tamaño del búfer en un valor lo suficientemente grande para su seguimiento:
    echo 96000 > /sys/kernel/tracing/buffer_size_kb
  2. Habilitar seguimiento:
    echo 1 > /sys/kernel/tracing/tracing_on
  3. Ejecute su prueba, luego deshabilite el seguimiento:
    echo 0 > /sys/kernel/tracing/tracing_on
  4. Volcar el rastro:
    cat /sys/kernel/tracing/trace > /data/local/tmp/trace_output

trace_output proporciona el seguimiento en forma de texto. Para visualizarlo usando Catapult, obtenga el repositorio de Catapult de GitHub y ejecute trace2html:

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

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

Eventos correlacionados

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

Para encontrar un evento ftrace determinado a partir de un evento Catapult:

  1. Abra el registro ftrace sin procesar. Los seguimientos en versiones recientes de systrace están comprimidos de forma predeterminada:
    • Si capturó su systrace con --no-compress , esto está en el archivo html en la sección que comienza con BEGIN TRACE.
    • De lo contrario, ejecute html2trace desde el árbol Catapult ( tracing/bin/html2trace ) para descomprimir el seguimiento.
  2. Encuentre la marca de tiempo relativa en la visualización de Catapult.
  3. Busque una línea al comienzo del seguimiento que contenga tracing_mark_sync . Debería verse así:
    <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 usó ftrace sin atrace), los tiempos serán relativos desde el primer evento en el registro de ftrace.
    1. Agregue la marca de tiempo relativa (en milisegundos) al valor en parent_ts (en segundos).
    2. Busque la nueva marca de tiempo.

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

Usando ftrace dinámico

Cuando systrace y ftrace estándar son insuficientes, hay un último recurso disponible: ftrace dinámico . Dynamic ftrace implica la reescritura del código del kernel después del arranque y, como resultado, no está disponible en los kernels de producción por razones de seguridad. Sin embargo, todos los errores de rendimiento difíciles en 2015 y 2016 fueron causados ​​en última instancia por el uso de ftrace dinámico. Es especialmente poderoso para depurar suspensiones ininterrumpidas porque puede obtener un seguimiento de la pila en el kernel cada vez que activa la función que activa la suspensión ininterrumpida. También puede depurar secciones con interrupciones y apropiaciones deshabilitadas, lo que puede resultar muy útil para demostrar problemas.

Para activar ftrace dinámico, edite la configuración defconfig de su kernel:

  1. Elimine CONFIG_STRICT_MEMORY_RWX (si está presente). Si tienes la versión 3.18 o posterior y arm64, no está allí.
  2. Agregue lo siguiente: CONFIG_DYNAMIC_FTRACE=y, CONFIG_FUNCTION_TRACER=y, CONFIG_IRQSOFF_TRACER=y, CONFIG_FUNCTION_PROFILER=y y CONFIG_PREEMPT_TRACER=y
  3. Reconstruya e inicie el nuevo kernel.
  4. Ejecute lo siguiente para comprobar si hay trazadores disponibles:
    cat /sys/kernel/tracing/available_tracers
  5. Confirme que el comando devuelve function , irqsoff , preemptoff y preemptirqsoff .
  6. Ejecute lo siguiente para asegurarse de que el ftrace dinámico esté funcionando:
    cat /sys/kernel/tracing/available_filter_functions | grep <a function you care about>

Después de completar estos pasos, tendrá disponibles el perfilador dinámico, el perfilador de funciones, el perfilador irqsoff y el perfilador preemptoff. Recomendamos encarecidamente leer 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 conductores pueden estar dejando las interrupciones o la preferencia desactivadas durante demasiado tiempo.

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

En este problema, usar un Pixel XL para tomar una foto HDR+ y luego girar inmediatamente el visor provocaba bloqueos en todo momento. Usamos el generador de perfiles de funciones para depurar el problema en menos de una hora. Para seguir el ejemplo, descargue el archivo zip de seguimientos (que también incluye otros seguimientos a los que se hace referencia en esta sección), descomprima el archivo y abra el archivo trace_30898724.html en su navegador.

El seguimiento muestra varios subprocesos en el proceso del servidor de cámaras bloqueados en suspensión ininterrumpida en ion_client_destroy . Es una función costosa, pero debería llamarse con muy poca frecuencia porque los clientes de iones deben abarcar muchas asignaciones. Inicialmente, la culpa recayó en el código Hexagon en Halide, que de hecho fue uno de los culpables (creó un nuevo cliente para cada asignación de iones y destruyó ese cliente cuando se liberó la asignación, lo cual era demasiado costoso). Pasar a un único cliente de iones para todas las asignaciones de Hexagon mejoró la situación, pero el problema no se solucionó.

En este punto necesitamos saber quién llama ion_client_destroy , así que es hora de usar la función generador de perfiles:

  1. Como a veces el compilador cambia el nombre de las funciones, confirme ion_client_destroy esté ahí usando:
    cat /sys/kernel/tracing/available_filter_functions | grep ion_client_destroy
  2. Después de confirmar que está allí, utilícelo como filtro ftrace:
    echo ion_client_destroy > /sys/kernel/tracing/set_ftrace_filter
  3. Active el generador de perfiles de funciones:
    echo function > /sys/kernel/tracing/current_tracer
  4. Active los seguimientos de pila cada vez que se llame a una función de filtro:
    echo func_stack_trace > /sys/kernel/tracing/trace_options
  5. Aumentar el tamaño del buffer:
    echo 64000 > /sys/kernel/tracing/buffer_size_kb
  6. Activar seguimiento:
    echo 1 > /sys/kernel/tracing/trace_on
  7. Ejecute la prueba y obtenga el seguimiento:
    cat /sys/kernel/tracing/trace > /data/local/tmp/trace
  8. Vea el seguimiento para ver muchísimos seguimientos de pila:
        cameraserver-643   [003] ...1    94.192991: ion_client_destroy <-ion_release
    cameraserver-643   [003] ...1    94.192997: <stack trace>
 => ftrace_ops_no_ops
 => ftrace_graph_call
 => ion_client_destroy
 => ion_release
 => __fput
 => ____fput
 => task_work_run
 => do_notify_resume
 => work_pending

Según la inspección del controlador ion, podemos ver que ion_client_destroy está siendo enviado como spam por una función del espacio de usuario que cierra un fd en /dev/ion , no por un controlador de kernel aleatorio. Al buscar \"/dev/ion\" en el código base de Android, encontramos varios controladores de proveedores que hacen lo mismo que el controlador Hexagon y abren/cierran /dev/ion (creando y destruyendo un nuevo cliente ion) cada vez que necesitan un nueva asignación de iones. Cambiarlos para usar un único cliente ion durante la vida útil del proceso solucionó el error.

Si los datos del generador de perfiles de funciones no son lo suficientemente específicos, puede combinar los puntos de seguimiento de ftrace con el generador de perfiles de funciones. Los eventos ftrace se pueden habilitar exactamente de la misma manera que de costumbre y se entrelazarán con su seguimiento. Esto es excelente si ocasionalmente hay una suspensión prolongada e ininterrumpida en una función específica que desea depurar: configure el filtro ftrace en la función que desea, habilite los puntos de seguimiento, realice un seguimiento. Puede analizar el seguimiento resultante con trace2html , encontrar el evento que desea y luego obtener seguimientos de pila cercanos en el seguimiento sin formato.

Usando lockstat

A veces, ftrace no es suficiente y realmente es necesario depurar lo que parece ser una contención de bloqueo del kernel. Hay una opción más del kernel que vale la pena probar: CONFIG_LOCK_STAT . Este es un último recurso, ya que es extremadamente difícil empezar a trabajar en dispositivos Android porque infla el tamaño del kernel más allá de lo que la mayoría de los dispositivos pueden manejar.

Sin embargo, lockstat utiliza la infraestructura de bloqueo de depuración, que es útil para muchas otras aplicaciones. Todos los que trabajan en la recuperación de dispositivos deberían encontrar alguna manera de hacer que esa opción funcione en todos los dispositivos porque habrá un momento en el que pensarás "Si tan solo pudiera activar LOCK_STAT , podría confirmar o refutar esto como el problema en cinco minutos en lugar de cinco días."

En este problema, el subproceso SCHED_FIFO se detuvo cuando todos los núcleos estaban en carga máxima con subprocesos que no eran SCHED_FIFO. Teníamos rastros que mostraban una importante contención de bloqueo en un fd en aplicaciones de realidad virtual, pero no pudimos identificar fácilmente el fd en uso. Para seguir el ejemplo, descargue el archivo zip de seguimientos (que también incluye otros seguimientos a los que se hace referencia en esta sección), descomprima el archivo y abra el archivo trace_30905547.html en su navegador.

Nuestra hipótesis fue que ftrace en sí era la fuente de la contención de bloqueo, cuando un subproceso de baja prioridad comenzaría a escribir en la tubería ftrace y luego sería reemplazado antes de que pudiera liberar el bloqueo. Este es el peor de los casos que se vio exacerbado por una combinación de subprocesos de prioridad extremadamente baja que escriben en el marcador ftrace junto con algunos subprocesos de mayor prioridad que giran en las CPU para simular un dispositivo completamente cargado.

Como no pudimos usar ftrace para depurar, hicimos funcionar LOCK_STAT y luego desactivamos todos los demás rastreos desde la aplicación. Los resultados mostraron que la contención del bloqueo en realidad provenía de ftrace porque ninguna de las contiendas apareció en el seguimiento del bloqueo cuando ftrace no se estaba ejecutando.

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

  1. Habilitar seguimiento:
    echo 1 > /proc/sys/kernel/lock_stat
  2. Ejecute su prueba.
  3. Deshabilitar el seguimiento:
    echo 0 > /proc/sys/kernel/lock_stat
  4. Deshazte de tu rastro:
    cat /proc/lock_stat > /data/local/tmp/lock_stat

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

Usar puntos de seguimiento de proveedores

Utilice primero los puntos de seguimiento ascendentes, pero a veces necesitará utilizar 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 son extensibles mediante el servicio HAL, lo que le permite agregar puntos/categorías de seguimiento específicos del dispositivo. Los puntos de seguimiento están integrados con perfetto, atrace/systrace y la aplicación de seguimiento del sistema en el dispositivo.

Las API para implementar puntos de seguimiento/categorías son:

  • listCategories()genera (categorías vec<TracingCategory>);
  • enableCategories(vec<string> categorías) genera (estado de estado);
  • enableAllCategories() genera (estado de estado);
Para obtener más información, consulte la definición de HAL y la implementación predeterminada en AOSP :