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