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 11 #include "qemu/osdep.h" 12 #ifndef _WIN32 13 #include <pthread.h> 14 #endif 15 #include "qemu/timer.h" 16 #include "trace/control.h" 17 #include "trace/simple.h" 18 #include "qemu/error-report.h" 19 #include "qemu/qemu-print.h" 20 21 /** Trace file header event ID, picked to avoid conflict with real event IDs */ 22 #define HEADER_EVENT_ID (~(uint64_t)0) 23 24 /** Trace file magic number */ 25 #define HEADER_MAGIC 0xf2b177cb0aa429b4ULL 26 27 /** Trace file version number, bump if format changes */ 28 #define HEADER_VERSION 4 29 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 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 */ 40 static GMutex trace_lock; 41 static GCond trace_available_cond; 42 static GCond trace_empty_cond; 43 44 static bool trace_available; 45 static bool trace_writeout_enabled; 46 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]; 53 static volatile gint trace_idx; 54 static unsigned int writeout_idx; 55 static volatile gint dropped_events; 56 static uint32_t trace_pid; 57 static FILE *trace_fp; 58 static char *trace_file_name; 59 60 #define TRACE_RECORD_TYPE_MAPPING 0 61 #define TRACE_RECORD_TYPE_EVENT 1 62 63 /* * Trace buffer entry */ 64 typedef struct { 65 uint64_t event; /* event ID value */ 66 uint64_t timestamp_ns; 67 uint32_t length; /* in bytes */ 68 uint32_t pid; 69 uint64_t arguments[]; 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 */ 76 } TraceLogHeader; 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 } 93 /** 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. 100 */ 101 static bool get_trace_record(unsigned int idx, TraceRecord **recordptr) 102 { 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)) { 109 return false; 110 } 111 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)); 115 *recordptr = malloc(record.length); /* don't use g_malloc, can deadlock when traced */ 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); 125 return true; 126 } 127 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) 134 { 135 g_mutex_lock(&trace_lock); 136 trace_available = true; 137 g_cond_signal(&trace_available_cond); 138 139 if (wait) { 140 g_cond_wait(&trace_empty_cond, &trace_lock); 141 } 142 143 g_mutex_unlock(&trace_lock); 144 } 145 146 static void wait_for_trace_records_available(void) 147 { 148 g_mutex_lock(&trace_lock); 149 while (!(trace_available && trace_writeout_enabled)) { 150 g_cond_signal(&trace_empty_cond); 151 g_cond_wait(&trace_available_cond, &trace_lock); 152 } 153 trace_available = false; 154 g_mutex_unlock(&trace_lock); 155 } 156 157 static gpointer writeout_thread(gpointer opaque) 158 { 159 TraceRecord *recordptr; 160 union { 161 TraceRecord rec; 162 uint8_t bytes[sizeof(TraceRecord) + sizeof(uint64_t)]; 163 } dropped; 164 unsigned int idx = 0; 165 int dropped_count; 166 size_t unused __attribute__ ((unused)); 167 uint64_t type = TRACE_RECORD_TYPE_EVENT; 168 169 for (;;) { 170 wait_for_trace_records_available(); 171 172 if (g_atomic_int_get(&dropped_events)) { 173 dropped.rec.event = DROPPED_EVENT_ID; 174 dropped.rec.timestamp_ns = get_clock(); 175 dropped.rec.length = sizeof(TraceRecord) + sizeof(uint64_t); 176 dropped.rec.pid = trace_pid; 177 do { 178 dropped_count = g_atomic_int_get(&dropped_events); 179 } while (!g_atomic_int_compare_and_exchange(&dropped_events, 180 dropped_count, 0)); 181 dropped.rec.arguments[0] = dropped_count; 182 unused = fwrite(&type, sizeof(type), 1, trace_fp); 183 unused = fwrite(&dropped.rec, dropped.rec.length, 1, trace_fp); 184 } 185 186 while (get_trace_record(idx, &recordptr)) { 187 unused = fwrite(&type, sizeof(type), 1, trace_fp); 188 unused = fwrite(recordptr, recordptr->length, 1, trace_fp); 189 writeout_idx += recordptr->length; 190 free(recordptr); /* don't use g_free, can deadlock when traced */ 191 idx = writeout_idx % TRACE_BUF_LEN; 192 } 193 194 fflush(trace_fp); 195 } 196 return NULL; 197 } 198 199 void trace_record_write_u64(TraceBufferRecord *rec, uint64_t val) 200 { 201 rec->rec_off = write_to_buffer(rec->rec_off, &val, sizeof(uint64_t)); 202 } 203 204 void trace_record_write_str(TraceBufferRecord *rec, const char *s, uint32_t slen) 205 { 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); 210 } 211 212 int trace_record_start(TraceBufferRecord *rec, uint32_t event, size_t datasize) 213 { 214 unsigned int idx, rec_off, old_idx, new_idx; 215 uint32_t rec_len = sizeof(TraceRecord) + datasize; 216 uint64_t event_u64 = event; 217 uint64_t timestamp_ns = get_clock(); 218 219 do { 220 old_idx = g_atomic_int_get(&trace_idx); 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 ! */ 226 g_atomic_int_inc(&dropped_events); 227 return -ENOSPC; 228 } 229 } while (!g_atomic_int_compare_and_exchange(&trace_idx, old_idx, new_idx)); 230 231 idx = old_idx % TRACE_BUF_LEN; 232 233 rec_off = idx; 234 rec_off = write_to_buffer(rec_off, &event_u64, sizeof(event_u64)); 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)); 237 rec_off = write_to_buffer(rec_off, &trace_pid, sizeof(trace_pid)); 238 239 rec->tbuf_idx = idx; 240 rec->rec_off = (idx + sizeof(TraceRecord)) % TRACE_BUF_LEN; 241 return 0; 242 } 243 244 static void read_from_buffer(unsigned int idx, void *dataptr, size_t size) 245 { 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 } 254 } 255 256 static unsigned int write_to_buffer(unsigned int idx, void *dataptr, size_t size) 257 { 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 */ 267 } 268 269 void trace_record_finish(TraceBufferRecord *rec) 270 { 271 TraceRecord record; 272 read_from_buffer(rec->tbuf_idx, &record, sizeof(TraceRecord)); 273 smp_wmb(); /* write barrier before marking as valid */ 274 record.event |= TRACE_RECORD_VALID; 275 write_to_buffer(rec->tbuf_idx, &record, sizeof(TraceRecord)); 276 277 if (((unsigned int)g_atomic_int_get(&trace_idx) - writeout_idx) 278 > TRACE_BUF_FLUSH_THRESHOLD) { 279 flush_trace_file(false); 280 } 281 } 282 283 static int st_write_event_mapping(TraceEventIter *iter) 284 { 285 uint64_t type = TRACE_RECORD_TYPE_MAPPING; 286 TraceEvent *ev; 287 288 while ((ev = trace_event_iter_next(iter)) != NULL) { 289 uint64_t id = trace_event_get_id(ev); 290 const char *name = trace_event_get_name(ev); 291 uint32_t len = strlen(name); 292 if (fwrite(&type, sizeof(type), 1, trace_fp) != 1 || 293 fwrite(&id, sizeof(id), 1, trace_fp) != 1 || 294 fwrite(&len, sizeof(len), 1, trace_fp) != 1 || 295 fwrite(name, len, 1, trace_fp) != 1) { 296 return -1; 297 } 298 } 299 300 return 0; 301 } 302 303 /** 304 * Enable / disable tracing, return whether it was enabled. 305 * 306 * @enable: enable if %true, else disable. 307 */ 308 bool st_set_trace_file_enabled(bool enable) 309 { 310 TraceEventIter iter; 311 bool was_enabled = trace_fp; 312 313 if (enable == !!trace_fp) { 314 return was_enabled; /* no change */ 315 } 316 317 /* Halt trace writeout */ 318 flush_trace_file(true); 319 trace_writeout_enabled = false; 320 flush_trace_file(true); 321 322 if (enable) { 323 static const TraceLogHeader header = { 324 .header_event_id = HEADER_EVENT_ID, 325 .header_magic = HEADER_MAGIC, 326 /* Older log readers will check for version at next location */ 327 .header_version = HEADER_VERSION, 328 }; 329 330 trace_fp = fopen(trace_file_name, "wb"); 331 if (!trace_fp) { 332 return was_enabled; 333 } 334 335 trace_event_iter_init_all(&iter); 336 if (fwrite(&header, sizeof header, 1, trace_fp) != 1 || 337 st_write_event_mapping(&iter) < 0) { 338 fclose(trace_fp); 339 trace_fp = NULL; 340 return was_enabled; 341 } 342 343 /* Resume trace writeout */ 344 trace_writeout_enabled = true; 345 flush_trace_file(false); 346 } else { 347 fclose(trace_fp); 348 trace_fp = NULL; 349 } 350 return was_enabled; 351 } 352 353 /** 354 * Set the name of a trace file 355 * 356 * @file The trace file name or NULL for the default name-<pid> set at 357 * config time 358 */ 359 void st_set_trace_file(const char *file) 360 { 361 bool saved_enable = st_set_trace_file_enabled(false); 362 363 g_free(trace_file_name); 364 365 if (!file) { 366 /* Type cast needed for Windows where getpid() returns an int. */ 367 trace_file_name = g_strdup_printf(CONFIG_TRACE_FILE "-" FMT_pid, (pid_t)getpid()); 368 } else { 369 trace_file_name = g_strdup_printf("%s", file); 370 } 371 372 st_set_trace_file_enabled(saved_enable); 373 } 374 375 void st_print_trace_file_status(void) 376 { 377 qemu_printf("Trace file \"%s\" %s.\n", 378 trace_file_name, trace_fp ? "on" : "off"); 379 } 380 381 void st_flush_trace_buffer(void) 382 { 383 flush_trace_file(true); 384 } 385 386 /* Helper function to create a thread with signals blocked. Use glib's 387 * portable threads since QEMU abstractions cannot be used due to reentrancy in 388 * the tracer. Also note the signal masking on POSIX hosts so that the thread 389 * does not steal signals when the rest of the program wants them blocked. 390 */ 391 static GThread *trace_thread_create(GThreadFunc fn) 392 { 393 GThread *thread; 394 #ifndef _WIN32 395 sigset_t set, oldset; 396 397 sigfillset(&set); 398 pthread_sigmask(SIG_SETMASK, &set, &oldset); 399 #endif 400 401 thread = g_thread_new("trace-thread", fn, NULL); 402 403 #ifndef _WIN32 404 pthread_sigmask(SIG_SETMASK, &oldset, NULL); 405 #endif 406 407 return thread; 408 } 409 410 bool st_init(void) 411 { 412 GThread *thread; 413 414 trace_pid = getpid(); 415 416 thread = trace_thread_create(writeout_thread); 417 if (!thread) { 418 warn_report("unable to initialize simple trace backend"); 419 return false; 420 } 421 422 atexit(st_flush_trace_buffer); 423 return true; 424 } 425 426 void st_init_group(size_t group) 427 { 428 TraceEventIter iter; 429 430 if (!trace_writeout_enabled) { 431 return; 432 } 433 434 trace_event_iter_init_group(&iter, group); 435 st_write_event_mapping(&iter); 436 } 437