Stefan Hajnoczi | 81a97d9 | 2010-06-22 15:07:09 +0100 | [diff] [blame] | 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 --trace-backend=simple |
| 13 | make |
| 14 | |
Lluís | dd215f6 | 2011-08-31 20:31:38 +0200 | [diff] [blame^] | 15 | 2. Run the virtual machine to produce a trace file: |
Stefan Hajnoczi | 81a97d9 | 2010-06-22 15:07:09 +0100 | [diff] [blame] | 16 | |
| 17 | qemu ... # your normal QEMU invocation |
| 18 | |
Lluís | dd215f6 | 2011-08-31 20:31:38 +0200 | [diff] [blame^] | 19 | 3. Pretty-print the binary trace file: |
Stefan Hajnoczi | 81a97d9 | 2010-06-22 15:07:09 +0100 | [diff] [blame] | 20 | |
| 21 | ./simpletrace.py trace-events trace-* |
| 22 | |
| 23 | == Trace events == |
| 24 | |
Lluís | 7b92e5b | 2011-04-06 20:33:56 +0200 | [diff] [blame] | 25 | There is a set of static trace events declared in the "trace-events" source |
Stefan Hajnoczi | 81a97d9 | 2010-06-22 15:07:09 +0100 | [diff] [blame] | 26 | file. Each trace event declaration names the event, its arguments, and the |
| 27 | format string which can be used for pretty-printing: |
| 28 | |
| 29 | qemu_malloc(size_t size, void *ptr) "size %zu ptr %p" |
| 30 | qemu_free(void *ptr) "ptr %p" |
| 31 | |
Lluís | 7b92e5b | 2011-04-06 20:33:56 +0200 | [diff] [blame] | 32 | The "trace-events" file is processed by the "tracetool" script during build to |
Stefan Hajnoczi | 81a97d9 | 2010-06-22 15:07:09 +0100 | [diff] [blame] | 33 | generate code for the trace events. Trace events are invoked directly from |
| 34 | source code like this: |
| 35 | |
| 36 | #include "trace.h" /* needed for trace event prototype */ |
Lluís | 4992604 | 2011-08-31 20:31:10 +0200 | [diff] [blame] | 37 | |
Stefan Hajnoczi | 81a97d9 | 2010-06-22 15:07:09 +0100 | [diff] [blame] | 38 | void *qemu_malloc(size_t size) |
| 39 | { |
| 40 | void *ptr; |
| 41 | if (!size && !allow_zero_malloc()) { |
| 42 | abort(); |
| 43 | } |
| 44 | ptr = oom_check(malloc(size ? size : 1)); |
| 45 | trace_qemu_malloc(size, ptr); /* <-- trace event */ |
| 46 | return ptr; |
| 47 | } |
| 48 | |
| 49 | === Declaring trace events === |
| 50 | |
Lluís | 7b92e5b | 2011-04-06 20:33:56 +0200 | [diff] [blame] | 51 | The "tracetool" script produces the trace.h header file which is included by |
Stefan Hajnoczi | 81a97d9 | 2010-06-22 15:07:09 +0100 | [diff] [blame] | 52 | every source file that uses trace events. Since many source files include |
Lluís | 7b92e5b | 2011-04-06 20:33:56 +0200 | [diff] [blame] | 53 | trace.h, it uses a minimum of types and other header files included to keep the |
| 54 | namespace clean and compile times and dependencies down. |
Stefan Hajnoczi | 81a97d9 | 2010-06-22 15:07:09 +0100 | [diff] [blame] | 55 | |
| 56 | Trace events should use types as follows: |
| 57 | |
| 58 | * Use stdint.h types for fixed-size types. Most offsets and guest memory |
| 59 | addresses are best represented with uint32_t or uint64_t. Use fixed-size |
| 60 | types over primitive types whose size may change depending on the host |
| 61 | (32-bit versus 64-bit) so trace events don't truncate values or break |
| 62 | the build. |
| 63 | |
| 64 | * Use void * for pointers to structs or for arrays. The trace.h header |
| 65 | cannot include all user-defined struct declarations and it is therefore |
| 66 | necessary to use void * for pointers to structs. |
| 67 | |
Stefan Hajnoczi | e6a750a | 2011-04-14 18:24:50 +0100 | [diff] [blame] | 68 | Pointers (including char *) cannot be dereferenced easily (or at all) in |
| 69 | some trace backends. If pointers are used, ensure they are meaningful by |
| 70 | themselves and do not assume the data they point to will be traced. Do |
| 71 | not pass in string arguments. |
| 72 | |
Stefan Hajnoczi | 81a97d9 | 2010-06-22 15:07:09 +0100 | [diff] [blame] | 73 | * For everything else, use primitive scalar types (char, int, long) with the |
| 74 | appropriate signedness. |
| 75 | |
Stefan Hajnoczi | 9a85d39 | 2010-10-05 14:28:50 +0100 | [diff] [blame] | 76 | Format strings should reflect the types defined in the trace event. Take |
| 77 | special care to use PRId64 and PRIu64 for int64_t and uint64_t types, |
Stefan Hajnoczi | cf85cf8 | 2010-10-20 16:41:31 +0000 | [diff] [blame] | 78 | respectively. This ensures portability between 32- and 64-bit platforms. Note |
| 79 | that format strings must begin and end with double quotes. When using |
| 80 | portability macros, ensure they are preceded and followed by double quotes: |
| 81 | "value %"PRIx64"". |
Stefan Hajnoczi | 9a85d39 | 2010-10-05 14:28:50 +0100 | [diff] [blame] | 82 | |
Stefan Hajnoczi | 81a97d9 | 2010-06-22 15:07:09 +0100 | [diff] [blame] | 83 | === Hints for adding new trace events === |
| 84 | |
| 85 | 1. Trace state changes in the code. Interesting points in the code usually |
| 86 | involve a state change like starting, stopping, allocating, freeing. State |
| 87 | changes are good trace events because they can be used to understand the |
| 88 | execution of the system. |
| 89 | |
| 90 | 2. Trace guest operations. Guest I/O accesses like reading device registers |
| 91 | are good trace events because they can be used to understand guest |
| 92 | interactions. |
| 93 | |
| 94 | 3. Use correlator fields so the context of an individual line of trace output |
| 95 | can be understood. For example, trace the pointer returned by malloc and |
| 96 | used as an argument to free. This way mallocs and frees can be matched up. |
| 97 | Trace events with no context are not very useful. |
| 98 | |
| 99 | 4. Name trace events after their function. If there are multiple trace events |
| 100 | in one function, append a unique distinguisher at the end of the name. |
| 101 | |
Lluís | dd215f6 | 2011-08-31 20:31:38 +0200 | [diff] [blame^] | 102 | 5. If specific trace events are going to be called a huge number of times, this |
| 103 | might have a noticeable performance impact even when the trace events are |
| 104 | programmatically disabled. In this case you should declare the trace event |
| 105 | with the "disable" property, which will effectively disable it at compile |
| 106 | time (using the "nop" backend). |
Stefan Hajnoczi | 81a97d9 | 2010-06-22 15:07:09 +0100 | [diff] [blame] | 107 | |
Lluís | 31965ae | 2011-08-31 20:31:24 +0200 | [diff] [blame] | 108 | == Generic interface and monitor commands == |
| 109 | |
| 110 | You can programmatically query and control the dynamic state of trace events |
| 111 | through a backend-agnostic interface: |
| 112 | |
| 113 | * trace_print_events |
| 114 | |
| 115 | * trace_event_set_state |
| 116 | Enables or disables trace events at runtime inside QEMU. |
| 117 | The function returns "true" if the state of the event has been successfully |
| 118 | changed, or "false" otherwise: |
| 119 | |
| 120 | #include "trace/control.h" |
| 121 | |
| 122 | trace_event_set_state("virtio_irq", true); /* enable */ |
| 123 | [...] |
| 124 | trace_event_set_state("virtio_irq", false); /* disable */ |
| 125 | |
| 126 | Note that some of the backends do not provide an implementation for this |
| 127 | interface, in which case QEMU will just print a warning. |
| 128 | |
| 129 | This functionality is also provided through monitor commands: |
| 130 | |
| 131 | * info trace-events |
| 132 | View available trace events and their state. State 1 means enabled, state 0 |
| 133 | means disabled. |
| 134 | |
| 135 | * trace-event NAME on|off |
| 136 | Enable/disable a given trace event. |
| 137 | |
Lluís | 23d15e8 | 2011-08-31 20:31:31 +0200 | [diff] [blame] | 138 | The "-trace events=<file>" command line argument can be used to enable the |
| 139 | events listed in <file> from the very beginning of the program. This file must |
| 140 | contain one event name per line. |
| 141 | |
Stefan Hajnoczi | 81a97d9 | 2010-06-22 15:07:09 +0100 | [diff] [blame] | 142 | == Trace backends == |
| 143 | |
Lluís | 7b92e5b | 2011-04-06 20:33:56 +0200 | [diff] [blame] | 144 | The "tracetool" script automates tedious trace event code generation and also |
Stefan Hajnoczi | 81a97d9 | 2010-06-22 15:07:09 +0100 | [diff] [blame] | 145 | keeps the trace event declarations independent of the trace backend. The trace |
| 146 | events are not tightly coupled to a specific trace backend, such as LTTng or |
Lluís | 7b92e5b | 2011-04-06 20:33:56 +0200 | [diff] [blame] | 147 | SystemTap. Support for trace backends can be added by extending the "tracetool" |
Stefan Hajnoczi | 81a97d9 | 2010-06-22 15:07:09 +0100 | [diff] [blame] | 148 | script. |
| 149 | |
| 150 | The trace backend is chosen at configure time and only one trace backend can |
| 151 | be built into the binary: |
| 152 | |
| 153 | ./configure --trace-backend=simple |
| 154 | |
| 155 | For a list of supported trace backends, try ./configure --help or see below. |
| 156 | |
| 157 | The following subsections describe the supported trace backends. |
| 158 | |
| 159 | === Nop === |
| 160 | |
| 161 | The "nop" backend generates empty trace event functions so that the compiler |
| 162 | can optimize out trace events completely. This is the default and imposes no |
| 163 | performance penalty. |
| 164 | |
Lluís | dd215f6 | 2011-08-31 20:31:38 +0200 | [diff] [blame^] | 165 | Note that regardless of the selected trace backend, events with the "disable" |
| 166 | property will be generated with the "nop" backend. |
| 167 | |
Stefan Hajnoczi | b48c20f | 2011-02-23 14:00:21 +0000 | [diff] [blame] | 168 | === Stderr === |
| 169 | |
| 170 | The "stderr" backend sends trace events directly to standard error. This |
| 171 | effectively turns trace events into debug printfs. |
| 172 | |
| 173 | This is the simplest backend and can be used together with existing code that |
| 174 | uses DPRINTF(). |
| 175 | |
Lluís | dd215f6 | 2011-08-31 20:31:38 +0200 | [diff] [blame^] | 176 | Note that with this backend trace events cannot be programmatically |
| 177 | enabled/disabled. Thus, in order to trim down the amount of output and the |
| 178 | performance impact of tracing, you might want to add the "disable" property in |
| 179 | the "trace-events" file for those events you are not interested in. |
| 180 | |
Stefan Hajnoczi | 81a97d9 | 2010-06-22 15:07:09 +0100 | [diff] [blame] | 181 | === Simpletrace === |
| 182 | |
| 183 | The "simple" backend supports common use cases and comes as part of the QEMU |
| 184 | source tree. It may not be as powerful as platform-specific or third-party |
| 185 | trace backends but it is portable. This is the recommended trace backend |
| 186 | unless you have specific needs for more advanced backends. |
| 187 | |
Stefan Hajnoczi | 81a97d9 | 2010-06-22 15:07:09 +0100 | [diff] [blame] | 188 | ==== Monitor commands ==== |
| 189 | |
| 190 | * info trace |
| 191 | Display the contents of trace buffer. This command dumps the trace buffer |
| 192 | with simple formatting. For full pretty-printing, use the simpletrace.py |
| 193 | script on a binary trace file. |
| 194 | |
| 195 | The trace buffer is written into until full. The full trace buffer is |
| 196 | flushed and emptied. This means the 'info trace' will display few or no |
| 197 | entries if the buffer has just been flushed. |
| 198 | |
Stefan Hajnoczi | 81a97d9 | 2010-06-22 15:07:09 +0100 | [diff] [blame] | 199 | * trace-file on|off|flush|set <path> |
| 200 | Enable/disable/flush the trace file or set the trace file name. |
| 201 | |
Stefan Hajnoczi | 81a97d9 | 2010-06-22 15:07:09 +0100 | [diff] [blame] | 202 | ==== Analyzing trace files ==== |
| 203 | |
| 204 | The "simple" backend produces binary trace files that can be formatted with the |
Lluís | 7b92e5b | 2011-04-06 20:33:56 +0200 | [diff] [blame] | 205 | simpletrace.py script. The script takes the "trace-events" file and the binary |
Stefan Hajnoczi | 81a97d9 | 2010-06-22 15:07:09 +0100 | [diff] [blame] | 206 | trace: |
| 207 | |
| 208 | ./simpletrace.py trace-events trace-12345 |
| 209 | |
Lluís | 7b92e5b | 2011-04-06 20:33:56 +0200 | [diff] [blame] | 210 | You must ensure that the same "trace-events" file was used to build QEMU, |
Stefan Hajnoczi | 81a97d9 | 2010-06-22 15:07:09 +0100 | [diff] [blame] | 211 | otherwise trace event declarations may have changed and output will not be |
| 212 | consistent. |
| 213 | |
| 214 | === LTTng Userspace Tracer === |
| 215 | |
| 216 | The "ust" backend uses the LTTng Userspace Tracer library. There are no |
| 217 | monitor commands built into QEMU, instead UST utilities should be used to list, |
| 218 | enable/disable, and dump traces. |
Stefan Hajnoczi | b48c20f | 2011-02-23 14:00:21 +0000 | [diff] [blame] | 219 | |
| 220 | === SystemTap === |
| 221 | |
| 222 | The "dtrace" backend uses DTrace sdt probes but has only been tested with |
| 223 | SystemTap. When SystemTap support is detected a .stp file with wrapper probes |
| 224 | is generated to make use in scripts more convenient. This step can also be |
| 225 | performed manually after a build in order to change the binary name in the .stp |
| 226 | probes: |
| 227 | |
| 228 | scripts/tracetool --dtrace --stap \ |
| 229 | --binary path/to/qemu-binary \ |
| 230 | --target-type system \ |
| 231 | --target-arch x86_64 \ |
| 232 | <trace-events >qemu.stp |