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 /tmp/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 <stefa...@linux.vnet.ibm.com> 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 <pre...@linux.vnet.ibm.com>. Signed-off-by: Prerna Saxena <pre...@linux.vnet.ibm.com> Signed-off-by: Stefan Hajnoczi <stefa...@linux.vnet.ibm.com> --- .gitignore | 1 + Makefile | 2 + Makefile.objs | 3 + configure | 2 +- simpletrace.c | 127 ++++++++++++++++++++++++++++++++++++++++++++++++++++++++ simpletrace.h | 26 +++++++++++ simpletrace.py | 96 ++++++++++++++++++++++++++++++++++++++++++ tracetool | 82 ++++++++++++++++++++++++++++++++++-- 8 files changed, 333 insertions(+), 6 deletions(-) create mode 100644 simpletrace.c create mode 100644 simpletrace.h create mode 100755 simpletrace.py diff --git a/.gitignore b/.gitignore index f3f2bb7..72bff98 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 3c5e6a0..ab91d42 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 c61332d..3ef6d80 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 d3648b2..62dd10d 100755 --- a/configure +++ b/configure @@ -898,7 +898,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 0000000..a6afc51 --- /dev/null +++ b/simpletrace.c @@ -0,0 +1,127 @@ +/* + * 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 <stdlib.h> +#include <stdint.h> +#include <stdio.h> +#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; +} 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) +{ + 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("/tmp/trace.log", "w"); + if (trace_fp) { + write_header(trace_fp); + atexit(flush_trace_buffer); + } + } + 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; +} + +static void trace(TraceEventID event, unsigned long x1, + unsigned long x2, unsigned long x3, + unsigned long x4, unsigned long x5) +{ + 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; + + if (++trace_idx == TRACE_BUF_LEN) { + flush_trace_buffer(); + } +} + +void trace0(TraceEventID event) +{ + trace(event, 0, 0, 0, 0, 0); +} + +void trace1(TraceEventID event, uint64_t x1) +{ + trace(event, x1, 0, 0, 0, 0); +} + +void trace2(TraceEventID event, uint64_t x1, uint64_t x2) +{ + trace(event, x1, x2, 0, 0, 0); +} + +void trace3(TraceEventID event, uint64_t x1, uint64_t x2, uint64_t x3) +{ + trace(event, x1, x2, x3, 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); +} + +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); +} diff --git a/simpletrace.h b/simpletrace.h new file mode 100644 index 0000000..e4e9759 --- /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 <stdbool.h> +#include <stdint.h> + +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); + +#endif /* SIMPLETRACE_H */ diff --git a/simpletrace.py b/simpletrace.py new file mode 100755 index 0000000..fdf0eb5 --- /dev/null +++ b/simpletrace.py @@ -0,0 +1,96 @@ +#!/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 = '=QQQQQQQ' +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() + if disable: + continue + + 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 <trace-events> <trace-file>' % 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 86b6446..66df685 100755 --- a/tracetool +++ b/tracetool @@ -13,11 +13,12 @@ set -f usage() { cat >&2 <<EOF -usage: $0 --nop [-h | -c] +usage: $0 [--nop | --simple] [-h | -c] Generate tracing code for a file on stdin. Backends: - --nop Tracing disabled + --nop Tracing disabled + --simple Simple built-in backend Output formats: -h Generate .h file @@ -56,16 +57,27 @@ get_argnames() name=${field%,} test "$field" = "$name" && continue - echo -n "$name, " + printf "%s" "$name, " done # Last argument name if [ "$nfields" -gt 1 ] then - echo -n "$name" + printf "%s" "$name" fi } +# Get the number of arguments to a trace event +get_argc() +{ + local name argc + argc=0 + for name in $(get_argnames "$1"); do + argc=$((argc + 1)) + done + echo $argc +} + # Get the format string for a trace event get_fmt() { @@ -115,6 +127,66 @@ linetoc_end_nop() return } +linetoh_begin_simple() +{ + cat <<EOF +#include "simpletrace.h" +EOF + + simple_event_num=0 +} + +cast_args_to_uint64_t() +{ + local arg + for arg in $(get_argnames "$1"); do + printf "%s" "(uint64_t)(uintptr_t)$arg" + done +} + +linetoh_simple() +{ + local name args argc trace_args + name=$(get_name "$1") + args=$(get_args "$1") + argc=$(get_argc "$1") + + trace_args="$simple_event_num" + if [ "$argc" -gt 0 ] + then + trace_args="$trace_args, $(cast_args_to_uint64_t "$1")" + fi + + cat <<EOF +static inline void trace_$name($args) +{ + trace$argc($trace_args); +} +EOF + + simple_event_num=$((simple_event_num + 1)) +} + +linetoh_end_simple() +{ + return +} + +linetoc_begin_simple() +{ + return +} + +linetoc_simple() +{ + return +} + +linetoc_end_simple() +{ + return +} + # Process stdin by calling begin, line, and end functions for the backend convert() { @@ -160,7 +232,7 @@ tracetoc() # Choose backend case "$1" in -"--nop") backend="${1#--}" ;; +"--nop" | "--simple") backend="${1#--}" ;; *) usage ;; esac shift -- 1.7.1