From patchwork Mon Aug 30 13:27:04 2010 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Stefan Hajnoczi X-Patchwork-Id: 63034 Return-Path: X-Original-To: incoming@patchwork.ozlabs.org Delivered-To: patchwork-incoming@bilbo.ozlabs.org Received: from lists.gnu.org (lists.gnu.org [199.232.76.165]) (using TLSv1 with cipher DHE-RSA-AES256-SHA (256/256 bits)) (Client did not present a certificate) by ozlabs.org (Postfix) with ESMTPS id 78C5FB70F1 for ; Mon, 30 Aug 2010 23:51:39 +1000 (EST) Received: from localhost ([127.0.0.1]:48867 helo=lists.gnu.org) by lists.gnu.org with esmtp (Exim 4.43) id 1Oq4lr-0001cC-MH for incoming@patchwork.ozlabs.org; Mon, 30 Aug 2010 09:51:35 -0400 Received: from [140.186.70.92] (port=48425 helo=eggs.gnu.org) by lists.gnu.org with esmtp (Exim 4.43) id 1Oq4OY-00019m-0U for qemu-devel@nongnu.org; Mon, 30 Aug 2010 09:27:32 -0400 Received: from Debian-exim by eggs.gnu.org with spam-scanned (Exim 4.69) (envelope-from ) id 1Oq4OW-00042o-68 for qemu-devel@nongnu.org; Mon, 30 Aug 2010 09:27:29 -0400 Received: from mtagate7.de.ibm.com ([195.212.17.167]:37093) by eggs.gnu.org with esmtp (Exim 4.69) (envelope-from ) id 1Oq4OV-000427-O3 for qemu-devel@nongnu.org; Mon, 30 Aug 2010 09:27:28 -0400 Received: from d12nrmr1607.megacenter.de.ibm.com (d12nrmr1607.megacenter.de.ibm.com [9.149.167.49]) by mtagate7.de.ibm.com (8.13.1/8.13.1) with ESMTP id o7UDRQv2017600 for ; Mon, 30 Aug 2010 13:27:26 GMT Received: from d12av04.megacenter.de.ibm.com (d12av04.megacenter.de.ibm.com [9.149.165.229]) by d12nrmr1607.megacenter.de.ibm.com (8.13.8/8.13.8/NCO v10.0) with ESMTP id o7UDRQ6T4079846 for ; Mon, 30 Aug 2010 15:27:26 +0200 Received: from d12av04.megacenter.de.ibm.com (loopback [127.0.0.1]) by d12av04.megacenter.de.ibm.com (8.12.11.20060308/8.13.3) with ESMTP id o7UDRQ4Z007653 for ; Mon, 30 Aug 2010 15:27:26 +0200 Received: from stefan-thinkpad.ibm.com (sig-9-146-224-127.de.ibm.com [9.146.224.127]) by d12av04.megacenter.de.ibm.com (8.12.11.20060308/8.12.11) with ESMTP id o7UDROUK007601; Mon, 30 Aug 2010 15:27:25 +0200 From: Stefan Hajnoczi To: Date: Mon, 30 Aug 2010 14:27:04 +0100 Message-Id: <1283174836-6330-3-git-send-email-stefanha@linux.vnet.ibm.com> X-Mailer: git-send-email 1.7.1 In-Reply-To: <1283174836-6330-1-git-send-email-stefanha@linux.vnet.ibm.com> References: <1283174836-6330-1-git-send-email-stefanha@linux.vnet.ibm.com> X-detected-operating-system: by eggs.gnu.org: GNU/Linux 2.6, seldom 2.4 (older, 4) Cc: Blue Swirl , Anthony Liguori , Stefan Hajnoczi , Prerna Saxena Subject: [Qemu-devel] [PATCH 02/14] trace: Add simple built-in tracing backend X-BeenThere: qemu-devel@nongnu.org X-Mailman-Version: 2.1.5 Precedence: list List-Id: qemu-devel.nongnu.org List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Sender: qemu-devel-bounces+incoming=patchwork.ozlabs.org@nongnu.org Errors-To: qemu-devel-bounces+incoming=patchwork.ozlabs.org@nongnu.org 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 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 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 38613c3..6729dbe 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 0000000..59b18c6 --- /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("/tmp/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 0000000..7d0661b --- /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 0000000..c2cf168 --- /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 d640100..66df685 100755 --- a/tracetool +++ b/tracetool @@ -13,11 +13,12 @@ set -f usage() { cat >&2 <