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.rst
  11
  12 import sys
  13 import struct
  14 import inspect
  15 import warnings
  16 from tracetool import read_events, Event
  17 from tracetool.backend.simple import is_string
  18
  19 __all__ = ['Analyzer', 'Analyzer2', 'process', 'run']
  20
  21 # This is the binary format that the QEMU "simple" trace backend
  22 # emits. There is no specification documentation because the format is
  23 # not guaranteed to be stable. Trace files must be parsed with the
  24 # same trace-events-all file and the same simpletrace.py file that
  25 # QEMU was built with.
  26 header_event_id = 0xffffffffffffffff
  27 header_magic    = 0xf2b177cb0aa429b4
  28 dropped_event_id = 0xfffffffffffffffe
  29
  30 record_type_mapping = 0
  31 record_type_event = 1
  32
  33 log_header_fmt = '=QQQ'
  34 rec_header_fmt = '=QQII'
  35 rec_header_fmt_len = struct.calcsize(rec_header_fmt)
  36
  37 class SimpleException(Exception):
  38     pass
  39
  40 def read_header(fobj, hfmt):
  41     '''Read a trace record header'''
  42     hlen = struct.calcsize(hfmt)
  43     hdr = fobj.read(hlen)
  44     if len(hdr) != hlen:
  45         raise SimpleException('Error reading header. Wrong filetype provided?')
  46     return struct.unpack(hfmt, hdr)
  47
  48 def get_mapping(fobj):
  49     (event_id, ) = struct.unpack('=Q', fobj.read(8))
  50     (len, ) = struct.unpack('=L', fobj.read(4))
  51     name = fobj.read(len).decode()
  52
  53     return (event_id, name)
  54
  55 def read_record(fobj):
  56     """Deserialize a trace record from a file into a tuple (event_num, timestamp, pid, args)."""
  57     event_id, timestamp_ns, record_length, record_pid = read_header(fobj, rec_header_fmt)
  58     args_payload = fobj.read(record_length - rec_header_fmt_len)
  59     return (event_id, timestamp_ns, record_pid, args_payload)
  60
  61 def read_trace_header(fobj):
  62     """Read and verify trace file header"""
  63     _header_event_id, _header_magic, log_version = read_header(fobj, log_header_fmt)
  64     if _header_event_id != header_event_id:
  65         raise ValueError(f'Not a valid trace file, header id {_header_event_id} != {header_event_id}')
  66     if _header_magic != header_magic:
  67         raise ValueError(f'Not a valid trace file, header magic {_header_magic} != {header_magic}')
  68
  69     if log_version not in [0, 2, 3, 4]:
  70         raise ValueError(f'Unknown version {log_version} of tracelog format!')
  71     if log_version != 4:
  72         raise ValueError(f'Log format {log_version} not supported with this QEMU release!')
  73
  74 def read_trace_records(events, fobj, read_header):
  75     """Deserialize trace records from a file, yielding record tuples (event, event_num, timestamp, pid, arg1, ..., arg6).
  76
  77     Args:
  78         event_mapping (str -> Event): events dict, indexed by name
  79         fobj (file): input file
  80         read_header (bool): whether headers were read from fobj
  81
  82     """
  83     frameinfo = inspect.getframeinfo(inspect.currentframe())
  84     dropped_event = Event.build("Dropped_Event(uint64_t num_events_dropped)",
  85                                 frameinfo.lineno + 1, frameinfo.filename)
  86
  87     event_mapping = {e.name: e for e in events}
  88     event_mapping["dropped"] = dropped_event
  89     event_id_to_name = {dropped_event_id: "dropped"}
  90
  91     # If there is no header assume event ID mapping matches events list
  92     if not read_header:
  93         for event_id, event in enumerate(events):
  94             event_id_to_name[event_id] = event.name
  95
  96     while True:
  97         t = fobj.read(8)
  98         if len(t) == 0:
  99             break
 100
 101         (rectype, ) = struct.unpack('=Q', t)
 102         if rectype == record_type_mapping:
 103             event_id, event_name = get_mapping(fobj)
 104             event_id_to_name[event_id] = event_name
 105         else:
 106             event_id, timestamp_ns, pid, args_payload = read_record(fobj)
 107             event_name = event_id_to_name[event_id]
 108
 109             try:
 110                 event = event_mapping[event_name]
 111             except KeyError as e:
 112                 raise SimpleException(
 113                     f'{e} event is logged but is not declared in the trace events'
 114                     'file, try using trace-events-all instead.'
 115                 )
 116
 117             offset = 0
 118             args = []
 119             for type, _ in event.args:
 120                 if is_string(type):
 121                     (length,) = struct.unpack_from('=L', args_payload, offset=offset)
 122                     offset += 4
 123                     s = args_payload[offset:offset+length]
 124                     offset += length
 125                     args.append(s)
 126                 else:
 127                     (value,) = struct.unpack_from('=Q', args_payload, offset=offset)
 128                     offset += 8
 129                     args.append(value)
 130
 131             yield (event_mapping[event_name], event_name, timestamp_ns, pid) + tuple(args)
 132
 133 class Analyzer:
 134     """[Deprecated. Refer to Analyzer2 instead.]
 135
 136     A trace file analyzer which processes trace records.
 137
 138     An analyzer can be passed to run() or process().  The begin() method is
 139     invoked, then each trace record is processed, and finally the end() method
 140     is invoked. When Analyzer is used as a context-manager (using the `with`
 141     statement), begin() and end() are called automatically.
 142
 143     If a method matching a trace event name exists, it is invoked to process
 144     that trace record.  Otherwise the catchall() method is invoked.
 145
 146     Example:
 147     The following method handles the runstate_set(int new_state) trace event::
 148
 149       def runstate_set(self, new_state):
 150           ...
 151
 152     The method can also take a timestamp argument before the trace event
 153     arguments::
 154
 155       def runstate_set(self, timestamp, new_state):
 156           ...
 157
 158     Timestamps have the uint64_t type and are in nanoseconds.
 159
 160     The pid can be included in addition to the timestamp and is useful when
 161     dealing with traces from multiple processes::
 162
 163       def runstate_set(self, timestamp, pid, new_state):
 164           ...
 165     """
 166
 167     def begin(self):
 168         """Called at the start of the trace."""
 169         pass
 170
 171     def catchall(self, event, rec):
 172         """Called if no specific method for processing a trace event has been found."""
 173         pass
 174
 175     def _build_fn(self, event):
 176         fn = getattr(self, event.name, None)
 177         if fn is None:
 178             # Return early to avoid costly call to inspect.getfullargspec
 179             return self.catchall
 180
 181         event_argcount = len(event.args)
 182         fn_argcount = len(inspect.getfullargspec(fn)[0]) - 1
 183         if fn_argcount == event_argcount + 1:
 184             # Include timestamp as first argument
 185             return lambda _, rec: fn(*(rec[1:2] + rec[3:3 + event_argcount]))
 186         elif fn_argcount == event_argcount + 2:
 187             # Include timestamp and pid
 188             return lambda _, rec: fn(*rec[1:3 + event_argcount])
 189         else:
 190             # Just arguments, no timestamp or pid
 191             return lambda _, rec: fn(*rec[3:3 + event_argcount])
 192
 193     def _process_event(self, rec_args, *, event, event_id, timestamp_ns, pid, **kwargs):
 194         warnings.warn(
 195             "Use of deprecated Analyzer class. Refer to Analyzer2 instead.",
 196             DeprecationWarning,
 197         )
 198
 199         if not hasattr(self, '_fn_cache'):
 200             # NOTE: Cannot depend on downstream subclasses to have
 201             # super().__init__() because of legacy.
 202             self._fn_cache = {}
 203
 204         rec = (event_id, timestamp_ns, pid, *rec_args)
 205         if event_id not in self._fn_cache:
 206             self._fn_cache[event_id] = self._build_fn(event)
 207         self._fn_cache[event_id](event, rec)
 208
 209     def end(self):
 210         """Called at the end of the trace."""
 211         pass
 212
 213     def __enter__(self):
 214         self.begin()
 215         return self
 216
 217     def __exit__(self, exc_type, exc_val, exc_tb):
 218         if exc_type is None:
 219             self.end()
 220         return False
 221
 222 class Analyzer2(Analyzer):
 223     """A trace file analyzer which processes trace records.
 224
 225     An analyzer can be passed to run() or process().  The begin() method is
 226     invoked, then each trace record is processed, and finally the end() method
 227     is invoked. When Analyzer is used as a context-manager (using the `with`
 228     statement), begin() and end() are called automatically.
 229
 230     If a method matching a trace event name exists, it is invoked to process
 231     that trace record.  Otherwise the catchall() method is invoked.
 232
 233     The methods are called with a set of keyword-arguments. These can be ignored
 234     using `**kwargs` or defined like any keyword-argument.
 235
 236     The following keyword-arguments are available, but make sure to have an
 237     **kwargs to allow for unmatched arguments in the future:
 238         event: Event object of current trace
 239         event_id: The id of the event in the current trace file
 240         timestamp_ns: The timestamp in nanoseconds of the trace
 241         pid: The process id recorded for the given trace
 242
 243     Example:
 244     The following method handles the runstate_set(int new_state) trace event::
 245
 246       def runstate_set(self, new_state, **kwargs):
 247           ...
 248
 249     The method can also explicitly take a timestamp keyword-argument with the
 250     trace event arguments::
 251
 252       def runstate_set(self, new_state, *, timestamp_ns, **kwargs):
 253           ...
 254
 255     Timestamps have the uint64_t type and are in nanoseconds.
 256
 257     The pid can be included in addition to the timestamp and is useful when
 258     dealing with traces from multiple processes:
 259
 260       def runstate_set(self, new_state, *, timestamp_ns, pid, **kwargs):
 261           ...
 262     """
 263
 264     def catchall(self, *rec_args, event, timestamp_ns, pid, event_id, **kwargs):
 265         """Called if no specific method for processing a trace event has been found."""
 266         pass
 267
 268     def _process_event(self, rec_args, *, event, **kwargs):
 269         fn = getattr(self, event.name, self.catchall)
 270         fn(*rec_args, event=event, **kwargs)
 271
 272 def process(events, log, analyzer, read_header=True):
 273     """Invoke an analyzer on each event in a log.
 274     Args:
 275         events (file-object or list or str): events list or file-like object or file path as str to read event data from
 276         log (file-object or str): file-like object or file path as str to read log data from
 277         analyzer (Analyzer): Instance of Analyzer to interpret the event data
 278         read_header (bool, optional): Whether to read header data from the log data. Defaults to True.
 279     """
 280
 281     if isinstance(events, str):
 282         with open(events, 'r') as f:
 283             events_list = read_events(f, events)
 284     elif isinstance(events, list):
 285         # Treat as a list of events already produced by tracetool.read_events
 286         events_list = events
 287     else:
 288         # Treat as an already opened file-object
 289         events_list = read_events(events, events.name)
 290
 291     if isinstance(log, str):
 292         with open(log, 'rb') as log_fobj:
 293             _process(events_list, log_fobj, analyzer, read_header)
 294     else:
 295         # Treat `log` as an already opened file-object. We will not close it,
 296         # as we do not own it.
 297         _process(events_list, log, analyzer, read_header)
 298
 299 def _process(events, log_fobj, analyzer, read_header=True):
 300     """Internal function for processing
 301
 302     Args:
 303         events (list): list of events already produced by tracetool.read_events
 304         log_fobj (file): file-object to read log data from
 305         analyzer (Analyzer): the Analyzer to interpret the event data
 306         read_header (bool, optional): Whether to read header data from the log data. Defaults to True.
 307     """
 308
 309     if read_header:
 310         read_trace_header(log_fobj)
 311
 312     with analyzer:
 313         for event, event_id, timestamp_ns, record_pid, *rec_args in read_trace_records(events, log_fobj, read_header):
 314             analyzer._process_event(
 315                 rec_args,
 316                 event=event,
 317                 event_id=event_id,
 318                 timestamp_ns=timestamp_ns,
 319                 pid=record_pid,
 320             )
 321
 322 def run(analyzer):
 323     """Execute an analyzer on a trace file given on the command-line.
 324
 325     This function is useful as a driver for simple analysis scripts.  More
 326     advanced scripts will want to call process() instead."""
 327
 328     try:
 329         # NOTE: See built-in `argparse` module for a more robust cli interface
 330         *no_header, trace_event_path, trace_file_path = sys.argv[1:]
 331         assert no_header == [] or no_header == ['--no-header'], 'Invalid no-header argument'
 332     except (AssertionError, ValueError):
 333         raise SimpleException(f'usage: {sys.argv[0]} [--no-header] <trace-events> <trace-file>\n')
 334
 335     with open(trace_event_path, 'r') as events_fobj, open(trace_file_path, 'rb') as log_fobj:
 336         process(events_fobj, log_fobj, analyzer, read_header=not no_header)
 337
 338 if __name__ == '__main__':
 339     class Formatter2(Analyzer2):
 340         def __init__(self):
 341             self.last_timestamp_ns = None
 342
 343         def catchall(self, *rec_args, event, timestamp_ns, pid, event_id):
 344             if self.last_timestamp_ns is None:
 345                 self.last_timestamp_ns = timestamp_ns
 346             delta_ns = timestamp_ns - self.last_timestamp_ns
 347             self.last_timestamp_ns = timestamp_ns
 348
 349             fields = [
 350                 f'{name}={r}' if is_string(type) else f'{name}=0x{r:x}'
 351                 for r, (type, name) in zip(rec_args, event.args)
 352             ]
 353             print(f'{event.name} {delta_ns / 1000:0.3f} {pid=} ' + ' '.join(fields))
 354
 355     try:
 356         run(Formatter2())
 357     except SimpleException as e:
 358         sys.stderr.write(str(e) + "\n")
 359         sys.exit(1)