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

[Harsh Prateek Bora <harsh@linux.vnet.ibm.com>]

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