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:
- 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 sottoposto a 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 svolgere, 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 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.)
- 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:
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.
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.
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.
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.
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:
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.
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.)
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 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:
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.
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).
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.
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.
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.
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.
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.