| #!/usr/bin/env python3 |
| # |
| # Pretty-printer for simple trace backend binary trace files |
| # |
| # Copyright IBM, Corp. 2010 |
| # |
| # This work is licensed under the terms of the GNU GPL, version 2. See |
| # the COPYING file in the top-level directory. |
| # |
| # For help see docs/devel/tracing.rst |
| |
| import struct |
| import inspect |
| from tracetool import read_events, Event |
| from tracetool.backend.simple import is_string |
| |
| header_event_id = 0xffffffffffffffff |
| header_magic = 0xf2b177cb0aa429b4 |
| dropped_event_id = 0xfffffffffffffffe |
| |
| record_type_mapping = 0 |
| record_type_event = 1 |
| |
| log_header_fmt = '=QQQ' |
| rec_header_fmt = '=QQII' |
| |
| def read_header(fobj, hfmt): |
| '''Read a trace record header''' |
| hlen = struct.calcsize(hfmt) |
| hdr = fobj.read(hlen) |
| if len(hdr) != hlen: |
| return None |
| return struct.unpack(hfmt, hdr) |
| |
| def get_record(edict, idtoname, rechdr, fobj): |
| """Deserialize a trace record from a file into a tuple |
| (name, timestamp, pid, arg1, ..., arg6).""" |
| if rechdr is None: |
| return None |
| if rechdr[0] != dropped_event_id: |
| event_id = rechdr[0] |
| name = idtoname[event_id] |
| rec = (name, rechdr[1], rechdr[3]) |
| try: |
| event = edict[name] |
| except KeyError as e: |
| import sys |
| sys.stderr.write('%s event is logged but is not declared ' \ |
| 'in the trace events file, try using ' \ |
| 'trace-events-all instead.\n' % str(e)) |
| sys.exit(1) |
| |
| for type, name in event.args: |
| if is_string(type): |
| l = fobj.read(4) |
| (len,) = struct.unpack('=L', l) |
| s = fobj.read(len) |
| rec = rec + (s,) |
| else: |
| (value,) = struct.unpack('=Q', fobj.read(8)) |
| rec = rec + (value,) |
| else: |
| rec = ("dropped", rechdr[1], rechdr[3]) |
| (value,) = struct.unpack('=Q', fobj.read(8)) |
| rec = rec + (value,) |
| return rec |
| |
| def get_mapping(fobj): |
| (event_id, ) = struct.unpack('=Q', fobj.read(8)) |
| (len, ) = struct.unpack('=L', fobj.read(4)) |
| name = fobj.read(len).decode() |
| |
| return (event_id, name) |
| |
| def read_record(edict, idtoname, fobj): |
| """Deserialize a trace record from a file into a tuple (event_num, timestamp, pid, arg1, ..., arg6).""" |
| rechdr = read_header(fobj, rec_header_fmt) |
| return get_record(edict, idtoname, rechdr, fobj) |
| |
| def read_trace_header(fobj): |
| """Read and verify trace file header""" |
| header = read_header(fobj, log_header_fmt) |
| if header is None: |
| raise ValueError('Not a valid trace file!') |
| if header[0] != header_event_id: |
| raise ValueError('Not a valid trace file, header id %d != %d' % |
| (header[0], header_event_id)) |
| if header[1] != header_magic: |
| raise ValueError('Not a valid trace file, header magic %d != %d' % |
| (header[1], header_magic)) |
| |
| log_version = header[2] |
| if log_version not in [0, 2, 3, 4]: |
| raise ValueError('Unknown version of tracelog format!') |
| if log_version != 4: |
| raise ValueError('Log format %d not supported with this QEMU release!' |
| % log_version) |
| |
| def read_trace_records(edict, idtoname, fobj): |
| """Deserialize trace records from a file, yielding record tuples (event_num, timestamp, pid, arg1, ..., arg6). |
| |
| Note that `idtoname` is modified if the file contains mapping records. |
| |
| Args: |
| edict (str -> Event): events dict, indexed by name |
| idtoname (int -> str): event names dict, indexed by event ID |
| fobj (file): input file |
| |
| """ |
| while True: |
| t = fobj.read(8) |
| if len(t) == 0: |
| break |
| |
| (rectype, ) = struct.unpack('=Q', t) |
| if rectype == record_type_mapping: |
| event_id, name = get_mapping(fobj) |
| idtoname[event_id] = name |
| else: |
| rec = read_record(edict, idtoname, fobj) |
| |
| yield rec |
| |
| class Analyzer(object): |
| """A trace file analyzer which processes trace records. |
| |
| An analyzer can be passed to run() or process(). The begin() method is |
| invoked, then each trace record is processed, and finally the end() method |
| is invoked. |
| |
| If a method matching a trace event name exists, it is invoked to process |
| that trace record. Otherwise the catchall() method is invoked. |
| |
| Example: |
| The following method handles the runstate_set(int new_state) trace event:: |
| |
| def runstate_set(self, new_state): |
| ... |
| |
| The method can also take a timestamp argument before the trace event |
| arguments:: |
| |
| def runstate_set(self, timestamp, new_state): |
| ... |
| |
| Timestamps have the uint64_t type and are in nanoseconds. |
| |
| The pid can be included in addition to the timestamp and is useful when |
| dealing with traces from multiple processes:: |
| |
| def runstate_set(self, timestamp, pid, new_state): |
| ... |
| """ |
| |
| def begin(self): |
| """Called at the start of the trace.""" |
| pass |
| |
| def catchall(self, event, rec): |
| """Called if no specific method for processing a trace event has been found.""" |
| pass |
| |
| def end(self): |
| """Called at the end of the trace.""" |
| pass |
| |
| def process(events, log, analyzer, read_header=True): |
| """Invoke an analyzer on each event in a log.""" |
| if isinstance(events, str): |
| events = read_events(open(events, 'r'), events) |
| if isinstance(log, str): |
| log = open(log, 'rb') |
| |
| if read_header: |
| read_trace_header(log) |
| |
| frameinfo = inspect.getframeinfo(inspect.currentframe()) |
| dropped_event = Event.build("Dropped_Event(uint64_t num_events_dropped)", |
| frameinfo.lineno + 1, frameinfo.filename) |
| edict = {"dropped": dropped_event} |
| idtoname = {dropped_event_id: "dropped"} |
| |
| for event in events: |
| edict[event.name] = event |
| |
| # If there is no header assume event ID mapping matches events list |
| if not read_header: |
| for event_id, event in enumerate(events): |
| idtoname[event_id] = event.name |
| |
| def build_fn(analyzer, event): |
| if isinstance(event, str): |
| return analyzer.catchall |
| |
| fn = getattr(analyzer, event.name, None) |
| if fn is None: |
| return analyzer.catchall |
| |
| event_argcount = len(event.args) |
| fn_argcount = len(inspect.getargspec(fn)[0]) - 1 |
| if fn_argcount == event_argcount + 1: |
| # Include timestamp as first argument |
| return lambda _, rec: fn(*(rec[1:2] + rec[3:3 + event_argcount])) |
| elif fn_argcount == event_argcount + 2: |
| # Include timestamp and pid |
| return lambda _, rec: fn(*rec[1:3 + event_argcount]) |
| else: |
| # Just arguments, no timestamp or pid |
| return lambda _, rec: fn(*rec[3:3 + event_argcount]) |
| |
| analyzer.begin() |
| fn_cache = {} |
| for rec in read_trace_records(edict, idtoname, log): |
| event_num = rec[0] |
| event = edict[event_num] |
| if event_num not in fn_cache: |
| fn_cache[event_num] = build_fn(analyzer, event) |
| fn_cache[event_num](event, rec) |
| analyzer.end() |
| |
| def run(analyzer): |
| """Execute an analyzer on a trace file given on the command-line. |
| |
| This function is useful as a driver for simple analysis scripts. More |
| advanced scripts will want to call process() instead.""" |
| import sys |
| |
| read_header = True |
| if len(sys.argv) == 4 and sys.argv[1] == '--no-header': |
| read_header = False |
| del sys.argv[1] |
| elif len(sys.argv) != 3: |
| sys.stderr.write('usage: %s [--no-header] <trace-events> ' \ |
| '<trace-file>\n' % sys.argv[0]) |
| sys.exit(1) |
| |
| events = read_events(open(sys.argv[1], 'r'), sys.argv[1]) |
| process(events, sys.argv[2], analyzer, read_header=read_header) |
| |
| if __name__ == '__main__': |
| class Formatter(Analyzer): |
| def __init__(self): |
| self.last_timestamp = None |
| |
| def catchall(self, event, rec): |
| timestamp = rec[1] |
| if self.last_timestamp is None: |
| self.last_timestamp = timestamp |
| delta_ns = timestamp - self.last_timestamp |
| self.last_timestamp = timestamp |
| |
| fields = [event.name, '%0.3f' % (delta_ns / 1000.0), |
| 'pid=%d' % rec[2]] |
| i = 3 |
| for type, name in event.args: |
| if is_string(type): |
| fields.append('%s=%s' % (name, rec[i])) |
| else: |
| fields.append('%s=0x%x' % (name, rec[i])) |
| i += 1 |
| print(' '.join(fields)) |
| |
| run(Formatter()) |
