systrace es la herramienta principal para analizar el rendimiento del dispositivo Android. Sin embargo, en realidad es una envoltura para otras herramientas. Es el contenedor del lado del host alrededor de atrace , el ejecutable del lado 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, luego lee el búfer ftrace y lo envuelve todo en un visor HTML autónomo. (Si bien los kernels más nuevos son compatibles con el filtro de paquetes Berkeley mejorado de Linux (eBPF), la siguiente documentación pertenece al kernel 3.18 (sin eFPF), ya que eso 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 de las que systrace o atrace pueden habilitar directamente y contiene algunas funciones avanzadas que son fundamentales para depurar problemas de rendimiento. (Estas funciones requieren acceso de root y, a menudo, un nuevo kernel).
Ejecutando la ruta del sistema
Al depurar la fluctuación en Pixel/Pixel XL, comience 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 GPU y la actividad de la canalización de visualización, esto le brinda la capacidad de rastrear desde la entrada del usuario hasta el fotograma que se muestra en la pantalla. Establezca el tamaño del búfer en algo grande para evitar perder eventos (porque sin un búfer grande algunas CPU no contienen eventos después de algún punto en el seguimiento).
Al revisar systrace, tenga en cuenta que cada evento es desencadenado por algo en la CPU .
Debido a que systrace está construido sobre ftrace y ftrace se ejecuta en la CPU, algo en la CPU debe escribir el búfer ftrace que registra los cambios de hardware. Esto significa que si tiene curiosidad acerca de por qué una barrera de visualización cambió de estado, puede ver qué se estaba ejecutando en la CPU en el punto exacto de su transición (algo que se ejecuta en la CPU desencadenó ese cambio en el registro). Este concepto es la base para analizar el rendimiento utilizando systrace.
Ejemplo: marco de trabajo
Este ejemplo describe una ruta del sistema para una canalización de interfaz de usuario normal. 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 systrace_tutorial.html en su navegador. Tenga en cuenta que esta ruta del sistema es un archivo grande; A menos que utilice systrace en su trabajo diario, es probable que se trate de un rastro mucho más grande con mucha más información de la que jamás haya visto en un solo rastro.
Para una carga de trabajo periódica y coherente, como TouchLatency, la canalización de la interfaz de usuario contiene lo siguiente:
- EventThread en SurfaceFlinger activa el subproceso de la interfaz de usuario de la aplicación, lo que indica que es hora de representar un nuevo fotograma.
- La aplicación representa un marco en el subproceso de la interfaz de usuario, RenderThread y hwuiTasks, utilizando recursos de CPU y GPU. Esta es la mayor parte de la capacidad gastada en la interfaz de usuario.
- La aplicación envía el fotograma renderizado a SurfaceFlinger mediante una carpeta y luego SurfaceFlinger entra en modo de suspensión.
- Un segundo EventThread en SurfaceFlinger activa SurfaceFlinger para activar la composición y mostrar la salida. Si SurfaceFlinger determina que no hay trabajo que hacer, vuelve a dormir.
- SurfaceFlinger maneja la composición usando Hardware Composer (HWC)/Hardware Composer 2 (HWC2) o GL. La composición HWC/HWC2 es más rápida y de menor consumo, pero tiene limitaciones según el sistema en un chip (SoC). Esto suele tardar entre 4 y 6 ms, pero puede superponerse con el paso 2 porque las aplicaciones de Android siempre tienen un buffer triple. (Si bien las aplicaciones siempre tienen un almacenamiento en búfer triple, es posible que solo haya un fotograma pendiente esperando en SurfaceFlinger, lo que hace que parezca idéntico al almacenamiento en búfer doble).
- SurfaceFlinger envía el resultado final para mostrarlo con un controlador de proveedor y vuelve a dormir, esperando que EventThread se active.
Repasemos el cuadro comenzando en 15409 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 interfaz de usuario. La fila del hilo de la interfaz de usuario para TouchLatency incluye diferentes colores en diferentes momentos. Las barras indican diferentes estados del hilo:
- Gris . Durmiendo.
- Azul. Ejecutable (podría ejecutarse, pero el programador aún no lo ha elegido para ejecutarse).
- Verde. Ejecutándose activamente (el programador cree que se está ejecutando).
- Rojo. Sueño ininterrumpido (generalmente durmiendo en un candado en el kernel). Puede ser indicativo de la carga de E/S. Extremadamente útil para depurar problemas de rendimiento.
- Naranja. Suspensión ininterrumpida debido a la carga de E/S.
Para ver el motivo del sueño ininterrumpido (disponible en el punto de seguimiento sched_blocked_reason ), seleccione el segmento rojo del sueño ininterrumpido.
Mientras se ejecuta EventThread, el hilo de la interfaz de usuario para TouchLatency se vuelve ejecutable. Para ver qué lo despertó, haga clic en la sección azul.
La Figura 2 muestra que el hilo de la interfaz de usuario TouchLatency fue activado por el tid 6843, que corresponde a EventThread. El subproceso de la interfaz de usuario se activa, representa un fotograma y lo pone en cola para que SurfaceFlinger lo consuma.
Si la etiqueta binder_driver está habilitada en un seguimiento, puede seleccionar una transacción de binder para ver información sobre todos los procesos involucrados en esa transacción.
La Figura 4 muestra que, a 15.423,65 ms, Binder:6832_1 en SurfaceFlinger se vuelve ejecutable debido al tid 9579, que es RenderThread de TouchLatency. También puede ver queueBuffer en ambos lados de la transacción del cuaderno.
Durante el queueBuffer en el lado de SurfaceFlinger, el número de fotogramas pendientes de TouchLatency pasa de 1 a 2.
La Figura 5 muestra el almacenamiento en búfer triple, donde hay dos fotogramas completos y la aplicación está a punto de comenzar a renderizar un tercero. Esto se debe a que ya hemos eliminado algunos fotogramas, por lo que la aplicación mantiene dos fotogramas pendientes en lugar de uno para intentar evitar más fotogramas eliminados.
Poco después, el hilo principal de SurfaceFlinger se activa con un segundo EventThread para que pueda mostrar el fotograma pendiente más antiguo en la pantalla:
SurfaceFlinger primero bloquea el búfer pendiente más antiguo, lo que hace que el recuento del búfer pendiente disminuya de 2 a 1.
Después de bloquear 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 estén incluidas en su SoC).
A continuación, mdss_fb0 se activa en la CPU 0. mdss_fb0 es el subproceso del núcleo de la canalización de visualización para generar un fotograma renderizado en la pantalla. Podemos ver mdss_fb0 como su propia fila en el seguimiento (desplácese hacia abajo para ver).
mdss_fb0 se activa, se ejecuta brevemente, entra en suspensión ininterrumpida y luego se activa nuevamente.
Ejemplo: marco que no funciona
Este ejemplo describe una ruta del sistema utilizada para depurar la fluctuación de Pixel/Pixel XL. Para seguir el ejemplo, descargue el archivo zip de seguimientos (que incluye otros seguimientos a los que se hace referencia en esta sección), descomprima el archivo y abra el archivo systrace_tutorial.html en su navegador.
Cuando abras la ruta del sistema, verás algo como esto:
Cuando busque jank, verifique la fila FrameMissed en SurfaceFlinger. FrameMissed es una mejora en la calidad de vida proporcionada por HWC2. Al visualizar 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 a SurfaceFlinger le falta uno de sus tiempos de ejecución extremadamente regulares y un recuento de búfer pendiente sin cambios para la aplicación ( com.prefabulated.touchlatency ) en una vsync.
La Figura 11 muestra un cuadro perdido a 15598,29 ms. SurfaceFlinger se despertó brevemente en el intervalo 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 cuadro a la pantalla nuevamente. ¿Por qué?
Para comprender cómo se dividió la canalización para este marco, primero revise el ejemplo del marco de trabajo anterior para ver cómo aparece una canalización de UI normal en systrace. Cuando esté listo, regrese al cuadro perdido y trabaje hacia atrás. Observe que SurfaceFlinger se despierta y se duerme inmediatamente. Al ver la cantidad de fotogramas pendientes de TouchLatency, hay dos fotogramas (una buena pista para ayudar a descubrir qué está pasando).
Como tenemos marcos en SurfaceFlinger, no es un problema de la aplicación. Además, SurfaceFlinger se activa en el momento correcto, por lo que no es un problema de SurfaceFlinger. Si SurfaceFlinger y la aplicación parecen normales, probablemente se trate de un problema con el controlador.
Debido a que mdss y los puntos de seguimiento sync están habilitados, podemos obtener información sobre las barreras (compartidas entre el controlador de pantalla y SurfaceFlinger) que controlan cuándo se envían los fotogramas a la pantalla. Estas vallas se enumeran en mdss_fb0_retire , que indica cuándo hay un marco en la pantalla. Estas barreras se proporcionan como parte de la categoría de seguimiento sync . Las barreras que corresponden a eventos particulares en SurfaceFlinger dependen de su SOC y de su pila de controladores, así que trabaje con su proveedor de SOC para comprender el significado de las categorías de barreras en sus trazados.
La Figura 13 muestra un fotograma que se mostró durante 33 ms, no 16,7 ms como se esperaba. A mitad de ese corte, ese marco debería haber sido reemplazado por uno nuevo, pero no fue así. Vea el fotograma anterior y busque cualquier cosa.
La Figura 14 muestra 14,482 ms por trama. El segmento roto de dos fotogramas fue de 33,6 ms, que es aproximadamente lo que esperaríamos para dos fotogramas (renderizamos a 60 Hz, 16,7 ms por fotograma, lo cual está cerca). Pero 14,482 ms no se acerca en absoluto a 16,7 ms, lo que sugiere que algo anda muy mal con el tubo de visualización.
Investiga exactamente dónde termina esa valla para determinar qué la controla.
Una cola de trabajo contiene __vsync_retire_work_handler , que se ejecuta cuando cambia la valla. Al revisar la fuente del kernel, puede ver que es parte del controlador de pantalla. Parece estar en la ruta crítica para el proceso de visualización, por lo que debe ejecutarse lo más rápido posible. Se puede ejecutar durante aproximadamente 70 us (no es un retraso de programación largo), pero es una cola de trabajo y es posible que no se programe con precisión.
Verifique el cuadro anterior para determinar si eso contribuyó; A veces, la inquietud puede acumularse con el tiempo y, finalmente, provocar el incumplimiento de una fecha límite.
La línea ejecutable en kworker no es visible porque el espectador la vuelve blanca cuando se selecciona, pero las estadísticas cuentan la historia: 2,3 ms de retraso del programador para parte de la ruta crítica del canal de visualización es malo . Antes de continuar, solucione el retraso que se produce al mover esta parte de la ruta crítica del canal de visualización desde una cola de trabajo (que se ejecuta como un subproceso SCHED_OTHER CFS) a un subproceso SCHED_FIFO dedicado. Esta función necesita garantías de sincronización que las colas de trabajo no pueden (y no están destinadas a) proporcionar.
¿Es este el motivo del jank? Es difícil decirlo de manera concluyente. Fuera de los casos fáciles de diagnosticar, como la contención de bloqueo del kernel que provoca que los subprocesos críticos para la visualización entren en suspensión, los seguimientos generalmente no especifican el problema. ¿Podría esta inquietud haber sido la causa de la caída del fotograma? Absolutamente. Los tiempos de valla deberían ser de 16,7 ms, pero no se acercan en absoluto a eso en los fotogramas previos al fotograma eliminado. Dado lo estrechamente acoplado que está el canal de visualización, es posible que la fluctuación alrededor de los tiempos de la valla haya provocado una caída del fotograma.
En este ejemplo, la solución implicó convertir __vsync_retire_work_handler de una cola de trabajo a un kthread dedicado. Esto dio como resultado mejoras notables en la inquietud y redujo los bloqueos en la prueba de rebote de la pelota. Los seguimientos posteriores muestran tiempos de valla que se sitúan muy cerca de 16,7 ms.