| page.title=Profiling with Traceview and dmtracedump |
| parent.title=Debugging |
| parent.link=index.html |
| @jd:body |
| |
| <div id="qv-wrapper"> |
| <div id="qv"> |
| <h2>In this document</h2> |
| |
| <ol> |
| <li> |
| <a href="#traceviewLayout">Traceview Layout</a> |
| |
| <ol> |
| <li><a href="#timelinepanel">Timeline Panel</a></li> |
| |
| <li><a href="#profilepanel">Profile Panel</a></li> |
| </ol> |
| </li> |
| |
| <li> |
| <a href="#format">Traceview File Format</a> |
| <ol> |
| <li><a href="#datafileformat">Data File Format</a></li> |
| |
| <li><a href="#keyfileformat">Key File Format</a></li> |
| </ol> |
| </li> |
| |
| <li><a href="#creatingtracefiles">Creating Trace Files</a></li> |
| |
| <li><a href="#copyingfiles">Copying Trace Files to a Host Machine</a></li> |
| |
| <li><a href="#runningtraceview">Viewing Trace Files in Traceview</a></li> |
| |
| <li><a href="#dmtracedump">Using dmtracedump</a></li> |
| |
| <li><a href="#knownissues">Traceview Known Issues</a></li> |
| </ol> |
| </div> |
| </div> |
| |
| <p>Traceview is a graphical viewer for execution logs that you create by using the {@link |
| android.os.Debug} class to log tracing information in your code. Traceview can help you debug |
| your application and profile its performance.</p> |
| |
| <h2 id="traceviewLayout">Traceview Layout</h2> |
| |
| <p>When you have a trace log file (generated by adding tracing code to your application or by DDMS), |
| you can have Traceview load the log files and display their data in a window visualizes your application |
| in two panels:</p> |
| |
| <ul> |
| <li>A <a href="#timelinepanel">timeline panel</a> -- describes when each thread and method |
| started and stopped</li> |
| |
| <li>A <a href="#timelinepanel">profile panel</a> -- provides a summary of what happened inside |
| a method</li> |
| </ul> |
| |
| <p>The sections below provide addition information about the traceview output panes.</p> |
| |
| <h3 id="timelinepanel">Timeline Panel</h3> |
| |
| <p>The image below shows a close up of the timeline panel. Each thread’s execution is shown |
| in its own row, with time increasing to the right. Each method is shown in another color (colors |
| are reused in a round-robin fashion starting with the methods that have the most inclusive time). |
| The thin lines underneath the first row show the extent (entry to exit) of all the calls to the |
| selected method. The method in this case is <code>LoadListener.nativeFinished()</code> and it was selected in |
| the profile view.</p> |
| |
| <img src="{@docRoot}images/traceview_timeline.png" |
| alt="Traceview timeline panel" |
| width="893" |
| height="284" /> |
| <p class="img-caption"><strong>Figure 1.</strong> The Traceview Timeline Panel</p> |
| |
| <h3 id="profilepanel">Profile Panel</h3> |
| |
| <p>Figure 2 shows the profile pane, a summary of all the time spent |
| in a method. The table shows both the inclusive and exclusive times (as well as the percentage of |
| the total time). Exclusive time is the time spent in the method. Inclusive time is the time spent |
| in the method plus the time spent in any called functions. We refer to calling methods as |
| "parents" and called methods as "children." When a method is selected (by clicking on it), it |
| expands to show the parents and children. Parents are shown with a purple background and children |
| with a yellow background. The last column in the table shows the number of calls to this method |
| plus the number of recursive calls. The last column shows the number of calls out of the total |
| number of calls made to that method. In this view, we can see that there were 14 calls to |
| <code>LoadListener.nativeFinished();</code> looking at the timeline panel shows that one of those calls took |
| an unusually long time.</p> |
| |
| <img src="{@docRoot}images/traceview_profile.png" |
| alt="Traceview profile panel." |
| width="892" |
| height="630" /> |
| <p class="img-caption"><strong>Figure 2.</strong> The Traceview Profile Panel</p> |
| |
| <h2 id="format">Traceview File Format</h2> |
| |
| <p>Tracing creates two distinct pieces of output: a <em>data</em> file, which holds the trace |
| data, and a <em>key</em> file, which provides a mapping from binary identifiers to thread and |
| method names. The files are concatenated when tracing completes, into a single <em>.trace</em> |
| file.</p> |
| |
| <p class="note"><strong>Note:</strong> The previous version of Traceview did not concatenate |
| these files for you. If you have old key and data files that you'd still like to trace, you can |
| concatenate them yourself with <code>cat mytrace.key mytrace.data > |
| mytrace.trace</code>.</p> |
| |
| <h3 id="datafileformat">Data File Format</h3> |
| |
| <p>The data file is binary, structured as follows (all values are stored in little-endian |
| order):</p> |
| <pre> |
| * 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 |
| </pre> |
| |
| <p>The application is expected to parse all of the header fields, then seek to "offset to data" |
| from the start of the file. From there it just reads 9-byte records until EOF is reached.</p> |
| |
| <p><em>u8 start date/time in usec</em> is the output from <code>gettimeofday()</code>. It's mainly there so |
| that you can tell if the output was generated yesterday or three months ago.</p> |
| |
| <p><em>method action</em> sits in the two least-significant bits of the <em>method</em> word. The |
| currently defined meanings are:</p> |
| |
| <ul> |
| <li>0 - method entry</li> |
| |
| <li>1 - method exit</li> |
| |
| <li>2 - method "exited" when unrolled by exception handling</li> |
| |
| <li>3 - (reserved)</li> |
| </ul> |
| |
| <p>An unsigned 32-bit integer can hold about 70 minutes of time in microseconds.</p> |
| |
| <h3 id="keyfileformat">Key File Format</h3> |
| |
| <p>The key file is a plain text file divided into three sections. Each section starts with a |
| keyword that begins with '*'. If you see a '*' at the start of a line, you have found the start |
| of a new section.</p> |
| |
| <p>An example file might look like this:</p> |
| <pre> |
| *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 |
| </pre> |
| <p>The following list describes the major sections of a key file:</p> |
| <dl> |
| <dt><em>version section</em></dt> |
| |
| <dd>The first line is the file version number, currently 1. The second line, |
| <code>clock=global</code>, indicates that we use a common clock across all threads. A future |
| version may use per-thread CPU time counters that are independent for every thread.</dd> |
| |
| <dt><em>threads section</em></dt> |
| |
| <dd>One line per thread. Each line consists of two parts: the thread ID, followed by a tab, |
| followed by the thread name. There are few restrictions on what a valid thread name is, so |
| include everything to the end of the line.</dd> |
| |
| <dt><em>methods section</em></dt> |
| |
| <dd>One line per method entry or exit. A line consists of four pieces, separated by tab marks: |
| <em>method-ID</em> [TAB] <em>class-name</em> [TAB] <em>method-name</em> [TAB] |
| <em>signature</em> . Only the methods that were actually entered or exited are included in the |
| list. Note that all three identifiers are required to uniquely identify a method.</dd> |
| </dl> |
| |
| <p>Neither the threads nor methods sections are sorted.</p> |
| |
| <h2 id="creatingtracefiles">Creating Trace Files</h2> |
| |
| <p>To use Traceview, you need to generate log files containing the trace information you want to |
| analyze.</p> |
| |
| <p>There are two ways to generate trace logs:</p> |
| <ul> |
| <li>Include the {@link android.os.Debug} class in your code and call its |
| methods to start and stop logging of trace information to disk. This method is very precise because |
| you can specify in your code exactly where to start and stop logging trace data.</li> |
| <li>Use the method profiling feature of DDMS to generate trace logs. This method is less |
| precise since you do not modify code, but rather specify when to start and stop logging with |
| a DDMS. Although you have less control on exactly where the data is logged, this method is useful |
| if you don't have access to the application's code, or if you do not need the precision of the first method. |
| </li> |
| </ul> |
| |
| <p>Before you start generating trace logs, be aware of the following restrictions:</p> |
| <ul> |
| <li>If you are using the {@link android.os.Debug} class, your device or emulator must have an SD card |
| and your application must have permission to write to the SD card. </li> |
| <li>If you are using DDMS, Android 1.5 devices are not supported.</li> |
| <li>If you are using DDMS, Android 2.1 and earlier devices must |
| have an SD card present and your application must have permission to write to the SD card. |
| <li>If you are using DDMS, Android 2.2 and later devices do not need an SD card. The trace log files are |
| streamed directly to your development machine.</li> |
| </ul> |
| |
| <p>This document focuses on using the {@link android.os.Debug} class to generate trace data. For more information on using DDMS |
| to generate trace data, see <a href="ddms.html#profiling">Using the Dalvik Debug Monitor Server.</a> |
| </p> |
| |
| <p>To create the trace files, include the {@link android.os.Debug} class and call one of the |
| {@link android.os.Debug#startMethodTracing() startMethodTracing()} methods. In the call, you |
| specify a base name for the trace files that the system generates. To stop tracing, call {@link |
| android.os.Debug#stopMethodTracing() stopMethodTracing()}. These methods start and stop method |
| tracing across the entire virtual machine. For example, you could call |
| {@link android.os.Debug#startMethodTracing() startMethodTracing()} in |
| your activity's {@link android.app.Activity#onCreate onCreate()} method, and call |
| {@link android.os.Debug#stopMethodTracing() stopMethodTracing()} in that activity's |
| {@link android.app.Activity#onDestroy()} method.</p> |
| <pre> |
| // start tracing to "/sdcard/calc.trace" |
| Debug.startMethodTracing("calc"); |
| // ... |
| // stop tracing |
| Debug.stopMethodTracing(); |
| </pre> |
| |
| <p>When your application calls startMethodTracing(), the system creates a file called |
| <code><trace-base-name>.trace</code>. This contains the binary method trace data and a |
| mapping table with thread and method names.</p> |
| |
| <p>The system then begins buffering the generated trace data, until your application calls |
| stopMethodTracing(), at which time it writes the buffered data to the output file. If the system |
| reaches the maximum buffer size before stopMethodTracing() is called, the system stops tracing |
| and sends a notification to the console.</p> |
| |
| <p>Interpreted code will run more slowly when profiling is enabled. Don't try to generate |
| absolute timings from the profiler results (i.e. "function X takes 2.5 seconds to run"). The |
| times are only useful in relation to other profile output, so you can see if changes have made |
| the code faster or slower.</p> |
| |
| <p>When using the Android emulator, you must specify an SD card when you create your AVD because the trace files |
| are written to the SD card. Your application must have permission to write to the SD card as well. |
| |
| <p>The format of the trace files is previously described <a href="#format">in this |
| document</a>.</p> |
| |
| <h2 id="copyingfiles">Copying Trace Files to a Host Machine</h2> |
| |
| <p>After your application has run and the system has created your trace files |
| <code><trace-base-name>.trace</code> on a device or emulator, you must copy those files to |
| your development computer. You can use <code>adb pull</code> to copy the files. Here's an example |
| that shows how to copy an example file, calc.trace, from the default location on the emulator to |
| the /tmp directory on the emulator host machine:</p> |
| <pre> |
| adb pull /sdcard/calc.trace /tmp |
| </pre> |
| |
| <h2 id="runningtraceview">Viewing Trace Files in Traceview</h2> |
| |
| <p>To run Traceview and view the trace files, enter <code>traceview |
| <trace-base-name></code>. For example, to run Traceview on the example files copied in the |
| previous section, use:</p> |
| <pre> |
| traceview /tmp/calc |
| </pre> |
| |
| <p class="note"><strong>Note:</strong> If you are trying to view the trace logs of an application |
| that is built with ProGuard enabled (release mode build), some method and member names might be obfuscated. |
| You can use the Proguard <code>mapping.txt</code> file to figure out the original unobfuscated names. For more information |
| on this file, see the <a href="{@docRoot}tools/help/proguard.html">Proguard</a> documentation.</p> |
| |
| <h2 id="dmtracedump">Using dmtracdedump</h2> |
| |
| <p><code>dmtracedump</code> is a tool that gives you an alternate way of generating |
| graphical call-stack diagrams from trace log files. The tool uses the Graphviz Dot utility to |
| create the graphical output, so you need to install Graphviz before running dmtracedump.</p> |
| |
| <p>The dmtracedump tool generates the call stack data as a tree diagram, with each call |
| represented as a node. It shows call flow (from parent node to child nodes) using arrows. The |
| diagram below shows an example of dmtracedump output.</p> |
| <img src= |
| "{@docRoot}images/tracedump.png" |
| width="485" |
| height="401" /> |
| <p class="image-caption"><strong>Figure 3.</strong> Screenshot of dmtracedump</p> |
| |
| <p>For each node, dmtracedump shows <code><ref> |
| <em>callname</em> (<inc-ms>, <exc-ms>,<numcalls>)</code>, where</p> |
| |
| <ul> |
| <li><code><ref></code> -- Call reference number, as used in trace logs</li> |
| |
| <li><code><inc-ms></code> -- Inclusive elapsed time (milliseconds spent in method, |
| including all child methods)</li> |
| |
| <li><code><exc-ms></code> -- Exclusive elapsed time (milliseconds spent in method, |
| not including any child methods)</li> |
| |
| <li><code><numcalls></code> -- Number of calls</li> |
| </ul> |
| |
| <p>The usage for dmtracedump is:</p> |
| <pre> |
| dmtracedump [-ho] [-s sortable] [-d trace-base-name] [-g outfile] <trace-base-name> |
| </pre> |
| |
| <p>The tool then loads trace log data from <code><trace-base-name>.data</code> and |
| <code><trace-base-name>.key</code>. The table below lists the options for dmtracedump.</p> |
| |
| <table> |
| <tr> |
| <th>Option</th> |
| |
| <th>Description</th> |
| </tr> |
| |
| <tr> |
| <td><code>-d <trace-base-name></code></td> |
| |
| <td>Diff with this trace name</td> |
| </tr> |
| |
| <tr> |
| <td><code>-g <outfile></code></td> |
| |
| <td>Generate output to <outfile></td> |
| </tr> |
| |
| <tr> |
| <td><code>-h</code></td> |
| |
| <td>Turn on HTML output</td> |
| </tr> |
| |
| <tr> |
| <td><code>-o</code></td> |
| |
| <td>Dump the trace file instead of profiling</td> |
| </tr> |
| |
| <tr> |
| <td><code>-d <trace-base-name></code></td> |
| |
| <td>URL base to the location of the sortable javascript file</td> |
| </tr> |
| |
| <tr> |
| <td><code>-t <percent></code></td> |
| |
| <td>Minimum threshold for including child nodes in the graph (child's inclusive time as a |
| percentage of parent inclusive time). If this option is not used, the default threshold |
| is 20%.</td> |
| </tr> |
| </table> |
| |
| |
| |
| <h2 id="knownissues">Traceview Known Issues</h2> |
| |
| <dl> |
| <dt>Threads</dt> |
| |
| <dd> |
| Traceview logging does not handle threads well, resulting in these two problems: |
| |
| <ol> |
| <li>If a thread exits during profiling, the thread name is not emitted;</li> |
| |
| <li>The VM reuses thread IDs. If a thread stops and another starts, they may get the same |
| ID.</li> |
| </ol> |
| </dd> |
| |
| </dl> |