Usando ftrace

ftrace è uno strumento di debug per capire cosa sta succedendo all'interno del kernel Linux. Le sezioni seguenti descrivono in dettaglio le funzionalità di base di ftrace, l'utilizzo di ftrace con atrace (che cattura gli eventi del kernel) e ftrace dinamico.

Per dettagli sulla funzionalità avanzata di ftrace che non è disponibile da systrace, fare riferimento alla documentazione di ftrace su <kernel tree>/Documentation/trace/ftrace.txt .

Catturare eventi del kernel con atrace

atrace ( frameworks/native/cmds/atrace ) utilizza ftrace per acquisire eventi del kernel. A sua volta, systrace.py (o run_systrace.py nelle versioni successive di Catapult ) utilizza adb per eseguire atrace sul dispositivo. atrace fa quanto segue:

• Imposta la traccia in modalità utente impostando una proprietà ( debug.atrace.tags.enableflags ).
• Abilita la funzionalità ftrace desiderata scrivendo sui nodi ftrace sysfs appropriati. Tuttavia, poiché ftrace supporta più funzionalità, potresti impostare tu stesso alcuni nodi sysfs e quindi utilizzare atrace.

Con l'eccezione della traccia all'avvio, fare affidamento sull'utilizzo di atrace per impostare la proprietà sul valore appropriato. La proprietà è una maschera di bit e non esiste un buon modo per determinare i valori corretti se non guardando l'intestazione appropriata (che potrebbe cambiare tra le versioni di Android).

Abilitazione degli eventi ftrace

I nodi ftrace sysfs si trovano in /sys/kernel/tracing e gli eventi di traccia sono divisi in categorie in /sys/kernel/tracing/events .

Per abilitare gli eventi in base alla categoria, utilizzare:

echo 1 > /sys/kernel/tracing/events/irq/enable

Per abilitare gli eventi in base all'evento, utilizzare:

echo 1 > /sys/kernel/tracing/events/sched/sched_wakeup/enable

Se sono stati abilitati eventi aggiuntivi scrivendo sui nodi sysfs, non verranno ripristinati da atrace. Un modello comune per il portareup del dispositivo Qualcomm è abilitare i tracepoint kgsl (GPU) e mdss (pipeline di visualizzazione) e quindi utilizzare atrace o systrace :

adb shell "echo 1 > /sys/kernel/tracing/events/mdss/enable"
adb shell "echo 1 > /sys/kernel/tracing/events/kgsl/enable"
./systrace.py sched freq idle am wm gfx view binder_driver irq workq ss sync -t 10 -b 96000 -o full_trace.html

Puoi anche usare ftrace senza atrace o systrace, il che è utile quando vuoi tracce solo del kernel (o se ti sei preso il tempo di scrivere manualmente la proprietà di traccia in modalità utente). Per eseguire solo ftrace:

1. Imposta la dimensione del buffer su un valore sufficientemente grande per la tua traccia:

   echo 96000 > /sys/kernel/tracing/buffer_size_kb
   

2. Abilita traccia:

   echo 1 > /sys/kernel/tracing/tracing_on
   

3. Esegui il test, quindi disabilita la traccia:

   echo 0 > /sys/kernel/tracing/tracing_on
   

4. Scarica la traccia:

   cat /sys/kernel/tracing/trace > /data/local/tmp/trace_output
   

Il trace_output fornisce la traccia in forma di testo. Per visualizzarlo utilizzando Catapult, ottieni il repository Catapult da GitHub ed esegui trace2html:

catapult/tracing/bin/trace2html ~/path/to/trace_file

Per impostazione predefinita, scrive trace_file.html nella stessa directory.

Eventi correlati

Spesso è utile guardare contemporaneamente la visualizzazione Catapult e il log ftrace; ad esempio, alcuni eventi ftrace (specialmente quelli specifici del fornitore) non vengono visualizzati da Catapult. Tuttavia, i timestamp di Catapult sono relativi al primo evento nella traccia o a uno specifico timestamp scaricato da atrace, mentre i timestamp grezzi di ftrace sono basati su una particolare sorgente di clock assoluta nel kernel Linux.

Per trovare un determinato evento ftrace da un evento Catapult:

1. Apri il registro ftrace non elaborato. Le tracce nelle versioni recenti di systrace sono compresse per impostazione predefinita:
   • Se hai acquisito il tuo systrace con --no-compress , questo si trova nel file html nella sezione che inizia con BEGIN TRACE.
   • In caso contrario, esegui html2trace dall'albero Catapult ( tracing/bin/html2trace ) per decomprimere la traccia.
2. Trova il timestamp relativo nella visualizzazione Catapult.
3. Trova una riga all'inizio della traccia contenente tracing_mark_sync . Dovrebbe assomigliare a questo:

   <5134>-5134  (-----) [003] ...1    68.104349: tracing_mark_write: trace_event_clock_sync: parent_ts=68.104286
   

   
   Se questa riga non esiste (o se hai utilizzato ftrace senza atrace), i tempi saranno relativi a partire dal primo evento nel registro ftrace.
   1. Aggiungi il timestamp relativo (in millisecondi) al valore in parent_ts (in secondi).
   2. Cerca il nuovo timestamp.

Questi passaggi dovrebbero portarti al (o almeno molto vicino) all'evento.

Utilizzo di ftrace dinamico

Quando systrace e ftrace standard sono insufficienti, è disponibile un'ultima risorsa: ftrace dinamico . ftrace dinamico comporta la riscrittura del codice del kernel dopo l'avvio e di conseguenza non è disponibile nei kernel di produzione per motivi di sicurezza. Tuttavia, ogni singolo bug prestazionale nel 2015 e nel 2016 è stato causato in ultima analisi dall’utilizzo di ftrace dinamico. È particolarmente potente per il debug delle sospensioni senza interruzioni perché puoi ottenere un'analisi dello stack nel kernel ogni volta che premi la funzione che attiva la sospensione senza interruzioni. Puoi anche eseguire il debug di sezioni con interruzioni e prelazioni disabilitate, il che può essere molto utile per dimostrare problemi.

Per attivare ftrace dinamico, modifica il defconfig del tuo kernel:

1. Rimuovi CONFIG_STRICT_MEMORY_RWX (se è presente). Se utilizzi la versione 3.18 o successiva e arm64, non è presente.
2. Aggiungere quanto segue: CONFIG_DYNAMIC_FTRACE=y, CONFIG_FUNCTION_TRACER=y, CONFIG_IRQSOFF_TRACER=y, CONFIG_FUNCTION_PROFILER=y e CONFIG_PREEMPT_TRACER=y
3. Ricompilare e avviare il nuovo kernel.
4. Eseguire quanto segue per verificare la presenza di traccianti disponibili:

   cat /sys/kernel/tracing/available_tracers
   

5. Conferma che il comando restituisce function , irqsoff , preemptoff e preemptirqsoff .
6. Esegui quanto segue per assicurarti che ftrace dinamico funzioni:

   cat /sys/kernel/tracing/available_filter_functions | grep <a function you care about>
   

Dopo aver completato questi passaggi, avrai a disposizione ftrace dinamico, il profiler delle funzioni, il profiler irqsoff e il profiler preemptoff. Consigliamo vivamente di leggere la documentazione ftrace su questi argomenti prima di utilizzarli poiché sono potenti ma complessi. irqsoff e preemptoff sono utili principalmente per confermare che i driver potrebbero lasciare gli interrupt o la preemptoff disattivati ​​per troppo tempo.

Il profiler della funzione è l'opzione migliore per problemi di prestazioni e viene spesso utilizzato per scoprire dove viene chiamata una funzione.

Mostra problema: foto HDR + mirino rotante

In questo numero, utilizzare un Pixel XL per scattare una foto HDR+ e poi ruotare immediatamente il mirino causava problemi ogni volta. Abbiamo utilizzato la funzione profiler per eseguire il debug del problema in meno di un'ora. 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 trace_30898724.html nel tuo browser.

La traccia mostra diversi thread nel processo cameraserver bloccati in modalità di sospensione ininterrotta su ion_client_destroy . Questa è una funzione costosa, ma dovrebbe essere chiamata molto raramente perché i client ionici dovrebbero comprendere molte allocazioni. Inizialmente, la colpa ricadeva sul codice Hexagon in Halide, che era effettivamente uno dei colpevoli (creava un nuovo client per ogni allocazione di ioni e distruggeva quel client quando l'allocazione veniva liberata, il che era decisamente troppo costoso). Il passaggio a un singolo client ion per tutte le allocazioni Hexagon ha migliorato la situazione, ma il problema non è stato risolto.

A questo punto dobbiamo sapere chi sta chiamando ion_client_destroy , quindi è il momento di utilizzare la funzione profiler:

1. Poiché le funzioni a volte vengono rinominate dal compilatore, conferma che ion_client_destroy è presente utilizzando:

   cat /sys/kernel/tracing/available_filter_functions | grep ion_client_destroy
   

2. Dopo aver confermato che sia lì, usalo come filtro ftrace:

   echo ion_client_destroy > /sys/kernel/tracing/set_ftrace_filter
   

3. Attiva la funzione profiler:

   echo function > /sys/kernel/tracing/current_tracer
   

4. Attiva le analisi dello stack ogni volta che viene chiamata una funzione di filtro:

   echo func_stack_trace > /sys/kernel/tracing/trace_options
   

5. Aumenta la dimensione del buffer:

   echo 64000 > /sys/kernel/tracing/buffer_size_kb
   

6. Attiva il tracciamento:

   echo 1 > /sys/kernel/tracing/trace_on
   

7. Esegui il test e ottieni la traccia:

   cat /sys/kernel/tracing/trace > /data/local/tmp/trace
   

8. Visualizza la traccia per vedere tantissime tracce dello stack:

       cameraserver-643   [003] ...1    94.192991: ion_client_destroy <-ion_release
       cameraserver-643   [003] ...1    94.192997: <stack trace>
    => ftrace_ops_no_ops
    => ftrace_graph_call
    => ion_client_destroy
    => ion_release
    => __fput
    => ____fput
    => task_work_run
    => do_notify_resume
    => work_pending
    

Dall'ispezione del driver ion, possiamo vedere che ion_client_destroy è stato spammato da una funzione dello spazio utente che chiude un fd in /dev/ion , non da un driver del kernel casuale. Cercando \"/dev/ion\" nel codice base di Android, troviamo diversi driver di fornitori che fanno la stessa cosa del driver Hexagon e aprono/chiudono /dev/ion (creando e distruggendo un nuovo client ion) ogni volta che hanno bisogno di un nuova allocazione di ioni. La modifica di questi per utilizzare un singolo client ionico per l'intera durata del processo ha risolto il bug.

---

Se i dati del function profiler non sono sufficientemente specifici, puoi combinare i tracepoint ftrace con il function profiler. Gli eventi ftrace possono essere abilitati esattamente nello stesso modo del solito e verranno interlacciati con la tua traccia. Questo è fantastico se occasionalmente c'è una lunga sospensione ininterrotta in una funzione specifica di cui vuoi eseguire il debug: imposta il filtro ftrace sulla funzione che desideri, abilita i tracepoint, prendi una traccia. Puoi analizzare la traccia risultante con trace2html , trovare l'evento desiderato, quindi ottenere le tracce dello stack vicine nella traccia grezza.

Utilizzando lockstat

A volte, ftrace non è sufficiente ed è davvero necessario eseguire il debug di ciò che sembra essere un conflitto di blocco del kernel. C'è un'altra opzione del kernel che vale la pena provare: CONFIG_LOCK_STAT . Questa è l'ultima risorsa poiché è estremamente difficile far funzionare i dispositivi Android perché gonfia la dimensione del kernel oltre ciò che la maggior parte dei dispositivi può gestire.

Tuttavia, lockstat utilizza l'infrastruttura di blocco del debug, utile per molte altre applicazioni. Tutti coloro che lavorano sull'attivazione del dispositivo dovrebbero trovare un modo per far funzionare quell'opzione su ogni dispositivo perché ci sarà un momento in cui penserai "Se solo potessi attivare LOCK_STAT , potrei confermare o confutare questo problema in cinque minuti invece di cinque giorni."

Mostra problema: stallo in SCHED_FIFO quando i core sono al massimo carico con non SCHED_FIFO

In questo problema, il thread SCHED_FIFO si bloccava quando tutti i core erano al carico massimo con thread non SCHED_FIFO. Abbiamo riscontrato tracce che mostravano un significativo conflitto di blocco su un fd nelle app VR, ma non siamo riusciti a identificare facilmente il fd in uso. 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 trace_30905547.html nel tuo browser.

Abbiamo ipotizzato che ftrace stesso fosse la fonte del conflitto di lock, quando un thread a bassa priorità iniziava a scrivere sulla pipe ftrace e veniva quindi bloccato prima di poter rilasciare il lock. Questo è lo scenario peggiore che è stato esacerbato da una combinazione di thread con priorità estremamente bassa che scrivono sul marcatore ftrace insieme ad alcuni thread con priorità più alta che girano sulle CPU per simulare un dispositivo completamente caricato.

Dato che non potevamo usare ftrace per eseguire il debug, abbiamo fatto funzionare LOCK_STAT e poi abbiamo disattivato tutte le altre tracce dall'app. I risultati hanno mostrato che il conflitto di blocco proveniva in realtà da ftrace perché nessuno dei conflitti veniva visualizzato nella traccia di blocco quando ftrace non era in esecuzione.

---

Se puoi avviare un kernel con l'opzione config, il lock tracing è simile a ftrace:

1. Abilita traccia:

   echo 1 > /proc/sys/kernel/lock_stat
   

2. Esegui il test.
3. Disabilita traccia:

   echo 0 > /proc/sys/kernel/lock_stat
   

4. Scarica la traccia:

   cat /proc/lock_stat > /data/local/tmp/lock_stat
   

Per assistenza nell'interpretazione dell'output risultante, fare riferimento alla documentazione lockstat su <kernel>/Documentation/locking/lockstat.txt .

Utilizzo dei tracepoint del fornitore

Utilizza prima i tracepoint upstream, ma a volte dovrai utilizzare i tracepoint del fornitore:

  { "gfx",        "Graphics",         ATRACE_TAG_GRAPHICS, {
        { OPT,      "events/mdss/enable" },
        { OPT,      "events/sde/enable" },
        { OPT,      "events/mali_systrace/enable" },
    } },

I tracepoint sono estensibili tramite il servizio HAL che consente di aggiungere tracepoint/categorie specifici del dispositivo. I Tracepoint sono integrati con Perfetto, atrace/systrace e l'app di tracciamento del sistema sul dispositivo.

Le API per l'implementazione di tracepoint/categorie sono:

• listCategories()genera (categorie vec<TracingCategory>);
• abilitaCategorie(vec<string> categorie) genera (Stato stato);
• disableAllCategories() genera (stato di stato);

Per ulteriori informazioni, fare riferimento alla definizione HAL e all'implementazione predefinita in AOSP :