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/devel/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         try:
  46             event = edict[name]
  47         except KeyError, e:
  48             import sys
  49             sys.stderr.write('%s event is logged but is not declared ' \
  50                              'in the trace events file, try using ' \
  51                              'trace-events-all instead.\n' % str(e))
  52             sys.exit(1)
  53
  54         for type, name in event.args:
  55             if is_string(type):
  56                 l = fobj.read(4)
  57                 (len,) = struct.unpack('=L', l)
  58                 s = fobj.read(len)
  59                 rec = rec + (s,)
  60             else:
  61                 (value,) = struct.unpack('=Q', fobj.read(8))
  62                 rec = rec + (value,)
  63     else:
  64         rec = ("dropped", rechdr[1], rechdr[3])
  65         (value,) = struct.unpack('=Q', fobj.read(8))
  66         rec = rec + (value,)
  67     return rec
  68
  69 def get_mapping(fobj):
  70     (event_id, ) = struct.unpack('=Q', fobj.read(8))
  71     (len, ) = struct.unpack('=L', fobj.read(4))
  72     name = fobj.read(len)
  73
  74     return (event_id, name)
  75
  76 def read_record(edict, idtoname, fobj):
  77     """Deserialize a trace record from a file into a tuple (event_num, timestamp, pid, arg1, ..., arg6)."""
  78     rechdr = read_header(fobj, rec_header_fmt)
  79     return get_record(edict, idtoname, rechdr, fobj)
  80
  81 def read_trace_header(fobj):
  82     """Read and verify trace file header"""
  83     header = read_header(fobj, log_header_fmt)
  84     if header is None:
  85         raise ValueError('Not a valid trace file!')
  86     if header[0] != header_event_id:
  87         raise ValueError('Not a valid trace file, header id %d != %d' %
  88                          (header[0], header_event_id))
  89     if header[1] != header_magic:
  90         raise ValueError('Not a valid trace file, header magic %d != %d' %
  91                          (header[1], header_magic))
  92
  93     log_version = header[2]
  94     if log_version not in [0, 2, 3, 4]:
  95         raise ValueError('Unknown version of tracelog format!')
  96     if log_version != 4:
  97         raise ValueError('Log format %d not supported with this QEMU release!'
  98                          % log_version)
  99
 100 def read_trace_records(edict, idtoname, fobj):
 101     """Deserialize trace records from a file, yielding record tuples (event_num, timestamp, pid, arg1, ..., arg6).
 102
 103     Note that `idtoname` is modified if the file contains mapping records.
 104
 105     Args:
 106         edict (str -> Event): events dict, indexed by name
 107         idtoname (int -> str): event names dict, indexed by event ID
 108         fobj (file): input file
 109
 110     """
 111     while True:
 112         t = fobj.read(8)
 113         if len(t) == 0:
 114             break
 115
 116         (rectype, ) = struct.unpack('=Q', t)
 117         if rectype == record_type_mapping:
 118             event_id, name = get_mapping(fobj)
 119             idtoname[event_id] = name
 120         else:
 121             rec = read_record(edict, idtoname, fobj)
 122
 123             yield rec
 124
 125 class Analyzer(object):
 126     """A trace file analyzer which processes trace records.
 127
 128     An analyzer can be passed to run() or process().  The begin() method is
 129     invoked, then each trace record is processed, and finally the end() method
 130     is invoked.
 131
 132     If a method matching a trace event name exists, it is invoked to process
 133     that trace record.  Otherwise the catchall() method is invoked.
 134
 135     Example:
 136     The following method handles the runstate_set(int new_state) trace event::
 137
 138       def runstate_set(self, new_state):
 139           ...
 140
 141     The method can also take a timestamp argument before the trace event
 142     arguments::
 143
 144       def runstate_set(self, timestamp, new_state):
 145           ...
 146
 147     Timestamps have the uint64_t type and are in nanoseconds.
 148
 149     The pid can be included in addition to the timestamp and is useful when
 150     dealing with traces from multiple processes::
 151
 152       def runstate_set(self, timestamp, pid, new_state):
 153           ...
 154     """
 155
 156     def begin(self):
 157         """Called at the start of the trace."""
 158         pass
 159
 160     def catchall(self, event, rec):
 161         """Called if no specific method for processing a trace event has been found."""
 162         pass
 163
 164     def end(self):
 165         """Called at the end of the trace."""
 166         pass
 167
 168 def process(events, log, analyzer, read_header=True):
 169     """Invoke an analyzer on each event in a log."""
 170     if isinstance(events, str):
 171         events = read_events(open(events, 'r'))
 172     if isinstance(log, str):
 173         log = open(log, 'rb')
 174
 175     if read_header:
 176         read_trace_header(log)
 177
 178     dropped_event = Event.build("Dropped_Event(uint64_t num_events_dropped)")
 179     edict = {"dropped": dropped_event}
 180     idtoname = {dropped_event_id: "dropped"}
 181
 182     for event in events:
 183         edict[event.name] = event
 184
 185     # If there is no header assume event ID mapping matches events list
 186     if not read_header:
 187         for event_id, event in enumerate(events):
 188             idtoname[event_id] = event.name
 189
 190     def build_fn(analyzer, event):
 191         if isinstance(event, str):
 192             return analyzer.catchall
 193
 194         fn = getattr(analyzer, event.name, None)
 195         if fn is None:
 196             return analyzer.catchall
 197
 198         event_argcount = len(event.args)
 199         fn_argcount = len(inspect.getargspec(fn)[0]) - 1
 200         if fn_argcount == event_argcount + 1:
 201             # Include timestamp as first argument
 202             return lambda _, rec: fn(*((rec[1:2],) + rec[3:3 + event_argcount]))
 203         elif fn_argcount == event_argcount + 2:
 204             # Include timestamp and pid
 205             return lambda _, rec: fn(*rec[1:3 + event_argcount])
 206         else:
 207             # Just arguments, no timestamp or pid
 208             return lambda _, rec: fn(*rec[3:3 + event_argcount])
 209
 210     analyzer.begin()
 211     fn_cache = {}
 212     for rec in read_trace_records(edict, idtoname, log):
 213         event_num = rec[0]
 214         event = edict[event_num]
 215         if event_num not in fn_cache:
 216             fn_cache[event_num] = build_fn(analyzer, event)
 217         fn_cache[event_num](event, rec)
 218     analyzer.end()
 219
 220 def run(analyzer):
 221     """Execute an analyzer on a trace file given on the command-line.
 222
 223     This function is useful as a driver for simple analysis scripts.  More
 224     advanced scripts will want to call process() instead."""
 225     import sys
 226
 227     read_header = True
 228     if len(sys.argv) == 4 and sys.argv[1] == '--no-header':
 229         read_header = False
 230         del sys.argv[1]
 231     elif len(sys.argv) != 3:
 232         sys.stderr.write('usage: %s [--no-header] <trace-events> ' \
 233                          '<trace-file>\n' % sys.argv[0])
 234         sys.exit(1)
 235
 236     events = read_events(open(sys.argv[1], 'r'))
 237     process(events, sys.argv[2], analyzer, read_header=read_header)
 238
 239 if __name__ == '__main__':
 240     class Formatter(Analyzer):
 241         def __init__(self):
 242             self.last_timestamp = None
 243
 244         def catchall(self, event, rec):
 245             timestamp = rec[1]
 246             if self.last_timestamp is None:
 247                 self.last_timestamp = timestamp
 248             delta_ns = timestamp - self.last_timestamp
 249             self.last_timestamp = timestamp
 250
 251             fields = [event.name, '%0.3f' % (delta_ns / 1000.0),
 252                       'pid=%d' % rec[2]]
 253             i = 3
 254             for type, name in event.args:
 255                 if is_string(type):
 256                     fields.append('%s=%s' % (name, rec[i]))
 257                 else:
 258                     fields.append('%s=0x%x' % (name, rec[i]))
 259                 i += 1
 260             print ' '.join(fields)
 261
 262     run(Formatter())