[07/14] 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 /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 <stefanha@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 <prerna@linux.vnet.ibm.com>.

Signed-off-by: Prerna Saxena <prerna@linux.vnet.ibm.com>
Signed-off-by: Stefan Hajnoczi <stefanha@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

On Thu, Aug 12, 2010 at 10:36 AM, Stefan Hajnoczi
<stefanha@linux.vnet.ibm.com> wrote:
> 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 <stefanha@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 <prerna@linux.vnet.ibm.com>.
>
> Signed-off-by: Prerna Saxena <prerna@linux.vnet.ibm.com>
> Signed-off-by: Stefan Hajnoczi <stefanha@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 = {

This should be 'static const'.

> +        .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>

Why?

> +#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
>
>
>

On Thu, Aug 12, 2010 at 6:56 PM, Blue Swirl <blauwirbel@gmail.com> wrote:
> On Thu, Aug 12, 2010 at 10:36 AM, Stefan Hajnoczi
>> +static bool write_header(FILE *fp)
>> +{
>> +    TraceRecord header = {
>
> This should be 'static const'.

Okay.

>> 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>
>
> Why?

The stdbool.h header is not needed here.  This is an artifact of
rebasing the tracing branch to squash and order commits logically.
The header is only needed starting in "[PATCH 08/14] trace: Support
for dynamically enabling/disabling trace events".

Will fix in v2.

Stefan