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