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