Home | History | Annotate | Download | only in debugging
      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><a href="#creatingtracefiles">Creating Trace Files</a></li>
     22 
     23         <li><a href="#copyingfiles">Copying Trace Files to a Host Machine</a></li>
     24 
     25         <li><a href="#runningtraceview">Viewing Trace Files in Traceview</a></li>
     26 
     27         <li><a href="#dmtracedump">Using dmtracedump</a></li>
     28         
     29         <li><a href="#knownissues">Traceview Known Issues</a></li>
     30       </ol>
     31     </div>
     32   </div>
     33 
     34   <p>Traceview is a graphical viewer for execution logs that you create by using the {@link
     35   android.os.Debug} class to log tracing information in your code. Traceview can help you debug
     36   your application and profile its performance.</p>
     37 
     38   <h2 id="traceviewLayout">Traceview Layout</h2>
     39 
     40   <p>When you have a trace log file (generated by adding tracing code to your application or by DDMS),
     41   you can load the log files in Traceview, which displays the log data in two panels:</p>
     42 
     43   <ul>
     44     <li>A <a href="#timelinepanel">timeline panel</a> -- describes when each thread and method
     45     started and stopped</li>
     46 
     47     <li>A <a href="#timelinepanel">profile panel</a> -- provides a summary of what happened inside
     48     a method</li>
     49   </ul>
     50 
     51   <p>The sections below provide addition information about the traceview output panes.</p>
     52   
     53   <h3 id="timelinepanel">Timeline Panel</h3>
     54 
     55   <p>Figure 1 shows a close up of the timeline panel. Each thread&rsquo;s execution is shown
     56   in its own row, with time increasing to the right. Each method is shown in another color (colors
     57   are reused in a round-robin fashion starting with the methods that have the most inclusive time).
     58   The thin lines underneath the first row show the extent (entry to exit) of all the calls to the
     59   selected method.</p>
     60 
     61   <img src="{@docRoot}images/traceview_timeline.png"
     62        alt="Traceview timeline panel"
     63        width="893"
     64        height="284" />
     65        <p class="img-caption"><strong>Figure 1.</strong> The Traceview Timeline Panel</p>
     66 
     67   <h3 id="profilepanel">Profile Panel</h3>
     68 
     69   <p>Figure 2 shows the profile pane, a summary of all the time spent
     70   in a method. The table shows both the inclusive and exclusive times (as well as the percentage of
     71   the total time). Exclusive time is the time spent in the method. Inclusive time is the time spent
     72   in the method plus the time spent in any called functions. We refer to calling methods as
     73   "parents" and called methods as "children." When a method is selected (by clicking on it), it
     74   expands to show the parents and children. Parents are shown with a purple background and children
     75   with a yellow background. The last column in the table shows the number of calls to this method
     76   plus the number of recursive calls. The last column shows the number of calls out of the total
     77   number of calls made to that method. In this view, we can see that there were 14 calls to
     78   <code>LoadListener.nativeFinished();</code> looking at the timeline panel shows that one of those calls took
     79   an unusually long time.</p>
     80 
     81   <img src="{@docRoot}images/traceview_profile.png"
     82        alt="Traceview profile panel."
     83        width="892"
     84        height="630" />
     85   <p class="img-caption"><strong>Figure 2.</strong> The Traceview Profile Panel</p>
     86 
     87   <h2 id="creatingtracefiles">Creating Trace Files</h2>
     88 
     89   <p>To use Traceview, you need to generate log files containing the trace information you want to
     90   analyze.</p>
     91   
     92   <p>There are two ways to generate trace logs:</p>
     93   <ul>
     94     <li>Include the {@link android.os.Debug} class in your code and call its
     95   methods such as {@link android.os.Debug#startMethodTracing()} and {@link
     96   android.os.Debug#stopMethodTracing()}, to start and stop logging of trace information to disk.
     97   This option is very precise because
     98   you can specify exactly where to start and stop logging trace data in your code.</li>
     99     <li>Use the method profiling feature of DDMS to generate trace logs. This option is less
    100     precise because you do not modify code, but rather specify when to start and stop logging with
    101     DDMS. Although you have less control on exactly where logging starts and stops,
    102     this option is useful if you don't have access to the application's code, or if you do
    103     not need precise log timing.
    104     </li>
    105   </ul>
    106   
    107   <p>Before you start generating trace logs, be aware of the following restrictions:</p>
    108   <ul>
    109     <li>If you are using the {@link android.os.Debug} class,
    110      your application must have permission to write to external storage
    111      ({@link android.Manifest.permission#READ_EXTERNAL_STORAGE}). </li>
    112     <li>If you are using DDMS:
    113       <ul>
    114         <li>Android 2.1 and earlier devices must
    115     have an SD card present and your application must have permission to write to the SD card.
    116         <li>Android 2.2 and later devices do not need an SD card. The trace log files are
    117     streamed directly to your development machine.</li>
    118       </ul>
    119     </li>
    120   </ul>
    121   
    122   <p>This document focuses on using the {@link android.os.Debug} class to generate trace data.  For more information on using DDMS
    123   to generate trace data, see <a href="ddms.html#profiling">Using the Dalvik Debug Monitor Server.</a>
    124   </p>
    125   
    126   <p>To create the trace files, include the {@link android.os.Debug} class and call one of the
    127   {@link android.os.Debug#startMethodTracing() startMethodTracing()} methods. In the call, you
    128   specify a base name for the trace files that the system generates. To stop tracing, call {@link
    129   android.os.Debug#stopMethodTracing() stopMethodTracing()}. These methods start and stop method
    130   tracing across the entire virtual machine. For example, you could call 
    131   {@link android.os.Debug#startMethodTracing() startMethodTracing()} in
    132   your activity's {@link android.app.Activity#onCreate onCreate()} method, and call
    133   {@link android.os.Debug#stopMethodTracing() stopMethodTracing()} in that activity's
    134   {@link android.app.Activity#onDestroy()} method.</p>
    135   <pre>
    136     // start tracing to "/sdcard/calc.trace"
    137     Debug.startMethodTracing("calc");
    138     // ...
    139     // stop tracing
    140     Debug.stopMethodTracing();
    141 </pre>
    142 
    143   <p>When your application calls {@link android.os.Debug#startMethodTracing() startMethodTracing()},
    144   the system creates a file called
    145   <code>&lt;trace-base-name&gt;.trace</code>. This contains the binary method trace data and a
    146   mapping table with thread and method names.</p>
    147 
    148   <p>The system then begins buffering the generated trace data, until your application calls
    149   {@link android.os.Debug#stopMethodTracing() stopMethodTracing()}, at which time it writes
    150   the buffered data to the output file. If the system
    151   reaches the maximum buffer size before you call {@link android.os.Debug#stopMethodTracing()
    152   stopMethodTracing()}, the system stops tracing
    153   and sends a notification to the console.</p>
    154 
    155   <p>Interpreted code runs more slowly when profiling is enabled. Don't try to generate
    156   absolute timings from the profiler results (such as, "function X takes 2.5 seconds to run"). The
    157   times are only useful in relation to other profile output, so you can see if changes have made
    158   the code faster or slower relative to a previous profiling run.</p>
    159 
    160   <h2 id="copyingfiles">Copying Trace Files to a Host Machine</h2>
    161 
    162   <p>After your application has run and the system has created your trace files
    163   <code>&lt;trace-base-name&gt;.trace</code> on a device or emulator, you must copy those files to
    164   your development computer. You can use <code>adb pull</code> to copy the files. Here's an example
    165   that shows how to copy an example file, calc.trace, from the default location on the emulator to
    166   the /tmp directory on the emulator host machine:</p>
    167   <pre>
    168 adb pull /sdcard/calc.trace /tmp
    169 </pre>
    170 
    171   <h2 id="runningtraceview">Viewing Trace Files in Traceview</h2>
    172 
    173   <p>To run Traceview and view the trace files, enter <code>traceview
    174   &lt;trace-base-name&gt;</code>. For example, to run Traceview on the example files copied in the
    175   previous section, use:</p>
    176   <pre>
    177 traceview /tmp/calc
    178 </pre>
    179 
    180   <p class="note"><strong>Note:</strong> If you are trying to view the trace logs of an application 
    181   that is built with ProGuard enabled (release mode build), some method and member names might be obfuscated.
    182   You can use the Proguard <code>mapping.txt</code> file to figure out the original unobfuscated names. For more information
    183   on this file, see the <a href="{@docRoot}tools/help/proguard.html">Proguard</a> documentation.</p>
    184 
    185       <h2 id="dmtracedump">Using dmtracedump</h2>
    186 
    187       <p><code>dmtracedump</code> is a tool that gives you an alternate way of generating
    188       graphical call-stack diagrams from trace log files. The tool uses the Graphviz Dot utility to
    189       create the graphical output, so you need to install Graphviz before running dmtracedump.</p>
    190 
    191       <p>The dmtracedump tool generates the call stack data as a tree diagram, with each call
    192       represented as a node. It shows call flow (from parent node to child nodes) using arrows. The
    193       diagram below shows an example of dmtracedump output.</p>
    194       <img src=
    195       "{@docRoot}images/tracedump.png"
    196           width="485"
    197           height="401" />
    198        <p class="img-caption"><strong>Figure 3.</strong> Screenshot of dmtracedump</p>
    199 
    200       <p>For each node, dmtracedump shows <code>&lt;ref&gt;
    201       <em>callname</em> (&lt;inc-ms&gt;, &lt;exc-ms&gt;,&lt;numcalls&gt;)</code>, where</p>
    202 
    203       <ul>
    204         <li><code>&lt;ref&gt;</code> -- Call reference number, as used in trace logs</li>
    205 
    206         <li><code>&lt;inc-ms&gt;</code> -- Inclusive elapsed time (milliseconds spent in method,
    207         including all child methods)</li>
    208 
    209         <li><code>&lt;exc-ms&gt;</code> -- Exclusive elapsed time (milliseconds spent in method,
    210         not including any child methods)</li>
    211 
    212         <li><code>&lt;numcalls&gt;</code> -- Number of calls</li>
    213       </ul>
    214 
    215       <p>The usage for dmtracedump is:</p>
    216       <pre>
    217 dmtracedump [-ho] [-s sortable] [-d trace-base-name] [-g outfile] &lt;trace-base-name&gt;
    218 </pre>
    219 
    220       <p>The tool then loads trace log data from <code>&lt;trace-base-name&gt;.data</code> and
    221       <code>&lt;trace-base-name&gt;.key</code>. The table below lists the options for dmtracedump.</p>
    222 
    223       <table>
    224         <tr>
    225           <th>Option</th>
    226 
    227           <th>Description</th>
    228         </tr>
    229 
    230         <tr>
    231           <td><code>-d&nbsp;&lt;trace-base-name&gt;</code></td>
    232 
    233           <td>Diff with this trace name</td>
    234         </tr>
    235 
    236         <tr>
    237           <td><code>-g&nbsp;&lt;outfile&gt;</code></td>
    238 
    239           <td>Generate output to &lt;outfile&gt;</td>
    240         </tr>
    241 
    242         <tr>
    243           <td><code>-h</code></td>
    244 
    245           <td>Turn on HTML output</td>
    246         </tr>
    247 
    248         <tr>
    249           <td><code>-o</code></td>
    250 
    251           <td>Dump the trace file instead of profiling</td>
    252         </tr>
    253 
    254         <tr>
    255           <td><code>-d&nbsp;&lt;trace-base-name&gt;</code></td>
    256 
    257           <td>URL base to the location of the sortable javascript file</td>
    258         </tr>
    259 
    260         <tr>
    261           <td><code>-t&nbsp;&lt;percent&gt;</code></td>
    262 
    263           <td>Minimum threshold for including child nodes in the graph (child's inclusive time as a
    264           percentage of parent inclusive time). If this option is not used, the default threshold
    265           is 20%.</td>
    266         </tr>
    267       </table>
    268   
    269   
    270     
    271   <h2 id="knownissues">Traceview Known Issues</h2>
    272 
    273   <dl>
    274     <dt>Threads</dt>
    275 
    276     <dd>
    277       Traceview logging does not handle threads well, resulting in these two problems:
    278 
    279       <ol>
    280         <li>If a thread exits during profiling, the thread name is not emitted;</li>
    281 
    282         <li>The VM reuses thread IDs. If a thread stops and another starts, they may get the same
    283         ID.</li>
    284       </ol>
    285     </dd>
    286 
    287     </dl>
    288