320 lines
13 KiB
Plaintext
320 lines
13 KiB
Plaintext
page.title=Traceview: A Graphical Log Viewer
|
|
@jd:body
|
|
|
|
<div id="qv-wrapper">
|
|
<div id="qv">
|
|
|
|
<h2>In this document</h2>
|
|
<ol>
|
|
<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>
|
|
<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="#knownissues">Traceview Known Issues</a></li>
|
|
<li><a href="#dmtracedump">Using dmtracedump</a></li>
|
|
</ol>
|
|
</div>
|
|
</div>
|
|
|
|
<p>Traceview is a graphical viewer for execution logs
|
|
saved by your application. Traceview can help you debug your application and
|
|
profile its performance. The sections below describe how to use the program. </p>
|
|
|
|
<a name="creatingtracefiles"></a>
|
|
|
|
<h2>Creating Trace Files</h2>
|
|
|
|
<p>To use Traceview, you need to generate log files containing the trace information you want to analyze. To do that, you include the {@link android.os.Debug}
|
|
class in your code and call its methods to start and stop logging of trace information
|
|
to disk. When your application quits, you can then use Traceview to examine the log files
|
|
for useful run-time information such
|
|
as method calls and run times. </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 startMethodTracing() in your activity's onCreate()
|
|
method, and call stopMethodTracing() in that activity's 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 create an SD card image upon which
|
|
the trace files will be written. For example, from the <code>/tools</code> directory, you
|
|
can create an SD card image named "imgcd" and mount it when launching the emulator like so:</p>
|
|
<pre>
|
|
<b>$</b> mksdcard 1024M ./imgcd
|
|
<b>$</b> emulator -sdcard ./imgcd
|
|
</pre>
|
|
<p>For more information, read about the
|
|
<a href="{@docRoot}guide/developing/tools/othertools.html#mksdcard">mksdcard tool</a>.</p>
|
|
|
|
<p>The format of the trace files is described <a href="#format">later
|
|
in this document</a>. </p>
|
|
|
|
<a name="copyingfiles"></a>
|
|
|
|
<h2>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>
|
|
|
|
|
|
<a name="runningtraceview"></a>
|
|
|
|
<h2>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,
|
|
you would use: </p>
|
|
<pre>traceview /tmp/calc</pre>
|
|
|
|
<p>Traceview loads the log files and displays their data in a window that has 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>
|
|
|
|
<a name="timelinepanel"></a>
|
|
|
|
<h3>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 LoadListener.nativeFinished() and it was
|
|
selected in the profile view. </p>
|
|
<p><img src="/images/traceview_timeline.png" alt="Traceview timeline panel" width="893" height="284"></p>
|
|
<a name="profilepanel"></a>
|
|
<h3>Profile Panel</h3>
|
|
<p>The image below shows the profile pane. The profile pane shows 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 LoadListener.nativeFinished(); looking
|
|
at the timeline panel shows that one of those calls took an unusually
|
|
long time.</p>
|
|
<p><img src="/images/traceview_profile.png" alt="Traceview profile panel." width="892" height="630"></p>
|
|
|
|
<a name="format"></a>
|
|
<h2>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>
|
|
|
|
<a name="datafileformat"></a>
|
|
|
|
<h3>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 gettimeofday().
|
|
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>
|
|
|
|
<a name="keyfileformat"></a>
|
|
|
|
<h3>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>
|
|
<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>
|
|
|
|
<a name="knownissues"></a>
|
|
<h2>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>
|
|
|
|
<a name="dmtracedump"></a>
|
|
|
|
<h2>Using dmtracedump</h2>
|
|
|
|
<p>The Android SDK includes dmtracedump, 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" style="margin-top:1em;"/>
|
|
|
|
<p style="margin-top:1em;">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 <trace-base-name>.data and <trace-base-name>.key.
|
|
The table below lists the options for dmtracedump.</p>
|
|
|
|
<table>
|
|
<tr>
|
|
<th>Option</td>
|
|
<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>
|