Merge remote-tracking branch 'remotes/armbru/tags/pull-qapi-2017-03-16' into staging
[qemu.git] / docs / tracing.txt
1 = Tracing =
2
3 == Introduction ==
4
5 This document describes the tracing infrastructure in QEMU and how to use it
6 for debugging, profiling, and observing execution.
7
8 == Quickstart ==
9
10 1. Build with the 'simple' trace backend:
11
12     ./configure --enable-trace-backends=simple
13     make
14
15 2. Create a file with the events you want to trace:
16
17    echo bdrv_aio_readv   > /tmp/events
18    echo bdrv_aio_writev >> /tmp/events
19
20 3. Run the virtual machine to produce a trace file:
21
22     qemu -trace events=/tmp/events ... # your normal QEMU invocation
23
24 4. Pretty-print the binary trace file:
25
26     ./scripts/simpletrace.py trace-events-all trace-* # Override * with QEMU <pid>
27
28 == Trace events ==
29
30 === Sub-directory setup ===
31
32 Each directory in the source tree can declare a set of static trace events
33 in a local "trace-events" file. All directories which contain "trace-events"
34 files must be listed in the "trace-events-subdirs" make variable in the top
35 level Makefile.objs. During build, the "trace-events" file in each listed
36 subdirectory will be processed by the "tracetool" script to generate code for
37 the trace events.
38
39 The individual "trace-events" files are merged into a "trace-events-all" file,
40 which is also installed into "/usr/share/qemu" with the name "trace-events".
41 This merged file is to be used by the "simpletrace.py" script to later analyse
42 traces in the simpletrace data format.
43
44 In the sub-directory the following files will be automatically generated
45
46  - trace.c - the trace event state declarations
47  - trace.h - the trace event enums and probe functions
48  - trace-dtrace.h - DTrace event probe specification
49  - trace-dtrace.dtrace - DTrace event probe helper declaration
50  - trace-dtrace.o - binary DTrace provider (generated by dtrace)
51  - trace-ust.h - UST event probe helper declarations
52
53 Source files in the sub-directory should #include the local 'trace.h' file,
54 without any sub-directory path prefix. eg io/channel-buffer.c would do
55
56   #include "trace.h"
57
58 To access the 'io/trace.h' file. While it is possible to include a trace.h
59 file from outside a source files' own sub-directory, this is discouraged in
60 general. It is strongly preferred that all events be declared directly in
61 the sub-directory that uses them. The only exception is where there are some
62 shared trace events defined in the top level directory trace-events file.
63 The top level directory generates trace files with a filename prefix of
64 "trace-root" instead of just "trace". This is to avoid ambiguity between
65 a trace.h in the current directory, vs the top level directory.
66
67 === Using trace events ===
68
69 Trace events are invoked directly from source code like this:
70
71     #include "trace.h"  /* needed for trace event prototype */
72     
73     void *qemu_vmalloc(size_t size)
74     {
75         void *ptr;
76         size_t align = QEMU_VMALLOC_ALIGN;
77      
78         if (size < align) {
79             align = getpagesize();
80         }
81         ptr = qemu_memalign(align, size);
82         trace_qemu_vmalloc(size, ptr);
83         return ptr;
84     }
85
86 === Declaring trace events ===
87
88 The "tracetool" script produces the trace.h header file which is included by
89 every source file that uses trace events.  Since many source files include
90 trace.h, it uses a minimum of types and other header files included to keep the
91 namespace clean and compile times and dependencies down.
92
93 Trace events should use types as follows:
94
95  * Use stdint.h types for fixed-size types.  Most offsets and guest memory
96    addresses are best represented with uint32_t or uint64_t.  Use fixed-size
97    types over primitive types whose size may change depending on the host
98    (32-bit versus 64-bit) so trace events don't truncate values or break
99    the build.
100
101  * Use void * for pointers to structs or for arrays.  The trace.h header
102    cannot include all user-defined struct declarations and it is therefore
103    necessary to use void * for pointers to structs.
104
105  * For everything else, use primitive scalar types (char, int, long) with the
106    appropriate signedness.
107
108 Format strings should reflect the types defined in the trace event.  Take
109 special care to use PRId64 and PRIu64 for int64_t and uint64_t types,
110 respectively.  This ensures portability between 32- and 64-bit platforms.
111
112 Each event declaration will start with the event name, then its arguments,
113 finally a format string for pretty-printing. For example:
114
115     qemu_vmalloc(size_t size, void *ptr) "size %zu ptr %p"
116     qemu_vfree(void *ptr) "ptr %p"
117
118
119 === Hints for adding new trace events ===
120
121 1. Trace state changes in the code.  Interesting points in the code usually
122    involve a state change like starting, stopping, allocating, freeing.  State
123    changes are good trace events because they can be used to understand the
124    execution of the system.
125
126 2. Trace guest operations.  Guest I/O accesses like reading device registers
127    are good trace events because they can be used to understand guest
128    interactions.
129
130 3. Use correlator fields so the context of an individual line of trace output
131    can be understood.  For example, trace the pointer returned by malloc and
132    used as an argument to free.  This way mallocs and frees can be matched up.
133    Trace events with no context are not very useful.
134
135 4. Name trace events after their function.  If there are multiple trace events
136    in one function, append a unique distinguisher at the end of the name.
137
138 == Generic interface and monitor commands ==
139
140 You can programmatically query and control the state of trace events through a
141 backend-agnostic interface provided by the header "trace/control.h".
142
143 Note that some of the backends do not provide an implementation for some parts
144 of this interface, in which case QEMU will just print a warning (please refer to
145 header "trace/control.h" to see which routines are backend-dependent).
146
147 The state of events can also be queried and modified through monitor commands:
148
149 * info trace-events
150   View available trace events and their state.  State 1 means enabled, state 0
151   means disabled.
152
153 * trace-event NAME on|off
154   Enable/disable a given trace event or a group of events (using wildcards).
155
156 The "-trace events=<file>" command line argument can be used to enable the
157 events listed in <file> from the very beginning of the program. This file must
158 contain one event name per line.
159
160 If a line in the "-trace events=<file>" file begins with a '-', the trace event
161 will be disabled instead of enabled.  This is useful when a wildcard was used
162 to enable an entire family of events but one noisy event needs to be disabled.
163
164 Wildcard matching is supported in both the monitor command "trace-event" and the
165 events list file. That means you can enable/disable the events having a common
166 prefix in a batch. For example, virtio-blk trace events could be enabled using
167 the following monitor command:
168
169     trace-event virtio_blk_* on
170
171 == Trace backends ==
172
173 The "tracetool" script automates tedious trace event code generation and also
174 keeps the trace event declarations independent of the trace backend.  The trace
175 events are not tightly coupled to a specific trace backend, such as LTTng or
176 SystemTap.  Support for trace backends can be added by extending the "tracetool"
177 script.
178
179 The trace backends are chosen at configure time:
180
181     ./configure --enable-trace-backends=simple
182
183 For a list of supported trace backends, try ./configure --help or see below.
184 If multiple backends are enabled, the trace is sent to them all.
185
186 If no backends are explicitly selected, configure will default to the
187 "log" backend.
188
189 The following subsections describe the supported trace backends.
190
191 === Nop ===
192
193 The "nop" backend generates empty trace event functions so that the compiler
194 can optimize out trace events completely.  This imposes no performance
195 penalty.
196
197 Note that regardless of the selected trace backend, events with the "disable"
198 property will be generated with the "nop" backend.
199
200 === Log ===
201
202 The "log" backend sends trace events directly to standard error.  This
203 effectively turns trace events into debug printfs.
204
205 This is the simplest backend and can be used together with existing code that
206 uses DPRINTF().
207
208 === Simpletrace ===
209
210 The "simple" backend supports common use cases and comes as part of the QEMU
211 source tree.  It may not be as powerful as platform-specific or third-party
212 trace backends but it is portable.  This is the recommended trace backend
213 unless you have specific needs for more advanced backends.
214
215 === Ftrace ===
216
217 The "ftrace" backend writes trace data to ftrace marker. This effectively
218 sends trace events to ftrace ring buffer, and you can compare qemu trace
219 data and kernel(especially kvm.ko when using KVM) trace data.
220
221 if you use KVM, enable kvm events in ftrace:
222
223    # echo 1 > /sys/kernel/debug/tracing/events/kvm/enable
224
225 After running qemu by root user, you can get the trace:
226
227    # cat /sys/kernel/debug/tracing/trace
228
229 Restriction: "ftrace" backend is restricted to Linux only.
230
231 === Syslog ===
232
233 The "syslog" backend sends trace events using the POSIX syslog API. The log
234 is opened specifying the LOG_DAEMON facility and LOG_PID option (so events
235 are tagged with the pid of the particular QEMU process that generated
236 them). All events are logged at LOG_INFO level.
237
238 NOTE: syslog may squash duplicate consecutive trace events and apply rate
239       limiting.
240
241 Restriction: "syslog" backend is restricted to POSIX compliant OS.
242
243 ==== Monitor commands ====
244
245 * trace-file on|off|flush|set <path>
246   Enable/disable/flush the trace file or set the trace file name.
247
248 ==== Analyzing trace files ====
249
250 The "simple" backend produces binary trace files that can be formatted with the
251 simpletrace.py script.  The script takes the "trace-events-all" file and the
252 binary trace:
253
254     ./scripts/simpletrace.py trace-events-all trace-12345
255
256 You must ensure that the same "trace-events-all" file was used to build QEMU,
257 otherwise trace event declarations may have changed and output will not be
258 consistent.
259
260 === LTTng Userspace Tracer ===
261
262 The "ust" backend uses the LTTng Userspace Tracer library.  There are no
263 monitor commands built into QEMU, instead UST utilities should be used to list,
264 enable/disable, and dump traces.
265
266 Package lttng-tools is required for userspace tracing. You must ensure that the
267 current user belongs to the "tracing" group, or manually launch the
268 lttng-sessiond daemon for the current user prior to running any instance of
269 QEMU.
270
271 While running an instrumented QEMU, LTTng should be able to list all available
272 events:
273
274     lttng list -u
275
276 Create tracing session:
277
278     lttng create mysession
279
280 Enable events:
281
282     lttng enable-event qemu:g_malloc -u
283
284 Where the events can either be a comma-separated list of events, or "-a" to
285 enable all tracepoint events. Start and stop tracing as needed:
286
287     lttng start
288     lttng stop
289
290 View the trace:
291
292     lttng view
293
294 Destroy tracing session:
295
296     lttng destroy
297
298 Babeltrace can be used at any later time to view the trace:
299
300     babeltrace $HOME/lttng-traces/mysession-<date>-<time>
301
302 === SystemTap ===
303
304 The "dtrace" backend uses DTrace sdt probes but has only been tested with
305 SystemTap.  When SystemTap support is detected a .stp file with wrapper probes
306 is generated to make use in scripts more convenient.  This step can also be
307 performed manually after a build in order to change the binary name in the .stp
308 probes:
309
310     scripts/tracetool.py --backends=dtrace --format=stap \
311                          --binary path/to/qemu-binary \
312                          --target-type system \
313                          --target-name x86_64 \
314                          <trace-events-all >qemu.stp
315
316 == Trace event properties ==
317
318 Each event in the "trace-events-all" file can be prefixed with a space-separated
319 list of zero or more of the following event properties.
320
321 === "disable" ===
322
323 If a specific trace event is going to be invoked a huge number of times, this
324 might have a noticeable performance impact even when the event is
325 programmatically disabled.
326
327 In this case you should declare such event with the "disable" property. This
328 will effectively disable the event at compile time (by using the "nop" backend),
329 thus having no performance impact at all on regular builds (i.e., unless you
330 edit the "trace-events-all" file).
331
332 In addition, there might be cases where relatively complex computations must be
333 performed to generate values that are only used as arguments for a trace
334 function. In these cases you can use the macro 'TRACE_${EVENT_NAME}_ENABLED' to
335 guard such computations and avoid its compilation when the event is disabled:
336
337     #include "trace.h"  /* needed for trace event prototype */
338     
339     void *qemu_vmalloc(size_t size)
340     {
341         void *ptr;
342         size_t align = QEMU_VMALLOC_ALIGN;
343     
344         if (size < align) {
345             align = getpagesize();
346         }
347         ptr = qemu_memalign(align, size);
348         if (TRACE_QEMU_VMALLOC_ENABLED) { /* preprocessor macro */
349             void *complex;
350             /* some complex computations to produce the 'complex' value */
351             trace_qemu_vmalloc(size, ptr, complex);
352         }
353         return ptr;
354     }
355
356 You can check both if the event has been disabled and is dynamically enabled at
357 the same time using the 'trace_event_get_state' routine (see header
358 "trace/control.h" for more information).
359
360 === "tcg" ===
361
362 Guest code generated by TCG can be traced by defining an event with the "tcg"
363 event property. Internally, this property generates two events:
364 "<eventname>_trans" to trace the event at translation time, and
365 "<eventname>_exec" to trace the event at execution time.
366
367 Instead of using these two events, you should instead use the function
368 "trace_<eventname>_tcg" during translation (TCG code generation). This function
369 will automatically call "trace_<eventname>_trans", and will generate the
370 necessary TCG code to call "trace_<eventname>_exec" during guest code execution.
371
372 Events with the "tcg" property can be declared in the "trace-events" file with a
373 mix of native and TCG types, and "trace_<eventname>_tcg" will gracefully forward
374 them to the "<eventname>_trans" and "<eventname>_exec" events. Since TCG values
375 are not known at translation time, these are ignored by the "<eventname>_trans"
376 event. Because of this, the entry in the "trace-events" file needs two printing
377 formats (separated by a comma):
378
379     tcg foo(uint8_t a1, TCGv_i32 a2) "a1=%d", "a1=%d a2=%d"
380
381 For example:
382
383     #include "trace-tcg.h"
384     
385     void some_disassembly_func (...)
386     {
387         uint8_t a1 = ...;
388         TCGv_i32 a2 = ...;
389         trace_foo_tcg(a1, a2);
390     }
391
392 This will immediately call:
393
394     void trace_foo_trans(uint8_t a1);
395
396 and will generate the TCG code to call:
397
398     void trace_foo(uint8_t a1, uint32_t a2);
399
400 === "vcpu" ===
401
402 Identifies events that trace vCPU-specific information. It implicitly adds a
403 "CPUState*" argument, and extends the tracing print format to show the vCPU
404 information. If used together with the "tcg" property, it adds a second
405 "TCGv_env" argument that must point to the per-target global TCG register that
406 points to the vCPU when guest code is executed (usually the "cpu_env" variable).
407
408 The following example events:
409
410     foo(uint32_t a) "a=%x"
411     vcpu bar(uint32_t a) "a=%x"
412     tcg vcpu baz(uint32_t a) "a=%x", "a=%x"
413
414 Can be used as:
415
416     #include "trace-tcg.h"
417     
418     CPUArchState *env;
419     TCGv_ptr cpu_env;
420     
421     void some_disassembly_func(...)
422     {
423         /* trace emitted at this point */
424         trace_foo(0xd1);
425         /* trace emitted at this point */
426         trace_bar(ENV_GET_CPU(env), 0xd2);
427         /* trace emitted at this point (env) and when guest code is executed (cpu_env) */
428         trace_baz_tcg(ENV_GET_CPU(env), cpu_env, 0xd3);
429     }
430
431 If the translating vCPU has address 0xc1 and code is later executed by vCPU
432 0xc2, this would be an example output:
433
434     // at guest code translation
435     foo a=0xd1
436     bar cpu=0xc1 a=0xd2
437     baz_trans cpu=0xc1 a=0xd3
438     // at guest code execution
439     baz_exec cpu=0xc2 a=0xd3