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