Google se compromete a promover la equidad racial para las comunidades negras. Ver cómo.
Se usó la API de Cloud Translation para traducir esta página.
Switch to English

Entendiendo Systrace

systrace es la herramienta principal para analizar el rendimiento del dispositivo Android. Sin embargo, es realmente una envoltura alrededor de otras herramientas. Es el contenedor del lado del host alrededor de atrace , el ejecutable del lado del dispositivo que controla el rastreo del espacio del usuario y configura ftrace , y el mecanismo de rastreo primario en el kernel de Linux. systrace usa atrace para habilitar el rastreo, luego lee el búfer ftrace y lo envuelve todo en un visor HTML autónomo. (Si bien los núcleos más nuevos son compatibles con el filtro de paquetes Berkeley mejorado de Linux (eBPF), la siguiente documentación se refiere al núcleo 3.18 (sin eFPF), ya que eso fue lo que se usó en Pixel / Pixel XL).

systrace es propiedad de los equipos 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 puede habilitar directamente systrace o atrace y contiene algunas funciones avanzadas que son críticas para la depuración de problemas de rendimiento. (Estas características requieren acceso de root y, a menudo, un nuevo núcleo).

Ejecución de systrace

Cuando depure jitter 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 rastreo adicionales necesarios para la GPU y muestra la actividad de la tubería, esto le brinda la capacidad de rastrear desde la entrada del usuario hasta el marco que se muestra en la pantalla. Establezca el tamaño del búfer en algo grande para evitar la pérdida de eventos (porque sin un búfer grande algunas CPU no contienen eventos después de algún punto en la traza).

Al pasar por systrace, tenga en cuenta que cada evento se desencadena 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 valla de visualización cambió de estado, puede ver lo que se estaba ejecutando en la CPU en el punto exacto de su transición (algo que se ejecuta en la CPU activó ese cambio en el registro). Este concepto es la base para analizar el rendimiento utilizando systrace.

Ejemplo: marco de trabajo

Este ejemplo describe un systrace para una tubería de interfaz de usuario normal. Para seguir el ejemplo, descargue el archivo zip de trazas (que también incluye otras trazas a las 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 este systrace es un archivo grande; a menos que use systrace en su trabajo diario, es probable que sea una traza mucho más grande con mucha más información de la que haya visto en una sola traza.

Para una carga de trabajo periódica y consistente, como TouchLatency, la canalización de la interfaz de usuario contiene lo siguiente:

  1. EventThread en SurfaceFlinger activa el hilo de la interfaz de usuario de la aplicación, lo que indica que es hora de renderizar un nuevo marco.
  2. La aplicación presenta un marco en el subproceso de interfaz de usuario, RenderThread y hwuiTasks, utilizando recursos de CPU y GPU. Esta es la mayor parte de la capacidad gastada para la interfaz de usuario.
  3. La aplicación envía el marco renderizado a SurfaceFlinger usando un aglutinante, luego SurfaceFlinger se duerme.
  4. 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.
  5. SurfaceFlinger maneja la composición usando Hardware Composer (HWC) / Hardware Composer 2 (HWC2) o GL. La composición de HWC / HWC2 es más rápida y de menor potencia, pero tiene limitaciones dependiendo del sistema en un chip (SoC). Esto generalmente demora entre 4 y 6 ms, pero puede superponerse con el paso 2 porque las aplicaciones de Android siempre tienen triple búfer. (Si bien las aplicaciones siempre tienen triple búfer, solo puede haber un marco pendiente esperando en SurfaceFlinger, lo que hace que parezca idéntico al doble búfer).
  6. SurfaceFlinger envía la salida final para mostrar con un controlador de proveedor y vuelve a dormir, esperando la activación de EventThread.

Veamos el marco comenzando en 15409 ms:

Canalización de interfaz de usuario normal con EventThread en ejecución
Figura 1. Canalización de la interfaz de usuario normal, EventThread en ejecución

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 de subprocesos de la interfaz de usuario para TouchLatency incluye diferentes colores en diferentes momentos. Las barras denotan diferentes estados para el hilo:

  • Gris Dormido.
  • Azul. Ejecutable (podría ejecutarse, pero el programador aún no lo ha elegido para ejecutarse).
  • Verde. Activamente en ejecución (el planificador cree que se está ejecutando).
  • Rojo. Sueño ininterrumpible (generalmente durmiendo en una cerradura en el núcleo). Puede ser indicativo de 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 de la suspensión ininterrumpida (disponible desde el punto de sched_blocked_reason sched_blocked_reason), seleccione la división roja de suspensión ininterrumpible.

Mientras se ejecuta EventThread, el subproceso de interfaz de usuario para TouchLatency se vuelve ejecutable. Para ver qué lo despertó, haga clic en la sección azul.

Hilo de UI para TouchLatency
Figura 2. Subproceso de interfaz de usuario para TouchLatency

La Figura 2 muestra que el hilo de la interfaz de usuario TouchLatency fue despertado por tid 6843, que corresponde a EventThread. El subproceso de la interfaz de usuario se activa, renderiza un marco y lo coloca en cola para que SurfaceFlinger lo consuma.

El subproceso de la interfaz de usuario se activa, renderiza un marco y lo atrapa para que SurfaceFlinger lo consuma
Figura 3. El subproceso de la interfaz de usuario se activa, renderiza un marco y lo pone en cola para que SurfaceFlinger lo consuma

Si la etiqueta binder_driver está habilitada en una traza, puede seleccionar una transacción de carpeta para ver información sobre todos los procesos involucrados en esa transacción.

Figura 4. Transacción de carpeta

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 de la carpeta.

Durante el queueBuffer en el lado de SurfaceFlinger, el número de fotogramas pendientes de TouchLatency va de 1 a 2.

Los cuadros pendientes van del 1 al 2
Figura 5. Los cuadros pendientes van del 1 al 2

La Figura 5 muestra el triple almacenamiento en búfer, donde hay dos cuadros completos y la aplicación está a punto de comenzar a generar 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 tratar de evitar que se eliminen más.

Poco después, el subproceso principal de SurfaceFlinger se despierta con un segundo EventThread para que pueda mostrar el marco pendiente anterior en la pantalla:

El hilo principal de SurfaceFlinger es despertado por un segundo evento
Figura 6. El hilo principal de SurfaceFlinger es despertado por un segundo EventThread

SurfaceFlinger primero bloquea el búfer pendiente anterior, lo que hace que el recuento del búfer pendiente disminuya de 2 a 1.

SurfaceFlinger se engancha primero en el búfer pendiente anterior
Figura 7. SurfaceFlinger se engancha primero en el búfer pendiente anterior

Después de bloquear el búfer, SurfaceFlinger configura la composición y envía el cuadro final a la pantalla. (Algunas de estas secciones están habilitadas como parte del punto de mdss mdss, por lo que es posible que no se incluyan en su SoC).

SurfaceFlinger configura la composición y envía el marco final
Figura 8. SurfaceFlinger configura la composición y envía el marco final

A continuación, mdss_fb0 se mdss_fb0 en la CPU 0. mdss_fb0 es el subproceso del núcleo de la canalización de visualización para generar un marco renderizado en la pantalla. Podemos ver mdss_fb0 como su propia fila en la traza (desplácese hacia abajo para ver).

mdss_fb0 se activa en la CPU 0
Figura 9. mdss_fb0 se activa en la CPU 0

mdss_fb0 despierta, corre brevemente, entra en suspensión ininterrumpida y luego se despierta nuevamente.

Ejemplo: marco no operativo

Este ejemplo describe un systrace utilizado para depurar la fluctuación de fase de Pixel / Pixel XL. Para seguir el ejemplo, descargue el archivo zip de los rastros (que incluye otros rastros mencionados en esta sección), descomprima el archivo y abra el archivo systrace_tutorial.html en su navegador.

Cuando abras el sistema, verás algo como esto:

TouchLatency ejecutándose en Pixel XL con la mayoría de las opciones habilitadas
Figura 10. TouchLatency ejecutándose en Pixel XL (la mayoría de las opciones habilitadas, incluidos los puntos de rastreo mdss y kgsl)

Cuando busque jank, verifique la fila FrameMissed debajo de SurfaceFlinger. FrameMissed es una mejora de la calidad de vida proporcionada por HWC2. Al visualizar systrace para otros dispositivos, la fila FrameMissed puede no estar presente si el dispositivo no usa HWC2. En cualquier caso, FrameMissed está correlacionado con SurfaceFlinger que pierde 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 un vsync.

Correlación de FrameMissed con SurfaceFlinger
Figura 11. Correlación de FrameMissed con SurfaceFlinger

La Figura 11 muestra una trama perdida en 15598.29 & nbps; 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 marco a la pantalla nuevamente. ¿Por qué?

Para comprender cómo se descompuso la tubería para este marco, primero revise el ejemplo de marco de trabajo anterior para ver cómo aparece una tubería de interfaz de usuario normal en systrace. Cuando esté listo, regrese al cuadro perdido y trabaje hacia atrás. Tenga en cuenta que SurfaceFlinger se despierta e inmediatamente se va a dormir. Al ver la cantidad de fotogramas pendientes de TouchLatency, hay dos fotogramas (una buena pista para ayudar a descubrir qué está pasando).

SurfaceFlinger se despierta e inmediatamente se va a dormir
Figura 12. SurfaceFlinger se despierta e inmediatamente se va a dormir

Debido a que tenemos marcos en SurfaceFlinger, no es un problema de aplicación. Además, SurfaceFlinger se está despertando en el momento correcto, por lo que no es un problema de SurfaceFlinger. Si SurfaceFlinger y la aplicación parecen normales, probablemente sea un problema de controlador.

Debido a que los mdss y sync están habilitados, podemos obtener información sobre las cercas (compartidas entre el controlador de pantalla y SurfaceFlinger) que controlan cuándo se envían los marcos a la pantalla. Estas cercas se enumeran en mdss_fb0_retire , que denota cuando hay un marco en la pantalla. Estas cercas se proporcionan como parte de la categoría de seguimiento de sync . Qué cercas corresponden a eventos particulares en SurfaceFlinger depende de su SOC y la pila de controladores, así que trabaje con su proveedor de SOC para comprender el significado de las categorías de cercas en sus trazas.

mdss_fb0_retire vallas
Figura 13. cercas de mdss_fb0_retire

La Figura 13 muestra un cuadro 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í. Ver el cuadro anterior y buscar cualquier cosa.

Marco anterior al marco reventado
Figura 14. Cuadro anterior al cuadro reventado

La figura 14 muestra 14.482 ms por trama. El segmento roto de dos cuadros era de 33,6 ms, que es aproximadamente lo que esperaríamos para dos cuadros (renderizamos a 60 Hz, 16,7 ms por cuadro, que está cerca). Pero 14.482 ms no está cerca de 16.7 ms en absoluto, lo que sugiere que algo está muy mal con la tubería de visualización.

Investigue exactamente dónde termina esa cerca para determinar qué la controla.

Investigar el extremo de la cerca
Figura 15. Investigue el extremo de la cerca

Una cola de trabajo contiene __vsync_retire_work_handler , que se ejecuta cuando cambia el cercado. Mirando a través de la fuente del núcleo, puede ver que es 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. Es ejecutable para 70 us aproximadamente (no un retraso de programación largo), pero es una cola de trabajo y puede que no se programe con precisión.

Verifique el marco anterior para determinar si eso contribuyó; a veces, la inquietud puede acumularse con el tiempo y eventualmente causar una fecha límite perdida.

Fotograma anterior
Figura 16. Cuadro anterior

La línea ejecutable en el kworker no es visible porque el visor se vuelve blanco cuando se selecciona, pero las estadísticas cuentan la historia: 2.3 ms de retraso del planificador para parte de la ruta crítica de la tubería de visualización es mala . Antes de continuar, corrija la demora al mover esta parte de la ruta crítica de la tubería de visualización desde una cola de trabajo (que se ejecuta como un hilo SCHED_OTHER CFS) a un hilo de rosca SCHED_FIFO dedicado. Esta función necesita garantías de tiempo que las colas de trabajo no pueden (y no están destinadas a proporcionar).

¿Es esta la razón del jank? Es difícil decir de manera concluyente. Fuera de los casos fáciles de diagnosticar, como la contención del bloqueo del kernel que causa que los hilos críticos de la pantalla se suspendan, las trazas generalmente no especifican el problema. ¿Podría esta inquietud haber sido la causa de la caída del marco? Absolutamente. Los tiempos de valla deben ser de 16,7 ms, pero no están cerca de eso en los cuadros que conducen al cuadro caído. Dado lo apretada que está la tubería de visualización, es posible que la fluctuación alrededor de los tiempos de la cerca provoque una caída del marco.

En este ejemplo, la solución consistía en convertir __vsync_retire_work_handler de una cola de trabajo a un kthread dedicado. Esto dio como resultado notables mejoras en el jitter y una reducción del jank en la prueba de la pelota que rebota. Las trazas posteriores muestran tiempos de cerca que rondan muy cerca de 16,7 ms.