Re: [Qemu-devel] [PATCH 1/2] trace: Add simple tracing support

[Anthony Liguori <anthony@codemonkey.ws>]

On 05/21/2010 04:42 AM, Stefan Hajnoczi wrote:
> Trace events should be defined in trace.h.  Events are written to
> /tmp/trace.log and can be formatted using trace.py.  Remember to add
> events to trace.py for pretty-printing.
>
> Signed-off-by: Stefan Hajnoczi<stefanha@linux.vnet.ibm.com>
> ---
>   Makefile.objs |    2 +-
>   trace.c       |   64 +++++++++++++++++++++++++++++++++++++++++++++++++++++++++
>   trace.h       |    9 ++++++++
>   trace.py      |   30 ++++++++++++++++++++++++++
>   4 files changed, 104 insertions(+), 1 deletions(-)
>   create mode 100644 trace.c
>   create mode 100644 trace.h
>   create mode 100755 trace.py
>
> diff --git a/Makefile.objs b/Makefile.objs
> index acbaf22..307e989 100644
> --- a/Makefile.objs
> +++ b/Makefile.objs
> @@ -8,7 +8,7 @@ qobject-obj-y += qerror.o
>   # block-obj-y is code used by both qemu system emulation and qemu-img
>
>   block-obj-y = cutils.o cache-utils.o qemu-malloc.o qemu-option.o module.o
> -block-obj-y += nbd.o block.o aio.o aes.o osdep.o qemu-config.o
> +block-obj-y += nbd.o block.o aio.o aes.o osdep.o qemu-config.o trace.o
>   block-obj-$(CONFIG_POSIX) += posix-aio-compat.o
>   block-obj-$(CONFIG_LINUX_AIO) += linux-aio.o
>
> diff --git a/trace.c b/trace.c
> new file mode 100644
> index 0000000..2fec4d3
> --- /dev/null
> +++ b/trace.c
> @@ -0,0 +1,64 @@
> +#include<stdlib.h>
> +#include<stdio.h>
> +#include "trace.h"
> +
> +typedef struct {
> +    unsigned long event;
> +    unsigned long x1;
> +    unsigned long x2;
> +    unsigned long x3;
> +    unsigned long x4;
> +    unsigned long 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 void trace(TraceEvent event, unsigned long x1,
> +                  unsigned long x2, unsigned long x3,
> +                  unsigned long x4, unsigned long x5) {
> +    TraceRecord *rec =&trace_buf[trace_idx];
> +    rec->event = event;
> +    rec->x1 = x1;
> +    rec->x2 = x2;
> +    rec->x3 = x3;
> +    rec->x4 = x4;
> +    rec->x5 = x5;
> +
> +    if (++trace_idx == TRACE_BUF_LEN) {
> +        trace_idx = 0;
> +
> +        if (!trace_fp) {
> +            trace_fp = fopen("/tmp/trace.log", "w");
> +        }
> +        if (trace_fp) {
> +            size_t result = fwrite(trace_buf, sizeof trace_buf, 1, trace_fp);
> +            result = result;
> +        }
> +    }
> +}
>    

It is probably worth while to read trace points via the monitor or 
through some other mechanism.  My concern would be that writing even 64k 
out to disk would introduce enough performance overhead mainly because 
it runs lock-step with the guest's VCPU.

Maybe it's worth adding a thread that syncs the ring to disk if we want 
to write to disk?

> +void trace1(TraceEvent event, unsigned long x1) {
> +    trace(event, x1, 0, 0, 0, 0);
> +}
> +
> +void trace2(TraceEvent event, unsigned long x1, unsigned long x2) {
> +    trace(event, x1, x2, 0, 0, 0);
> +}
> +
> +void trace3(TraceEvent event, unsigned long x1, unsigned long x2, unsigned long x3) {
> +    trace(event, x1, x2, x3, 0, 0);
> +}
> +
> +void trace4(TraceEvent event, unsigned long x1, unsigned long x2, unsigned long x3, unsigned long x4) {
> +    trace(event, x1, x2, x3, x4, 0);
> +}
> +
> +void trace5(TraceEvent event, unsigned long x1, unsigned long x2, unsigned long x3, unsigned long x4, unsigned long x5) {
> +    trace(event, x1, x2, x3, x4, x5);
> +}
> diff --git a/trace.h b/trace.h
> new file mode 100644
> index 0000000..144aa1e
> --- /dev/null
> +++ b/trace.h
> @@ -0,0 +1,9 @@
> +typedef enum {
> +    TRACE_MAX
> +} TraceEvent;
> +
> +void trace1(TraceEvent event, unsigned long x1);
> +void trace2(TraceEvent event, unsigned long x1, unsigned long x2);
> +void trace3(TraceEvent event, unsigned long x1, unsigned long x2, unsigned long x3);
> +void trace4(TraceEvent event, unsigned long x1, unsigned long x2, unsigned long x3, unsigned long x4);
> +void trace5(TraceEvent event, unsigned long x1, unsigned long x2, unsigned long x3, unsigned long x4, unsigned long x5);
>    

Looks good.  I think we definitely need something like this.

Regards,

Anthony Liguori

> diff --git a/trace.py b/trace.py
> new file mode 100755
> index 0000000..f38ab6b
> --- /dev/null
> +++ b/trace.py
> @@ -0,0 +1,30 @@
> +#!/usr/bin/env python
> +import sys
> +import struct
> +
> +trace_fmt = 'LLLLLL'
> +trace_len = struct.calcsize(trace_fmt)
> +
> +events = {
> +}
> +
> +def read_record(fobj):
> +    s = fobj.read(trace_len)
> +    if len(s) != trace_len:
> +        return None
> +    return struct.unpack(trace_fmt, s)
> +
> +def format_record(rec):
> +    event = events[rec[0]]
> +    fields = [event[0]]
> +    for i in xrange(1, len(event)):
> +        fields.append('%s=0x%x' % (event[i], rec[i]))
> +    return ' '.join(fields)
> +
> +f = open(sys.argv[1], 'rb')
> +while True:
> +    rec = read_record(f)
> +    if rec is None:
> +        break
> +
> +    print format_record(rec)
>