scripts/simpletrace.py

   1 #!/usr/bin/env python
   2 #
   3 # Pretty-printer for simple trace backend binary trace files
   4 #
   5 # Copyright IBM, Corp. 2010
   6 #
   7 # This work is licensed under the terms of the GNU GPL, version 2.  See
   8 # the COPYING file in the top-level directory.
   9 #
  10 # For help see docs/tracing.txt
  11
  12 import struct
  13 import re
  14 import inspect
  15 from tracetool import read_events, Event
  16 from tracetool.backend.simple import is_string
  17
  18 header_event_id = 0xffffffffffffffff
  19 header_magic    = 0xf2b177cb0aa429b4
  20 dropped_event_id = 0xfffffffffffffffe
  21
  22 record_type_mapping = 0
  23 record_type_event = 1
  24
  25 log_header_fmt = '=QQQ'
  26 rec_header_fmt = '=QQII'
  27
  28 def read_header(fobj, hfmt):
  29     '''Read a trace record header'''
  30     hlen = struct.calcsize(hfmt)
  31     hdr = fobj.read(hlen)
  32     if len(hdr) != hlen:
  33         return None
  34     return struct.unpack(hfmt, hdr)
  35
  36 def get_record(edict, idtoname, rechdr, fobj):
  37     """Deserialize a trace record from a file into a tuple
  38        (name, timestamp, pid, arg1, ..., arg6)."""
  39     if rechdr is None:
  40         return None
  41     if rechdr[0] != dropped_event_id:
  42         event_id = rechdr[0]
  43         name = idtoname[event_id]
  44         rec = (name, rechdr[1], rechdr[3])
  45         event = edict[name]
  46         for type, name in event.args:
  47             if is_string(type):
  48                 l = fobj.read(4)
  49                 (len,) = struct.unpack('=L', l)
  50                 s = fobj.read(len)
  51                 rec = rec + (s,)
  52             else:
  53                 (value,) = struct.unpack('=Q', fobj.read(8))
  54                 rec = rec + (value,)
  55     else:
  56         rec = ("dropped", rechdr[1], rechdr[3])
  57         (value,) = struct.unpack('=Q', fobj.read(8))
  58         rec = rec + (value,)
  59     return rec
  60
  61 def get_mapping(fobj):
  62     (event_id, ) = struct.unpack('=Q', fobj.read(8))
  63     (len, ) = struct.unpack('=L', fobj.read(4))
  64     name = fobj.read(len)
  65
  66     return (event_id, name)
  67
  68 def read_record(edict, idtoname, fobj):
  69     """Deserialize a trace record from a file into a tuple (event_num, timestamp, pid, arg1, ..., arg6)."""
  70     rechdr = read_header(fobj, rec_header_fmt)
  71     return get_record(edict, idtoname, rechdr, fobj)
  72
  73 def read_trace_header(fobj):
  74     """Read and verify trace file header"""
  75     header = read_header(fobj, log_header_fmt)
  76     if header is None or \
  77        header[0] != header_event_id or \
  78        header[1] != header_magic:
  79         raise ValueError('Not a valid trace file!')
  80
  81     log_version = header[2]
  82     if log_version not in [0, 2, 3, 4]:
  83         raise ValueError('Unknown version of tracelog format!')
  84     if log_version != 4:
  85         raise ValueError('Log format %d not supported with this QEMU release!'
  86                          % log_version)
  87
  88 def read_trace_records(edict, fobj):
  89     """Deserialize trace records from a file, yielding record tuples (event_num, timestamp, pid, arg1, ..., arg6)."""
  90     idtoname = {
  91         dropped_event_id: "dropped"
  92     }
  93     while True:
  94         t = fobj.read(8)
  95         if len(t) == 0:
  96             break
  97
  98         (rectype, ) = struct.unpack('=Q', t)
  99         if rectype == record_type_mapping:
 100             event_id, name = get_mapping(fobj)
 101             idtoname[event_id] = name
 102         else:
 103             rec = read_record(edict, idtoname, fobj)
 104
 105             yield rec
 106
 107 class Analyzer(object):
 108     """A trace file analyzer which processes trace records.
 109
 110     An analyzer can be passed to run() or process().  The begin() method is
 111     invoked, then each trace record is processed, and finally the end() method
 112     is invoked.
 113
 114     If a method matching a trace event name exists, it is invoked to process
 115     that trace record.  Otherwise the catchall() method is invoked."""
 116
 117     def begin(self):
 118         """Called at the start of the trace."""
 119         pass
 120
 121     def catchall(self, event, rec):
 122         """Called if no specific method for processing a trace event has been found."""
 123         pass
 124
 125     def end(self):
 126         """Called at the end of the trace."""
 127         pass
 128
 129 def process(events, log, analyzer, read_header=True):
 130     """Invoke an analyzer on each event in a log."""
 131     if isinstance(events, str):
 132         events = read_events(open(events, 'r'))
 133     if isinstance(log, str):
 134         log = open(log, 'rb')
 135
 136     if read_header:
 137         read_trace_header(log)
 138
 139     dropped_event = Event.build("Dropped_Event(uint64_t num_events_dropped)")
 140     edict = {"dropped": dropped_event}
 141
 142     for event in events:
 143         edict[event.name] = event
 144
 145     def build_fn(analyzer, event):
 146         if isinstance(event, str):
 147             return analyzer.catchall
 148
 149         fn = getattr(analyzer, event.name, None)
 150         if fn is None:
 151             return analyzer.catchall
 152
 153         event_argcount = len(event.args)
 154         fn_argcount = len(inspect.getargspec(fn)[0]) - 1
 155         if fn_argcount == event_argcount + 1:
 156             # Include timestamp as first argument
 157             return lambda _, rec: fn(*((rec[1:2],) + rec[3:3 + event_argcount]))
 158         elif fn_argcount == event_argcount + 2:
 159             # Include timestamp and pid
 160             return lambda _, rec: fn(*rec[1:3 + event_argcount])
 161         else:
 162             # Just arguments, no timestamp or pid
 163             return lambda _, rec: fn(*rec[3:3 + event_argcount])
 164
 165     analyzer.begin()
 166     fn_cache = {}
 167     for rec in read_trace_records(edict, log):
 168         event_num = rec[0]
 169         event = edict[event_num]
 170         if event_num not in fn_cache:
 171             fn_cache[event_num] = build_fn(analyzer, event)
 172         fn_cache[event_num](event, rec)
 173     analyzer.end()
 174
 175 def run(analyzer):
 176     """Execute an analyzer on a trace file given on the command-line.
 177
 178     This function is useful as a driver for simple analysis scripts.  More
 179     advanced scripts will want to call process() instead."""
 180     import sys
 181
 182     read_header = True
 183     if len(sys.argv) == 4 and sys.argv[1] == '--no-header':
 184         read_header = False
 185         del sys.argv[1]
 186     elif len(sys.argv) != 3:
 187         sys.stderr.write('usage: %s [--no-header] <trace-events> ' \
 188                          '<trace-file>\n' % sys.argv[0])
 189         sys.exit(1)
 190
 191     events = read_events(open(sys.argv[1], 'r'))
 192     process(events, sys.argv[2], analyzer, read_header=read_header)
 193
 194 if __name__ == '__main__':
 195     class Formatter(Analyzer):
 196         def __init__(self):
 197             self.last_timestamp = None
 198
 199         def catchall(self, event, rec):
 200             timestamp = rec[1]
 201             if self.last_timestamp is None:
 202                 self.last_timestamp = timestamp
 203             delta_ns = timestamp - self.last_timestamp
 204             self.last_timestamp = timestamp
 205
 206             fields = [event.name, '%0.3f' % (delta_ns / 1000.0),
 207                       'pid=%d' % rec[2]]
 208             i = 3
 209             for type, name in event.args:
 210                 if is_string(type):
 211                     fields.append('%s=%s' % (name, rec[i]))
 212                 else:
 213                     fields.append('%s=0x%x' % (name, rec[i]))
 214                 i += 1
 215             print ' '.join(fields)
 216
 217     run(Formatter())