blob: 7d389263940d09531a882d8157256daa2475b5b8 [file] [log] [blame]
Stefan Hajnoczi81a97d92010-06-22 15:07:09 +01001= Tracing =
2
3== Introduction ==
4
5This document describes the tracing infrastructure in QEMU and how to use it
6for debugging, profiling, and observing execution.
7
8== Quickstart ==
9
101. Build with the 'simple' trace backend:
11
Lluís Vilanova5b808272014-05-27 15:02:14 +020012 ./configure --enable-trace-backends=simple
Stefan Hajnoczi81a97d92010-06-22 15:07:09 +010013 make
14
Lluís03727e62011-08-31 20:31:45 +0200152. Create a file with the events you want to trace:
Stefan Hajnoczi81a97d92010-06-22 15:07:09 +010016
Lluís03727e62011-08-31 20:31:45 +020017 echo bdrv_aio_readv > /tmp/events
18 echo bdrv_aio_writev >> /tmp/events
Stefan Hajnoczi81a97d92010-06-22 15:07:09 +010019
Lluís03727e62011-08-31 20:31:45 +0200203. Run the virtual machine to produce a trace file:
21
22 qemu -trace events=/tmp/events ... # your normal QEMU invocation
23
244. Pretty-print the binary trace file:
Stefan Hajnoczi81a97d92010-06-22 15:07:09 +010025
Chen Fan60e17d22014-07-11 11:24:37 +080026 ./scripts/simpletrace.py trace-events trace-* # Override * with QEMU <pid>
Stefan Hajnoczi81a97d92010-06-22 15:07:09 +010027
28== Trace events ==
29
Lluís7b92e5b2011-04-06 20:33:56 +020030There is a set of static trace events declared in the "trace-events" source
Stefan Hajnoczi81a97d92010-06-22 15:07:09 +010031file. Each trace event declaration names the event, its arguments, and the
32format string which can be used for pretty-printing:
33
Lluís Vilanova4b710a32011-09-20 21:03:48 +020034 qemu_vmalloc(size_t size, void *ptr) "size %zu ptr %p"
35 qemu_vfree(void *ptr) "ptr %p"
Stefan Hajnoczi81a97d92010-06-22 15:07:09 +010036
Lluís7b92e5b2011-04-06 20:33:56 +020037The "trace-events" file is processed by the "tracetool" script during build to
Stefan Hajnoczi81a97d92010-06-22 15:07:09 +010038generate code for the trace events. Trace events are invoked directly from
39source code like this:
40
41 #include "trace.h" /* needed for trace event prototype */
Lluís49926042011-08-31 20:31:10 +020042
Lluís Vilanova4b710a32011-09-20 21:03:48 +020043 void *qemu_vmalloc(size_t size)
Stefan Hajnoczi81a97d92010-06-22 15:07:09 +010044 {
45 void *ptr;
Lluís Vilanova4b710a32011-09-20 21:03:48 +020046 size_t align = QEMU_VMALLOC_ALIGN;
47
48 if (size < align) {
49 align = getpagesize();
Stefan Hajnoczi81a97d92010-06-22 15:07:09 +010050 }
Lluís Vilanova4b710a32011-09-20 21:03:48 +020051 ptr = qemu_memalign(align, size);
52 trace_qemu_vmalloc(size, ptr);
Stefan Hajnoczi81a97d92010-06-22 15:07:09 +010053 return ptr;
54 }
55
56=== Declaring trace events ===
57
Lluís7b92e5b2011-04-06 20:33:56 +020058The "tracetool" script produces the trace.h header file which is included by
Stefan Hajnoczi81a97d92010-06-22 15:07:09 +010059every source file that uses trace events. Since many source files include
Lluís7b92e5b2011-04-06 20:33:56 +020060trace.h, it uses a minimum of types and other header files included to keep the
61namespace clean and compile times and dependencies down.
Stefan Hajnoczi81a97d92010-06-22 15:07:09 +010062
63Trace events should use types as follows:
64
65 * Use stdint.h types for fixed-size types. Most offsets and guest memory
66 addresses are best represented with uint32_t or uint64_t. Use fixed-size
67 types over primitive types whose size may change depending on the host
68 (32-bit versus 64-bit) so trace events don't truncate values or break
69 the build.
70
71 * Use void * for pointers to structs or for arrays. The trace.h header
72 cannot include all user-defined struct declarations and it is therefore
73 necessary to use void * for pointers to structs.
74
75 * For everything else, use primitive scalar types (char, int, long) with the
76 appropriate signedness.
77
Stefan Hajnoczi9a85d392010-10-05 14:28:50 +010078Format strings should reflect the types defined in the trace event. Take
79special care to use PRId64 and PRIu64 for int64_t and uint64_t types,
Stefan Hajnoczi913540a2011-09-13 13:34:35 +010080respectively. This ensures portability between 32- and 64-bit platforms.
Stefan Hajnoczi9a85d392010-10-05 14:28:50 +010081
Stefan Hajnoczi81a97d92010-06-22 15:07:09 +010082=== Hints for adding new trace events ===
83
841. Trace state changes in the code. Interesting points in the code usually
85 involve a state change like starting, stopping, allocating, freeing. State
86 changes are good trace events because they can be used to understand the
87 execution of the system.
88
892. Trace guest operations. Guest I/O accesses like reading device registers
90 are good trace events because they can be used to understand guest
91 interactions.
92
933. Use correlator fields so the context of an individual line of trace output
94 can be understood. For example, trace the pointer returned by malloc and
95 used as an argument to free. This way mallocs and frees can be matched up.
96 Trace events with no context are not very useful.
97
984. Name trace events after their function. If there are multiple trace events
99 in one function, append a unique distinguisher at the end of the name.
100
Lluís31965ae2011-08-31 20:31:24 +0200101== Generic interface and monitor commands ==
102
Lluís Vilanovab1bae812013-03-05 14:47:38 +0100103You can programmatically query and control the state of trace events through a
104backend-agnostic interface provided by the header "trace/control.h".
Lluís31965ae2011-08-31 20:31:24 +0200105
Lluís Vilanovab1bae812013-03-05 14:47:38 +0100106Note that some of the backends do not provide an implementation for some parts
107of this interface, in which case QEMU will just print a warning (please refer to
108header "trace/control.h" to see which routines are backend-dependent).
Lluís31965ae2011-08-31 20:31:24 +0200109
Lluís Vilanovab1bae812013-03-05 14:47:38 +0100110The state of events can also be queried and modified through monitor commands:
Lluís31965ae2011-08-31 20:31:24 +0200111
112* info trace-events
113 View available trace events and their state. State 1 means enabled, state 0
114 means disabled.
115
116* trace-event NAME on|off
Lluís Vilanovab1bae812013-03-05 14:47:38 +0100117 Enable/disable a given trace event or a group of events (using wildcards).
Lluís31965ae2011-08-31 20:31:24 +0200118
Lluís23d15e82011-08-31 20:31:31 +0200119The "-trace events=<file>" command line argument can be used to enable the
120events listed in <file> from the very beginning of the program. This file must
121contain one event name per line.
122
Stefan Hajnoczi8f5a0fb2012-11-05 08:48:29 +0100123If a line in the "-trace events=<file>" file begins with a '-', the trace event
124will be disabled instead of enabled. This is useful when a wildcard was used
125to enable an entire family of events but one noisy event needs to be disabled.
126
Lluís Vilanovab1bae812013-03-05 14:47:38 +0100127Wildcard matching is supported in both the monitor command "trace-event" and the
128events list file. That means you can enable/disable the events having a common
129prefix in a batch. For example, virtio-blk trace events could be enabled using
130the following monitor command:
131
132 trace-event virtio_blk_* on
133
Stefan Hajnoczi81a97d92010-06-22 15:07:09 +0100134== Trace backends ==
135
Lluís7b92e5b2011-04-06 20:33:56 +0200136The "tracetool" script automates tedious trace event code generation and also
Stefan Hajnoczi81a97d92010-06-22 15:07:09 +0100137keeps the trace event declarations independent of the trace backend. The trace
138events are not tightly coupled to a specific trace backend, such as LTTng or
Lluís7b92e5b2011-04-06 20:33:56 +0200139SystemTap. Support for trace backends can be added by extending the "tracetool"
Stefan Hajnoczi81a97d92010-06-22 15:07:09 +0100140script.
141
142The trace backend is chosen at configure time and only one trace backend can
143be built into the binary:
144
Lluís Vilanova5b808272014-05-27 15:02:14 +0200145 ./configure --trace-backends=simple
Stefan Hajnoczi81a97d92010-06-22 15:07:09 +0100146
147For a list of supported trace backends, try ./configure --help or see below.
148
149The following subsections describe the supported trace backends.
150
151=== Nop ===
152
153The "nop" backend generates empty trace event functions so that the compiler
154can optimize out trace events completely. This is the default and imposes no
155performance penalty.
156
Lluísdd215f62011-08-31 20:31:38 +0200157Note that regardless of the selected trace backend, events with the "disable"
158property will be generated with the "nop" backend.
159
Stefan Hajnoczib48c20f2011-02-23 14:00:21 +0000160=== Stderr ===
161
162The "stderr" backend sends trace events directly to standard error. This
163effectively turns trace events into debug printfs.
164
165This is the simplest backend and can be used together with existing code that
166uses DPRINTF().
167
Stefan Hajnoczi81a97d92010-06-22 15:07:09 +0100168=== Simpletrace ===
169
170The "simple" backend supports common use cases and comes as part of the QEMU
171source tree. It may not be as powerful as platform-specific or third-party
172trace backends but it is portable. This is the recommended trace backend
173unless you have specific needs for more advanced backends.
174
Stefan Hajnoczi8f642112011-09-05 16:31:45 +0100175The "simple" backend currently does not capture string arguments, it simply
176records the char* pointer value instead of the string that is pointed to.
177
Eiichi Tsukatae64dd5e2013-04-11 20:25:16 +0900178=== Ftrace ===
179
180The "ftrace" backend writes trace data to ftrace marker. This effectively
181sends trace events to ftrace ring buffer, and you can compare qemu trace
182data and kernel(especially kvm.ko when using KVM) trace data.
183
184if you use KVM, enable kvm events in ftrace:
185
186 # echo 1 > /sys/kernel/debug/tracing/events/kvm/enable
187
188After running qemu by root user, you can get the trace:
189
190 # cat /sys/kernel/debug/tracing/trace
191
192Restriction: "ftrace" backend is restricted to Linux only.
193
Stefan Hajnoczi81a97d92010-06-22 15:07:09 +0100194==== Monitor commands ====
195
Stefan Hajnoczi81a97d92010-06-22 15:07:09 +0100196* trace-file on|off|flush|set <path>
197 Enable/disable/flush the trace file or set the trace file name.
198
Stefan Hajnoczi81a97d92010-06-22 15:07:09 +0100199==== Analyzing trace files ====
200
201The "simple" backend produces binary trace files that can be formatted with the
Lluís7b92e5b2011-04-06 20:33:56 +0200202simpletrace.py script. The script takes the "trace-events" file and the binary
Stefan Hajnoczi81a97d92010-06-22 15:07:09 +0100203trace:
204
Markus Armbruster8f440152013-01-25 16:43:40 +0100205 ./scripts/simpletrace.py trace-events trace-12345
Stefan Hajnoczi81a97d92010-06-22 15:07:09 +0100206
Lluís7b92e5b2011-04-06 20:33:56 +0200207You must ensure that the same "trace-events" file was used to build QEMU,
Stefan Hajnoczi81a97d92010-06-22 15:07:09 +0100208otherwise trace event declarations may have changed and output will not be
209consistent.
210
211=== LTTng Userspace Tracer ===
212
213The "ust" backend uses the LTTng Userspace Tracer library. There are no
214monitor commands built into QEMU, instead UST utilities should be used to list,
215enable/disable, and dump traces.
Stefan Hajnoczib48c20f2011-02-23 14:00:21 +0000216
Mohamad Gebaief3ef4a2014-01-29 22:47:57 -0500217Package lttng-tools is required for userspace tracing. You must ensure that the
218current user belongs to the "tracing" group, or manually launch the
219lttng-sessiond daemon for the current user prior to running any instance of
220QEMU.
221
222While running an instrumented QEMU, LTTng should be able to list all available
223events:
224
225 lttng list -u
226
227Create tracing session:
228
229 lttng create mysession
230
231Enable events:
232
233 lttng enable-event qemu:g_malloc -u
234
235Where the events can either be a comma-separated list of events, or "-a" to
236enable all tracepoint events. Start and stop tracing as needed:
237
238 lttng start
239 lttng stop
240
241View the trace:
242
243 lttng view
244
245Destroy tracing session:
246
247 lttng destroy
248
249Babeltrace can be used at any later time to view the trace:
250
251 babeltrace $HOME/lttng-traces/mysession-<date>-<time>
252
Stefan Hajnoczib48c20f2011-02-23 14:00:21 +0000253=== SystemTap ===
254
255The "dtrace" backend uses DTrace sdt probes but has only been tested with
256SystemTap. When SystemTap support is detected a .stp file with wrapper probes
257is generated to make use in scripts more convenient. This step can also be
258performed manually after a build in order to change the binary name in the .stp
259probes:
260
261 scripts/tracetool --dtrace --stap \
262 --binary path/to/qemu-binary \
263 --target-type system \
Paolo Bonzinib9a7b742013-06-04 14:45:26 +0200264 --target-name x86_64 \
Stefan Hajnoczib48c20f2011-02-23 14:00:21 +0000265 <trace-events >qemu.stp
Lluís Vilanovab7d66a72011-12-06 17:38:15 +0100266
267== Trace event properties ==
268
269Each event in the "trace-events" file can be prefixed with a space-separated
270list of zero or more of the following event properties.
271
272=== "disable" ===
273
274If a specific trace event is going to be invoked a huge number of times, this
275might have a noticeable performance impact even when the event is
276programmatically disabled.
277
278In this case you should declare such event with the "disable" property. This
279will effectively disable the event at compile time (by using the "nop" backend),
280thus having no performance impact at all on regular builds (i.e., unless you
281edit the "trace-events" file).
282
283In addition, there might be cases where relatively complex computations must be
284performed to generate values that are only used as arguments for a trace
285function. In these cases you can use the macro 'TRACE_${EVENT_NAME}_ENABLED' to
286guard such computations and avoid its compilation when the event is disabled:
287
288 #include "trace.h" /* needed for trace event prototype */
289
290 void *qemu_vmalloc(size_t size)
291 {
292 void *ptr;
293 size_t align = QEMU_VMALLOC_ALIGN;
294
295 if (size < align) {
296 align = getpagesize();
297 }
298 ptr = qemu_memalign(align, size);
299 if (TRACE_QEMU_VMALLOC_ENABLED) { /* preprocessor macro */
300 void *complex;
301 /* some complex computations to produce the 'complex' value */
302 trace_qemu_vmalloc(size, ptr, complex);
303 }
304 return ptr;
305 }
Lluís Vilanovab1bae812013-03-05 14:47:38 +0100306
307You can check both if the event has been disabled and is dynamically enabled at
308the same time using the 'trace_event_get_state' routine (see header
309"trace/control.h" for more information).
Lluís Vilanova0bb403b2014-05-30 14:11:26 +0200310
311=== "tcg" ===
312
313Guest code generated by TCG can be traced by defining an event with the "tcg"
314event property. Internally, this property generates two events:
315"<eventname>_trans" to trace the event at translation time, and
316"<eventname>_exec" to trace the event at execution time.
317
318Instead of using these two events, you should instead use the function
319"trace_<eventname>_tcg" during translation (TCG code generation). This function
320will automatically call "trace_<eventname>_trans", and will generate the
321necessary TCG code to call "trace_<eventname>_exec" during guest code execution.
322
323Events with the "tcg" property can be declared in the "trace-events" file with a
324mix of native and TCG types, and "trace_<eventname>_tcg" will gracefully forward
325them to the "<eventname>_trans" and "<eventname>_exec" events. Since TCG values
326are not known at translation time, these are ignored by the "<eventname>_trans"
327event. Because of this, the entry in the "trace-events" file needs two printing
328formats (separated by a comma):
329
330 tcg foo(uint8_t a1, TCGv_i32 a2) "a1=%d", "a1=%d a2=%d"
331
332For example:
333
334 #include "trace-tcg.h"
335
336 void some_disassembly_func (...)
337 {
338 uint8_t a1 = ...;
339 TCGv_i32 a2 = ...;
340 trace_foo_tcg(a1, a2);
341 }
342
343This will immediately call:
344
345 void trace_foo_trans(uint8_t a1);
346
347and will generate the TCG code to call:
348
349 void trace_foo(uint8_t a1, uint32_t a2);