diff options
Diffstat (limited to 'docs/html/guide/developing/debugging/debugging-tracing.jd')
| -rw-r--r-- | docs/html/guide/developing/debugging/debugging-tracing.jd | 400 |
1 files changed, 400 insertions, 0 deletions
diff --git a/docs/html/guide/developing/debugging/debugging-tracing.jd b/docs/html/guide/developing/debugging/debugging-tracing.jd new file mode 100644 index 0000000..0401966 --- /dev/null +++ b/docs/html/guide/developing/debugging/debugging-tracing.jd @@ -0,0 +1,400 @@ +page.title=Profiling with Traceview and dmtracedump +@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}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><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>
\ No newline at end of file |