systrace è lo strumento principale per analizzare il rendimento dei dispositivi Android. Tuttavia, è in realtà un wrapper per altri strumenti. È il wrapper lato host per atrace, l'eseguibile lato dispositivo che controlla il monitoraggio nello spazio utente e configura ftrace, nonché il meccanismo di monitoraggio principale nel kernel Linux. systrace utilizza atrace per attivare il monitoraggio, quindi legge il buffer ftrace e lo racchiude in un visualizzatore HTML autonomo. Sebbene i kernel più recenti supportino il filtro pacchetti Berkeley avanzato (eBPF) di Linux, la seguente documentazione riguarda il kernel 3.18 (senza eFPF) perché è quello utilizzato su Pixel/Pixel XL.
systrace è di proprietà dei team di Google Android e Google Chrome ed è open source nell'ambito del progetto Catapult. Oltre a systrace, Catapult include altre utilità utili. Ad esempio, ftrace ha più funzionalità di quelle che possono essere attivate direttamente da systrace o atrace e contiene alcune funzionalità avanzate fondamentali per il debug dei problemi di rendimento. Queste funzionalità richiedono l'accesso come utente root e spesso un nuovo kernel.
Esegui 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 l'attività della pipeline GPU e del display, ti consente di eseguire il tracciamento dall'input dell'utente al frame visualizzato sullo schermo. Imposta le dimensioni del buffer su un valore elevato per evitare di perdere eventi (infatti, senza un buffer di grandi dimensioni alcune CPU non contengono eventi dopo un determinato punto della traccia).
Quando esamini systrace, tieni 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 vuoi sapere perché un recinto virtuale della visualizzazione ha cambiato stato, puoi vedere cosa era in esecuzione sulla CPU nel momento esatto della transizione (qualcosa in esecuzione sulla CPU ha attivato la modifica nel log). Questo concetto è alla base dell'analisi delle prestazioni utilizzando systrace.
Esempio: frame di lavoro
Questo esempio descrive un 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), decomprimilo e apri il file systrace_tutorial.html nel browser. Tieni presente
che questo file systrace è di grandi dimensioni. A meno che non utilizzi systrace nel tuo lavoro quotidiano, è probabile che si tratti di una traccia molto più grande con molte più informazioni di quelle che hai
mai visto 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, in RenderThread e in hwuiTasks, utilizzando le risorse della CPU e della GPU. Si tratta della maggior parte della capacità spesa per l'interfaccia utente.
- L'app invia il frame visualizzato a SurfaceFlinger utilizzando un binder, quindi SurfaceFlinger entra in modalità di sospensione.
- Un secondo thread Event in SurfaceFlinger riattiva SurfaceFlinger per attivare la composizione e l'output del display. 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 energia, ma presenta limitazioni a seconda del SoC (System on a Chip). In genere sono necessari circa 4-6 ms, ma l'operazione può sovrapporsi al passaggio 2 perché le app Android sono sempre con triplo buffering. Sebbene le app siano sempre con triplo buffering, in SurfaceFlinger potrebbe esserci un solo frame in attesa, il che rende l'effetto simile al doppio buffering.
- SurfaceFlinger invia l'output finale al display con un driver del fornitore e torna in modalità di sospensione, in attesa del risveglio di EventThread.
Esaminiamo il frame a partire da 15409 ms:
La Figura 1 mostra un frame normale circondato da frame normali, quindi è un buon punto di partenza per comprendere il funzionamento della 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 il programmatore non lo ha ancora scelto).
- Verde. In esecuzione (il programmatore ritiene che sia in esecuzione).
- Rosso. Sospensione non interrompibile (in genere in stato di sospensione su un blocco nel kernel). Può essere indicativo del carico I/O. Molto utile per il debug di problemi di prestazioni.
- Arancione. Sospensione non interrompibile a causa del carico I/O.
Per visualizzare il motivo del sonno ininterrotto (disponibile dal tracepoint
sched_blocked_reason), seleziona il segmento di sonno ininterrotto rosso.
Mentre EventThread è in esecuzione, il thread dell'interfaccia utente per TouchLatency diventa eseguito. Per vedere cosa lo ha attivato, fai clic sulla sezione blu.
La Figura 2 mostra che il thread dell'interfaccia utente TouchLatency è stato riattivato dal thread 6843, che corrisponde a EventThread. Il thread dell'interfaccia utente si riattiva, esegue il rendering di un frame e lo mette in coda per il consumo da parte di SurfaceFlinger.
Se il tag binder_driver è attivato in una traccia, puoi selezionare una transazione del binder per visualizzare informazioni su tutte le procedure coinvolte in quella transazione.
La Figura 4 mostra che, a 15.423,65 ms, Binder:6832_1 in SurfaceFlinger diventa eseguito a causa del thread di rendering di TouchLatency (tid 9579). Puoi anche vedere la codaBuffer su entrambi i lati della transazione del binder.
Durante la coda del buffer lato SurfaceFlinger, il numero di frame in attesa di TouchLatency passa da 1 a 2.
La Figura 5 mostra il buffering triplo, in cui sono presenti due frame completati e l'app sta per iniziare a eseguire il rendering di un terzo. Questo accade perché abbiamo già perso alcuni frame, quindi l'app conserva due frame in attesa anziché uno per cercare di evitare ulteriori perdite di frame.
Poco dopo, il thread principale di SurfaceFlinger viene riattivato da un secondo thread EventThread in modo da poter visualizzare il fotogramma in attesa precedente sul display:
SurfaceFlinger acquisisce prima il buffer in attesa precedente, il che fa diminuire il conto dei buffer in attesa da 2 a 1.
Dopo aver bloccato il buffer, SurfaceFlinger configura la composizione e invia il frame finale al display. Alcune di queste sezioni sono attivate nell'ambito del tracepoint mdss, pertanto 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 visualizzato sul display.
Possiamo vedere mdss_fb0 come riga separata nella traccia (scorri verso il basso per visualizzarla).
mdss_fb0 si riattiva, viene eseguito brevemente, entra in sospensione non interrompibile,
quindi si riattiva di nuovo.
Esempio: frame non funzionante
Questo esempio descrive un file systrace utilizzato per eseguire il debug del jitter di 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 browser.
Quando apri systrace, viene visualizzato un messaggio simile al seguente:
Quando cerchi il jitter, controlla la riga FrameMissed in SurfaceFlinger.
FrameMissed è un miglioramento della qualità della vita fornito da HWC2. Quando visualizzi
systrace per altri dispositivi, la riga FrameMissed potrebbe non essere presente se il dispositivo
non utilizza HWC2. In entrambi i casi, FrameMissed è correlato al mancato aggiornamento di uno dei runtime estremamente regolari di SurfaceFlinger e a un conteggio invariato del buffer in attesa per l'app (com.prefabulated.touchlatency) in un vsync.
La Figura 11 mostra un frame perso a 15598,29&nbps;ms. SurfaceFlinger si è riattivato brevemente all'intervallo vsync e si è rimesso in sospensione senza eseguire alcuna operazione, il che significa che SurfaceFlinger ha stabilito che non valeva la pena provare a inviare di nuovo un frame al display. Perché?
Per capire in che modo la pipeline è stata suddivisa per questo frame, esamina prima l'esempio di frame funzionante sopra per vedere come appare una normale pipeline dell'interfaccia utente in systrace. Quando è tutto pronto, torna al frame perso e vai a ritroso. Nota che SurfaceFlinger si riattiva e va immediatamente in sospensione. Quando visualizzi il numero di frame in attesa da TouchLatency, sono presenti due frame (un buon indizio per capire cosa sta succedendo).
Poiché abbiamo frame in SurfaceFlinger, non si tratta di un problema dell'app. Inoltre, SurfaceFlinger si riattiva all'ora corretta, quindi non si tratta di un problema di SurfaceFlinger. Se sia SurfaceFlinger sia l'app sembrano normali, è probabile che si tratti di un problema del driver.
Poiché i tracepoint mdss e sync sono abilitati,
possiamo ottenere informazioni sui recinti (condivisi tra il driver del display e
SurfaceFlinger) che controllano quando i frame vengono inviati al display.
Questi recinti sono elencati in mdss_fb0_retire, che indica quando un frame è visualizzato. Questi recinti sono forniti come parte della categoria di traccia sync. I recinti che corrispondono a determinati eventi in SurfaceFlinger dipendono dal tuo SOC e dallo stack di driver, quindi collabora con il tuo fornitore SOC per comprendere il significato delle categorie di recinti nelle tracce.
La Figura 13 mostra un frame visualizzato per 33 ms, non 16,7 ms come previsto. A metà di questo segmento, l'inquadratura avrebbe dovuto essere sostituita da una nuova, ma non è stato così. Visualizza il frame precedente e cerca qualcosa.
La Figura 14 mostra 14.482 ms per frame. Il segmento di due frame interrotto era di 33,6 ms, che è approssimativamente ciò che ci aspetteremmo per due frame (eseguiamo il rendering a 60 Hz, 16,7 ms per frame, che è simile). Tuttavia, 14.482 ms non è affatto vicino a 16,7 ms, suggerendo che c'è qualcosa di molto sbagliato con il canale di visualizzazione.
Controlla esattamente dove termina la recinzione per determinare cosa la controlla.
Una coda di lavoro contiene __vsync_retire_work_handler, che viene eseguita quando la recinzione cambia. Se esamini il codice sorgente del kernel, puoi vedere che fa parte del driver del display. Sembra che si trovi nel percorso critico per la pipeline di visualizzazione, quindi deve essere eseguita il più rapidamente possibile. È eseguibile per circa 70 µs (non è un ritardo di pianificazione lungo), ma è una coda di lavoro e potrebbe non essere pianificata con precisione.
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 riga eseguibile nel kworker non è visibile perché lo spettatore la sbianca quando è selezionata, ma le statistiche raccontano la storia: 2,3 ms di ritardo dello scheduler per parte del percorso critico della pipeline di visualizzazione è cattivo.
Prima di continuare, correggi il ritardo spostando questa parte del percorso critico della pipeline di visualizzazione da una coda di lavoro (che viene eseguita come SCHED_OTHERthread CFS) a un SCHED_FIFO
kthread dedicato. Questa funzione richiede garanzie sui tempi che le code di lavoro non possono (e non devono) fornire.
È questo il motivo del problema? È difficile dare una risposta definitiva. A parte i casi facili da diagnosticare, come la contesa per i blocchi del kernel che causa la sospensione dei thread critici per la visualizzazione, in genere le tracce non specificano il problema. Questo jitter potrebbe essere la causa della perdita del frame? Certamente. I tempi di recinzione dovrebbero essere 16,7 ms, ma non sono affatto vicini a questo valore nei frame che precedono il frame perso. Dato il forte accoppiamento della pipeline di visualizzazione, è possibile che il jitter intorno ai tempi di recinzione abbia causato la perdita di un frame.
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 del jitter nel
test della palla che rimbalza. Le tracce successive mostrano tempistiche di recinzione molto vicine
a 16,7 ms.