[Qemu-devel] [RFC PATCH 0/4] simpletrace : support var num/size of args, strings.

[Qemu-devel] [RFC PATCH 0/4] simpletrace : support var num/size of args, strings.

[Harsh Prateek Bora]

Existing simple trace can log upto 6 args per trace event and does not
support strings in trace record format. Introducing new trace format as
discussed earlier on list to support variable number/size of arguments.
(Ref: http://lists.gnu.org/archive/html/qemu-devel/2011-11/msg03426.html)

Basic testing of this patch is successful. Stress testing not yet done.

Apply patches, then run:

make distclean
./configure with --enable-trace-backend=simple
make
sudo make install

TODO: Add suppport for other backends in tracetool.py

Harsh Prateek Bora (4):
  Converting tracetool.sh to tracetool.py
  Makefile and configure changes for tracetool.py
  simpletrace-v2: Handle variable number/size of elements per trace record.
  simpletrace.py: updated log reader script to handle new log format

 Makefile.objs          |    4 +-
 configure              |    4 +-
 monitor.c              |    2 +-
 scripts/simpletrace.py |  110 ++++++++++++++++--
 scripts/tracetool.py   |  299 ++++++++++++++++++++++++++++++++++++++++++++++++
 trace/simple.c         |  178 ++++++++++------------------
 trace/simple.h         |   31 ++++-
 7 files changed, 490 insertions(+), 138 deletions(-)
 create mode 100755 scripts/tracetool.py

[Qemu-devel] [RFC PATCH 1/4] Converting tracetool.sh to tracetool.py

[Harsh Prateek Bora]

Note: As of now, tracetool.py only supports simpletrace backend.
TODO: Add support for other tracing backends.

Signed-off-by: Harsh Prateek Bora <harsh@linux.vnet.ibm.com>
---
 scripts/tracetool.py |  299 ++++++++++++++++++++++++++++++++++++++++++++++++++
 1 files changed, 299 insertions(+), 0 deletions(-)
 create mode 100755 scripts/tracetool.py

diff --git a/scripts/tracetool.py b/scripts/tracetool.py
new file mode 100755
index 0000000..95c3c2e
--- /dev/null
+++ b/scripts/tracetool.py
@@ -0,0 +1,299 @@
+#!/usr/bin/env python
+# Python based tracetool script (Code generator for trace events)
+#
+# Copyright IBM, Corp. 2011
+#
+# This work is licensed under the terms of the GNU GPL, version 2.  See
+# the COPYING file in the top-level directory.
+#
+#
+
+import sys
+import getopt
+
+def usage():
+    print "Tracetool: Generate tracing code for trace events."
+    print "           Takes input from stdin, output can be redirected from stdout."
+    print "Usage:"
+    print sys.argv[0]+" --backend=simple [-h | -c]"
+    sys.exit(1)
+
+def get_name(line, sep='('):
+    head, sep, tail = line.partition(sep)
+    return head
+
+def get_args(line, sep1='(', sep2=')'):
+    head, sep1, tail = line.partition(sep1)
+    args, sep2, fmt_str = tail.partition(sep2)
+    return args
+
+def get_argnames(line, sep=','):
+    nfields = 0
+    str = []
+    args = get_args(line)
+    for field in args.split():
+      nfields = nfields + 1
+      # Drop pointer star
+      type, ptr, tail = field.partition('*')
+      if type != field:
+        field = tail
+
+      name, sep, tail = field.partition(',')
+
+      if name == field:
+        continue
+      str.append(name)
+      str.append(", ")
+
+    if nfields > 1:
+      str.append(name)
+      return ''.join(str)
+    else:
+      return
+
+def get_argc(line):
+    argc = 0
+    argnames = get_argnames(line)
+    if argnames:
+      for name in argnames.split(','):
+        argc = argc + 1
+    return argc
+
+def cast_args_to_uint64_t(line):
+    str = []
+    argnames = line.argnames
+    if argnames:
+      for name in argnames.split():
+        str.append("(uint64_t)(uintptr_t)")
+        str.append(name)
+    return ''.join(str)
+
+# trace args to be generated for simpletrace backend
+def trace_args_simple(event):
+    if event.argc:
+        return (str(event.num) + ', ' + cast_args_to_uint64_t(event))
+    else:
+        return str(event.num)
+
+def calc_sizeofargs(line):
+    args = get_args(line)
+    argc = get_argc(line)
+    strtype = ('const char*', 'char*', 'const char *', 'char *')
+    str = []
+    newstr = ""
+    if argc > 0:
+      str = args.split(',')
+      for elem in str:
+        if elem.lstrip().startswith(strtype): #strings
+          type, sep, var = elem.rpartition('*')
+          newstr = newstr+"4 + strlen("+var.lstrip()+") + "
+        #elif '*' in elem:
+        #  newstr = newstr + "4 + " # pointer vars
+        else:
+          #type, sep, var = elem.rpartition(' ')
+          #newstr = newstr+"sizeof("+type.lstrip()+") + "
+          newstr = newstr + '8 + '
+    newstr = newstr + '0' # for last +
+    return newstr
+
+
+def trace_h_begin():
+    print '''#ifndef TRACE_H
+#define TRACE_H
+
+/* This file is autogenerated by tracetool, do not edit. */
+
+#include "qemu-common.h"'''
+    return
+
+def trace_h_end():
+    print '#endif /* TRACE_H */'
+    return
+
+def trace_c_begin():
+    print '/* This file is autogenerated by tracetool, do not edit. */'
+    return
+
+def trace_c_end():
+    # nop, required for trace_gen
+    return
+
+def simple_h(events):
+    print '#include "trace/simple.h"'
+    print
+    for event in events:
+        print 'void trace_%(name)s(%(args)s);' % {
+    'name': event.name,
+    'args': event.args
+}
+    print
+    print '#define NR_TRACE_EVENTS %d' % (event.num + 1)
+    print 'extern TraceEvent trace_list[NR_TRACE_EVENTS];'
+
+    return
+
+def is_string(arg):
+    strtype = ('const char*', 'char*', 'const char *', 'char *')
+    if arg.lstrip().startswith(strtype):
+        return True
+    else:
+        return False
+
+def simple_c(events):
+    rec_off = 0
+    print '#include "trace.h"'
+    print '#include "trace/simple.h"'
+    print
+    print 'TraceEvent trace_list[] = {'
+    print
+    eventlist = list(events)
+    for event in eventlist:
+        print '{.tp_name = "%(name)s", .state=0},' % {
+    'name': event.name
+}
+        print
+    print '};'
+    print
+    for event in eventlist:
+        argc = event.argc
+        print '''void trace_%(name)s(%(args)s)
+{
+    unsigned int tbuf_idx, rec_off;
+    uint64_t var64 __attribute__ ((unused));
+    uint64_t pvar64 __attribute__ ((unused));
+    uint32_t slen __attribute__ ((unused));
+
+    if (!trace_list[%(event_id)s].state) {
+        return;
+    }
+''' % {
+    'name': event.name,
+    'args': event.args,
+    'event_id': event.num,
+}
+        print '''    tbuf_idx = trace_alloc_record(%(event_id)s, %(sizestr)s);
+    rec_off = (tbuf_idx + ST_V2_REC_HDR_LEN) %% TRACE_BUF_LEN; /* seek record header */
+''' % {'event_id': event.num, 'sizestr': event.sizestr,}
+
+        if argc > 0:
+            str = event.arglist
+            for elem in str:
+                if is_string(elem): # if string
+                    type, sep, var = elem.rpartition('*')
+                    print '''    slen = strlen(%(var)s);
+    write_to_buffer(rec_off, (uint8_t*)&slen, sizeof(slen));
+    rec_off += sizeof(slen);''' % {
+    'var': var.lstrip()
+}
+                    print '''    write_to_buffer(rec_off, (uint8_t*)%(var)s, slen);
+    rec_off += slen;''' % {
+    'var': var.lstrip()
+}
+                elif '*' in elem: # pointer var (not string)
+                    type, sep, var = elem.rpartition('*')
+                    print '''    pvar64 = (uint64_t)(uint64_t*)%(var)s;
+    write_to_buffer(rec_off, (uint8_t*)&pvar64, sizeof(uint64_t));
+    rec_off += sizeof(uint64_t);''' % {
+    'var': var.lstrip()
+}
+                else: # primitive data type
+                    type, sep, var = elem.rpartition(' ')
+                    print '''    var64 = (uint64_t)%(var)s;
+    write_to_buffer(rec_off, (uint8_t*)&var64, sizeof(uint64_t));
+    rec_off += sizeof(uint64_t);''' % {
+    'var': var.lstrip()
+}
+        print '''
+    trace_mark_record_complete(tbuf_idx);'''
+        print '}'
+        print
+
+    return
+
+# Registry of backends and their converter functions
+converters = {
+    'simple': {
+        'h': simple_h,
+	'c': simple_c,
+    },
+}
+
+# Trace file header and footer code generators
+trace_gen = {
+    'h': {
+        'begin': trace_h_begin,
+        'end': trace_h_end,
+    },
+    'c': {
+        'begin': trace_c_begin,
+        'end': trace_c_end,
+    },
+}
+
+# A trace event
+class Event(object):
+    def __init__(self, num, line):
+        self.num = num
+        self.args = get_args(line)
+        self.arglist = self.args.split(',')
+        self.name = get_name(line)
+        self.argc = get_argc(line)
+        self.argnames = get_argnames(line)
+        self.sizestr = calc_sizeofargs(line)
+
+
+# Generator that yields Event objects given a trace-events file object
+def read_events(fobj):
+    event_num = 0
+    for line in fobj:
+        if not line.strip():
+            continue
+        if line.lstrip().startswith('#'):
+	    continue
+	yield Event(event_num, line)
+	event_num += 1
+
+def main():
+    supported_backends = ["simple", "todo"]
+    try:
+      opts, args = getopt.getopt(sys.argv[1:], "hc", ["backend=", "list-backends", "check-backend"])
+    except getopt.GetoptError, err:
+      # print help information and exit:
+      print str(err) # will print something like "option -a not recognized"
+      usage()
+      sys.exit(2)
+    output = ""
+    backend = ""
+    for opt, arg in opts:
+      if opt == "-h":
+        output = 'h'
+      elif opt == "-c":
+        output = 'c'
+      elif opt == "--backend":
+        backend = arg
+      elif opt == "--list-backends":
+        print "simple (other backends not supported yet)"
+        sys.exit(0)
+      elif opt == "--check-backend":
+        if any(backend in s for s in supported_backends):
+          sys.exit(0)
+        else:
+          sys.exit(1)
+      else:
+        #assert False, "unhandled option"
+        print "unhandled option: ", opt
+        usage()
+
+    if backend == "" or output == "":
+      usage()
+      sys.exit(0)
+
+    events = read_events(sys.stdin)
+    trace_gen[output]['begin']()
+    converters[backend][output](events)
+    trace_gen[output]['end']()
+    return
+
+if __name__ == "__main__":
+    main()
+
-- 
1.7.1.1

[Qemu-devel] [RFC PATCH 2/4] Makefile and configure changes for tracetool.py

[Harsh Prateek Bora]

Use tracetool.py to generate tracing code for requested backend.

TODO: tracetool.py needs to be updated to add support for other backends.

Signed-off-by: Harsh Prateek Bora <harsh@linux.vnet.ibm.com>
---
 Makefile.objs |    4 ++--
 configure     |    4 ++--
 2 files changed, 4 insertions(+), 4 deletions(-)

diff --git a/Makefile.objs b/Makefile.objs
index 804bc3c..24123a8 100644
--- a/Makefile.objs
+++ b/Makefile.objs
@@ -344,12 +344,12 @@ else
 trace.h: trace.h-timestamp
 endif
 trace.h-timestamp: $(SRC_PATH)/trace-events $(BUILD_DIR)/config-host.mak
-	$(call quiet-command,sh $(SRC_PATH)/scripts/tracetool --$(TRACE_BACKEND) -h < $< > $@,"  GEN   trace.h")
+	$(call quiet-command,$(PYTHON) $(SRC_PATH)/scripts/tracetool.py --backend=$(TRACE_BACKEND) -h < $< > $@,"  GEN   trace.h")
 	@cmp -s $@ trace.h || cp $@ trace.h
 
 trace.c: trace.c-timestamp
 trace.c-timestamp: $(SRC_PATH)/trace-events $(BUILD_DIR)/config-host.mak
-	$(call quiet-command,sh $(SRC_PATH)/scripts/tracetool --$(TRACE_BACKEND) -c < $< > $@,"  GEN   trace.c")
+	$(call quiet-command,$(PYTHON) $(SRC_PATH)/scripts/tracetool.py --backend=$(TRACE_BACKEND) -c < $< > $@,"  GEN   trace.c")
 	@cmp -s $@ trace.c || cp $@ trace.c
 
 trace.o: trace.c $(GENERATED_HEADERS)
diff --git a/configure b/configure
index 19e8394..0ea8634 100755
--- a/configure
+++ b/configure
@@ -1040,7 +1040,7 @@ 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 "  --enable-trace-backend=B Set trace backend"
-echo "                           Available backends:" $("$source_path"/scripts/tracetool --list-backends)
+echo "                           Available backends:" $("$source_path"/scripts/tracetool.py --list-backends)
 echo "  --with-trace-file=NAME   Full PATH,NAME of file to store traces"
 echo "                           Default:trace-<pid>"
 echo "  --disable-spice          disable spice"
@@ -2477,7 +2477,7 @@ fi
 ##########################################
 # check if trace backend exists
 
-sh "$source_path/scripts/tracetool" "--$trace_backend" --check-backend > /dev/null 2> /dev/null
+$python "$source_path/scripts/tracetool.py" "--backend=$trace_backend" --check-backend  > /dev/null 2> /dev/null
 if test "$?" -ne 0 ; then
   echo
   echo "Error: invalid trace backend"
-- 
1.7.1.1

[Qemu-devel] [RFC PATCH 3/4] simpletrace-v2: Handle variable number/size of elements per trace record.

[Harsh Prateek Bora]

Advantages over existing simpletrace backend:
- More than 6 elements (vitually unlimited) arguments can be traced.
- This allows to trace strings (variable size element) as well.

Signed-off-by: Harsh Prateek Bora <harsh@linux.vnet.ibm.com>
---
 monitor.c      |    2 +-
 trace/simple.c |  178 ++++++++++++++++++++------------------------------------
 trace/simple.h |   31 ++++++++--
 3 files changed, 88 insertions(+), 123 deletions(-)

diff --git a/monitor.c b/monitor.c
index ffda0fe..b6f85d1 100644
--- a/monitor.c
+++ b/monitor.c
@@ -945,7 +945,7 @@ static void do_info_cpu_stats(Monitor *mon)
 #if defined(CONFIG_TRACE_SIMPLE)
 static void do_info_trace(Monitor *mon)
 {
-    st_print_trace((FILE *)mon, &monitor_fprintf);
+    /* FIXME: st_print_trace((FILE *)mon, &monitor_fprintf); */
 }
 #endif
 
diff --git a/trace/simple.c b/trace/simple.c
index b639dda..f7e7967 100644
--- a/trace/simple.c
+++ b/trace/simple.c
@@ -27,7 +27,7 @@
 #define HEADER_MAGIC 0xf2b177cb0aa429b4ULL
 
 /** Trace file version number, bump if format changes */
-#define HEADER_VERSION 0
+#define HEADER_VERSION 2
 
 /** Records were dropped event ID */
 #define DROPPED_EVENT_ID (~(uint64_t)0 - 1)
@@ -35,23 +35,6 @@
 /** Trace record is valid */
 #define TRACE_RECORD_VALID ((uint64_t)1 << 63)
 
-/** 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 = 4096,
-    TRACE_BUF_FLUSH_THRESHOLD = TRACE_BUF_LEN / 4,
-};
-
 /*
  * Trace records are written out by a dedicated thread.  The thread waits for
  * records to become available, writes them out, and then waits again.
@@ -62,11 +45,12 @@ static GCond *trace_empty_cond;
 static bool trace_available;
 static bool trace_writeout_enabled;
 
-static TraceRecord trace_buf[TRACE_BUF_LEN];
+uint8_t trace_buf[TRACE_BUF_LEN];
 static unsigned int trace_idx;
 static FILE *trace_fp;
 static char *trace_file_name = NULL;
 
+
 /**
  * Read a trace record from the trace buffer
  *
@@ -75,16 +59,19 @@ static char *trace_file_name = NULL;
  *
  * Returns false if the record is not valid.
  */
-static bool get_trace_record(unsigned int idx, TraceRecord *record)
+static bool get_trace_record(unsigned int idx, TraceRecord **recordptr)
 {
-    if (!(trace_buf[idx].event & TRACE_RECORD_VALID)) {
+    TraceRecord *record = (TraceRecord *) &trace_buf[idx];
+    if (!(record->event & TRACE_RECORD_VALID)) {
         return false;
     }
 
     __sync_synchronize(); /* read memory barrier before accessing record */
 
-    *record = trace_buf[idx];
-    record->event &= ~TRACE_RECORD_VALID;
+    *recordptr = g_malloc(record->length);
+    /* make a copy of record to avoid being overwritten */
+    memcpy(*recordptr, record, record->length);
+    (*recordptr)->event &= ~TRACE_RECORD_VALID;
     return true;
 }
 
@@ -106,6 +93,47 @@ static void flush_trace_file(bool wait)
     g_static_mutex_unlock(&trace_lock);
 }
 
+unsigned int trace_alloc_record(TraceEventID event, uint32_t datasize)
+{
+    unsigned int idx, rec_off;
+    uint32_t rec_len = ST_V2_REC_HDR_LEN + datasize;
+    uint64_t timestamp_ns = get_clock();
+
+    idx = g_atomic_int_exchange_and_add((gint *)&trace_idx, rec_len) % TRACE_BUF_LEN;
+    rec_off = idx;
+    write_to_buffer(rec_off, (uint8_t*)&event, sizeof(event));
+    rec_off += sizeof(event);
+    write_to_buffer(rec_off, (uint8_t*)&timestamp_ns, sizeof(timestamp_ns));
+    rec_off += sizeof(timestamp_ns);
+    write_to_buffer(rec_off, (uint8_t*)&rec_len, sizeof(rec_len));
+    rec_off += sizeof(rec_len);
+    return idx;
+}
+
+void write_to_buffer(unsigned int idx, uint8_t *dataptr, uint32_t size)
+{
+    uint32_t x = 0;
+    while (x < size)
+    {
+        if (idx >= TRACE_BUF_LEN) {
+            idx = idx % TRACE_BUF_LEN;
+        }
+        trace_buf[idx++] = dataptr[x++];
+    }
+}
+
+void trace_mark_record_complete(unsigned int idx)
+{
+    TraceRecord *record = (TraceRecord*) &trace_buf[idx];;
+
+    __sync_synchronize(); /* write barrier before marking as valid */
+    record->event |= TRACE_RECORD_VALID;
+
+    if (idx > TRACE_BUF_FLUSH_THRESHOLD) {
+        flush_trace_file(false);
+    }
+}
+
 static void wait_for_trace_records_available(void)
 {
     g_static_mutex_lock(&trace_lock);
@@ -120,7 +148,7 @@ static void wait_for_trace_records_available(void)
 
 static gpointer writeout_thread(gpointer opaque)
 {
-    TraceRecord record;
+    TraceRecord record, *recordptr;
     unsigned int writeout_idx = 0;
     unsigned int num_available, idx;
     size_t unused __attribute__ ((unused));
@@ -130,19 +158,20 @@ static gpointer writeout_thread(gpointer opaque)
 
         num_available = trace_idx - writeout_idx;
         if (num_available > TRACE_BUF_LEN) {
-            record = (TraceRecord){
-                .event = DROPPED_EVENT_ID,
-                .x1 = num_available,
-            };
-            unused = fwrite(&record, sizeof(record), 1, trace_fp);
+            record.event = DROPPED_EVENT_ID,
+            record.length = num_available,
+            unused = fwrite(&record, ST_V2_REC_HDR_LEN, 1, trace_fp);
             writeout_idx += num_available;
         }
 
         idx = writeout_idx % TRACE_BUF_LEN;
-        while (get_trace_record(idx, &record)) {
-            trace_buf[idx].event = 0; /* clear valid bit */
-            unused = fwrite(&record, sizeof(record), 1, trace_fp);
-            idx = ++writeout_idx % TRACE_BUF_LEN;
+        while (get_trace_record(idx, &recordptr)) {
+            unused = fwrite(recordptr, recordptr->length, 1, trace_fp);
+            writeout_idx += recordptr->length;
+            g_free(recordptr);
+            recordptr = (TraceRecord *) &trace_buf[idx];
+            recordptr->event = 0;
+            idx = writeout_idx % TRACE_BUF_LEN;
         }
 
         fflush(trace_fp);
@@ -150,71 +179,7 @@ static gpointer writeout_thread(gpointer opaque)
     return NULL;
 }
 
-static void trace(TraceEventID event, uint64_t x1, uint64_t x2, uint64_t x3,
-                  uint64_t x4, uint64_t x5, uint64_t x6)
-{
-    unsigned int idx;
-    uint64_t timestamp;
-
-    if (!trace_list[event].state) {
-        return;
-    }
-
-    timestamp = get_clock();
-
-    idx = g_atomic_int_exchange_and_add((gint *)&trace_idx, 1) % TRACE_BUF_LEN;
-    trace_buf[idx] = (TraceRecord){
-        .event = event,
-        .timestamp_ns = timestamp,
-        .x1 = x1,
-        .x2 = x2,
-        .x3 = x3,
-        .x4 = x4,
-        .x5 = x5,
-        .x6 = x6,
-    };
-    __sync_synchronize(); /* write barrier before marking as valid */
-    trace_buf[idx].event |= TRACE_RECORD_VALID;
-
-    if ((idx + 1) % TRACE_BUF_FLUSH_THRESHOLD == 0) {
-        flush_trace_file(false);
-    }
-}
-
-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);
-}
 
 void st_set_trace_file_enabled(bool enable)
 {
@@ -231,7 +196,7 @@ void st_set_trace_file_enabled(bool enable)
         static const TraceRecord header = {
             .event = HEADER_EVENT_ID,
             .timestamp_ns = HEADER_MAGIC,
-            .x1 = HEADER_VERSION,
+            .length = HEADER_VERSION,
         };
 
         trace_fp = fopen(trace_file_name, "wb");
@@ -288,23 +253,6 @@ void st_print_trace_file_status(FILE *stream, int (*stream_printf)(FILE *stream,
                   trace_file_name, trace_fp ? "on" : "off");
 }
 
-void st_print_trace(FILE *stream, int (*stream_printf)(FILE *stream, const char *fmt, ...))
-{
-    unsigned int i;
-
-    for (i = 0; i < TRACE_BUF_LEN; i++) {
-        TraceRecord record;
-
-        if (!get_trace_record(i, &record)) {
-            continue;
-        }
-        stream_printf(stream, "Event %" PRIu64 " : %" PRIx64 " %" PRIx64
-                      " %" PRIx64 " %" PRIx64 " %" PRIx64 " %" PRIx64 "\n",
-                      record.event, record.x1, record.x2,
-                      record.x3, record.x4, record.x5,
-                      record.x6);
-    }
-}
 
 void st_flush_trace_buffer(void)
 {
diff --git a/trace/simple.h b/trace/simple.h
index 466e75b..671cbeb 100644
--- a/trace/simple.h
+++ b/trace/simple.h
@@ -22,17 +22,34 @@ typedef struct {
     bool state;
 } TraceEvent;
 
-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);
 void st_print_trace(FILE *stream, fprintf_function stream_printf);
 void st_print_trace_file_status(FILE *stream, fprintf_function stream_printf);
 void st_set_trace_file_enabled(bool enable);
 bool st_set_trace_file(const char *file);
 void st_flush_trace_buffer(void);
 
+/* Interfaces for simpletrace v2 */
+
+/** Trace buffer entry */
+typedef struct {
+    uint64_t event; /*  TraceEventID */
+    uint64_t timestamp_ns;
+    uint32_t length;   /*   in bytes */
+    uint32_t reserved; /*   unused */
+    uint8_t arguments[]; /* arguments position affects ST_V2_REC_HDR_LEN */
+} TraceRecord;
+
+#define ST_V2_REC_HDR_LEN 24
+
+enum {
+    TRACE_BUF_LEN = 4096 * 64,
+    TRACE_BUF_FLUSH_THRESHOLD = TRACE_BUF_LEN / 4,
+};
+
+extern uint8_t trace_buf[TRACE_BUF_LEN];
+
+unsigned int trace_alloc_record(TraceEventID event, uint32_t datasize);
+void write_to_buffer(unsigned int idx, uint8_t *dataptr, uint32_t size);
+void trace_mark_record_complete(unsigned int idx);
+
 #endif /* TRACE_SIMPLE_H */
-- 
1.7.1.1

[Qemu-devel] [PATCH 4/4] simpletrace.py: Simpletrace v2 tracelog reader script

[Harsh Prateek Bora]

Signed-off-by: Harsh Prateek Bora <harsh@linux.vnet.ibm.com>
---
 scripts/simpletrace.py |  110 +++++++++++++++++++++++++++++++++++++++++++-----
 1 files changed, 99 insertions(+), 11 deletions(-)

diff --git a/scripts/simpletrace.py b/scripts/simpletrace.py
index f55e5e6..69829dd 100755
--- a/scripts/simpletrace.py
+++ b/scripts/simpletrace.py
@@ -12,16 +12,37 @@
 import struct
 import re
 import inspect
+import sys
+from tracetool import *
 
 header_event_id = 0xffffffffffffffff
 header_magic    = 0xf2b177cb0aa429b4
 header_version  = 0
+log_header_ver  = 2
 dropped_event_id = 0xfffffffffffffffe
 
 trace_fmt = '=QQQQQQQQ'
+header_fmt = '=QQII'
+header_len = struct.calcsize(header_fmt)
 trace_len = struct.calcsize(trace_fmt)
 event_re  = re.compile(r'(disable\s+)?([a-zA-Z0-9_]+)\(([^)]*)\).*')
 
+def get_event_argtypes(fobj):
+    """Parse a trace-events file into {event_num: (name, type arg, ...)}."""
+
+    events = {dropped_event_id: ('name', 'args')}
+    event_num = 0
+    for line in fobj:
+        m = event_re.match(line.strip())
+        if m is None:
+            continue
+
+        disable, name, args = m.groups()
+        events[event_num] = tuple(args.split(','))
+        event_num += 1
+    return events
+
+
 def parse_events(fobj):
     """Parse a trace-events file into {event_num: (name, arg1, ...)}."""
 
@@ -48,15 +69,16 @@ def read_record(fobj):
         return None
     return struct.unpack(trace_fmt, s)
 
+def read_header(fobj):
+    '''Read a trace record header'''
+    s = fobj.read(header_len)
+    if len(s) != header_len:
+        return None
+    return struct.unpack(header_fmt, s)
+
+
 def read_trace_file(fobj):
     """Deserialize trace records from a file, yielding record tuples (event_num, timestamp, arg1, ..., arg6)."""
-    header = read_record(fobj)
-    if header is None or \
-       header[0] != header_event_id or \
-       header[1] != header_magic or \
-       header[2] != header_version:
-        raise ValueError('not a trace file or incompatible version')
-
     while True:
         rec = read_record(fobj)
         if rec is None:
@@ -64,6 +86,59 @@ def read_trace_file(fobj):
 
         yield rec
 
+def process_event(event_id, fobj):
+    params = etypes[event_id]
+    for elem in params:
+        if is_string(elem):
+            l = fobj.read(4)
+            (len,) = struct.unpack('=L', l)
+            s = fobj.read(len)
+            sfmt = `len`+'s'
+            (str,) = struct.unpack_from(sfmt, s)
+            type, sep, var = elem.rpartition('*')
+            print '%(arg)s=%(val)s' % { 'arg': var.lstrip(), 'val': str },
+        elif '*' in elem:
+            (value,) = struct.unpack('=Q', fobj.read(8))
+            type, sep, var = elem.rpartition('*')
+            print '%(arg)s=0x%(val)u' % { 'arg': var.lstrip(), 'val': value },
+        else:
+            (value,) = struct.unpack('=Q', fobj.read(8))
+            type, sep, var = elem.rpartition(' ')
+            print '%(arg)s=%(val)u' % { 'arg': var.lstrip(), 'val': value },
+    print
+    return
+
+etypes = get_event_argtypes(open(sys.argv[1], 'r'))
+def processv2(fobj):
+    '''Process simpletrace v2 log trace records'''
+    events = parse_events(open(sys.argv[1], 'r'))
+    #print events
+    max_events = len(events) - 1
+    last_timestamp = None
+    while True:
+        # read record header
+        rechdr = read_header(fobj)
+        if rechdr is None:
+            print "No more records"
+            break
+
+        if rechdr[0] >= max_events:
+            print "Invalid Event ID found, Trace Log may be corrupted !!!"
+            sys.exit(1)
+
+        if last_timestamp is None:
+            last_timestamp = rechdr[1]
+        delta_ns = rechdr[1] - last_timestamp
+        last_timestamp = rechdr[1]
+
+        print events[rechdr[0]][0],  '%0.3f' % (delta_ns / 1000.0),
+        # read data
+        # process_event(rec[0], fobj)
+        # rechdr[2] is record length (including header)
+        #print etypes[rechdr[0]]
+        #data = fobj.read(rechdr[2] - header_len)
+        process_event(rechdr[0], fobj)
+
 class Analyzer(object):
     """A trace file analyzer which processes trace records.
 
@@ -90,8 +165,6 @@ def process(events, log, analyzer):
     """Invoke an analyzer on each event in a log."""
     if isinstance(events, str):
         events = parse_events(open(events, 'r'))
-    if isinstance(log, str):
-        log = open(log, 'rb')
 
     def build_fn(analyzer, event):
         fn = getattr(analyzer, event[0], None)
@@ -129,8 +202,10 @@ def run(analyzer):
         sys.exit(1)
 
     events = parse_events(open(sys.argv[1], 'r'))
-    process(events, sys.argv[2], analyzer)
+    process(events, log, analyzer)
+
 
+log = open(sys.argv[2], 'rb')
 if __name__ == '__main__':
     class Formatter(Analyzer):
         def __init__(self):
@@ -148,4 +223,17 @@ if __name__ == '__main__':
                 fields.append('%s=0x%x' % (event[i], rec[i + 1]))
             print ' '.join(fields)
 
-    run(Formatter())
+    #run(Formatter())
+    header = read_header(log)
+    if header is None or \
+        header[0] != header_event_id or \
+        header[1] != header_magic:
+         raise ValueError('not a valid trace file')
+    if header[2] == 0:   # version 1
+        # ver 1 tracelog header contains few more unused bytes
+        temp = log.read(40) # read those bytes and continue
+        run(Formatter())
+    elif header[2] == 2: # version 2
+        processv2(log)
+    else:
+        raise ValueError('trace file version not supported')
-- 
1.7.1.1

[Qemu-devel] [RFC PATCH 4/4] simpletrace.py: updated log reader script to handle new log format

[Harsh Prateek Bora]

Note: This script has been updated with minimal changes required to observe
the new trace log format in action and therefore can be improved for a
better design. It can still read the logs from older log format as well.

Signed-off-by: Harsh Prateek Bora <harsh@linux.vnet.ibm.com>
---
 scripts/simpletrace.py |  110 +++++++++++++++++++++++++++++++++++++++++++-----
 1 files changed, 99 insertions(+), 11 deletions(-)

diff --git a/scripts/simpletrace.py b/scripts/simpletrace.py
index f55e5e6..69829dd 100755
--- a/scripts/simpletrace.py
+++ b/scripts/simpletrace.py
@@ -12,16 +12,37 @@
 import struct
 import re
 import inspect
+import sys
+from tracetool import *
 
 header_event_id = 0xffffffffffffffff
 header_magic    = 0xf2b177cb0aa429b4
 header_version  = 0
+log_header_ver  = 2
 dropped_event_id = 0xfffffffffffffffe
 
 trace_fmt = '=QQQQQQQQ'
+header_fmt = '=QQII'
+header_len = struct.calcsize(header_fmt)
 trace_len = struct.calcsize(trace_fmt)
 event_re  = re.compile(r'(disable\s+)?([a-zA-Z0-9_]+)\(([^)]*)\).*')
 
+def get_event_argtypes(fobj):
+    """Parse a trace-events file into {event_num: (name, type arg, ...)}."""
+
+    events = {dropped_event_id: ('name', 'args')}
+    event_num = 0
+    for line in fobj:
+        m = event_re.match(line.strip())
+        if m is None:
+            continue
+
+        disable, name, args = m.groups()
+        events[event_num] = tuple(args.split(','))
+        event_num += 1
+    return events
+
+
 def parse_events(fobj):
     """Parse a trace-events file into {event_num: (name, arg1, ...)}."""
 
@@ -48,15 +69,16 @@ def read_record(fobj):
         return None
     return struct.unpack(trace_fmt, s)
 
+def read_header(fobj):
+    '''Read a trace record header'''
+    s = fobj.read(header_len)
+    if len(s) != header_len:
+        return None
+    return struct.unpack(header_fmt, s)
+
+
 def read_trace_file(fobj):
     """Deserialize trace records from a file, yielding record tuples (event_num, timestamp, arg1, ..., arg6)."""
-    header = read_record(fobj)
-    if header is None or \
-       header[0] != header_event_id or \
-       header[1] != header_magic or \
-       header[2] != header_version:
-        raise ValueError('not a trace file or incompatible version')
-
     while True:
         rec = read_record(fobj)
         if rec is None:
@@ -64,6 +86,59 @@ def read_trace_file(fobj):
 
         yield rec
 
+def process_event(event_id, fobj):
+    params = etypes[event_id]
+    for elem in params:
+        if is_string(elem):
+            l = fobj.read(4)
+            (len,) = struct.unpack('=L', l)
+            s = fobj.read(len)
+            sfmt = `len`+'s'
+            (str,) = struct.unpack_from(sfmt, s)
+            type, sep, var = elem.rpartition('*')
+            print '%(arg)s=%(val)s' % { 'arg': var.lstrip(), 'val': str },
+        elif '*' in elem:
+            (value,) = struct.unpack('=Q', fobj.read(8))
+            type, sep, var = elem.rpartition('*')
+            print '%(arg)s=0x%(val)u' % { 'arg': var.lstrip(), 'val': value },
+        else:
+            (value,) = struct.unpack('=Q', fobj.read(8))
+            type, sep, var = elem.rpartition(' ')
+            print '%(arg)s=%(val)u' % { 'arg': var.lstrip(), 'val': value },
+    print
+    return
+
+etypes = get_event_argtypes(open(sys.argv[1], 'r'))
+def processv2(fobj):
+    '''Process simpletrace v2 log trace records'''
+    events = parse_events(open(sys.argv[1], 'r'))
+    #print events
+    max_events = len(events) - 1
+    last_timestamp = None
+    while True:
+        # read record header
+        rechdr = read_header(fobj)
+        if rechdr is None:
+            print "No more records"
+            break
+
+        if rechdr[0] >= max_events:
+            print "Invalid Event ID found, Trace Log may be corrupted !!!"
+            sys.exit(1)
+
+        if last_timestamp is None:
+            last_timestamp = rechdr[1]
+        delta_ns = rechdr[1] - last_timestamp
+        last_timestamp = rechdr[1]
+
+        print events[rechdr[0]][0],  '%0.3f' % (delta_ns / 1000.0),
+        # read data
+        # process_event(rec[0], fobj)
+        # rechdr[2] is record length (including header)
+        #print etypes[rechdr[0]]
+        #data = fobj.read(rechdr[2] - header_len)
+        process_event(rechdr[0], fobj)
+
 class Analyzer(object):
     """A trace file analyzer which processes trace records.
 
@@ -90,8 +165,6 @@ def process(events, log, analyzer):
     """Invoke an analyzer on each event in a log."""
     if isinstance(events, str):
         events = parse_events(open(events, 'r'))
-    if isinstance(log, str):
-        log = open(log, 'rb')
 
     def build_fn(analyzer, event):
         fn = getattr(analyzer, event[0], None)
@@ -129,8 +202,10 @@ def run(analyzer):
         sys.exit(1)
 
     events = parse_events(open(sys.argv[1], 'r'))
-    process(events, sys.argv[2], analyzer)
+    process(events, log, analyzer)
+
 
+log = open(sys.argv[2], 'rb')
 if __name__ == '__main__':
     class Formatter(Analyzer):
         def __init__(self):
@@ -148,4 +223,17 @@ if __name__ == '__main__':
                 fields.append('%s=0x%x' % (event[i], rec[i + 1]))
             print ' '.join(fields)
 
-    run(Formatter())
+    #run(Formatter())
+    header = read_header(log)
+    if header is None or \
+        header[0] != header_event_id or \
+        header[1] != header_magic:
+         raise ValueError('not a valid trace file')
+    if header[2] == 0:   # version 1
+        # ver 1 tracelog header contains few more unused bytes
+        temp = log.read(40) # read those bytes and continue
+        run(Formatter())
+    elif header[2] == 2: # version 2
+        processv2(log)
+    else:
+        raise ValueError('trace file version not supported')
-- 
1.7.1.1

Re: [Qemu-devel] [PATCH 4/4] simpletrace.py: Simpletrace v2 tracelog reader script

[Harsh Bora]

Hi,
Please ignore this duplicate patch in the series which was sent by 
mistake, consider the one with subject '[RFC PATCH 4/4] simpletrace.py: 
updated log reader script to handle new log format'. Sorry for 
inconvenience.

- Harsh

On 01/02/2012 12:20 PM, Harsh Prateek Bora wrote:
> Signed-off-by: Harsh Prateek Bora<harsh@linux.vnet.ibm.com>
> ---
>   scripts/simpletrace.py |  110 +++++++++++++++++++++++++++++++++++++++++++-----
>   1 files changed, 99 insertions(+), 11 deletions(-)
>
> diff --git a/scripts/simpletrace.py b/scripts/simpletrace.py
> index f55e5e6..69829dd 100755
> --- a/scripts/simpletrace.py
> +++ b/scripts/simpletrace.py
> @@ -12,16 +12,37 @@
>   import struct
>   import re
>   import inspect
> +import sys
> +from tracetool import *
>
>   header_event_id = 0xffffffffffffffff
>   header_magic    = 0xf2b177cb0aa429b4
>   header_version  = 0
> +log_header_ver  = 2
>   dropped_event_id = 0xfffffffffffffffe
>
>   trace_fmt = '=QQQQQQQQ'
> +header_fmt = '=QQII'
> +header_len = struct.calcsize(header_fmt)
>   trace_len = struct.calcsize(trace_fmt)
>   event_re  = re.compile(r'(disable\s+)?([a-zA-Z0-9_]+)\(([^)]*)\).*')
>
> +def get_event_argtypes(fobj):
> +    """Parse a trace-events file into {event_num: (name, type arg, ...)}."""
> +
> +    events = {dropped_event_id: ('name', 'args')}
> +    event_num = 0
> +    for line in fobj:
> +        m = event_re.match(line.strip())
> +        if m is None:
> +            continue
> +
> +        disable, name, args = m.groups()
> +        events[event_num] = tuple(args.split(','))
> +        event_num += 1
> +    return events
> +
> +
>   def parse_events(fobj):
>       """Parse a trace-events file into {event_num: (name, arg1, ...)}."""
>
> @@ -48,15 +69,16 @@ def read_record(fobj):
>           return None
>       return struct.unpack(trace_fmt, s)
>
> +def read_header(fobj):
> +    '''Read a trace record header'''
> +    s = fobj.read(header_len)
> +    if len(s) != header_len:
> +        return None
> +    return struct.unpack(header_fmt, s)
> +
> +
>   def read_trace_file(fobj):
>       """Deserialize trace records from a file, yielding record tuples (event_num, timestamp, arg1, ..., arg6)."""
> -    header = read_record(fobj)
> -    if header is None or \
> -       header[0] != header_event_id or \
> -       header[1] != header_magic or \
> -       header[2] != header_version:
> -        raise ValueError('not a trace file or incompatible version')
> -
>       while True:
>           rec = read_record(fobj)
>           if rec is None:
> @@ -64,6 +86,59 @@ def read_trace_file(fobj):
>
>           yield rec
>
> +def process_event(event_id, fobj):
> +    params = etypes[event_id]
> +    for elem in params:
> +        if is_string(elem):
> +            l = fobj.read(4)
> +            (len,) = struct.unpack('=L', l)
> +            s = fobj.read(len)
> +            sfmt = `len`+'s'
> +            (str,) = struct.unpack_from(sfmt, s)
> +            type, sep, var = elem.rpartition('*')
> +            print '%(arg)s=%(val)s' % { 'arg': var.lstrip(), 'val': str },
> +        elif '*' in elem:
> +            (value,) = struct.unpack('=Q', fobj.read(8))
> +            type, sep, var = elem.rpartition('*')
> +            print '%(arg)s=0x%(val)u' % { 'arg': var.lstrip(), 'val': value },
> +        else:
> +            (value,) = struct.unpack('=Q', fobj.read(8))
> +            type, sep, var = elem.rpartition(' ')
> +            print '%(arg)s=%(val)u' % { 'arg': var.lstrip(), 'val': value },
> +    print
> +    return
> +
> +etypes = get_event_argtypes(open(sys.argv[1], 'r'))
> +def processv2(fobj):
> +    '''Process simpletrace v2 log trace records'''
> +    events = parse_events(open(sys.argv[1], 'r'))
> +    #print events
> +    max_events = len(events) - 1
> +    last_timestamp = None
> +    while True:
> +        # read record header
> +        rechdr = read_header(fobj)
> +        if rechdr is None:
> +            print "No more records"
> +            break
> +
> +        if rechdr[0]>= max_events:
> +            print "Invalid Event ID found, Trace Log may be corrupted !!!"
> +            sys.exit(1)
> +
> +        if last_timestamp is None:
> +            last_timestamp = rechdr[1]
> +        delta_ns = rechdr[1] - last_timestamp
> +        last_timestamp = rechdr[1]
> +
> +        print events[rechdr[0]][0],  '%0.3f' % (delta_ns / 1000.0),
> +        # read data
> +        # process_event(rec[0], fobj)
> +        # rechdr[2] is record length (including header)
> +        #print etypes[rechdr[0]]
> +        #data = fobj.read(rechdr[2] - header_len)
> +        process_event(rechdr[0], fobj)
> +
>   class Analyzer(object):
>       """A trace file analyzer which processes trace records.
>
> @@ -90,8 +165,6 @@ def process(events, log, analyzer):
>       """Invoke an analyzer on each event in a log."""
>       if isinstance(events, str):
>           events = parse_events(open(events, 'r'))
> -    if isinstance(log, str):
> -        log = open(log, 'rb')
>
>       def build_fn(analyzer, event):
>           fn = getattr(analyzer, event[0], None)
> @@ -129,8 +202,10 @@ def run(analyzer):
>           sys.exit(1)
>
>       events = parse_events(open(sys.argv[1], 'r'))
> -    process(events, sys.argv[2], analyzer)
> +    process(events, log, analyzer)
> +
>
> +log = open(sys.argv[2], 'rb')
>   if __name__ == '__main__':
>       class Formatter(Analyzer):
>           def __init__(self):
> @@ -148,4 +223,17 @@ if __name__ == '__main__':
>                   fields.append('%s=0x%x' % (event[i], rec[i + 1]))
>               print ' '.join(fields)
>
> -    run(Formatter())
> +    #run(Formatter())
> +    header = read_header(log)
> +    if header is None or \
> +        header[0] != header_event_id or \
> +        header[1] != header_magic:
> +         raise ValueError('not a valid trace file')
> +    if header[2] == 0:   # version 1
> +        # ver 1 tracelog header contains few more unused bytes
> +        temp = log.read(40) # read those bytes and continue
> +        run(Formatter())
> +    elif header[2] == 2: # version 2
> +        processv2(log)
> +    else:
> +        raise ValueError('trace file version not supported')

Re: [Qemu-devel] [RFC PATCH 0/4] simpletrace : support var num/size of args, strings.

[Lluís Vilanova]

Harsh Prateek Bora writes:

>   Converting tracetool.sh to tracetool.py

Excellent! I was thinking about switching the script language to python, but
wasn't sure if python was an acceptable build dependency for the project.

I was modifying the bash tracetool to add a tracing layer more amenable to
instrumentation (together with the API that Avi suggested for 3rd party tracing
tools to interact with QEMU).

It currently looks like:

* trace.h (includes trace-backend.h)
  -> backend={no instrumentation, static instr, dynamic instr (dlopen)}
* trace-backend.h
  -> backend={nop,stderr,simple,dtrace,...}

And similarly for TCG tracing.

What I'd like to know is if I can switch right away into this new script to
finish these changes (and avoid doing the work twice).


Lluis

-- 
 "And it's much the same thing with knowledge, for whenever you learn
 something new, the whole world becomes that much richer."
 -- The Princess of Pure Reason, as told by Norton Juster in The Phantom
 Tollbooth

Re: [Qemu-devel] [RFC PATCH 0/4] simpletrace : support var num/size of args, strings.

[Harsh Bora]

On 01/02/2012 06:20 PM, Lluís Vilanova wrote:
> Harsh Prateek Bora writes:
>
>>    Converting tracetool.sh to tracetool.py
>
> Excellent! I was thinking about switching the script language to python, but
> wasn't sure if python was an acceptable build dependency for the project.

Thanks, Python appears to become mandatory requirement soon as per
  http://lists.gnu.org/archive/html/qemu-devel/2012-01/msg00169.html

>
> I was modifying the bash tracetool to add a tracing layer more amenable to
> instrumentation (together with the API that Avi suggested for 3rd party tracing
> tools to interact with QEMU).
>
> It currently looks like:
>
> * trace.h (includes trace-backend.h)
>    ->  backend={no instrumentation, static instr, dynamic instr (dlopen)}
> * trace-backend.h
>    ->  backend={nop,stderr,simple,dtrace,...}
>
> And similarly for TCG tracing.
>
> What I'd like to know is if I can switch right away into this new script to
> finish these changes (and avoid doing the work twice).

I guess yes, however this patch still needs to be updated for code 
generation for other tracing backends.

- Harsh

>
>
> Lluis
>