1page.title=Traceview: A Graphical Log Viewer 2@jd:body 3 4<div id="qv-wrapper"> 5<div id="qv"> 6 7 <h2>In this document</h2> 8<ol> 9 <li><a href="#creatingtracefiles">Creating Trace Files</a></li> 10 <li><a href="#copyingfiles">Copying Trace Files to a Host Machine</a></li> 11 <li><a href="#runningtraceview">Viewing Trace Files in Traceview</a> 12 <ol> 13 <li><a href="#timelinepanel">Timeline Panel</a></li> 14 <li><a href="#profilepanel">Profile Panel</a></li> 15 </ol></li> 16 <li><a href="#format">Traceview File Format</a> 17 <ol> 18 <li><a href="#datafileformat">Data File Format</a></li> 19 <li><a href="#keyfileformat">Key File Format</a></li> 20 </ol></li> 21 <li><a href="#knownissues">Traceview Known Issues</a></li> 22 <li><a href="#dmtracedump">Using dmtracedump</a></li> 23</ol> 24</div> 25</div> 26 27<p>Traceview is a graphical viewer for execution logs 28saved by your application. Traceview can help you debug your application and 29profile its performance. The sections below describe how to use the program. </p> 30 31<a name="creatingtracefiles"></a> 32 33<h2>Creating Trace Files</h2> 34 35<p>To use Traceview, you need to generate log files containing the trace information you want to analyze. To do that, you include the {@link android.os.Debug} 36 class in your code and call its methods to start and stop logging of trace information 37 to disk. When your application quits, you can then use Traceview to examine the log files 38 for useful run-time information such 39 as method calls and run times. </p> 40<p>To create the trace files, include the {@link android.os.Debug} class and call one 41 of the {@link android.os.Debug#startMethodTracing() startMethodTracing()} methods. 42 In the call, you specify a base name for the trace files that the system generates. 43 To stop tracing, call {@link android.os.Debug#stopMethodTracing() stopMethodTracing()}. 44 These methods start and stop method tracing across the entire virtual machine. For 45 example, you could call startMethodTracing() in your activity's onCreate() 46 method, and call stopMethodTracing() in that activity's onDestroy() method.</p> 47 48<pre> 49 // start tracing to "/sdcard/calc.trace" 50 Debug.startMethodTracing("calc"); 51 // ... 52 // stop tracing 53 Debug.stopMethodTracing(); 54</pre> 55 56<p>When your application calls startMethodTracing(), the system creates a 57file called <code><trace-base-name>.trace</code>. This contains the 58binary method trace data and a mapping table with thread and method names.</p> 59 60<p>The system then begins buffering the generated trace data, until your application calls 61 stopMethodTracing(), at which time it writes the buffered data to the 62 output file. 63 If the system reaches the maximum buffer size before stopMethodTracing() 64 is called, the system stops tracing and sends a notification 65 to the console. </p> 66 67<p>Interpreted code will run more slowly when profiling is enabled. Don't 68try to generate absolute timings from the profiler results (i.e. "function 69X takes 2.5 seconds to run"). The times are only 70useful in relation to other profile output, so you can see if changes 71have made the code faster or slower. </p> 72 73<p>When using the Android emulator, you must create an SD card image upon which 74the trace files will be written. For example, from the <code>/tools</code> directory, you 75can create an SD card image named "imgcd" and mount it when launching the emulator like so:</p> 76<pre> 77<b>$</b> mksdcard 1024M ./imgcd 78<b>$</b> emulator -sdcard ./imgcd 79</pre> 80<p>For more information, read about the 81<a href="{@docRoot}guide/developing/tools/othertools.html#mksdcard">mksdcard tool</a>.</p> 82 83<p>The format of the trace files is described <a href="#format">later 84 in this document</a>. </p> 85 86<a name="copyingfiles"></a> 87 88<h2>Copying Trace Files to a Host Machine</h2> 89<p>After your application has run and the system has created your trace files <code><trace-base-name>.trace</code> 90 on a device or emulator, you must copy those files to your development computer. You can use <code>adb pull</code> to copy 91 the files. Here's an example that shows how to copy an example file, 92 calc.trace, from the default location on the emulator to the /tmp directory on 93the emulator host machine:</p> 94<pre>adb pull /sdcard/calc.trace /tmp</pre> 95 96 97<a name="runningtraceview"></a> 98 99<h2>Viewing Trace Files in Traceview</h2> 100<p>To run traceview and view the trace files, enter <code>traceview <trace-base-name></code>. 101 For example, to run Traceview on the example files copied in the previous section, 102 you would use: </p> 103 <pre>traceview /tmp/calc</pre> 104 105 <p>Traceview loads the log files and displays their data in a window that has two panels:</p> 106 <ul> 107 <li>A <a href="#timelinepanel">timeline panel</a> -- describes when each thread 108 and method started and stopped</li> 109 <li>A <a href="#timelinepanel">profile panel</a> -- provides a summary of what happened inside a method</li> 110 </ul> 111 <p>The sections below provide addition information about the traceview output panes. </p> 112 113<a name="timelinepanel"></a> 114 115<h3>Timeline Panel </h3> 116<p>The image below shows a close up of the timeline panel. Each thread’s 117 execution is shown in its own row, with time increasing to the right. Each method 118 is shown in another color (colors are reused in a round-robin fashion starting 119 with the methods that have the most inclusive time). The thin lines underneath 120 the first row show the extent (entry to exit) of all the calls to the selected 121 method. The method in this case is LoadListener.nativeFinished() and it was 122 selected in the profile view. </p> 123<p><img src="/images/traceview_timeline.png" alt="Traceview timeline panel" width="893" height="284"></p> 124<a name="profilepanel"></a> 125<h3>Profile Panel</h3> 126<p>The image below shows the profile pane. The profile pane shows a 127 summary of all the time spent in a method. The table shows 128 both the inclusive and exclusive times (as well as the percentage of the total 129 time). Exclusive time is the time spent in the method. Inclusive time is the 130 time spent in the method plus the time spent in any called functions. We refer 131 to calling methods as "parents" and called methods as "children." 132 When a method is selected (by clicking on it), it expands to show the parents 133 and children. Parents are shown with a purple background and children 134 with a yellow background. The last column in the table shows the number of calls 135 to this method plus the number of recursive calls. The last column shows the 136 number of calls out of the total number of calls made to that method. In this 137 view, we can see that there were 14 calls to LoadListener.nativeFinished(); looking 138 at the timeline panel shows that one of those calls took an unusually 139 long time.</p> 140<p><img src="/images/traceview_profile.png" alt="Traceview profile panel." width="892" height="630"></p> 141 142<a name="format"></a> 143<h2>Traceview File Format</h2> 144<p>Tracing creates two distinct pieces of output: a <em>data</em> file, 145 which holds the trace data, and a <em>key</em> file, which 146 provides a mapping from binary identifiers to thread and method names. 147 The files are concatenated when tracing completes, into a 148 single <em>.trace</em> file. </p> 149 150<p class="note"><strong>Note:</strong> The previous version of Traceview did not concatenate 151these files for you. If you have old key and data files that you'd still like to trace, you 152can concatenate them yourself with <code>cat mytrace.key mytrace.data > mytrace.trace</code>.</p> 153 154<a name="datafileformat"></a> 155 156<h3>Data File Format</h3> 157<p>The data file is binary, structured as 158 follows (all values are stored in little-endian order):</p> 159<pre>* File format: 160* header 161* record 0 162* record 1 163* ... 164* 165* Header format: 166* u4 magic 0x574f4c53 ('SLOW') 167* u2 version 168* u2 offset to data 169* u8 start date/time in usec 170* 171* Record format: 172* u1 thread ID 173* u4 method ID | method action 174* u4 time delta since start, in usec 175</pre> 176<p>The application is expected to parse all of the header fields, then seek 177 to "offset to data" from the start of the file. From there it just 178 reads 179 9-byte records until EOF is reached.</p> 180<p><em>u8 start date/time in usec</em> is the output from gettimeofday(). 181 It's mainly there so that you can tell if the output was generated yesterday 182 or three months ago.</p> 183<p><em>method action</em> sits in the two least-significant bits of the 184 <em>method</em> word. The currently defined meanings are: </p> 185<ul> 186 <li>0 - method entry </li> 187 <li>1 - method exit </li> 188 <li>2 - method "exited" when unrolled by exception handling </li> 189 <li>3 - (reserved)</li> 190</ul> 191<p>An unsigned 32-bit integer can hold about 70 minutes of time in microseconds. 192</p> 193 194<a name="keyfileformat"></a> 195 196<h3>Key File Format</h3> 197<p>The key file is a plain text file divided into three sections. Each 198 section starts with a keyword that begins with '*'. If you see a '*' at the start 199 of a line, you have found the start of a new section.</p> 200<p>An example file might look like this:</p> 201<pre>*version 2021 203clock=global 204*threads 2051 main 2066 JDWP Handler 2075 Async GC 2084 Reference Handler 2093 Finalizer 2102 Signal Handler 211*methods 2120x080f23f8 java/io/PrintStream write ([BII)V 2130x080f25d4 java/io/PrintStream print (Ljava/lang/String;)V 2140x080f27f4 java/io/PrintStream println (Ljava/lang/String;)V 2150x080da620 java/lang/RuntimeException <init> ()V 216[...] 2170x080f630c android/os/Debug startMethodTracing ()V 2180x080f6350 android/os/Debug startMethodTracing (Ljava/lang/String;Ljava/lang/String;I)V 219*end</pre> 220<dl> 221 <dt><em>version section</em></dt> 222 <dd>The first line is the file version number, currently 223 1. 224 The second line, <code>clock=global</code>, indicates that we use a common 225 clock across all threads. A future version may use per-thread CPU time counters 226 that are independent for every thread.</dd> 227 <dt><em>threads section</em></dt> 228 <dd>One line per thread. Each line consists of two parts: the thread ID, followed 229 by a tab, followed by the thread name. There are few restrictions on what 230 a valid thread name is, so include everything to the end of the line.</dd> 231 <dt><em>methods section </em></dt> 232 <dd>One line per method entry or exit. A line consists of four pieces, 233 separated by tab marks: <em>method-ID</em> [TAB] <em>class-name</em> [TAB] 234 <em>method-name</em> [TAB] 235 <em>signature</em> . Only 236 the methods that were actually entered or exited are included in the list. 237 Note that all three identifiers are required to uniquely identify a 238 method.</dd> 239</dl> 240<p>Neither the threads nor methods sections are sorted.</p> 241 242<a name="knownissues"></a> 243<h2>Traceview Known Issues</h2> 244<dl> 245 <dt>Threads</dt> 246 <dd>Traceview logging does not handle threads well, resulting in these two problems: 247<ol> 248 <li> If a thread exits during profiling, the thread name is not emitted; </li> 249 <li>The VM reuses thread IDs. If a thread stops and another starts, they 250 may get the same ID. </li> 251</ol> 252</dd> 253 254<a name="dmtracedump"></a> 255 256<h2>Using dmtracedump</h2> 257 258<p>The Android SDK includes dmtracedump, a tool that gives you an alternate way 259 of generating graphical call-stack diagrams from trace log files. The tool 260 uses the Graphviz Dot utility to create the graphical output, so you need to 261 install Graphviz before running dmtracedump.</p> 262 263<p>The dmtracedump tool generates the call stack data as a tree diagram, with each call 264 represented as a node. It shows call flow (from parent node to child nodes) using 265 arrows. The diagram below shows an example of dmtracedump output.</p> 266 267<img src="{@docRoot}images/tracedump.png" width="485" height="401" style="margin-top:1em;"/> 268 269<p style="margin-top:1em;">For each node, dmtracedump shows <code><ref> <em>callname</em> (<inc-ms>, 270 <exc-ms>,<numcalls>)</code>, where</p> 271 272<ul> 273 <li><code><ref></code> -- Call reference number, as used in trace logs</li> 274 <li><code><inc-ms></code> -- Inclusive elapsed time (milliseconds spent in method, including all child methods)</li> 275 <li><code><exc-ms></code> -- Exclusive elapsed time (milliseconds spent in method, not including any child methods)</li> 276 <li><code><numcalls></code> -- Number of calls</li> 277</ul> 278 279<p>The usage for dmtracedump is: </p> 280 281<pre>dmtracedump [-ho] [-s sortable] [-d trace-base-name] [-g outfile] <trace-base-name></pre> 282 283<p>The tool then loads trace log data from <trace-base-name>.data and <trace-base-name>.key. 284 The table below lists the options for dmtracedump.</p> 285 286<table> 287<tr> 288 <th>Option</td> 289 <th>Description</th> 290</tr> 291 292 <tr> 293 <td><code>-d <trace-base-name> </code></td> 294 <td>Diff with this trace name</td> 295 </tr> 296 <tr> 297 <td><code>-g <outfile> </code></td> 298 <td>Generate output to <outfile></td> 299 </tr> 300 <tr> 301 <td><code>-h </code></td> 302 <td>Turn on HTML output</td> 303 </tr> 304 <tr> 305 <td><code>-o </code></td> 306 <td>Dump the trace file instead of profiling</td> 307 </tr> 308 <tr> 309 <td><code>-d <trace-base-name> </code></td> 310 <td>URL base to the location of the sortable javascript file</td> 311 </tr> 312 <tr> 313 <td><code>-t <percent> </code></td> 314 <td>Minimum threshold for including child nodes in the graph (child's inclusive 315 time as a percentage of parent inclusive time). If this option is not used, 316 the default threshold is 20%. </td> 317 </tr> 318 319</table> 320
