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 <[email protected]>

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 <[email protected]>.

Signed-off-by: Prerna Saxena <[email protected]>
Signed-off-by: Stefan Hajnoczi <[email protected]>

.gitignore

@@ -42,6 +42,7 @@ QMP/qmp-commands.txt
 *.log
 *.pdf
 *.pg
+*.pyc
 *.toc
 *.tp
 *.vr

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

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)
 

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

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 <stdlib.h>
+#include <stdint.h>
+#include <stdio.h>
+#include <time.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;
+    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);
+}

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 <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);
+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 */

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 <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)