]>
Commit | Line | Data |
---|---|---|
26f7227b SH |
1 | /* |
2 | * Simple trace backend | |
3 | * | |
4 | * Copyright IBM, Corp. 2010 | |
5 | * | |
6 | * This work is licensed under the terms of the GNU GPL, version 2. See | |
7 | * the COPYING file in the top-level directory. | |
8 | * | |
9 | */ | |
10 | ||
d38ea87a | 11 | #include "qemu/osdep.h" |
85aff158 | 12 | #ifndef _WIN32 |
0b5538c3 | 13 | #include <pthread.h> |
85aff158 | 14 | #endif |
1de7afc9 | 15 | #include "qemu/timer.h" |
e4858974 | 16 | #include "trace/control.h" |
b618c288 | 17 | #include "trace/simple.h" |
2ab4b135 | 18 | #include "qemu/error-report.h" |
ba4912cb | 19 | #include "qemu/qemu-print.h" |
26f7227b | 20 | |
ef4c9fc8 DB |
21 | /** Trace file header event ID, picked to avoid conflict with real event IDs */ |
22 | #define HEADER_EVENT_ID (~(uint64_t)0) | |
26f7227b SH |
23 | |
24 | /** Trace file magic number */ | |
25 | #define HEADER_MAGIC 0xf2b177cb0aa429b4ULL | |
26 | ||
27 | /** Trace file version number, bump if format changes */ | |
7f1b588f | 28 | #define HEADER_VERSION 4 |
26f7227b | 29 | |
0b5538c3 SH |
30 | /** Records were dropped event ID */ |
31 | #define DROPPED_EVENT_ID (~(uint64_t)0 - 1) | |
32 | ||
33 | /** Trace record is valid */ | |
34 | #define TRACE_RECORD_VALID ((uint64_t)1 << 63) | |
35 | ||
0b5538c3 SH |
36 | /* |
37 | * Trace records are written out by a dedicated thread. The thread waits for | |
38 | * records to become available, writes them out, and then waits again. | |
39 | */ | |
e7b3af81 DB |
40 | static GMutex trace_lock; |
41 | static GCond trace_available_cond; | |
42 | static GCond trace_empty_cond; | |
4a0e6714 | 43 | |
0b5538c3 SH |
44 | static bool trace_available; |
45 | static bool trace_writeout_enabled; | |
46 | ||
62bab732 HPB |
47 | enum { |
48 | TRACE_BUF_LEN = 4096 * 64, | |
49 | TRACE_BUF_FLUSH_THRESHOLD = TRACE_BUF_LEN / 4, | |
50 | }; | |
51 | ||
52 | uint8_t trace_buf[TRACE_BUF_LEN]; | |
30d94087 | 53 | static volatile gint trace_idx; |
62bab732 | 54 | static unsigned int writeout_idx; |
30d94087 | 55 | static volatile gint dropped_events; |
26896cbf | 56 | static uint32_t trace_pid; |
26f7227b | 57 | static FILE *trace_fp; |
4552e410 | 58 | static char *trace_file_name; |
26f7227b | 59 | |
7f1b588f DB |
60 | #define TRACE_RECORD_TYPE_MAPPING 0 |
61 | #define TRACE_RECORD_TYPE_EVENT 1 | |
62 | ||
62bab732 HPB |
63 | /* * Trace buffer entry */ |
64 | typedef struct { | |
ef4c9fc8 | 65 | uint64_t event; /* event ID value */ |
62bab732 HPB |
66 | uint64_t timestamp_ns; |
67 | uint32_t length; /* in bytes */ | |
26896cbf | 68 | uint32_t pid; |
fb3a5085 | 69 | uint64_t arguments[]; |
62bab732 HPB |
70 | } TraceRecord; |
71 | ||
72 | typedef struct { | |
73 | uint64_t header_event_id; /* HEADER_EVENT_ID */ | |
74 | uint64_t header_magic; /* HEADER_MAGIC */ | |
75 | uint64_t header_version; /* HEADER_VERSION */ | |
8ae601e8 | 76 | } TraceLogHeader; |
62bab732 HPB |
77 | |
78 | ||
79 | static void read_from_buffer(unsigned int idx, void *dataptr, size_t size); | |
80 | static unsigned int write_to_buffer(unsigned int idx, void *dataptr, size_t size); | |
81 | ||
82 | static void clear_buffer_range(unsigned int idx, size_t len) | |
83 | { | |
84 | uint32_t num = 0; | |
85 | while (num < len) { | |
86 | if (idx >= TRACE_BUF_LEN) { | |
87 | idx = idx % TRACE_BUF_LEN; | |
88 | } | |
89 | trace_buf[idx++] = 0; | |
90 | num++; | |
91 | } | |
92 | } | |
c5ceb523 | 93 | /** |
0b5538c3 SH |
94 | * Read a trace record from the trace buffer |
95 | * | |
96 | * @idx Trace buffer index | |
97 | * @record Trace record to fill | |
98 | * | |
99 | * Returns false if the record is not valid. | |
c5ceb523 | 100 | */ |
62bab732 | 101 | static bool get_trace_record(unsigned int idx, TraceRecord **recordptr) |
9410b56c | 102 | { |
62bab732 HPB |
103 | uint64_t event_flag = 0; |
104 | TraceRecord record; | |
105 | /* read the event flag to see if its a valid record */ | |
106 | read_from_buffer(idx, &record, sizeof(event_flag)); | |
107 | ||
108 | if (!(record.event & TRACE_RECORD_VALID)) { | |
0b5538c3 | 109 | return false; |
9410b56c PS |
110 | } |
111 | ||
62bab732 HPB |
112 | smp_rmb(); /* read memory barrier before accessing record */ |
113 | /* read the record header to know record length */ | |
114 | read_from_buffer(idx, &record, sizeof(TraceRecord)); | |
cb8d4c8f | 115 | *recordptr = malloc(record.length); /* don't use g_malloc, can deadlock when traced */ |
62bab732 HPB |
116 | /* make a copy of record to avoid being overwritten */ |
117 | read_from_buffer(idx, *recordptr, record.length); | |
118 | smp_rmb(); /* memory barrier before clearing valid flag */ | |
119 | (*recordptr)->event &= ~TRACE_RECORD_VALID; | |
120 | /* clear the trace buffer range for consumed record otherwise any byte | |
121 | * with its MSB set may be considered as a valid event id when the writer | |
122 | * thread crosses this range of buffer again. | |
123 | */ | |
124 | clear_buffer_range(idx, record.length); | |
c5ceb523 | 125 | return true; |
9410b56c PS |
126 | } |
127 | ||
0b5538c3 SH |
128 | /** |
129 | * Kick writeout thread | |
130 | * | |
131 | * @wait Whether to wait for writeout thread to complete | |
132 | */ | |
133 | static void flush_trace_file(bool wait) | |
26f7227b | 134 | { |
86946a2d | 135 | g_mutex_lock(&trace_lock); |
0b5538c3 | 136 | trace_available = true; |
86946a2d | 137 | g_cond_signal(&trace_available_cond); |
c5ceb523 | 138 | |
0b5538c3 | 139 | if (wait) { |
86946a2d | 140 | g_cond_wait(&trace_empty_cond, &trace_lock); |
26f7227b | 141 | } |
0b5538c3 | 142 | |
86946a2d | 143 | g_mutex_unlock(&trace_lock); |
c5ceb523 SH |
144 | } |
145 | ||
0b5538c3 | 146 | static void wait_for_trace_records_available(void) |
c5ceb523 | 147 | { |
86946a2d | 148 | g_mutex_lock(&trace_lock); |
0b5538c3 | 149 | while (!(trace_available && trace_writeout_enabled)) { |
86946a2d MT |
150 | g_cond_signal(&trace_empty_cond); |
151 | g_cond_wait(&trace_available_cond, &trace_lock); | |
c5ceb523 | 152 | } |
0b5538c3 | 153 | trace_available = false; |
86946a2d | 154 | g_mutex_unlock(&trace_lock); |
26f7227b SH |
155 | } |
156 | ||
85aff158 | 157 | static gpointer writeout_thread(gpointer opaque) |
26f7227b | 158 | { |
62bab732 HPB |
159 | TraceRecord *recordptr; |
160 | union { | |
161 | TraceRecord rec; | |
162 | uint8_t bytes[sizeof(TraceRecord) + sizeof(uint64_t)]; | |
163 | } dropped; | |
164 | unsigned int idx = 0; | |
fb3a5085 | 165 | int dropped_count; |
0caf448b | 166 | size_t unused __attribute__ ((unused)); |
7f1b588f | 167 | uint64_t type = TRACE_RECORD_TYPE_EVENT; |
0b5538c3 SH |
168 | |
169 | for (;;) { | |
170 | wait_for_trace_records_available(); | |
171 | ||
e722d705 | 172 | if (g_atomic_int_get(&dropped_events)) { |
7ff59207 | 173 | dropped.rec.event = DROPPED_EVENT_ID; |
62bab732 | 174 | dropped.rec.timestamp_ns = get_clock(); |
7ff59207 | 175 | dropped.rec.length = sizeof(TraceRecord) + sizeof(uint64_t); |
26896cbf | 176 | dropped.rec.pid = trace_pid; |
b6b2c962 | 177 | do { |
e722d705 | 178 | dropped_count = g_atomic_int_get(&dropped_events); |
b6b2c962 MA |
179 | } while (!g_atomic_int_compare_and_exchange(&dropped_events, |
180 | dropped_count, 0)); | |
fb3a5085 | 181 | dropped.rec.arguments[0] = dropped_count; |
7f1b588f | 182 | unused = fwrite(&type, sizeof(type), 1, trace_fp); |
62bab732 | 183 | unused = fwrite(&dropped.rec, dropped.rec.length, 1, trace_fp); |
0b5538c3 | 184 | } |
26f7227b | 185 | |
62bab732 | 186 | while (get_trace_record(idx, &recordptr)) { |
7f1b588f | 187 | unused = fwrite(&type, sizeof(type), 1, trace_fp); |
62bab732 HPB |
188 | unused = fwrite(recordptr, recordptr->length, 1, trace_fp); |
189 | writeout_idx += recordptr->length; | |
cb8d4c8f | 190 | free(recordptr); /* don't use g_free, can deadlock when traced */ |
62bab732 | 191 | idx = writeout_idx % TRACE_BUF_LEN; |
0b5538c3 | 192 | } |
26f7227b | 193 | |
0b5538c3 | 194 | fflush(trace_fp); |
26f7227b | 195 | } |
0b5538c3 | 196 | return NULL; |
26f7227b SH |
197 | } |
198 | ||
62bab732 | 199 | void trace_record_write_u64(TraceBufferRecord *rec, uint64_t val) |
26f7227b | 200 | { |
62bab732 | 201 | rec->rec_off = write_to_buffer(rec->rec_off, &val, sizeof(uint64_t)); |
26f7227b SH |
202 | } |
203 | ||
62bab732 | 204 | void trace_record_write_str(TraceBufferRecord *rec, const char *s, uint32_t slen) |
26f7227b | 205 | { |
62bab732 HPB |
206 | /* Write string length first */ |
207 | rec->rec_off = write_to_buffer(rec->rec_off, &slen, sizeof(slen)); | |
208 | /* Write actual string now */ | |
209 | rec->rec_off = write_to_buffer(rec->rec_off, (void*)s, slen); | |
26f7227b SH |
210 | } |
211 | ||
ef4c9fc8 | 212 | int trace_record_start(TraceBufferRecord *rec, uint32_t event, size_t datasize) |
26f7227b | 213 | { |
62bab732 HPB |
214 | unsigned int idx, rec_off, old_idx, new_idx; |
215 | uint32_t rec_len = sizeof(TraceRecord) + datasize; | |
60481e21 | 216 | uint64_t event_u64 = event; |
62bab732 HPB |
217 | uint64_t timestamp_ns = get_clock(); |
218 | ||
b6b2c962 | 219 | do { |
e722d705 | 220 | old_idx = g_atomic_int_get(&trace_idx); |
62bab732 HPB |
221 | smp_rmb(); |
222 | new_idx = old_idx + rec_len; | |
223 | ||
224 | if (new_idx - writeout_idx > TRACE_BUF_LEN) { | |
225 | /* Trace Buffer Full, Event dropped ! */ | |
fb3a5085 | 226 | g_atomic_int_inc(&dropped_events); |
62bab732 HPB |
227 | return -ENOSPC; |
228 | } | |
b6b2c962 | 229 | } while (!g_atomic_int_compare_and_exchange(&trace_idx, old_idx, new_idx)); |
26f7227b | 230 | |
62bab732 | 231 | idx = old_idx % TRACE_BUF_LEN; |
62bab732 HPB |
232 | |
233 | rec_off = idx; | |
60481e21 | 234 | rec_off = write_to_buffer(rec_off, &event_u64, sizeof(event_u64)); |
83d35d3e HPB |
235 | rec_off = write_to_buffer(rec_off, ×tamp_ns, sizeof(timestamp_ns)); |
236 | rec_off = write_to_buffer(rec_off, &rec_len, sizeof(rec_len)); | |
26896cbf | 237 | rec_off = write_to_buffer(rec_off, &trace_pid, sizeof(trace_pid)); |
62bab732 HPB |
238 | |
239 | rec->tbuf_idx = idx; | |
240 | rec->rec_off = (idx + sizeof(TraceRecord)) % TRACE_BUF_LEN; | |
241 | return 0; | |
26f7227b SH |
242 | } |
243 | ||
62bab732 | 244 | static void read_from_buffer(unsigned int idx, void *dataptr, size_t size) |
26f7227b | 245 | { |
62bab732 HPB |
246 | uint8_t *data_ptr = dataptr; |
247 | uint32_t x = 0; | |
248 | while (x < size) { | |
249 | if (idx >= TRACE_BUF_LEN) { | |
250 | idx = idx % TRACE_BUF_LEN; | |
251 | } | |
252 | data_ptr[x++] = trace_buf[idx++]; | |
253 | } | |
26f7227b SH |
254 | } |
255 | ||
62bab732 | 256 | static unsigned int write_to_buffer(unsigned int idx, void *dataptr, size_t size) |
26f7227b | 257 | { |
62bab732 HPB |
258 | uint8_t *data_ptr = dataptr; |
259 | uint32_t x = 0; | |
260 | while (x < size) { | |
261 | if (idx >= TRACE_BUF_LEN) { | |
262 | idx = idx % TRACE_BUF_LEN; | |
263 | } | |
264 | trace_buf[idx++] = data_ptr[x++]; | |
265 | } | |
266 | return idx; /* most callers wants to know where to write next */ | |
26f7227b SH |
267 | } |
268 | ||
62bab732 | 269 | void trace_record_finish(TraceBufferRecord *rec) |
26f7227b | 270 | { |
db8894f2 HPB |
271 | TraceRecord record; |
272 | read_from_buffer(rec->tbuf_idx, &record, sizeof(TraceRecord)); | |
62bab732 | 273 | smp_wmb(); /* write barrier before marking as valid */ |
db8894f2 HPB |
274 | record.event |= TRACE_RECORD_VALID; |
275 | write_to_buffer(rec->tbuf_idx, &record, sizeof(TraceRecord)); | |
62bab732 | 276 | |
30d94087 | 277 | if (((unsigned int)g_atomic_int_get(&trace_idx) - writeout_idx) |
e722d705 | 278 | > TRACE_BUF_FLUSH_THRESHOLD) { |
62bab732 HPB |
279 | flush_trace_file(false); |
280 | } | |
26f7227b SH |
281 | } |
282 | ||
7f1b588f DB |
283 | static int st_write_event_mapping(void) |
284 | { | |
285 | uint64_t type = TRACE_RECORD_TYPE_MAPPING; | |
286 | TraceEventIter iter; | |
287 | TraceEvent *ev; | |
288 | ||
289 | trace_event_iter_init(&iter, NULL); | |
290 | while ((ev = trace_event_iter_next(&iter)) != NULL) { | |
291 | uint64_t id = trace_event_get_id(ev); | |
292 | const char *name = trace_event_get_name(ev); | |
293 | uint32_t len = strlen(name); | |
294 | if (fwrite(&type, sizeof(type), 1, trace_fp) != 1 || | |
295 | fwrite(&id, sizeof(id), 1, trace_fp) != 1 || | |
296 | fwrite(&len, sizeof(len), 1, trace_fp) != 1 || | |
297 | fwrite(name, len, 1, trace_fp) != 1) { | |
298 | return -1; | |
299 | } | |
300 | } | |
301 | ||
302 | return 0; | |
303 | } | |
304 | ||
0b5538c3 SH |
305 | void st_set_trace_file_enabled(bool enable) |
306 | { | |
307 | if (enable == !!trace_fp) { | |
308 | return; /* no change */ | |
309 | } | |
310 | ||
311 | /* Halt trace writeout */ | |
312 | flush_trace_file(true); | |
313 | trace_writeout_enabled = false; | |
314 | flush_trace_file(true); | |
315 | ||
316 | if (enable) { | |
8ae601e8 | 317 | static const TraceLogHeader header = { |
62bab732 HPB |
318 | .header_event_id = HEADER_EVENT_ID, |
319 | .header_magic = HEADER_MAGIC, | |
320 | /* Older log readers will check for version at next location */ | |
321 | .header_version = HEADER_VERSION, | |
0b5538c3 SH |
322 | }; |
323 | ||
6c2a4074 | 324 | trace_fp = fopen(trace_file_name, "wb"); |
0b5538c3 SH |
325 | if (!trace_fp) { |
326 | return; | |
327 | } | |
328 | ||
7f1b588f DB |
329 | if (fwrite(&header, sizeof header, 1, trace_fp) != 1 || |
330 | st_write_event_mapping() < 0) { | |
0b5538c3 SH |
331 | fclose(trace_fp); |
332 | trace_fp = NULL; | |
333 | return; | |
334 | } | |
335 | ||
336 | /* Resume trace writeout */ | |
337 | trace_writeout_enabled = true; | |
338 | flush_trace_file(false); | |
339 | } else { | |
340 | fclose(trace_fp); | |
341 | trace_fp = NULL; | |
342 | } | |
343 | } | |
344 | ||
26f7227b | 345 | /** |
0b5538c3 SH |
346 | * Set the name of a trace file |
347 | * | |
348 | * @file The trace file name or NULL for the default name-<pid> set at | |
349 | * config time | |
26f7227b | 350 | */ |
41fc57e4 | 351 | void st_set_trace_file(const char *file) |
26f7227b | 352 | { |
0b5538c3 SH |
353 | st_set_trace_file_enabled(false); |
354 | ||
4552e410 | 355 | g_free(trace_file_name); |
0b5538c3 SH |
356 | |
357 | if (!file) { | |
857a0e38 SW |
358 | /* Type cast needed for Windows where getpid() returns an int. */ |
359 | trace_file_name = g_strdup_printf(CONFIG_TRACE_FILE, (pid_t)getpid()); | |
0b5538c3 | 360 | } else { |
4552e410 | 361 | trace_file_name = g_strdup_printf("%s", file); |
0b5538c3 SH |
362 | } |
363 | ||
364 | st_set_trace_file_enabled(true); | |
0b5538c3 SH |
365 | } |
366 | ||
ba4912cb | 367 | void st_print_trace_file_status(void) |
0b5538c3 | 368 | { |
ba4912cb MA |
369 | qemu_printf("Trace file \"%s\" %s.\n", |
370 | trace_file_name, trace_fp ? "on" : "off"); | |
26f7227b | 371 | } |
22890ab5 | 372 | |
fc764105 LV |
373 | void st_flush_trace_buffer(void) |
374 | { | |
375 | flush_trace_file(true); | |
376 | } | |
377 | ||
85aff158 SH |
378 | /* Helper function to create a thread with signals blocked. Use glib's |
379 | * portable threads since QEMU abstractions cannot be used due to reentrancy in | |
380 | * the tracer. Also note the signal masking on POSIX hosts so that the thread | |
381 | * does not steal signals when the rest of the program wants them blocked. | |
382 | */ | |
383 | static GThread *trace_thread_create(GThreadFunc fn) | |
22890ab5 | 384 | { |
85aff158 SH |
385 | GThread *thread; |
386 | #ifndef _WIN32 | |
0b5538c3 | 387 | sigset_t set, oldset; |
22890ab5 | 388 | |
0b5538c3 SH |
389 | sigfillset(&set); |
390 | pthread_sigmask(SIG_SETMASK, &set, &oldset); | |
85aff158 | 391 | #endif |
4a0e6714 | 392 | |
4a0e6714 | 393 | thread = g_thread_new("trace-thread", fn, NULL); |
4a0e6714 | 394 | |
85aff158 | 395 | #ifndef _WIN32 |
0b5538c3 | 396 | pthread_sigmask(SIG_SETMASK, &oldset, NULL); |
85aff158 | 397 | #endif |
0b5538c3 | 398 | |
85aff158 SH |
399 | return thread; |
400 | } | |
401 | ||
41fc57e4 | 402 | bool st_init(void) |
85aff158 SH |
403 | { |
404 | GThread *thread; | |
405 | ||
26896cbf SH |
406 | trace_pid = getpid(); |
407 | ||
85aff158 SH |
408 | thread = trace_thread_create(writeout_thread); |
409 | if (!thread) { | |
2ab4b135 | 410 | warn_report("unable to initialize simple trace backend"); |
85aff158 | 411 | return false; |
22890ab5 | 412 | } |
0b5538c3 | 413 | |
85aff158 | 414 | atexit(st_flush_trace_buffer); |
31d3c9b8 | 415 | return true; |
22890ab5 | 416 | } |