systrace es la herramienta principal para analizar el rendimiento de los dispositivos Android. Sin embargo, en realidad es un wrapper de otras herramientas. Es el wrapper del host alrededor de atrace, el ejecutable del dispositivo que controla el seguimiento del espacio de usuario y configura ftrace, y el mecanismo de seguimiento principal en el kernel de Linux. systrace usa atrace para habilitar el seguimiento y, luego, lee el búfer de ftrace y lo une todo en un visor de HTML independiente. (Si bien los kernels más nuevos admiten el filtro de paquetes extendido de Berkeley (eBPF) de Linux, la siguiente documentación corresponde al kernel 3.18 (sin eFPF), ya que es lo que se usó en Pixel/Pixel XL).
systrace es propiedad de los equipos de Google Android y Google Chrome, y es de código abierto como parte del proyecto Catapult. Además de systrace, Catapult incluye otras utilidades útiles. Por ejemplo, ftrace tiene más funciones que pueden habilitarse directamente con systrace o atrace, y contiene algunas funciones avanzadas que son fundamentales para depurar problemas de rendimiento. (Estas funciones requieren acceso de raíz y, a menudo, un kernel nuevo).
Ejecuta systrace
Cuando depures el jitter en Pixel o Pixel XL, comienza con el siguiente comando:
./systrace.py sched freq idle am wm gfx view sync binder_driver irq workq input -b 96000
Cuando se combina con los puntos de seguimiento adicionales necesarios para la actividad de la canalización de la GPU y la pantalla, te permite realizar un seguimiento desde la entrada del usuario hasta el fotograma que se muestra en la pantalla. Establece el tamaño del búfer en un valor alto para evitar perder eventos (ya que, sin un búfer grande, algunas CPU no contienen eventos después de un punto en el seguimiento).
Cuando revises systrace, ten en cuenta que cada evento se activa por algo en la CPU.
Dado que systrace se compila sobre ftrace y ftrace se ejecuta en la CPU, algo en la CPU debe escribir el búfer de ftrace que registra los cambios de hardware. Esto significa que, si te interesa saber por qué cambió de estado un límite de visualización, puedes ver lo que se estaba ejecutando en la CPU en el punto exacto de su transición (algo que se ejecutaba en la CPU activó ese cambio en el registro). Este conjunto de conceptos es la base del análisis del rendimiento con systrace.
Ejemplo: Marco de trabajo
En este ejemplo, se describe un systrace para una canalización de IU normal. Para seguir con el ejemplo, descarga el archivo ZIP de los seguimientos (que también incluye otros seguimientos a los que se hace referencia en esta sección), descomprímelo y abre el archivo systrace_tutorial.html en tu navegador. Ten en cuenta que este systrace es un archivo grande. A menos que uses systrace en tu trabajo diario, es probable que sea un registro mucho más grande con mucha más información de la que hayas visto en un solo registro.
Para una carga de trabajo periódica y coherente, como TouchLatency, la canalización de la IU contiene lo siguiente:
- EventThread en SurfaceFlinger activa el subproceso de IU de la app, lo que indica que es hora de renderizar un nuevo fotograma.
- La app renderiza un fotograma en el subproceso de IU, RenderThread y hwuiTasks, con recursos de CPU y GPU. Esta es la mayor parte de la capacidad que se invierte en la IU.
- La app envía el fotograma renderizado a SurfaceFlinger con un Binder y, luego, SurfaceFlinger se suspende.
- Un segundo EventThread en SurfaceFlinger activa SurfaceFlinger para activar la composición y mostrar el resultado. Si SurfaceFlinger determina que no hay trabajo por hacer, vuelve a suspenderse.
- SurfaceFlinger controla la composición con Hardware Composer (HWC), Hardware Composer 2 (HWC2) o GL. La composición de HWC/HWC2 es más rápida y consume menos energía, pero tiene limitaciones según el sistema en chip (SoC). Por lo general, este proceso tarda entre 4 y 6 ms, pero puede superponerse con el paso 2 porque las apps para Android siempre tienen un búfer triple. (Si bien las apps siempre tienen un búfer triple, solo puede haber un fotograma pendiente en espera en SurfaceFlinger, lo que hace que parezca idéntico al búfer doble).
- SurfaceFlinger envía el resultado final para mostrarlo con un controlador de proveedor y vuelve a suspenderse, a la espera de que se active EventThread.
Analicemos el fotograma que comienza a los 15,409 ms:
La Figura 1 es un marco normal rodeado de marcos normales, por lo que es un buen punto de partida para comprender cómo funciona la canalización de la IU. La fila del subproceso de IU para TouchLatency incluye diferentes colores en diferentes momentos. Las barras indican diferentes estados del subproceso:
- Gris. Dormir.
- Azul. Ejecutable (podría ejecutarse, pero el programador aún no lo eligió para que se ejecute).
- Verde. Se está ejecutando de forma activa (el programador cree que se está ejecutando).
- Rojo. Sueño ininterrumpido (por lo general, en un bloqueo en el kernel) Puede indicar una carga de E/S. Es muy útil para depurar problemas de rendimiento.
- Naranja. Modo de suspensión ininterrumpida debido a la carga de E/S
Para ver el motivo del estado de suspensión ininterrumpida (disponible en el punto de seguimiento sched_blocked_reason), selecciona la porción de suspensión ininterrumpida roja.
Mientras se ejecuta EventThread, el subproceso de IU para TouchLatency se vuelve ejecutable. Para ver qué lo activó, haz clic en la sección azul.
En la Figura 2, se muestra que el subproceso de IU de TouchLatency se activó con el ID de tarea 6843, que corresponde a EventThread. El subproceso de IU se activa, renderiza un fotograma y lo pone en cola para que SurfaceFlinger lo consuma.
Si la etiqueta binder_driver está habilitada en un registro, puedes seleccionar una transacción de Binder para ver información sobre todos los procesos involucrados en esa transacción.
En la Figura 4, se muestra que, a los 15,423.65 ms, Binder:6832_1 en SurfaceFlinger se vuelve ejecutable debido al ID de tarea 9579, que es RenderThread de TouchLatency. También puedes ver queueBuffer en ambos lados de la transacción de Binder.
Durante el queueBuffer en el lado de SurfaceFlinger, la cantidad de fotogramas pendientes de TouchLatency pasa de 1 a 2.
En la Figura 5, se muestra el almacenamiento en búfer triple, en el que hay dos fotogramas completos y la app está a punto de comenzar a renderizar un tercero. Esto se debe a que ya descartamos algunos fotogramas, por lo que la app mantiene dos fotogramas pendientes en lugar de uno para intentar evitar que se descarten más.
Poco después, un segundo EventThread activa el subproceso principal de SurfaceFlinger para que pueda enviar el fotograma pendiente más antiguo a la pantalla:
SurfaceFlinger primero bloquea el búfer pendiente más antiguo, lo que hace que el recuento de búferes pendientes disminuya de 2 a 1.
Después de activar el búfer, SurfaceFlinger configura la composición y envía el fotograma final a la pantalla. (Algunas de estas secciones están habilitadas como parte del punto de seguimiento mdss, por lo que es posible que no se incluyan en tu SoC).
A continuación, mdss_fb0 se activa en la CPU 0. mdss_fb0 es el subproceso del kernel de la canalización de la pantalla para enviar un fotograma renderizado a la pantalla.
Podemos ver mdss_fb0 como su propia fila en el seguimiento (desplázate hacia abajo para verla).
mdss_fb0 se activa, se ejecuta brevemente, entra en un estado de suspensión ininterrumpida y, luego, se vuelve a activar.
Ejemplo: Marco que no funciona
En este ejemplo, se describe un systrace que se usa para depurar el jitter de Pixel o Pixel XL. Para seguir el ejemplo, descarga el archivo ZIP de los seguimientos (que incluye otros seguimientos a los que se hace referencia en esta sección), descomprímelo y abre el archivo systrace_tutorial.html en tu navegador.
Cuando abras el systrace, verás algo como lo siguiente:
Cuando busques bloqueos, revisa la fila FrameMissed en SurfaceFlinger.
FrameMissed es una mejora de la calidad de vida que proporciona HWC2. Cuando veas systrace para otros dispositivos, es posible que la fila FrameMissed no esté presente si el dispositivo no usa HWC2. En cualquier caso, FrameMissed se correlaciona con que SurfaceFlinger no tenga uno de sus tiempos de ejecución extremadamente regulares y un recuento de búfer pendiente sin cambios para la app (com.prefabulated.touchlatency) en un vsync.
En la Figura 11, se muestra un fotograma perdido en 15598.29 ms. SurfaceFlinger se activó brevemente en el intervalo de vsync y volvió a dormir sin hacer ningún trabajo, lo que significa que SurfaceFlinger determinó que no valía la pena intentar enviar un fotograma a la pantalla nuevamente. ¿Por qué?
Para comprender cómo se produjo la falla de la canalización para este fotograma, primero revisa el ejemplo de fotograma de trabajo anterior para ver cómo aparece una canalización normal de la IU en systrace. Cuando esté todo listo, vuelve al fotograma perdido y trabaja hacia atrás. Observa que SurfaceFlinger se activa y se pone a dormir de inmediato. Cuando se ve la cantidad de fotogramas pendientes de TouchLatency, hay dos fotogramas (una buena pista para ayudar a descubrir qué sucede).
Como tenemos marcos en SurfaceFlinger, no es un problema de la app. Además, SurfaceFlinger se activa en el momento correcto, por lo que no es un problema de SurfaceFlinger. Si SurfaceFlinger y la app se ven normales, es probable que sea un problema de controlador.
Debido a que los puntos de seguimiento mdss y sync están habilitados, podemos obtener información sobre los cierres (compartidos entre el controlador de pantalla y SurfaceFlinger) que controlan cuándo se envían fotogramas a la pantalla.
Estos límites se enumeran en mdss_fb0_retire, que indica cuándo hay un marco en la pantalla. Estos límites se proporcionan como parte de la categoría de seguimiento sync. Los bloqueos que corresponden a eventos particulares en SurfaceFlinger dependen de tu SOC y de la pila de controladores, por lo que debes trabajar con tu proveedor de SOC para comprender el significado de las categorías de bloqueo en tus seguimientos.
En la Figura 13, se muestra un fotograma que se mostró durante 33 ms, no 16.7 ms como se esperaba. A mitad de esa porción, se debería haber reemplazado ese fotograma por uno nuevo, pero no fue así. Mira el fotograma anterior y busca algo.
En la Figura 14, se muestran 14.482 ms por fotograma. El segmento de dos fotogramas rotos fue de 33.6 ms, que es aproximadamente lo que esperaríamos para dos fotogramas (renderizamos a 60 Hz, 16.7 ms por fotograma, que es cercano). Sin embargo, 14.482 ms no está cerca de 16.7 ms, lo que sugiere que hay un problema grave con el embudo de visualización.
Investiga exactamente dónde termina esa cerca para determinar qué la controla.
Una lista de tareas en cola contiene __vsync_retire_work_handler, que se ejecuta cuando cambia la cerca. Si observas la fuente del kernel, puedes ver que forma parte del controlador de pantalla. Parece estar en la ruta crítica para la canalización de visualización, por lo que debe ejecutarse lo más rápido posible. Se puede ejecutar durante unos 70 μs (no es una demora de programación larga), pero es una lista de tareas en cola y es posible que no se programe con precisión.
Comprueba el fotograma anterior para determinar si eso contribuyó. A veces, el jitter puede acumularse con el tiempo y, en última instancia, provocar que se pierda una fecha límite.
La línea ejecutable en el kworker no es visible porque el visor la vuelve blanquecina cuando se selecciona, pero las estadísticas cuentan la historia: 2.3 ms de retraso del programador para una parte de la ruta crítica de la canalización de visualización es malo.
Antes de continuar, corrige la demora que se produce cuando se mueve esta parte de la ruta crítica de la canalización de visualización de un grupo de trabajo (que se ejecuta como un subproceso de SCHED_OTHER CFS) a un subproceso SCHED_FIFO dedicado. Esta función necesita garantías de tiempo que las filas de trabajo no pueden proporcionar (ni están diseñadas para proporcionar).
¿Es esta la razón del bloqueo? Es difícil decirlo con certeza. Fuera de los casos fáciles de diagnosticar, como la contención de bloqueo del kernel que hace que los subprocesos críticos de la pantalla entren en suspensión, los seguimientos suelen no especificar el problema. ¿Es posible que este jitter haya sido la causa de la pérdida de fotogramas? Por supuesto. Los tiempos de valla deben ser de 16.7 ms, pero no están cerca de eso en los fotogramas que preceden al fotograma descartado. Dado lo estrechamente acoplado que está el embudo de renderización, es posible que el jitter alrededor de los tiempos de valla haya provocado una disminución de fotogramas.
En este ejemplo, la solución consistió en convertir __vsync_retire_work_handler de un grupo de trabajo a un subproceso k dedicado. Esto generó mejoras notables en el jitter y redujo el bloqueo en la prueba de la bola rebotante. Los seguimientos posteriores muestran tiempos de valla que rondan los 16.7 ms.