scripts/simpletrace.py

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