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