root / trace / simple.c @ b618c288
History | View | Annotate | Download (12 kB)
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 |
} |