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