2010-06-22 18:07:09 +04:00
|
|
|
= Tracing =
|
|
|
|
|
|
|
|
== Introduction ==
|
|
|
|
|
|
|
|
This document describes the tracing infrastructure in QEMU and how to use it
|
|
|
|
for debugging, profiling, and observing execution.
|
|
|
|
|
|
|
|
== Quickstart ==
|
|
|
|
|
|
|
|
1. Build with the 'simple' trace backend:
|
|
|
|
|
2012-03-08 12:24:52 +04:00
|
|
|
./configure --enable-trace-backend=simple
|
2010-06-22 18:07:09 +04:00
|
|
|
make
|
|
|
|
|
2011-08-31 22:31:45 +04:00
|
|
|
2. Create a file with the events you want to trace:
|
2010-06-22 18:07:09 +04:00
|
|
|
|
2011-08-31 22:31:45 +04:00
|
|
|
echo bdrv_aio_readv > /tmp/events
|
|
|
|
echo bdrv_aio_writev >> /tmp/events
|
2010-06-22 18:07:09 +04:00
|
|
|
|
2011-08-31 22:31:45 +04:00
|
|
|
3. Run the virtual machine to produce a trace file:
|
|
|
|
|
|
|
|
qemu -trace events=/tmp/events ... # your normal QEMU invocation
|
|
|
|
|
|
|
|
4. Pretty-print the binary trace file:
|
2010-06-22 18:07:09 +04:00
|
|
|
|
|
|
|
./simpletrace.py trace-events trace-*
|
|
|
|
|
|
|
|
== Trace events ==
|
|
|
|
|
2011-04-06 22:33:56 +04:00
|
|
|
There is a set of static trace events declared in the "trace-events" source
|
2010-06-22 18:07:09 +04:00
|
|
|
file. Each trace event declaration names the event, its arguments, and the
|
|
|
|
format string which can be used for pretty-printing:
|
|
|
|
|
2011-09-20 23:03:48 +04:00
|
|
|
qemu_vmalloc(size_t size, void *ptr) "size %zu ptr %p"
|
|
|
|
qemu_vfree(void *ptr) "ptr %p"
|
2010-06-22 18:07:09 +04:00
|
|
|
|
2011-04-06 22:33:56 +04:00
|
|
|
The "trace-events" file is processed by the "tracetool" script during build to
|
2010-06-22 18:07:09 +04:00
|
|
|
generate code for the trace events. Trace events are invoked directly from
|
|
|
|
source code like this:
|
|
|
|
|
|
|
|
#include "trace.h" /* needed for trace event prototype */
|
2011-08-31 22:31:10 +04:00
|
|
|
|
2011-09-20 23:03:48 +04:00
|
|
|
void *qemu_vmalloc(size_t size)
|
2010-06-22 18:07:09 +04:00
|
|
|
{
|
|
|
|
void *ptr;
|
2011-09-20 23:03:48 +04:00
|
|
|
size_t align = QEMU_VMALLOC_ALIGN;
|
|
|
|
|
|
|
|
if (size < align) {
|
|
|
|
align = getpagesize();
|
2010-06-22 18:07:09 +04:00
|
|
|
}
|
2011-09-20 23:03:48 +04:00
|
|
|
ptr = qemu_memalign(align, size);
|
|
|
|
trace_qemu_vmalloc(size, ptr);
|
2010-06-22 18:07:09 +04:00
|
|
|
return ptr;
|
|
|
|
}
|
|
|
|
|
|
|
|
=== Declaring trace events ===
|
|
|
|
|
2011-04-06 22:33:56 +04:00
|
|
|
The "tracetool" script produces the trace.h header file which is included by
|
2010-06-22 18:07:09 +04:00
|
|
|
every source file that uses trace events. Since many source files include
|
2011-04-06 22:33:56 +04:00
|
|
|
trace.h, it uses a minimum of types and other header files included to keep the
|
|
|
|
namespace clean and compile times and dependencies down.
|
2010-06-22 18:07:09 +04:00
|
|
|
|
|
|
|
Trace events should use types as follows:
|
|
|
|
|
|
|
|
* Use stdint.h types for fixed-size types. Most offsets and guest memory
|
|
|
|
addresses are best represented with uint32_t or uint64_t. Use fixed-size
|
|
|
|
types over primitive types whose size may change depending on the host
|
|
|
|
(32-bit versus 64-bit) so trace events don't truncate values or break
|
|
|
|
the build.
|
|
|
|
|
|
|
|
* Use void * for pointers to structs or for arrays. The trace.h header
|
|
|
|
cannot include all user-defined struct declarations and it is therefore
|
|
|
|
necessary to use void * for pointers to structs.
|
|
|
|
|
|
|
|
* For everything else, use primitive scalar types (char, int, long) with the
|
|
|
|
appropriate signedness.
|
|
|
|
|
2010-10-05 17:28:50 +04:00
|
|
|
Format strings should reflect the types defined in the trace event. Take
|
|
|
|
special care to use PRId64 and PRIu64 for int64_t and uint64_t types,
|
2011-09-13 16:34:35 +04:00
|
|
|
respectively. This ensures portability between 32- and 64-bit platforms.
|
2010-10-05 17:28:50 +04:00
|
|
|
|
2010-06-22 18:07:09 +04:00
|
|
|
=== Hints for adding new trace events ===
|
|
|
|
|
|
|
|
1. Trace state changes in the code. Interesting points in the code usually
|
|
|
|
involve a state change like starting, stopping, allocating, freeing. State
|
|
|
|
changes are good trace events because they can be used to understand the
|
|
|
|
execution of the system.
|
|
|
|
|
|
|
|
2. Trace guest operations. Guest I/O accesses like reading device registers
|
|
|
|
are good trace events because they can be used to understand guest
|
|
|
|
interactions.
|
|
|
|
|
|
|
|
3. Use correlator fields so the context of an individual line of trace output
|
|
|
|
can be understood. For example, trace the pointer returned by malloc and
|
|
|
|
used as an argument to free. This way mallocs and frees can be matched up.
|
|
|
|
Trace events with no context are not very useful.
|
|
|
|
|
|
|
|
4. Name trace events after their function. If there are multiple trace events
|
|
|
|
in one function, append a unique distinguisher at the end of the name.
|
|
|
|
|
2011-08-31 22:31:24 +04:00
|
|
|
== Generic interface and monitor commands ==
|
|
|
|
|
|
|
|
You can programmatically query and control the dynamic state of trace events
|
|
|
|
through a backend-agnostic interface:
|
|
|
|
|
|
|
|
* trace_print_events
|
|
|
|
|
|
|
|
* trace_event_set_state
|
|
|
|
Enables or disables trace events at runtime inside QEMU.
|
|
|
|
The function returns "true" if the state of the event has been successfully
|
|
|
|
changed, or "false" otherwise:
|
|
|
|
|
|
|
|
#include "trace/control.h"
|
|
|
|
|
|
|
|
trace_event_set_state("virtio_irq", true); /* enable */
|
|
|
|
[...]
|
|
|
|
trace_event_set_state("virtio_irq", false); /* disable */
|
|
|
|
|
|
|
|
Note that some of the backends do not provide an implementation for this
|
|
|
|
interface, in which case QEMU will just print a warning.
|
|
|
|
|
|
|
|
This functionality is also provided through monitor commands:
|
|
|
|
|
|
|
|
* info trace-events
|
|
|
|
View available trace events and their state. State 1 means enabled, state 0
|
|
|
|
means disabled.
|
|
|
|
|
|
|
|
* trace-event NAME on|off
|
2011-10-31 07:29:04 +04:00
|
|
|
Enable/disable a given trace event or a group of events having common prefix
|
|
|
|
through wildcard.
|
2011-08-31 22:31:24 +04:00
|
|
|
|
2011-08-31 22:31:31 +04:00
|
|
|
The "-trace events=<file>" command line argument can be used to enable the
|
|
|
|
events listed in <file> from the very beginning of the program. This file must
|
|
|
|
contain one event name per line.
|
|
|
|
|
2011-10-31 07:29:04 +04:00
|
|
|
A basic wildcard matching is supported in both the monitor command "trace
|
|
|
|
-event" and the events list file. That means you can enable/disable the events
|
|
|
|
having a common prefix in a batch. For example, virtio-blk trace events could
|
|
|
|
be enabled using:
|
|
|
|
trace-event virtio_blk_* on
|
|
|
|
|
2010-06-22 18:07:09 +04:00
|
|
|
== Trace backends ==
|
|
|
|
|
2011-04-06 22:33:56 +04:00
|
|
|
The "tracetool" script automates tedious trace event code generation and also
|
2010-06-22 18:07:09 +04:00
|
|
|
keeps the trace event declarations independent of the trace backend. The trace
|
|
|
|
events are not tightly coupled to a specific trace backend, such as LTTng or
|
2011-04-06 22:33:56 +04:00
|
|
|
SystemTap. Support for trace backends can be added by extending the "tracetool"
|
2010-06-22 18:07:09 +04:00
|
|
|
script.
|
|
|
|
|
|
|
|
The trace backend is chosen at configure time and only one trace backend can
|
|
|
|
be built into the binary:
|
|
|
|
|
|
|
|
./configure --trace-backend=simple
|
|
|
|
|
|
|
|
For a list of supported trace backends, try ./configure --help or see below.
|
|
|
|
|
|
|
|
The following subsections describe the supported trace backends.
|
|
|
|
|
|
|
|
=== Nop ===
|
|
|
|
|
|
|
|
The "nop" backend generates empty trace event functions so that the compiler
|
|
|
|
can optimize out trace events completely. This is the default and imposes no
|
|
|
|
performance penalty.
|
|
|
|
|
2011-08-31 22:31:38 +04:00
|
|
|
Note that regardless of the selected trace backend, events with the "disable"
|
|
|
|
property will be generated with the "nop" backend.
|
|
|
|
|
2011-02-23 17:00:21 +03:00
|
|
|
=== Stderr ===
|
|
|
|
|
|
|
|
The "stderr" backend sends trace events directly to standard error. This
|
|
|
|
effectively turns trace events into debug printfs.
|
|
|
|
|
|
|
|
This is the simplest backend and can be used together with existing code that
|
|
|
|
uses DPRINTF().
|
|
|
|
|
2010-06-22 18:07:09 +04:00
|
|
|
=== Simpletrace ===
|
|
|
|
|
|
|
|
The "simple" backend supports common use cases and comes as part of the QEMU
|
|
|
|
source tree. It may not be as powerful as platform-specific or third-party
|
|
|
|
trace backends but it is portable. This is the recommended trace backend
|
|
|
|
unless you have specific needs for more advanced backends.
|
|
|
|
|
2011-09-05 19:31:45 +04:00
|
|
|
The "simple" backend currently does not capture string arguments, it simply
|
|
|
|
records the char* pointer value instead of the string that is pointed to.
|
|
|
|
|
2010-06-22 18:07:09 +04:00
|
|
|
==== Monitor commands ====
|
|
|
|
|
|
|
|
* info trace
|
|
|
|
Display the contents of trace buffer. This command dumps the trace buffer
|
|
|
|
with simple formatting. For full pretty-printing, use the simpletrace.py
|
|
|
|
script on a binary trace file.
|
|
|
|
|
|
|
|
The trace buffer is written into until full. The full trace buffer is
|
|
|
|
flushed and emptied. This means the 'info trace' will display few or no
|
|
|
|
entries if the buffer has just been flushed.
|
|
|
|
|
|
|
|
* trace-file on|off|flush|set <path>
|
|
|
|
Enable/disable/flush the trace file or set the trace file name.
|
|
|
|
|
|
|
|
==== Analyzing trace files ====
|
|
|
|
|
|
|
|
The "simple" backend produces binary trace files that can be formatted with the
|
2011-04-06 22:33:56 +04:00
|
|
|
simpletrace.py script. The script takes the "trace-events" file and the binary
|
2010-06-22 18:07:09 +04:00
|
|
|
trace:
|
|
|
|
|
|
|
|
./simpletrace.py trace-events trace-12345
|
|
|
|
|
2011-04-06 22:33:56 +04:00
|
|
|
You must ensure that the same "trace-events" file was used to build QEMU,
|
2010-06-22 18:07:09 +04:00
|
|
|
otherwise trace event declarations may have changed and output will not be
|
|
|
|
consistent.
|
|
|
|
|
|
|
|
=== LTTng Userspace Tracer ===
|
|
|
|
|
|
|
|
The "ust" backend uses the LTTng Userspace Tracer library. There are no
|
|
|
|
monitor commands built into QEMU, instead UST utilities should be used to list,
|
|
|
|
enable/disable, and dump traces.
|
2011-02-23 17:00:21 +03:00
|
|
|
|
|
|
|
=== SystemTap ===
|
|
|
|
|
|
|
|
The "dtrace" backend uses DTrace sdt probes but has only been tested with
|
|
|
|
SystemTap. When SystemTap support is detected a .stp file with wrapper probes
|
|
|
|
is generated to make use in scripts more convenient. This step can also be
|
|
|
|
performed manually after a build in order to change the binary name in the .stp
|
|
|
|
probes:
|
|
|
|
|
|
|
|
scripts/tracetool --dtrace --stap \
|
|
|
|
--binary path/to/qemu-binary \
|
|
|
|
--target-type system \
|
|
|
|
--target-arch x86_64 \
|
|
|
|
<trace-events >qemu.stp
|
2011-12-06 20:38:15 +04:00
|
|
|
|
|
|
|
== Trace event properties ==
|
|
|
|
|
|
|
|
Each event in the "trace-events" file can be prefixed with a space-separated
|
|
|
|
list of zero or more of the following event properties.
|
|
|
|
|
|
|
|
=== "disable" ===
|
|
|
|
|
|
|
|
If a specific trace event is going to be invoked a huge number of times, this
|
|
|
|
might have a noticeable performance impact even when the event is
|
|
|
|
programmatically disabled.
|
|
|
|
|
|
|
|
In this case you should declare such event with the "disable" property. This
|
|
|
|
will effectively disable the event at compile time (by using the "nop" backend),
|
|
|
|
thus having no performance impact at all on regular builds (i.e., unless you
|
|
|
|
edit the "trace-events" file).
|
|
|
|
|
|
|
|
In addition, there might be cases where relatively complex computations must be
|
|
|
|
performed to generate values that are only used as arguments for a trace
|
|
|
|
function. In these cases you can use the macro 'TRACE_${EVENT_NAME}_ENABLED' to
|
|
|
|
guard such computations and avoid its compilation when the event is disabled:
|
|
|
|
|
|
|
|
#include "trace.h" /* needed for trace event prototype */
|
|
|
|
|
|
|
|
void *qemu_vmalloc(size_t size)
|
|
|
|
{
|
|
|
|
void *ptr;
|
|
|
|
size_t align = QEMU_VMALLOC_ALIGN;
|
|
|
|
|
|
|
|
if (size < align) {
|
|
|
|
align = getpagesize();
|
|
|
|
}
|
|
|
|
ptr = qemu_memalign(align, size);
|
|
|
|
if (TRACE_QEMU_VMALLOC_ENABLED) { /* preprocessor macro */
|
|
|
|
void *complex;
|
|
|
|
/* some complex computations to produce the 'complex' value */
|
|
|
|
trace_qemu_vmalloc(size, ptr, complex);
|
|
|
|
}
|
|
|
|
return ptr;
|
|
|
|
}
|