Bookmark and Share
Document Actions

Traceview: un log viewer grafico

by Alice Narduzzo last modified 2008-04-03 09:33

Traceview è un viewer grafico per logs di esecuzione salvati dalla tua applicazione. Le sezioni seguenti descrivono come usare il programma.

Contenuti

Creare trace files

Copiare trace files in una host machine

Visualizzare trace files in Traceview

Pannello timeline

Pannello profilo

Formato dei files in Traceview

Formato dei data files

Formato dei key files

Problemi conosciuti di Traceview

Usare dmtracedump

Creare trace files

Per usare Traceview, devi generare files di log contenenti la trace information che vuoi analizzare. Per far ciò, devi includere la classe Debug nel tuo codice e richiamare i suoi metodi per avviare e fermare il logging delle trace information sul disco. Quando la tua applicazione viene chiusa, puoi usare Traceview per esaminare i files di log per utili informazioni di run-time come chiamate dei metodi e tempi di esecuzione.

Per creare i trace files, includi la classe Debug e richiama uno dei metodi startMethodTracing(). Nella chiamata, specifica un file di base per i trace files che vengono generati dal sistema. Per fermare il tracing, richiama stopMethodTracing(). Questi metodi avviano e fermano il tracing nell'intera virtual machine. Per esempio, potresti richiamare startMethodTracing() nel metodo onCreate() della tua activity, e richiamare stopMethodTracing() nel metodo onDestroy() di quell'activity.

// start tracing to "/tmp/calc"
Debug.startMethodTracing("/tmp/calc");
// ...
// stop tracing
Debug.stopMethodTracing();

Quando la tua applicazione richiama startMethodTracing(), il sistema crea due files:

  • <trace-base-name>.data -- continene un binary method trace data
  • <trace-base-name>.key -- un file di testo semplice che contiene mappatture da identifiers binari a nomi di threads e metodi

Il sistema inizia allora a fare il buffering dei trace data generati, fino a quando la tua applicazione non richiama stopMethodTracing(), momento in cui scrive i buffered data nel file. Se il sistema raggiunge il massimo livello di buffer prima che venga richiamato stopMethodTracing(), il sistema smette di fare il tracing e invia una notifica alla console.

Il formato dei trace files verrà descritto più avanti in questo documento.

Copiare trace files in una host machine

In seguito all'esecuzione della tua applicazione e alla creazione da parte del sistema dei trace files <trace-base-name>.data e <trace-base-name>.key su un dispositivo o emulatore, devi copiare questi files nel tuo computer per lo sviluppo. Puoi usare adp pull per fare quest'operazione. Questo è un esempio che mostra  come copiare due files campione, calc.data e calc.key, dalla posizione di default sull'emulatore alla directory /tmp sulla host machine dell'emulatore:

adb pull /tmp/calc.data /tmp 
adb pull /tmp/calc.key /tmp

Visualizzare trace files in Traceview

Per eseguire Traceview e visualizzare i trace files, introduci traceview <trace-base-name>. Per esempio, per eseguire Traceview sui files campione copiati nella fase precedente descritta qui sopra, dovresti usare:

traceview /tmp/calc

Traceview carica i files di log e mostra i loro dati in una finestra con due pannelli:

  • Un Pannello timeline -- descrive l'avvio e la fine di ogni thread e metodo
  • Un Pannello profilo -- fornisce un riassunto di cosa è successo all'interno di un metodo

Le sezioni seguenti forniscono ulteriori informazioni su pannelli di output del Traceview.

Pannello timeline

L'immagine qui sotto mostra un primo piano del pannello timeline. Ogni esecuzione di un thread è mostrata nella sua propria riga, con la variazione di tempo sulla destra. Ogni metodo è mostrato in un altro colore (i colori vengono riusati in maniera condivisa partendo con i metodi che hanno il tempo più inclusivo). Le sottili linee sotto la prima riga mostrano l'estensione (dall'entrata all'uscita) di tutte le chiamate del metodo selezionato. Il metodo in questo caso è LoadListener.nativeFinished() ed è stato selezionato anche nella visualizzazione del profilo.

Traceview timeline panel

Pannello profilo

L'immagine seguente mostra il pannello profilo, che mostra un sommario di tutto il tempo usato da un metodo. La  tabella mostra il tempo sia inclusivo che esclusivo (compresa la percentuale sul tempo totale). Il tempo esclusivo è il tempo speso per il metodo in questione. Il tempo inclusivo è il tempo speso per il metodo più il tempo speso per ogni funzione di chiamata.  Ci si riferisce a i metodi che effettuano la chiamata come a "parents" (genitori), e ai metodi richiamati come a "children" (figli). Quando un metodo viene selezionato, (cliccandoci sopra), si espande per mostrare i parents e i children. I parents vengono mostrati con uno sfondo viola e i children con uno sfondo giallo. L'ultima colonna della tabella mostra il numero di chiamate a questo metodo più il numero di chiamate ricorsive, con il numero di chiamate sul numero totale di chiamate fatte a quel metodo. In questa visualizzazione, possiamo vedere che ci sono state 14 chiamate a LoadListener.nativeFinished(); controllando il pannello timeline ci accorgiamo che una di queste chiamate ha impiegato un tempo insolitamente lungo.

Traceview profile panel.

Formato dei files in Traceview

Tracefile crea due trace files: un file .data, che contiene i trace data, e un file .key, che fornisce una mappatura dagli identifiers binari ai nomi dei threads e dei metodi. Questa sezione descrive i formati dei due files.

Formato dei data files

Il data file è un file binario con l'estensione .data. È strutturato come segue (tutti i valori sono immagazzinati in ordine little-endian, ovvero memorizzati dal meno significativo per finire col più significativo):

* File format:
* header
* record 0
* record 1
* ...
*
* Header format:
* u4 magic 0x574f4c53 ('SLOW')
* u2 version
* u2 offset to data
* u8 start date/time in usec
*
* Record format:
* u1 thread ID
* u4 method ID | method action
* u4 time delta since start, in usec

L'applicazione dovrebbe analizzare tutti i campi di testata (header fields), poi cercare di "offset to data" dall'inizio del file. Da qui legge semplicemente 9-byte records fino a raggiungere EOF.

u8 start date/time in usec è l'output da gettimeofday(). Serve principalmente a monitorare se l'output è stato generato ieri o tre mesi fa.

method action sta nei due bits meno significanti della parola method. I significati al momento definiti sono:

  • 0 - avvio del metodo (method entry)
  • 1 - uscita dal metodo (method exit)
  • 2 - uscita dal metodo quando maneggiato in maniera eccezionale (method "exited" when unrolled by exception handling
  • 3 - riservato (reserved)

Un numero intero non firmato di 32 bits (unsigned 32-bit integer) può supportare circa 70 minuti di tempo in microsecondi.

Formato dei key files

Un key file è un file di testo semplice diviso in tre sezioni. Ognuna di esse inizia con una parola chiave preceduta dal segno '*'. Se si vede questo segno all'inizio di una linea, significa che si è all'inizio di una nuova sezione.

Un esempio di file di questo tipo è il seguente:

*version
1
clock=global
*threads
1 main
6 JDWP Handler
5 Async GC
4 Reference Handler
3 Finalizer
2 Signal Handler
*methods
0x080f23f8 java/io/PrintStream write ([BII)V
0x080f25d4 java/io/PrintStream print (Ljava/lang/String;)V
0x080f27f4 java/io/PrintStream println (Ljava/lang/String;)V
0x080da620 java/lang/RuntimeException <init> ()V
[...]
0x080f630c android/os/Debug startMethodTracing ()V
0x080f6350 android/os/Debug startMethodTracing (Ljava/lang/String;Ljava/lang/String;I)V
*end
version section
La prima linea è il numero della versione del file, in questo caso 1. La seconda linea, clock=global, indica che si sta usando un normale orologio tra tutti i threads. Una futura versione del file potrebbe usare contatori del tempo della CPU che gestiscono i threads singolarmente (per-thread CPU time counters) , indipendenti per ogni thread.
threads section
Una linea per thread. Ogni linea è costituita da due parti: l'ID del thread, seguito da un tab, e di seguito il nome del thread. Ci sono poche restrizioni riguardo a come deve essere composto il nome di un thread in modo che sia valido, quindi si può includere quasi ogni cosa alla fine della linea.
methods section
Una linea per ogni avvio o uscita dal metodo. Una linea è costituita da quattro parti, separate da un segno di tab: method-ID [TAB] class-name [TAB] method-name [TAB] signature. Sono inclusi nella lista solamente i metodi che sono stati effettivamente usati. Nota che tutti e tre gli identifiers sono necessari per identificare in maniera univoca un metodo.

Non vengono immagazzinati né le threads sections né le methods sections.

Problemi conosciuti di Traceview

 

 

Threads
Il logging di Traceview non gestisce bene i threads, i problemi principali sono:
  1. Se un threads termina durante un profiling, il nome del thread non viene emesso;
  2. La VM riusa gli IDs dei threads. Se un thread termina e un altro si avvia, potrebbero acquisire lo stesso ID.

 

 

Usare dmtracedump

 

L'Android SDK include dmtracedump, uno strumento che fornisce un modo alternativo di generare diagrammi grafici di tipo call-stack da trace log files. Lo strumento usa la funzione Graphviz Dot per creare l'output grafico, quindi è necessario installare Graphviz prima di eseguire dmtracedump.

Lo strumento dmtracedump genera i dati call stack in forma di tre diagrammi, con ogni call rappresentato come un nodo. Mostra il flusso di calls (dal nodo parent ai nodi child) usando delle frecce. Il diagramma seguente mostra un esempio di output di dmtracedump:

Per ogni nodo, dmtracedump mostra <ref> callname (<inc-ms>, <exc-ms>,<numcalls>), in cui

  • <ref> -- Numero di riferimento della call (Call reference number), come utilizzato in trace logs
  • <inc-ms> -- Tempo passato inclusivo (Inclusive elapsed time - millisecondi spesi in metodo, inclusi tutti i metodi di tipo child)
  • <exc-ms> -- Tempo passato esclusivo (Exclusive elapsed time - millisecondi spesi in metodo, esclusi i metodi di tipo child) 
  • <numcalls> -- Numero delle calls

La sintassi per dmtracedump è:

dmtracedump [-ho] [-s sortable] [-d trace-base-name] [-g outfile] <trace-base-name>

LQuesto strumento carica dati di log da <trace-base-name>.data e <trace-base-name>.key. La tabella seguente elenca le opzioni possibili per dmtracedump.

Opzione Descrizione
-d <trace-base-name> Diffcon questo trace name
-g <outfile> Genera output a <outfile>
-h Avvia output HTML
-o Getta il trace file invece di eseguire il profiling
-d <trace-base-name> URL base alla posizione del file javascript
-t <percent> Minima sogli per includere nodi di tipo child nel grafico (tempo inclusivo del child come percentuale del tempo inclusivo del parent). Se questa opzione non viene usata, la soglia impostata di default è 20%.