Google is committed to advancing racial equity for Black communities. See how.
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 un envoltorio para otras herramientas. Es el contenedor del lado del host alrededor de atrace , el ejecutable del lado del dispositivo que controla el rastreo del espacio de usuario y configura ftrace , y el mecanismo de rastreo principal 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 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 systrace

Al depurar 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 requeridos 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 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 del seguimiento).

Al pasar por el rastreo del sistema, tenga en cuenta que cada evento se activa 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 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 del análisis del rendimiento mediante systrace.

Ejemplo: marco de trabajo

Este ejemplo describe una traza del sistema para una canalización de IU 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 este sea un rastro mucho más grande con mucha más información de la que haya visto antes en un solo rastro.

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 subproceso de la interfaz de usuario de la aplicación, lo que indica que es hora de renderizar un nuevo marco.
  2. La aplicación procesa un marco en el hilo 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.
  3. La aplicación envía el marco renderizado a SurfaceFlinger usando un archivador, luego SurfaceFlinger se pone en suspensión.
  4. Un segundo EventThread en SurfaceFlinger despierta SurfaceFlinger para activar la composición y mostrar la salida. Si SurfaceFlinger determina que no hay trabajo por 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 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 triple búfer. (Si bien las aplicaciones siempre tienen un búfer triple, es posible que solo haya un marco pendiente esperando en SurfaceFlinger, lo que hace que parezca idéntico al búfer doble).
  6. SurfaceFlinger envía la salida final para mostrar con un controlador de proveedor y vuelve a dormir, esperando la activación de EventThread.

Repasemos el marco que comienza en 15409 ms:

Canalización de IU normal con EventThread en ejecución
Figura 1. Canalización de IU 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. En ejecución activa (el planificador cree que se está ejecutando).
  • Rojo. Sueño ininterrumpido (generalmente durmiendo en una cerradura en el kernel). 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 en el punto de sched_blocked_reason sched_blocked_reason), seleccione el segmento rojo de suspensión ininterrumpida.

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

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

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

El subproceso de la interfaz de usuario se activa, renderiza un marco y lo solicita 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 vinculante

La Figura 4 muestra que, a 15,423.65 ms, Binder: 6832_1 en SurfaceFlinger se vuelve ejecutable debido a 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 fotogramas pendientes van de 1 a 2
Figura 5. Los marcos pendientes van de 1 a 2

La Figura 5 muestra el almacenamiento en búfer triple, donde hay dos fotogramas completados 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 tratar de evitar más fotogramas descartados.

Poco después, el hilo principal de SurfaceFlinger es despertado por un segundo EventThread para que pueda mostrar el marco pendiente más antiguo en la pantalla:

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

SurfaceFlinger primero bloquea el búfer pendiente más antiguo, lo que hace que el recuento de búfer pendiente disminuya de 2 a 1.

SurfaceFlinger se engancha primero al búfer pendiente más antiguo
Figura 7. SurfaceFlinger se engancha primero al búfer pendiente más antiguo

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 mdss mdss, por lo que es posible que no se incluyan en su SoC).

SurfaceFlinger configura la composición y envía el fotograma 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 hilo 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 despierta en la CPU 0
Figura 9. mdss_fb0 se activa en la CPU 0

mdss_fb0 despierta, se ejecuta brevemente, entra en suspensión ininterrumpida y luego se vuelve a mdss_fb0 .

Ejemplo: marco no funcional

Este ejemplo describe una traza del sistema utilizada para depurar la fluctuación de Pixel / Pixel XL. Para seguir el ejemplo, descargue el archivo zip de trazas (que 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.

Cuando abras la traza del sistema, verás algo como esto:

TouchLatency se ejecuta 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 están habilitadas, incluidos los puntos de seguimiento 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 ver el seguimiento del sistema 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 SurfaceFlinger sin 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.

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

La Figura 11 muestra una trama perdida a 15.598,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 canalización de este marco, primero revise el ejemplo de marco de trabajo anterior para ver cómo aparece una canalización de IU normal en systrace. Cuando esté listo, vuelva 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).

SurfaceFlinger se despierta e inmediatamente se duerme
Figura 12. SurfaceFlinger se despierta e inmediatamente se duerme

Debido a que tenemos marcos en SurfaceFlinger, no es un problema de 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 sea un problema de controlador.

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

mdss_fb0_retire cercas
Figura 13. vallas mdss_fb0_retire

La Figura 13 muestra una trama que se mostró durante 33 ms, no 16,7 ms como se esperaba. A la mitad de ese corte, ese marco debería haber sido reemplazado por uno nuevo, pero no lo fue. Vea el cuadro anterior y busque cualquier cosa.

Cuadro anterior al cuadro roto
Figura 14. Cuadro anterior al cuadro roto

La figura 14 muestra 14.482 ms por trama. El segmento de dos cuadros roto fue 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 se acerca en absoluto a 16.7 ms, lo que sugiere que algo anda muy mal con la tubería de visualización.

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

Investigar el final 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 la valla. Al mirar a través de la fuente del kernel, puede ver que es parte del controlador de pantalla. Parece estar en la ruta crítica para el canal de visualización, por lo que debe ejecutarse lo más rápido posible. Se puede ejecutar para aproximadamente 70 personas (no es un retraso de programación prolongado), 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 inestabilidad puede acumularse con el tiempo y, finalmente, provocar el incumplimiento de una fecha límite.

Fotograma anterior
Figura 16. Cuadro anterior

La línea ejecutable en el kworker no es visible porque el visor la pone en blanco 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, corrija el retraso al mover esta parte de la ruta crítica de la canalización de visualización de una cola de trabajo (que se ejecuta como un SCHED_OTHER CFS) a un SCHED_FIFO 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 decirlo de manera concluyente. 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 se suspendan, los seguimientos generalmente no especifican el problema. ¿Podría esta fluctuación haber sido la causa de la caída del cuadro? Absolutamente. Los tiempos de la valla deberían ser de 16,7 ms, pero no se acercan en absoluto a eso en los fotogramas que conducen al fotograma caído. Dado lo estrechamente acoplado que está el canal de visualización, es posible que la fluctuación alrededor de los tiempos de la cerca provoque la caída de un cuadro.

En este ejemplo, la solución implicó convertir __vsync_retire_work_handler de una cola de trabajo a un kthread dedicado. Esto resultó en notables mejoras en el jitter y una reducción del jank en la prueba de la pelota que rebota. Los rastros posteriores muestran tiempos de cerca que rondan muy cerca de 16.7 ms.