Información sobre Systrace

Systrace es la herramienta principal para analizar el rendimiento de dispositivos Android. Sin embargo, en realidad es un wrapper alrededor de otras herramientas. Es el wrapper del host con atrace, el ejecutable del dispositivo que controla el espacio del usuario seguimiento y configura ftrace, además del mecanismo de seguimiento principal en Linux kernel. Systrace usa atrace para habilitar el seguimiento, luego lee el búfer de ftrace lo une todo en un visualizador HTML autónomo. (Aunque los kernels más nuevos admiten para el Filtro de paquetes de Berkeley mejorado de Linux (eBPF), la siguiente documentación Pertenece al kernel 3.18 (sin eFPF), ya que es lo que se usó en el dispositivo Pixel o Pixel. XL).

systrace es propiedad de los equipos de Google Android y Google Chrome de código abierto como parte del Proyecto de catapult. En Además de Systrace, Catapult incluye otras utilidades útiles. Por ejemplo: ftrace tiene más funciones de las que pueden habilitar directamente Systrace o atrace. contiene algunas funciones avanzadas que son fundamentales para el rendimiento de la depuración problemas. (Estas funciones requieren acceso a la raíz y, a menudo, un kernel nuevo).

Ejecuta Systrace

Cuando depures el Jitter en un teléfono Pixel o Pixel XL, comienza con lo siguiente: :

./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 pantalla de canalización, te permite hacer un seguimiento desde la entrada del usuario hasta el fotograma se muestran en la pantalla. Establece el tamaño del búfer en un tamaño grande para evitar perderlo. eventos (porque, sin un búfer grande, algunas CPU no contienen eventos después algún punto del seguimiento).

Cuando ejecutes Systrace, recuerda que cada evento se activado por algún elemento de la CPU.

Como Systrace se basa en 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 te interesa saber por qué una valla de visualización cambió de estado, puede ver lo que se ejecutaba en la CPU en el punto exacto de su transición (algo que se ejecutaba en la CPU activó ese cambio en el registro). Esta es la base para analizar el rendimiento con Systrace.

Ejemplo: Marco de trabajo

En este ejemplo, se describe un Systrace para una canalización de IU normal. Para continuar En 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), descomprime el archivo, y abre el archivo systrace_tutorial.html en tu navegador. Advertencia que Systrace es un archivo grande. a menos que uses Systrace trabajo, este es probablemente un registro mucho más grande con mucha más información de la que que nunca se haya visto en un solo seguimiento.

Para una carga de trabajo coherente y periódica, como TouchLatency, la canalización de la IU contiene lo siguiente:

1. EventThread en SurfaceFlinger activa el subproceso de IU de la app, lo que indica que es hora para renderizar un nuevo marco.
2. La app renderiza un fotograma en el subproceso de IU, RenderThread y hwuiTasks con CPU y Recursos de GPU. Esta es la mayor parte de la capacidad gastada para la IU.
3. La app envía el marco renderizado a SurfaceFlinger mediante un Binder. Luego, SurfaceFlinger se desactiva.
4. Un segundo EventThread en SurfaceFlinger activa SurfaceFlinger para activar composición y visualización de resultados. Si SurfaceFlinger determina que no hay trabajo para se hace, vuelve a suspenderse.
5. SurfaceFlinger controla la composición con Hardware Composer (HWC)/Hardware Composer 2 (HWC2) o GL Composición de HWC/HWC2 es más rápida y más baja de energía, pero tiene limitaciones que dependen del sistema en un chip (SoC). Este proceso suele tardar entre 4 y 6 ms, pero se puede superponer con el paso 2 porque Android las apps siempre tienen almacenamiento en búfer triple. (Aunque las apps siempre tienen almacenamiento en búfer triple, solo puede haber un fotograma pendiente en SurfaceFlinger, lo que hace que aparezca es idéntico al doble almacenamiento en búfer).
6. SurfaceFlinger envía el resultado final para mostrarlo con un controlador de proveedor y va volver a suspenderse, esperando la activación de EventThread.

Analicemos el fotograma a partir de los 15,409 ms:

.

La figura 1 es un fotograma normal rodeado de fotogramas normales, por lo que como punto de partida para comprender cómo funciona la canalización de IU. La fila del subproceso de IU para TouchLatency incluye diferentes colores en distintos momentos. Las barras denotan diferentes estados del subproceso:

• Gris. Durmiendo.
• Azul. Ejecutable (podría ejecutarse, pero el programador no lo eligieron para ejecutarse).
• verde. Se está ejecutando de forma activa (el programador cree que en ejecución).
• Rojo. Suspensión ininterrumpida (por lo general, se duerme con un candado) en el kernel). Puede indicar carga de E/S. Extremadamente útil para la depuración problemas de rendimiento.
• Naranja Suspensión ininterrumpida debido a la carga de E/S.

Para ver el motivo del modo de suspensión sin interrupciones (disponible en sched_blocked_reason de punto de seguimiento), selecciona el modo rojo porción de sueño.

Mientras se ejecuta EventThread, el subproceso de IU de TouchLatency ejecutable. Para ver qué lo activó, haz clic en la sección azul.

.

En la Figura 2, se muestra que tid 6843 activó el subproceso de IU de TouchLatency, que corresponde a EventThread. El subproceso de IU se activa, renderiza un fotograma y pone en cola para que SurfaceFlinger lo consuma.

.

Si la etiqueta binder_driver está habilitada en un seguimiento, puedes seleccionar un 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 convierte en se pueda ejecutar debido a tid 9579, que es RenderThread de TouchLatency. También puedes consulta queueBuffer en ambos lados de la transacción de Binder.

En queueBuffer en el lado de SurfaceFlinger, la cantidad de valores de TouchLatency va de 1 a 2.

.

En la figura 5, se muestra el almacenamiento en búfer triple, en el que hay dos fotogramas completos y los app está a punto de empezar a renderizar un tercero. Esto se debe a que ya excluimos algunos fotogramas, por lo que la app mantiene dos fotogramas pendientes en lugar de uno para evitar más disminuciones de fotogramas.

Poco después, un segundo EventThread despierta el subproceso principal de SurfaceFlinger puede mostrar el fotograma pendiente más antiguo en la pantalla:

.

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

.

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

.

Luego, mdss_fb0 se activa en la CPU 0. mdss_fb0 es el subproceso del kernel de la canalización de pantalla para mostrar un fotograma renderizado en la pantalla. Podemos ver que mdss_fb0 es su propia fila en el seguimiento (desplázate hacia abajo hasta vista).

.

mdss_fb0 se activa, se ejecuta brevemente, entra en modo de suspensión ininterrumpida y, luego, vuelve a despertar.

Ejemplo: Marco que no funciona

En este ejemplo, se describe un Systrace que se usa para depurar el Jitter de Pixel/Pixel XL. Para sigue el ejemplo: descarga el archivo ZIP archivo de seguimientos (que incluye otros seguimientos a los que se hace referencia en esta descomprime el archivo y abre el archivo systrace_tutorial.html en tu navegador.

Cuando abras Systrace, verás algo como esto:

.

Cuando busques bloqueos, revisa la fila Frame Failed en SurfaceFlinger. Frame omitido es una mejora en la calidad de vida proporcionada por HWC2. Al ver Systrace para otros dispositivos, es posible que la fila FrameMissing no esté presente si el dispositivo no usa HWC2. En cualquiera de los dos caso, FrameMissing se correlaciona con que SurfaceFlinger no tenga una de sus tiempos de ejecución extremadamente regulares y un recuento de búferes pendientes sin cambios para la app (com.prefabulated.touchlatency) en un vsync.

.

La Figura 11 muestra un fotograma perdido a 15,598.29 ms. SurfaceFlinger se despertó brevemente a las el intervalo de vsync y se volvió a suspender sin realizar ningún trabajo, lo que significa SurfaceFlinger determinó que no valía la pena enviar un fotograma a la pantalla de nuevo. ¿Por qué?

Para entender cómo se desglosó la canalización en este marco, primero revisa el ejemplo de marco de trabajo anterior para ver cómo aparece una canalización de IU normal en Systrace. Cuando tengas todo listo, regresa al fotograma faltante y trabaja hacia atrás. Ten en cuenta que SurfaceFlinger se activa y se suspende de inmediato. Al consultar la cantidad de para los fotogramas pendientes de TouchLatency, hay dos fotogramas (una buena pista para averiguar qué sucede).

.

Debido a que 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 SurfaceFlinger problema. Si SurfaceFlinger y la app se ven normales, probablemente sea un problema con el controlador.

Debido a que los puntos de seguimiento mdss y sync están habilitados, podemos obtener información sobre las cercas (compartidas entre el controlador de la 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 un fotograma está en la pantalla. Estas cercas se proporcionan como parte de la categoría de seguimiento sync. Las vallas que corresponden eventos particulares en SurfaceFlinger depende de su SOC y de la pila de controladores, por lo que junto con su proveedor del SOC para comprender el significado de las categorías de vallas en su registros.

.

En la Figura 13, se muestra un fotograma que se mostró durante 33 ms, no 16.7 ms como se esperaba. En la mitad de esa porción, ese marco se debería haber reemplazado por uno nuevo pero no lo fue. Mira el marco anterior y busca algo.

.

En la Figura 14, se muestran 14.482 ms de un fotograma. El segmento dividido de dos fotogramas fue de 33.6 ms, que es más o menos lo que esperaríamos para dos fotogramas (procesamos a 60 Hz, 16.7 ms por fotograma, que es similar). Pero 14.482 ms no se acerca a 16.7 ms lo que sugiere que hay un problema con la canalización de la pantalla.

Investiga exactamente dónde finaliza la valla para determinar qué la controla.

.

Una cola de trabajo contiene __vsync_retire_work_handler, que es cuando la cerca cambie. Al revisar la fuente del kernel, puedes ver que es parte del controlador de pantalla. Parece estar en la etapa crítica ruta de acceso para la canalización de la Red de Display, de modo que debe ejecutarse lo más rápido posible. Es se puede ejecutar durante 70 us (no es un retraso de programación prolongado), pero es una cola de trabajo y podrían no programarse con precisión.

Revisa el fotograma anterior para determinar si eso contribuyó. a veces jitter pueden acumularse con el tiempo y, con el tiempo, hacer que no se cumpla un plazo.

.

La línea ejecutable en kworker no es visible porque el visualizador la gira de color blanco cuando está seleccionado, pero las estadísticas lo demuestran: 2.3 ms de programador. el retraso en una parte de la ruta crítica de la canalización de la Red de Display es incorrecto. Antes de continuar, corrige la demora que mueve esta parte de la mostrar la ruta crítica de la canalización desde una cola de trabajo (que se ejecuta como SCHED_OTHER subproceso CFS) a un SCHED_FIFO dedicado kthread. Esta función necesita garantías de tiempo que las colas de trabajo no pueden proporcionar.

¿Es este el motivo del bloqueo? Es difícil decirlo de manera concluyente. Fuera de casos fáciles de diagnosticar, como la contención de bloqueo de kernel, que causan que la pantalla sea crítica los subprocesos se suspendan, los seguimientos no suelen especificar el problema. ¿Es posible que este jitter haya sido la causa de la caída del fotograma? Por supuesto. El los tiempos de valla deben ser de 16.7 ms, pero no se acercan a eso en los marcos lo que lleva al fotograma descartado. Dada la gran acoplamiento de la canalización de anuncios gráficos es posible que el jitter alrededor de los tiempos de la valla haya provocado marco.

En este ejemplo, la solución consistió en convertir __vsync_retire_work_handler de una cola de trabajo a una cuenta dedicada kthread. Como resultado, se produjeron mejoras de Jitter notables y se redujeron los bloqueos en la una prueba de rebote y Los seguimientos posteriores muestran tiempos de vallas que colocan el cursor sobre un elemento muy cerca. a 16.7 ms.