docs/html/guide/developing/debugging/debugging-tracing.jd

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&rsquo;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 &gt;
  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   &lt;init&gt;    ()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>&lt;trace-base-name&gt;.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>&lt;trace-base-name&gt;.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
  &lt;trace-base-name&gt;</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}guide/developing/tools/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>&lt;ref&gt;
      <em>callname</em> (&lt;inc-ms&gt;, &lt;exc-ms&gt;,&lt;numcalls&gt;)</code>, where</p>

      <ul>
        <li><code>&lt;ref&gt;</code> -- Call reference number, as used in trace logs</li>

        <li><code>&lt;inc-ms&gt;</code> -- Inclusive elapsed time (milliseconds spent in method,
        including all child methods)</li>

        <li><code>&lt;exc-ms&gt;</code> -- Exclusive elapsed time (milliseconds spent in method,
        not including any child methods)</li>

        <li><code>&lt;numcalls&gt;</code> -- Number of calls</li>
      </ul>

      <p>The usage for dmtracedump is:</p>
      <pre>
dmtracedump [-ho] [-s sortable] [-d trace-base-name] [-g outfile] &lt;trace-base-name&gt;
</pre>

      <p>The tool then loads trace log data from <code>&lt;trace-base-name&gt;.data</code> and
      <code>&lt;trace-base-name&gt;.key</code>. The table below lists the options for dmtracedump.</p>

      <table>
        <tr>
          <th>Option</th>

          <th>Description</th>
        </tr>

        <tr>
          <td><code>-d&nbsp;&lt;trace-base-name&gt;</code></td>

          <td>Diff with this trace name</td>
        </tr>

        <tr>
          <td><code>-g&nbsp;&lt;outfile&gt;</code></td>

          <td>Generate output to &lt;outfile&gt;</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&nbsp;&lt;trace-base-name&gt;</code></td>

          <td>URL base to the location of the sortable javascript file</td>
        </tr>

        <tr>
          <td><code>-t&nbsp;&lt;percent&gt;</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>