Stefan Hajnoczi | 26f7227 | 2010-05-22 19:24:51 +0100 | [diff] [blame] | 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/tracing.txt |
| 11 | |
Stefan Hajnoczi | 26f7227 | 2010-05-22 19:24:51 +0100 | [diff] [blame] | 12 | import struct |
| 13 | import re |
Stefan Hajnoczi | 59da668 | 2011-02-22 13:59:41 +0000 | [diff] [blame] | 14 | import inspect |
Harsh Prateek Bora | 90a147a | 2012-07-18 15:16:00 +0530 | [diff] [blame] | 15 | from tracetool import _read_events, Event |
| 16 | from tracetool.backend.simple import is_string |
Stefan Hajnoczi | 26f7227 | 2010-05-22 19:24:51 +0100 | [diff] [blame] | 17 | |
| 18 | header_event_id = 0xffffffffffffffff |
| 19 | header_magic = 0xf2b177cb0aa429b4 |
Stefan Hajnoczi | 0b5538c | 2011-02-26 18:38:39 +0000 | [diff] [blame] | 20 | dropped_event_id = 0xfffffffffffffffe |
Stefan Hajnoczi | 26f7227 | 2010-05-22 19:24:51 +0100 | [diff] [blame] | 21 | |
Harsh Prateek Bora | 90a147a | 2012-07-18 15:16:00 +0530 | [diff] [blame] | 22 | log_header_fmt = '=QQQ' |
| 23 | rec_header_fmt = '=QQII' |
Stefan Hajnoczi | 26f7227 | 2010-05-22 19:24:51 +0100 | [diff] [blame] | 24 | |
Harsh Prateek Bora | 90a147a | 2012-07-18 15:16:00 +0530 | [diff] [blame] | 25 | def read_header(fobj, hfmt): |
| 26 | '''Read a trace record header''' |
| 27 | hlen = struct.calcsize(hfmt) |
| 28 | hdr = fobj.read(hlen) |
| 29 | if len(hdr) != hlen: |
Stefan Hajnoczi | 26f7227 | 2010-05-22 19:24:51 +0100 | [diff] [blame] | 30 | return None |
Harsh Prateek Bora | 90a147a | 2012-07-18 15:16:00 +0530 | [diff] [blame] | 31 | return struct.unpack(hfmt, hdr) |
Stefan Hajnoczi | 26f7227 | 2010-05-22 19:24:51 +0100 | [diff] [blame] | 32 | |
Harsh Prateek Bora | 90a147a | 2012-07-18 15:16:00 +0530 | [diff] [blame] | 33 | def get_record(edict, rechdr, fobj): |
Stefan Hajnoczi | 80ff35c | 2014-05-07 19:24:11 +0200 | [diff] [blame] | 34 | """Deserialize a trace record from a file into a tuple (event_num, timestamp, pid, arg1, ..., arg6).""" |
Harsh Prateek Bora | 90a147a | 2012-07-18 15:16:00 +0530 | [diff] [blame] | 35 | if rechdr is None: |
| 36 | return None |
Stefan Hajnoczi | 80ff35c | 2014-05-07 19:24:11 +0200 | [diff] [blame] | 37 | rec = (rechdr[0], rechdr[1], rechdr[3]) |
Harsh Prateek Bora | 90a147a | 2012-07-18 15:16:00 +0530 | [diff] [blame] | 38 | if rechdr[0] != dropped_event_id: |
| 39 | event_id = rechdr[0] |
| 40 | event = edict[event_id] |
| 41 | for type, name in event.args: |
| 42 | if is_string(type): |
| 43 | l = fobj.read(4) |
| 44 | (len,) = struct.unpack('=L', l) |
| 45 | s = fobj.read(len) |
| 46 | rec = rec + (s,) |
| 47 | else: |
| 48 | (value,) = struct.unpack('=Q', fobj.read(8)) |
| 49 | rec = rec + (value,) |
| 50 | else: |
| 51 | (value,) = struct.unpack('=Q', fobj.read(8)) |
| 52 | rec = rec + (value,) |
| 53 | return rec |
| 54 | |
| 55 | |
| 56 | def read_record(edict, fobj): |
Stefan Hajnoczi | 80ff35c | 2014-05-07 19:24:11 +0200 | [diff] [blame] | 57 | """Deserialize a trace record from a file into a tuple (event_num, timestamp, pid, arg1, ..., arg6).""" |
Harsh Prateek Bora | 90a147a | 2012-07-18 15:16:00 +0530 | [diff] [blame] | 58 | rechdr = read_header(fobj, rec_header_fmt) |
| 59 | return get_record(edict, rechdr, fobj) # return tuple of record elements |
| 60 | |
Stefan Hajnoczi | 15327c3 | 2014-06-22 21:46:06 +0800 | [diff] [blame] | 61 | def read_trace_header(fobj): |
| 62 | """Read and verify trace file header""" |
Harsh Prateek Bora | 90a147a | 2012-07-18 15:16:00 +0530 | [diff] [blame] | 63 | header = read_header(fobj, log_header_fmt) |
Stefan Hajnoczi | 26f7227 | 2010-05-22 19:24:51 +0100 | [diff] [blame] | 64 | if header is None or \ |
| 65 | header[0] != header_event_id or \ |
Harsh Prateek Bora | 90a147a | 2012-07-18 15:16:00 +0530 | [diff] [blame] | 66 | header[1] != header_magic: |
| 67 | raise ValueError('Not a valid trace file!') |
Harsh Prateek Bora | 90a147a | 2012-07-18 15:16:00 +0530 | [diff] [blame] | 68 | |
| 69 | log_version = header[2] |
Lluís Vilanova | ef0bd3b | 2014-02-23 20:37:35 +0100 | [diff] [blame] | 70 | if log_version not in [0, 2, 3]: |
| 71 | raise ValueError('Unknown version of tracelog format!') |
| 72 | if log_version != 3: |
| 73 | raise ValueError('Log format %d not supported with this QEMU release!' |
| 74 | % log_version) |
Stefan Hajnoczi | 26f7227 | 2010-05-22 19:24:51 +0100 | [diff] [blame] | 75 | |
Stefan Hajnoczi | 15327c3 | 2014-06-22 21:46:06 +0800 | [diff] [blame] | 76 | def read_trace_records(edict, fobj): |
| 77 | """Deserialize trace records from a file, yielding record tuples (event_num, timestamp, pid, arg1, ..., arg6).""" |
Stefan Hajnoczi | 26f7227 | 2010-05-22 19:24:51 +0100 | [diff] [blame] | 78 | while True: |
Harsh Prateek Bora | 90a147a | 2012-07-18 15:16:00 +0530 | [diff] [blame] | 79 | rec = read_record(edict, fobj) |
Stefan Hajnoczi | 26f7227 | 2010-05-22 19:24:51 +0100 | [diff] [blame] | 80 | if rec is None: |
| 81 | break |
| 82 | |
| 83 | yield rec |
| 84 | |
Stefan Hajnoczi | 59da668 | 2011-02-22 13:59:41 +0000 | [diff] [blame] | 85 | class Analyzer(object): |
| 86 | """A trace file analyzer which processes trace records. |
Stefan Hajnoczi | 26f7227 | 2010-05-22 19:24:51 +0100 | [diff] [blame] | 87 | |
Stefan Hajnoczi | 59da668 | 2011-02-22 13:59:41 +0000 | [diff] [blame] | 88 | An analyzer can be passed to run() or process(). The begin() method is |
| 89 | invoked, then each trace record is processed, and finally the end() method |
| 90 | is invoked. |
Stefan Hajnoczi | 26f7227 | 2010-05-22 19:24:51 +0100 | [diff] [blame] | 91 | |
Stefan Hajnoczi | 59da668 | 2011-02-22 13:59:41 +0000 | [diff] [blame] | 92 | If a method matching a trace event name exists, it is invoked to process |
| 93 | that trace record. Otherwise the catchall() method is invoked.""" |
Stefan Hajnoczi | 26f7227 | 2010-05-22 19:24:51 +0100 | [diff] [blame] | 94 | |
Stefan Hajnoczi | 59da668 | 2011-02-22 13:59:41 +0000 | [diff] [blame] | 95 | def begin(self): |
| 96 | """Called at the start of the trace.""" |
| 97 | pass |
Stefan Hajnoczi | 26f7227 | 2010-05-22 19:24:51 +0100 | [diff] [blame] | 98 | |
Stefan Hajnoczi | 59da668 | 2011-02-22 13:59:41 +0000 | [diff] [blame] | 99 | def catchall(self, event, rec): |
| 100 | """Called if no specific method for processing a trace event has been found.""" |
| 101 | pass |
| 102 | |
| 103 | def end(self): |
| 104 | """Called at the end of the trace.""" |
| 105 | pass |
| 106 | |
Stefan Hajnoczi | 15327c3 | 2014-06-22 21:46:06 +0800 | [diff] [blame] | 107 | def process(events, log, analyzer, read_header=True): |
Stefan Hajnoczi | 59da668 | 2011-02-22 13:59:41 +0000 | [diff] [blame] | 108 | """Invoke an analyzer on each event in a log.""" |
| 109 | if isinstance(events, str): |
Harsh Prateek Bora | 90a147a | 2012-07-18 15:16:00 +0530 | [diff] [blame] | 110 | events = _read_events(open(events, 'r')) |
Stefan Hajnoczi | 59da668 | 2011-02-22 13:59:41 +0000 | [diff] [blame] | 111 | if isinstance(log, str): |
| 112 | log = open(log, 'rb') |
| 113 | |
Stefan Hajnoczi | 15327c3 | 2014-06-22 21:46:06 +0800 | [diff] [blame] | 114 | if read_header: |
| 115 | read_trace_header(log) |
| 116 | |
Harsh Prateek Bora | 90a147a | 2012-07-18 15:16:00 +0530 | [diff] [blame] | 117 | dropped_event = Event.build("Dropped_Event(uint64_t num_events_dropped)") |
| 118 | edict = {dropped_event_id: dropped_event} |
| 119 | |
Lluís Vilanova | 1dad2ce | 2014-02-23 20:37:40 +0100 | [diff] [blame] | 120 | for num, event in enumerate(events): |
Harsh Prateek Bora | 90a147a | 2012-07-18 15:16:00 +0530 | [diff] [blame] | 121 | edict[num] = event |
| 122 | |
Stefan Hajnoczi | 59da668 | 2011-02-22 13:59:41 +0000 | [diff] [blame] | 123 | def build_fn(analyzer, event): |
Harsh Prateek Bora | 90a147a | 2012-07-18 15:16:00 +0530 | [diff] [blame] | 124 | if isinstance(event, str): |
| 125 | return analyzer.catchall |
| 126 | |
| 127 | fn = getattr(analyzer, event.name, None) |
Stefan Hajnoczi | 59da668 | 2011-02-22 13:59:41 +0000 | [diff] [blame] | 128 | if fn is None: |
| 129 | return analyzer.catchall |
| 130 | |
Harsh Prateek Bora | 90a147a | 2012-07-18 15:16:00 +0530 | [diff] [blame] | 131 | event_argcount = len(event.args) |
Stefan Hajnoczi | 59da668 | 2011-02-22 13:59:41 +0000 | [diff] [blame] | 132 | fn_argcount = len(inspect.getargspec(fn)[0]) - 1 |
| 133 | if fn_argcount == event_argcount + 1: |
| 134 | # Include timestamp as first argument |
Stefan Hajnoczi | 80ff35c | 2014-05-07 19:24:11 +0200 | [diff] [blame] | 135 | return lambda _, rec: fn(*((rec[1:2],) + rec[3:3 + event_argcount])) |
| 136 | elif fn_argcount == event_argcount + 2: |
| 137 | # Include timestamp and pid |
| 138 | return lambda _, rec: fn(*rec[1:3 + event_argcount]) |
Stefan Hajnoczi | 59da668 | 2011-02-22 13:59:41 +0000 | [diff] [blame] | 139 | else: |
Stefan Hajnoczi | 80ff35c | 2014-05-07 19:24:11 +0200 | [diff] [blame] | 140 | # Just arguments, no timestamp or pid |
| 141 | return lambda _, rec: fn(*rec[3:3 + event_argcount]) |
Stefan Hajnoczi | 59da668 | 2011-02-22 13:59:41 +0000 | [diff] [blame] | 142 | |
| 143 | analyzer.begin() |
| 144 | fn_cache = {} |
Stefan Hajnoczi | 15327c3 | 2014-06-22 21:46:06 +0800 | [diff] [blame] | 145 | for rec in read_trace_records(edict, log): |
Stefan Hajnoczi | 59da668 | 2011-02-22 13:59:41 +0000 | [diff] [blame] | 146 | event_num = rec[0] |
Harsh Prateek Bora | 90a147a | 2012-07-18 15:16:00 +0530 | [diff] [blame] | 147 | event = edict[event_num] |
Stefan Hajnoczi | 59da668 | 2011-02-22 13:59:41 +0000 | [diff] [blame] | 148 | if event_num not in fn_cache: |
| 149 | fn_cache[event_num] = build_fn(analyzer, event) |
| 150 | fn_cache[event_num](event, rec) |
| 151 | analyzer.end() |
| 152 | |
| 153 | def run(analyzer): |
| 154 | """Execute an analyzer on a trace file given on the command-line. |
| 155 | |
| 156 | This function is useful as a driver for simple analysis scripts. More |
| 157 | advanced scripts will want to call process() instead.""" |
| 158 | import sys |
| 159 | |
Stefan Hajnoczi | 15327c3 | 2014-06-22 21:46:06 +0800 | [diff] [blame] | 160 | read_header = True |
| 161 | if len(sys.argv) == 4 and sys.argv[1] == '--no-header': |
| 162 | read_header = False |
| 163 | del sys.argv[1] |
| 164 | elif len(sys.argv) != 3: |
| 165 | sys.stderr.write('usage: %s [--no-header] <trace-events> ' \ |
| 166 | '<trace-file>\n' % sys.argv[0]) |
Stefan Hajnoczi | 59da668 | 2011-02-22 13:59:41 +0000 | [diff] [blame] | 167 | sys.exit(1) |
| 168 | |
Harsh Prateek Bora | 90a147a | 2012-07-18 15:16:00 +0530 | [diff] [blame] | 169 | events = _read_events(open(sys.argv[1], 'r')) |
Stefan Hajnoczi | 15327c3 | 2014-06-22 21:46:06 +0800 | [diff] [blame] | 170 | process(events, sys.argv[2], analyzer, read_header=read_header) |
Stefan Hajnoczi | 59da668 | 2011-02-22 13:59:41 +0000 | [diff] [blame] | 171 | |
| 172 | if __name__ == '__main__': |
| 173 | class Formatter(Analyzer): |
| 174 | def __init__(self): |
| 175 | self.last_timestamp = None |
| 176 | |
| 177 | def catchall(self, event, rec): |
| 178 | timestamp = rec[1] |
| 179 | if self.last_timestamp is None: |
| 180 | self.last_timestamp = timestamp |
| 181 | delta_ns = timestamp - self.last_timestamp |
| 182 | self.last_timestamp = timestamp |
| 183 | |
Stefan Hajnoczi | 80ff35c | 2014-05-07 19:24:11 +0200 | [diff] [blame] | 184 | fields = [event.name, '%0.3f' % (delta_ns / 1000.0), |
| 185 | 'pid=%d' % rec[2]] |
| 186 | i = 3 |
Harsh Prateek Bora | 90a147a | 2012-07-18 15:16:00 +0530 | [diff] [blame] | 187 | for type, name in event.args: |
| 188 | if is_string(type): |
Stefan Hajnoczi | 80ff35c | 2014-05-07 19:24:11 +0200 | [diff] [blame] | 189 | fields.append('%s=%s' % (name, rec[i])) |
Harsh Prateek Bora | 90a147a | 2012-07-18 15:16:00 +0530 | [diff] [blame] | 190 | else: |
Stefan Hajnoczi | 80ff35c | 2014-05-07 19:24:11 +0200 | [diff] [blame] | 191 | fields.append('%s=0x%x' % (name, rec[i])) |
Harsh Prateek Bora | 90a147a | 2012-07-18 15:16:00 +0530 | [diff] [blame] | 192 | i += 1 |
Stefan Hajnoczi | 59da668 | 2011-02-22 13:59:41 +0000 | [diff] [blame] | 193 | print ' '.join(fields) |
| 194 | |
| 195 | run(Formatter()) |