systrace è lo strumento principale per analizzare le prestazioni dei dispositivi Android. Tuttavia, è davvero un wrapper attorno ad altri strumenti. È il wrapper lato host attorno ad atrace , l'eseguibile lato dispositivo che controlla la traccia dello spazio utente e imposta ftrace e il meccanismo di traccia principale nel kernel Linux. systrace usa 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 (senza eFPF) poiché è quello che è stato 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 utili utilità. Ad esempio, ftrace ha più funzionalità di quelle che possono essere abilitate direttamente da systrace o atrace e contiene alcune funzionalità avanzate che sono fondamentali per il debug dei problemi di prestazioni. (Queste funzionalità richiedono l'accesso come root e spesso un nuovo kernel.)
Systrace in esecuzione
Quando esegui il debug del jitter su Pixel/Pixel XL, inizia con il comando seguente:
./systrace.py sched freq idle am wm gfx view sync binder_driver irq workq input -b 96000
Se combinato con i punti di traccia aggiuntivi richiesti per la GPU e l'attività della pipeline di visualizzazione, ti dà la possibilità di tracciare dall'input dell'utente al frame visualizzato sullo schermo. Impostare 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 si esegue Systrace, tenere presente che ogni evento viene attivato da qualcosa sulla CPU .
Poiché systrace è basato su 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 display fence 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 è alla base dell'analisi delle prestazioni mediante systrace.
Esempio: telaio 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 systrace è un file di grandi dimensioni; a meno che tu non usi systrace nel tuo lavoro quotidiano, questa è probabilmente una traccia molto più grande con molte più informazioni di quelle che hai mai visto prima in una singola traccia.
Per un carico di lavoro periodico e coerente come TouchLatency, la pipeline dell'interfaccia utente contiene quanto segue:
- EventThread in SurfaceFlinger riattiva il thread dell'interfaccia utente dell'app, segnalando che è ora di eseguire il rendering di un nuovo frame.
- 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.
- L'app invia il frame di rendering a SurfaceFlinger utilizzando un raccoglitore, quindi SurfaceFlinger va in modalità di sospensione.
- Un secondo EventThread in SurfaceFlinger riattiva SurfaceFlinger per attivare la composizione e visualizzare l'output. Se SurfaceFlinger determina che non c'è lavoro da fare, torna in modalità di sospensione.
- SurfaceFlinger gestisce la composizione utilizzando Hardware Composer (HWC)/Hardware Composer 2 (HWC2) o GL. La composizione HWC/HWC2 è più veloce e ha una potenza inferiore, ma presenta limitazioni a seconda del sistema su chip (SoC). Questo di solito richiede circa 4-6 ms, ma può sovrapporsi al passaggio 2 perché le app Android hanno sempre un buffer triplo. (Anche se le app sono sempre a triplo buffer, potrebbe esserci solo un frame in sospeso in attesa in SurfaceFlinger, il che lo fa sembrare identico al doppio buffering.)
- SurfaceFlinger invia l'output finale da visualizzare con un driver del fornitore e torna alla modalità di sospensione, in attesa dell'attivazione di EventThread.
Esaminiamo il frame a partire da 15409 ms:
La figura 1 è un frame normale circondato da frame normali, quindi è un buon punto di partenza per capire come funziona la pipeline dell'interfaccia utente. La riga del thread dell'interfaccia utente per TouchLatency include colori diversi in momenti diversi. Le barre denotano stati diversi per il 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 dormendo su una serratura nel kernel). Può essere indicativo del carico di I/O. Estremamente utile per il debug dei problemi di prestazioni.
- Arancia. Sospensione ininterrotta a causa del carico di I/O.
Per visualizzare il motivo del sonno ininterrotto (disponibile dal sched_blocked_reason sched_blocked_reason), selezionare la sezione rossa del sonno ininterrotto.
Mentre EventThread è in esecuzione, il thread dell'interfaccia utente per TouchLatency diventa eseguibile. Per vedere cosa l'ha svegliato, fai clic sulla sezione blu.
La figura 2 mostra che il thread dell'interfaccia utente TouchLatency è stato attivato da tid 6843, che corrisponde a EventThread. Il thread dell'interfaccia utente si riattiva, esegue il rendering di un frame e lo mette in coda per l'utilizzo da parte di SurfaceFlinger.
Se il tag binder_driver è abilitato in una traccia, è possibile selezionare una transazione binder per visualizzare le informazioni su tutti i processi coinvolti in tale transazione.
La figura 4 mostra che, a 15.423,65 ms, Binder:6832_1 in SurfaceFlinger diventa eseguibile a causa di tid 9579, che è RenderThread di TouchLatency. Puoi anche vedere queueBuffer su entrambi i lati della transazione del raccoglitore.
Durante il queueBuffer sul lato SurfaceFlinger, il numero di frame in sospeso da TouchLatency va da 1 a 2.
La figura 5 mostra il triplo buffering, in cui sono presenti due frame completati e l'app sta per iniziare il rendering di un terzo. Questo perché abbiamo già eliminato alcuni frame, quindi l'app mantiene due frame in sospeso anziché uno per cercare di evitare ulteriori frame persi.
Subito dopo, il thread principale di SurfaceFlinger viene attivato da un secondo EventThread in modo che possa visualizzare sul display il frame in sospeso precedente:
SurfaceFlinger prima blocca il vecchio buffer in sospeso, il che fa sì che il conteggio del buffer in sospeso diminuisca da 2 a 1.
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 mdss mdss, quindi potrebbero non essere incluse nel tuo SoC.)
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 propria riga nella traccia (scorrere verso il basso per visualizzare).
mdss_fb0 si sveglia, viene eseguito brevemente, entra in modalità di sospensione ininterrotta, quindi si riattiva.
Esempio: telaio non funzionante
Questo esempio descrive un sistema utilizzato 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:
Quando cerchi jank, controlla la riga FrameMissed in SurfaceFlinger. FrameMissed è un miglioramento della qualità della vita fornito da HWC2. Durante la visualizzazione di Systrace per altri dispositivi, la riga FrameMissed potrebbe non essere presente se il dispositivo non utilizza HWC2. In entrambi i casi, FrameMissed è correlato a SurfaceFlinger mancante di uno dei suoi tempi di esecuzione estremamente regolari e di un numero di buffer in sospeso invariato per l'app ( com.prefabulated.touchlatency ) in un vsync.
La Figura 11 mostra un frame mancante a 15598.29&nbps;ms. SurfaceFlinger si è svegliato brevemente all'intervallo vsync ed è tornato a dormire senza eseguire alcun lavoro, il che significa che SurfaceFlinger ha stabilito che non valeva la pena provare a inviare di nuovo un frame al display. Come mai?
Per capire in che modo la pipeline si è interrotta per questo frame, prima esamina l'esempio del frame di lavoro sopra per vedere come appare una normale pipeline dell'interfaccia utente in systrace. Quando sei pronto, torna al fotogramma perso e lavora all'indietro. Si noti che SurfaceFlinger si riattiva e si addormenta immediatamente. Quando si visualizza il numero di frame in sospeso da TouchLatency, ci sono due frame (un buon indizio per aiutare a capire cosa sta succedendo).
Poiché abbiamo frame in SurfaceFlinger, non è un problema con l'app. Inoltre, SurfaceFlinger si sveglia all'ora corretta, quindi non è un problema di SurfaceFlinger. Se SurfaceFlinger e l'app sembrano entrambi normali, è probabilmente un problema di driver.
Poiché i mdss e sync sono abilitati, possiamo ottenere informazioni sui fence (condivisi tra il driver video e SurfaceFlinger) che controllano quando i frame vengono inviati al display. Queste barriere sono elencate in mdss_fb0_retire , che indica quando un frame è sul display. Queste barriere sono fornite come parte della categoria della traccia di sync . Quali barriere corrispondono a eventi particolari in SurfaceFlinger dipende dal tuo SOC e dallo stack di driver, quindi collabora con il tuo fornitore SOC per comprendere il significato delle categorie di recinzione nelle tue tracce.
La Figura 13 mostra un frame che è stato visualizzato per 33 ms, non 16,7 ms come previsto. A metà di quella fetta, quel fotogramma avrebbe dovuto essere sostituito da uno nuovo, ma non lo è stato. Visualizza il frame precedente e cerca qualsiasi cosa.
La Figura 14 mostra 14,482 ms per frame. Il segmento rotto di due frame era di 33,6 ms, che è più o meno quello che ci aspetteremmo per due frame (renderizziamo a 60 Hz, 16,7 ms per frame, che è vicino). Ma 14,482 ms non è affatto vicino a 16,7 ms, suggerendo che qualcosa non va nella pipe del display.
Indaga esattamente dove finisce quella recinzione per determinare cosa la controlla.
Una coda di lavoro contiene __vsync_retire_work_handler , che è in esecuzione quando cambia la recinzione. Guardando attraverso il sorgente 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 70 noi circa (non un lungo ritardo nella pianificazione), ma è una coda di lavoro e potrebbe non essere pianificata in modo accurato.
Controlla il frame precedente per determinare se ciò ha contribuito; a volte il jitter può aumentare nel tempo e alla fine causare una scadenza mancata.
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 non è valido . Prima di continuare, correggi il ritardo dovuto allo spostamento di questa parte del percorso critico della pipeline di visualizzazione da una coda di lavoro (che viene eseguita come thread CFS SCHED_OTHER ) a un SCHED_FIFO SCHED_FIFO dedicato. Questa funzione necessita di garanzie temporali che le code di lavoro non possono (e non sono destinate a) fornire.
È questo il motivo del jank? È difficile dirlo in modo definitivo. Al di fuori dei casi di facile diagnosi, come la contesa del blocco del kernel che causa la sospensione dei thread critici per la visualizzazione, le tracce di solito non specificano il problema. Questo jitter potrebbe essere stato la causa della caduta del frame? Assolutamente. I tempi di recinzione dovrebbero essere 16,7 ms, ma non sono affatto vicini a quelli nei frame che portano al frame abbandonato. Dato quanto strettamente accoppiato è la pipeline di visualizzazione, è possibile che il jitter attorno ai tempi della recinzione abbia provocato un frame caduto.
In questo esempio, la soluzione prevedeva la conversione di __vsync_retire_work_handler da una coda di lavoro a un kthread dedicato. Ciò ha comportato notevoli miglioramenti del jitter e una riduzione dello jank nel test della palla che rimbalza. Tracce successive mostrano tempi di recinzione che si aggirano molto vicini a 16,7 ms.