Comprendere Systrace

systrace è lo strumento principale per analizzare le prestazioni dei dispositivi Android. Tuttavia, è davvero un involucro attorno ad altri strumenti. È il wrapper lato host attorno a atrace , l'eseguibile lato dispositivo che controlla la traccia dello spazio utente e imposta ftrace e il meccanismo di tracciamento principale nel kernel Linux. systrace utilizza atrace per abilitare la traccia, quindi legge il buffer ftrace e lo racchiude in un visualizzatore HTML autonomo. (Mentre i kernel più recenti hanno il supporto per Linux Enhanced Berkeley Packet Filter (eBPF), la seguente documentazione riguarda il kernel 3.18 (no eFPF) poiché è quello utilizzato su Pixel/Pixel XL.)

systrace è di proprietà dei team di Google Android e Google Chrome ed è open source come parte del progetto Catapult . Oltre a systrace, Catapult include altre utilità utili. Ad esempio, ftrace ha più funzionalità di quelle che possono essere abilitate direttamente da systrace o atrace e contiene alcune funzionalità avanzate critiche per il debug dei problemi di prestazioni. (Queste funzionalità richiedono l'accesso root e spesso un nuovo kernel.)

Esecuzione di systrace

Quando esegui il debug del jitter su Pixel/Pixel XL, inizia con il seguente comando:

./systrace.py sched freq idle am wm gfx view sync binder_driver irq workq input -b 96000

Se combinato con i tracepoint aggiuntivi richiesti per la GPU e l'attività della pipeline di visualizzazione, questo offre la possibilità di tracciare dall'input dell'utente al frame visualizzato sullo schermo. Imposta la dimensione del buffer su qualcosa di grande per evitare di perdere eventi (perché senza un buffer di grandi dimensioni alcune CPU non contengono eventi dopo un certo punto della traccia).

Quando esegui il systrace, tieni presente che ogni evento viene attivato da qualcosa sulla CPU .

Poiché systrace è costruito sopra ftrace e ftrace viene eseguito sulla CPU, qualcosa sulla CPU deve scrivere il buffer ftrace che registra le modifiche hardware. Ciò significa che se sei curioso di sapere perché un recinto di visualizzazione ha cambiato stato, puoi vedere cosa era in esecuzione sulla CPU nel punto esatto della sua transizione (qualcosa in esecuzione sulla CPU ha attivato quella modifica nel registro). Questo concetto è il fondamento dell'analisi delle prestazioni utilizzando systrace.

Esempio: quadro di lavoro

Questo esempio descrive una systrace per una normale pipeline dell'interfaccia utente. Per seguire l'esempio, scarica il file zip delle tracce (che include anche altre tracce a cui si fa riferimento in questa sezione), decomprimi il file e apri il file systrace_tutorial.html nel tuo browser. Tieni presente che questa traccia di sistema è un file di grandi dimensioni; a meno che non utilizzi systrace nel tuo lavoro quotidiano, questa è probabilmente una traccia molto più grande con molte più informazioni di quanto tu abbia mai visto prima in una singola traccia.

Per un carico di lavoro coerente e periodico come TouchLatency, la pipeline dell'interfaccia utente contiene quanto segue:

  1. EventThread in SurfaceFlinger riattiva il thread dell'interfaccia utente dell'app, segnalando che è ora di eseguire il rendering di un nuovo frame.
  2. L'app esegue il rendering di un frame nel thread dell'interfaccia utente, RenderThread e hwuiTasks, utilizzando risorse CPU e GPU. Questa è la maggior parte della capacità spesa per l'interfaccia utente.
  3. L'app invia il frame sottoposto a rendering a SurfaceFlinger utilizzando un raccoglitore, quindi SurfaceFlinger va in modalità di sospensione.
  4. Un secondo EventThread in SurfaceFlinger riattiva SurfaceFlinger per attivare la composizione e visualizzare l'output. Se SurfaceFlinger determina che non c'è lavoro da svolgere, torna in modalità di sospensione.
  5. SurfaceFlinger gestisce la composizione utilizzando Hardware Composer (HWC)/Hardware Composer 2 (HWC2) o GL. La composizione HWC/HWC2 è più veloce e consuma meno, ma presenta limitazioni a seconda del sistema su chip (SoC). Di solito, questa operazione richiede circa 4-6 ms, ma può sovrapporsi al passaggio 2 perché le app Android hanno sempre un triplo buffer. (Mentre le app hanno sempre un triplo buffering, potrebbe esserci solo un frame in sospeso in attesa in SurfaceFlinger, il che lo fa sembrare identico al doppio buffering.)
  6. SurfaceFlinger invia l'output finale da visualizzare con un driver del fornitore e torna in modalità di sospensione, in attesa del riavvio di EventThread.

Esaminiamo il frame a partire da 15409 ms:

Pipeline dell'interfaccia utente normale con EventThread in esecuzione
Figura 1. Pipeline dell'interfaccia utente normale, EventThread in esecuzione

La Figura 1 è un frame normale circondato da frame normali, quindi è un buon punto di partenza per comprendere come funziona la pipeline dell'interfaccia utente. La riga del thread dell'interfaccia utente per TouchLatency include colori diversi in momenti diversi. Le barre indicano diversi stati del thread:

  • Grigio . Dormire.
  • Blu. Eseguibile (potrebbe essere eseguito, ma lo scheduler non lo ha ancora selezionato per l'esecuzione).
  • Verde. Attivamente in esecuzione (lo scheduler pensa che sia in esecuzione).
  • Rosso. Sonno ininterrotto (generalmente dorme su un blocco nel kernel). Può essere indicativo del carico I/O. Estremamente utile per il debug di problemi di prestazioni.
  • Arancia. Sospensione ininterrotta a causa del carico I/O.

Per visualizzare il motivo della sospensione senza interruzioni (disponibile dal tracepoint sched_blocked_reason ), selezionare la sezione rossa della sospensione senza interruzioni.

Mentre EventThread è in esecuzione, il thread dell'interfaccia utente per TouchLatency diventa eseguibile. Per vedere cosa lo ha svegliato, fai clic sulla sezione blu.

Thread dell'interfaccia utente per TouchLatency
Figura 2. Thread dell'interfaccia utente per TouchLatency

La Figura 2 mostra che il thread dell'interfaccia utente TouchLatency è stato riattivato dal tid 6843, che corrisponde a EventThread. Il thread dell'interfaccia utente si riattiva, esegue il rendering di un frame e lo accoda affinché SurfaceFlinger possa utilizzarlo.

Il thread dell'interfaccia utente si riattiva, esegue il rendering di un frame e lo accoda affinché SurfaceFlinger possa utilizzarlo
Figura 3. Il thread dell'interfaccia utente si riattiva, esegue il rendering di un frame e lo accoda affinché SurfaceFlinger possa utilizzarlo

Se il tag binder_driver è abilitato in una traccia, è possibile selezionare una transazione del raccoglitore per visualizzare le informazioni su tutti i processi coinvolti in tale transazione.

Figura 4. Transazione del raccoglitore

La Figura 4 mostra che, a 15.423,65 ms Binder:6832_1 in SurfaceFlinger diventa eseguibile a causa del tid 9579, che è RenderThread di TouchLatency. Puoi anche vedere tailBuffer su entrambi i lati della transazione del raccoglitore.

Durante il QueueBuffer sul lato SurfaceFlinger, il numero di fotogrammi in sospeso da TouchLatency va da 1 a 2.

I frame in sospeso vanno da 1 a 2
Figura 5. I frame in sospeso vanno da 1 a 2

La Figura 5 mostra il triplo buffering, in cui sono presenti due fotogrammi completati e l'app sta per iniziare il rendering di un terzo. Questo perché abbiamo già perso alcuni fotogrammi, quindi l'app mantiene due fotogrammi in sospeso invece di uno per cercare di evitare ulteriori fotogrammi persi.

Subito dopo, il thread principale di SurfaceFlinger viene riattivato da un secondo EventThread in modo che possa visualizzare sul display il frame in sospeso più vecchio:

Il thread principale di SurfaceFlinger viene riattivato da un secondo EventThread
Figura 6. Il thread principale di SurfaceFlinger viene riattivato da un secondo EventThread

SurfaceFlinger blocca prima il buffer in sospeso più vecchio, il che fa sì che il conteggio del buffer in sospeso diminuisca da 2 a 1.

SurfaceFlinger si aggancia prima al buffer in sospeso più vecchio
Figura 7. SurfaceFlinger si aggancia innanzitutto al buffer in sospeso più vecchio

Dopo aver bloccato il buffer, SurfaceFlinger imposta la composizione e invia il fotogramma finale al display. (Alcune di queste sezioni sono abilitate come parte del tracepoint mdss , quindi potrebbero non essere incluse nel tuo SoC.)

SurfaceFlinger imposta la composizione e invia il fotogramma finale
Figura 8. SurfaceFlinger imposta la composizione e invia il fotogramma finale

Successivamente, mdss_fb0 si riattiva sulla CPU 0. mdss_fb0 è il thread del kernel della pipeline di visualizzazione per l'output di un frame renderizzato sul display. Possiamo vedere mdss_fb0 come una riga a parte nella traccia (scorrere verso il basso per visualizzare).

mdss_fb0 si riattiva sulla CPU 0
Figura 9. mdss_fb0 si riattiva sulla CPU 0

mdss_fb0 si sveglia, funziona brevemente, entra in una modalità di sonno ininterrotto, quindi si sveglia di nuovo.

Esempio: telaio non funzionante

Questo esempio descrive una systrace utilizzata per eseguire il debug del jitter Pixel/Pixel XL. Per seguire l'esempio, scarica il file zip delle tracce (che include altre tracce a cui si fa riferimento in questa sezione), decomprimi il file e apri il file systrace_tutorial.html nel tuo browser.

Quando apri il systrace, vedrai qualcosa del genere:

TouchLatency in esecuzione su Pixel XL con la maggior parte delle opzioni abilitate
Figura 10. TouchLatency in esecuzione su Pixel XL (la maggior parte delle opzioni abilitate, inclusi i tracepoint mdss e kgsl)

Quando cerchi jank, controlla la riga FrameMissed sotto SurfaceFlinger. FrameMissed è un miglioramento della qualità della vita fornito da HWC2. Quando si visualizza systrace per altri dispositivi, la riga FrameMissed potrebbe non essere presente se il dispositivo non utilizza HWC2. In entrambi i casi, FrameMissed è correlato alla mancanza di SurfaceFlinger in uno dei suoi tempi di esecuzione estremamente regolari e al conteggio dei buffer in sospeso invariato per l'app ( com.prefabulated.touchlatency ) in un vsync.

Correlazione FrameMissed con SurfaceFlinger
Figura 11. Correlazione FrameMissed con SurfaceFlinger

La Figura 11 mostra un fotogramma mancato a 15598,29 ms. SurfaceFlinger si è svegliato brevemente durante l'intervallo vsync ed è tornato a dormire senza eseguire alcuna operazione, il che significa che SurfaceFlinger ha stabilito che non valeva la pena provare a inviare nuovamente un frame al display. Perché?

Per comprendere come si è interrotta la pipeline per questo frame, esaminare innanzitutto l'esempio del frame di lavoro riportato sopra per vedere come appare una normale pipeline dell'interfaccia utente in systrace. Quando sei pronto, torna al fotogramma mancato e lavora all'indietro. Nota che SurfaceFlinger si sveglia e va immediatamente a dormire. Quando si visualizza il numero di fotogrammi in sospeso da TouchLatency, ci sono due fotogrammi (un buon indizio per capire cosa sta succedendo).

SurfaceFlinger si sveglia e va immediatamente a dormire
Figura 12. SurfaceFlinger si sveglia e va immediatamente a dormire

Poiché in SurfaceFlinger sono presenti frame, non è un problema dell'app. Inoltre, SurfaceFlinger si riattiva all'ora corretta, quindi non è un problema di SurfaceFlinger. Se SurfaceFlinger e l'app sembrano entrambi normali, probabilmente si tratta di un problema di driver.

Poiché i tracepoint mdss e sync sono abilitati, possiamo ottenere informazioni sui recinti (condivisi tra il driver dello schermo e SurfaceFlinger) che controllano quando i fotogrammi vengono inviati al display. Queste recinzioni sono elencate sotto mdss_fb0_retire , che indica quando un frame è sul display. Questi recinti vengono forniti come parte della categoria di traccia sync . Quali recinzioni corrispondono a particolari eventi in SurfaceFlinger dipendono dal SOC e dallo stack di driver, quindi collabora con il tuo fornitore SOC per comprendere il significato delle categorie di fencing nelle tue tracce.

mdss_fb0_retire recinzioni
Figura 13. Recinzioni mdss_fb0_retire

La Figura 13 mostra un fotogramma visualizzato per 33 ms e non per 16,7 ms come previsto. A metà di quella fetta, quella cornice avrebbe dovuto essere sostituita da una nuova ma non lo fu. Visualizza il frame precedente e cerca qualsiasi cosa.

Telaio precedente al telaio rotto
Figura 14. Telaio precedente al telaio rotto

La Figura 14 mostra 14.482 ms un frame. Il segmento interrotto di due fotogrammi è stato di 33,6 ms, che è più o meno quello che ci aspetteremmo per due fotogrammi (renderizziamo a 60 Hz, 16,7 ms per fotogramma, che è vicino). Ma 14,482 ms non sono affatto vicini a 16,7 ms, suggerendo che qualcosa non va con il display.

Investiga esattamente dove finisce quella recinzione per determinare cosa la controlla.

Esaminare l'estremità della recinzione
Figura 15. Esaminare l'estremità della recinzione

Una coda di lavoro contiene __vsync_retire_work_handler , che è in esecuzione quando il recinto cambia. Osservando i sorgenti del kernel, puoi vedere che fa parte del driver video. Sembra essere sul percorso critico per la pipeline di visualizzazione, quindi deve essere eseguito il più rapidamente possibile. È eseguibile per circa 70 persone (non un lungo ritardo di programmazione), ma è una coda di lavoro e potrebbe non essere programmata in modo accurato.

Controlla il frame precedente per determinare se ha contribuito; a volte il jitter può accumularsi nel tempo e alla fine causare il mancato rispetto della scadenza.

Fotogramma precedente
Figura 16. Fotogramma precedente

La linea eseguibile su kworker non è visibile perché il visualizzatore la rende bianca quando è selezionata, ma le statistiche raccontano la storia: 2,3 ms di ritardo dello scheduler per parte del percorso critico della pipeline di visualizzazione è negativo . Prima di continuare, correggere il ritardo spostando questa parte del percorso critico della pipeline di visualizzazione da una coda di lavoro (che viene eseguita come thread CFS SCHED_OTHER ) a un kthread SCHED_FIFO dedicato. Questa funzione necessita di garanzie temporali che le code di lavoro non possono (e non sono destinate a) fornire.

E' questo il motivo della battuta? È difficile dirlo in modo definitivo. Al di fuori dei casi facili da diagnosticare, come il conflitto del blocco del kernel che causa la sospensione dei thread critici per la visualizzazione, le tracce di solito non specificano il problema. Potrebbe essere questo jitter la causa della caduta del fotogramma? Assolutamente. I tempi di recinzione dovrebbero essere 16,7 ms, ma non sono affatto vicini a quello nei fotogrammi che precedono il fotogramma saltato. Considerando quanto è strettamente accoppiata la pipeline del display, è possibile che il jitter attorno ai timing del recinto abbia provocato una perdita di fotogramma.

In questo esempio, la soluzione prevedeva la conversione __vsync_retire_work_handler da una coda di lavoro a un kthread dedicato. Ciò ha comportato notevoli miglioramenti del jitter e una riduzione del jerk nel test della palla rimbalzante. Le tracce successive mostrano tempi di recinzione che si aggirano molto vicini a 16,7 ms.