From 26f7227bfe9a9abee3fe5190cbfc35dd876e06d9 Mon Sep 17 00:00:00 2001 From: Stefan Hajnoczi Date: Sat, 22 May 2010 19:24:51 +0100 Subject: trace: Add simple built-in tracing backend This patch adds a simple tracer which produces binary trace files. To try out the simple backend: $ ./configure --trace-backend=simple $ make After running QEMU you can pretty-print the trace: $ ./simpletrace.py trace-events trace.log The output of simpletrace.py looks like this: qemu_realloc 0.699 ptr=0x24363f0 size=0x3 newptr=0x24363f0 qemu_free 0.768 ptr=0x24363f0 ^ ^---- timestamp delta (us) |____ trace event name Signed-off-by: Stefan Hajnoczi trace: Make trace record fields 64-bit Explicitly use 64-bit fields in trace records so that timestamps and magic numbers work for 32-bit host builds. Includes fixes from Prerna Saxena . Signed-off-by: Prerna Saxena Signed-off-by: Stefan Hajnoczi --- .gitignore | 1 + Makefile | 2 + Makefile.objs | 3 ++ configure | 2 +- simpletrace.c | 159 +++++++++++++++++++++++++++++++++++++++++++++++++++++++++ simpletrace.h | 26 ++++++++++ simpletrace.py | 93 +++++++++++++++++++++++++++++++++ tracetool | 78 ++++++++++++++++++++++++++-- 8 files changed, 360 insertions(+), 4 deletions(-) create mode 100644 simpletrace.c create mode 100644 simpletrace.h create mode 100755 simpletrace.py diff --git a/.gitignore b/.gitignore index f3f2bb7680..72bff98740 100644 --- a/.gitignore +++ b/.gitignore @@ -42,6 +42,7 @@ QMP/qmp-commands.txt *.log *.pdf *.pg +*.pyc *.toc *.tp *.vr diff --git a/Makefile b/Makefile index 3c5e6a060e..ab91d429f5 100644 --- a/Makefile +++ b/Makefile @@ -112,6 +112,8 @@ trace.c: $(SRC_PATH)/trace-events config-host.mak trace.o: trace.c $(GENERATED_HEADERS) +simpletrace.o: simpletrace.c $(GENERATED_HEADERS) + ###################################################################### qemu-img.o: qemu-img-cmds.h diff --git a/Makefile.objs b/Makefile.objs index c61332d85d..3ef6d80dfd 100644 --- a/Makefile.objs +++ b/Makefile.objs @@ -269,6 +269,9 @@ libdis-$(CONFIG_SPARC_DIS) += sparc-dis.o # trace trace-obj-y = trace.o +ifeq ($(TRACE_BACKEND),simple) +trace-obj-y += simpletrace.o +endif vl.o: QEMU_CFLAGS+=$(GPROF_CFLAGS) diff --git a/configure b/configure index 38613c350d..6729dbe0bb 100755 --- a/configure +++ b/configure @@ -900,7 +900,7 @@ echo " --enable-docs enable documentation build" echo " --disable-docs disable documentation build" echo " --disable-vhost-net disable vhost-net acceleration support" echo " --enable-vhost-net enable vhost-net acceleration support" -echo " --trace-backend=B Trace backend nop" +echo " --trace-backend=B Trace backend nop simple" echo "" echo "NOTE: The object files are built at the place where configure is launched" exit 1 diff --git a/simpletrace.c b/simpletrace.c new file mode 100644 index 0000000000..477730871c --- /dev/null +++ b/simpletrace.c @@ -0,0 +1,159 @@ +/* + * Simple trace backend + * + * Copyright IBM, Corp. 2010 + * + * This work is licensed under the terms of the GNU GPL, version 2. See + * the COPYING file in the top-level directory. + * + */ + +#include +#include +#include +#include +#include "trace.h" + +/** Trace file header event ID */ +#define HEADER_EVENT_ID (~(uint64_t)0) /* avoids conflicting with TraceEventIDs */ + +/** Trace file magic number */ +#define HEADER_MAGIC 0xf2b177cb0aa429b4ULL + +/** Trace file version number, bump if format changes */ +#define HEADER_VERSION 0 + +/** Trace buffer entry */ +typedef struct { + uint64_t event; + uint64_t timestamp_ns; + uint64_t x1; + uint64_t x2; + uint64_t x3; + uint64_t x4; + uint64_t x5; + uint64_t x6; +} TraceRecord; + +enum { + TRACE_BUF_LEN = 64 * 1024 / sizeof(TraceRecord), +}; + +static TraceRecord trace_buf[TRACE_BUF_LEN]; +static unsigned int trace_idx; +static FILE *trace_fp; + +static bool write_header(FILE *fp) +{ + static const TraceRecord header = { + .event = HEADER_EVENT_ID, + .timestamp_ns = HEADER_MAGIC, + .x1 = HEADER_VERSION, + }; + + return fwrite(&header, sizeof header, 1, fp) == 1; +} + +static void flush_trace_buffer(void) +{ + if (!trace_fp) { + trace_fp = fopen("trace.log", "w"); + if (trace_fp) { + write_header(trace_fp); + } + } + if (trace_fp) { + size_t unused; /* for when fwrite(3) is declared warn_unused_result */ + unused = fwrite(trace_buf, trace_idx * sizeof(trace_buf[0]), 1, trace_fp); + } + + /* Discard written trace records */ + trace_idx = 0; +} + +void st_set_trace_file_enabled(bool enable) +{ + if (enable == trace_file_enabled) { + return; /* no change */ + } + + /* Flush/discard trace buffer */ + st_flush_trace_buffer(); + + /* To disable, close trace file */ + if (!enable) { + fclose(trace_fp); + trace_fp = NULL; + } + + trace_file_enabled = enable; +} + +static void trace(TraceEventID event, uint64_t x1, uint64_t x2, uint64_t x3, + uint64_t x4, uint64_t x5, uint64_t x6) +{ + TraceRecord *rec = &trace_buf[trace_idx]; + struct timespec ts; + + /* TODO Windows? It would be good to use qemu-timer here but that isn't + * linked into qemu-tools. Also we should avoid recursion in the tracing + * code, therefore it is useful to be self-contained. + */ + clock_gettime(CLOCK_MONOTONIC, &ts); + + rec->event = event; + rec->timestamp_ns = ts.tv_sec * 1000000000LL + ts.tv_nsec; + rec->x1 = x1; + rec->x2 = x2; + rec->x3 = x3; + rec->x4 = x4; + rec->x5 = x5; + rec->x6 = x6; + + if (++trace_idx == TRACE_BUF_LEN) { + flush_trace_buffer(); + } +} + +void trace0(TraceEventID event) +{ + trace(event, 0, 0, 0, 0, 0, 0); +} + +void trace1(TraceEventID event, uint64_t x1) +{ + trace(event, x1, 0, 0, 0, 0, 0); +} + +void trace2(TraceEventID event, uint64_t x1, uint64_t x2) +{ + trace(event, x1, x2, 0, 0, 0, 0); +} + +void trace3(TraceEventID event, uint64_t x1, uint64_t x2, uint64_t x3) +{ + trace(event, x1, x2, x3, 0, 0, 0); +} + +void trace4(TraceEventID event, uint64_t x1, uint64_t x2, uint64_t x3, uint64_t x4) +{ + trace(event, x1, x2, x3, x4, 0, 0); +} + +void trace5(TraceEventID event, uint64_t x1, uint64_t x2, uint64_t x3, uint64_t x4, uint64_t x5) +{ + trace(event, x1, x2, x3, x4, x5, 0); +} + +void trace6(TraceEventID event, uint64_t x1, uint64_t x2, uint64_t x3, uint64_t x4, uint64_t x5, uint64_t x6) +{ + trace(event, x1, x2, x3, x4, x5, x6); +} + +/** + * Flush the trace buffer on exit + */ +static void __attribute__((constructor)) st_init(void) +{ + atexit(st_flush_trace_buffer); +} diff --git a/simpletrace.h b/simpletrace.h new file mode 100644 index 0000000000..7d0661b720 --- /dev/null +++ b/simpletrace.h @@ -0,0 +1,26 @@ +/* + * Simple trace backend + * + * Copyright IBM, Corp. 2010 + * + * This work is licensed under the terms of the GNU GPL, version 2. See + * the COPYING file in the top-level directory. + * + */ + +#ifndef SIMPLETRACE_H +#define SIMPLETRACE_H + +#include + +typedef uint64_t TraceEventID; + +void trace0(TraceEventID event); +void trace1(TraceEventID event, uint64_t x1); +void trace2(TraceEventID event, uint64_t x1, uint64_t x2); +void trace3(TraceEventID event, uint64_t x1, uint64_t x2, uint64_t x3); +void trace4(TraceEventID event, uint64_t x1, uint64_t x2, uint64_t x3, uint64_t x4); +void trace5(TraceEventID event, uint64_t x1, uint64_t x2, uint64_t x3, uint64_t x4, uint64_t x5); +void trace6(TraceEventID event, uint64_t x1, uint64_t x2, uint64_t x3, uint64_t x4, uint64_t x5, uint64_t x6); + +#endif /* SIMPLETRACE_H */ diff --git a/simpletrace.py b/simpletrace.py new file mode 100755 index 0000000000..c2cf1682d0 --- /dev/null +++ b/simpletrace.py @@ -0,0 +1,93 @@ +#!/usr/bin/env python +# +# Pretty-printer for simple trace backend binary trace files +# +# Copyright IBM, Corp. 2010 +# +# This work is licensed under the terms of the GNU GPL, version 2. See +# the COPYING file in the top-level directory. +# +# For help see docs/tracing.txt + +import sys +import struct +import re + +header_event_id = 0xffffffffffffffff +header_magic = 0xf2b177cb0aa429b4 +header_version = 0 + +trace_fmt = '=QQQQQQQQ' +trace_len = struct.calcsize(trace_fmt) +event_re = re.compile(r'(disable\s+)?([a-zA-Z0-9_]+)\(([^)]*)\)\s+"([^"]*)"') + +def err(msg): + sys.stderr.write(msg + '\n') + sys.exit(1) + +def parse_events(fobj): + """Parse a trace-events file.""" + + def get_argnames(args): + """Extract argument names from a parameter list.""" + return tuple(arg.split()[-1].lstrip('*') for arg in args.split(',')) + + events = {} + event_num = 0 + for line in fobj: + m = event_re.match(line.strip()) + if m is None: + continue + + disable, name, args, fmt = m.groups() + events[event_num] = (name,) + get_argnames(args) + event_num += 1 + return events + +def read_record(fobj): + """Deserialize a trace record from a file.""" + s = fobj.read(trace_len) + if len(s) != trace_len: + return None + return struct.unpack(trace_fmt, s) + +def read_trace_file(fobj): + """Deserialize trace records from a file.""" + header = read_record(fobj) + if header is None or \ + header[0] != header_event_id or \ + header[1] != header_magic or \ + header[2] != header_version: + err('not a trace file or incompatible version') + + while True: + rec = read_record(fobj) + if rec is None: + break + + yield rec + +class Formatter(object): + def __init__(self, events): + self.events = events + self.last_timestamp = None + + def format_record(self, rec): + if self.last_timestamp is None: + self.last_timestamp = rec[1] + delta_ns = rec[1] - self.last_timestamp + self.last_timestamp = rec[1] + + event = self.events[rec[0]] + fields = [event[0], '%0.3f' % (delta_ns / 1000.0)] + for i in xrange(1, len(event)): + fields.append('%s=0x%x' % (event[i], rec[i + 1])) + return ' '.join(fields) + +if len(sys.argv) != 3: + err('usage: %s ' % sys.argv[0]) + +events = parse_events(open(sys.argv[1], 'r')) +formatter = Formatter(events) +for rec in read_trace_file(open(sys.argv[2], 'rb')): + print formatter.format_record(rec) diff --git a/tracetool b/tracetool index 01de580c44..19b1659bc0 100755 --- a/tracetool +++ b/tracetool @@ -13,11 +13,12 @@ set -f usage() { cat >&2 <