]>
Commit | Line | Data |
---|---|---|
26f7227b SH |
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 | ||
26f7227b SH |
12 | import struct |
13 | import re | |
59da6684 | 14 | import inspect |
90a147a2 HPB |
15 | from tracetool import _read_events, Event |
16 | from tracetool.backend.simple import is_string | |
26f7227b SH |
17 | |
18 | header_event_id = 0xffffffffffffffff | |
19 | header_magic = 0xf2b177cb0aa429b4 | |
0b5538c3 | 20 | dropped_event_id = 0xfffffffffffffffe |
26f7227b | 21 | |
90a147a2 HPB |
22 | log_header_fmt = '=QQQ' |
23 | rec_header_fmt = '=QQII' | |
26f7227b | 24 | |
90a147a2 HPB |
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: | |
30 | return None | |
31 | return struct.unpack(hfmt, hdr) | |
26f7227b | 32 | |
90a147a2 | 33 | def get_record(edict, rechdr, fobj): |
80ff35cd | 34 | """Deserialize a trace record from a file into a tuple (event_num, timestamp, pid, arg1, ..., arg6).""" |
90a147a2 | 35 | if rechdr is None: |
26f7227b | 36 | return None |
80ff35cd | 37 | rec = (rechdr[0], rechdr[1], rechdr[3]) |
90a147a2 HPB |
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): | |
80ff35cd | 57 | """Deserialize a trace record from a file into a tuple (event_num, timestamp, pid, arg1, ..., arg6).""" |
90a147a2 HPB |
58 | rechdr = read_header(fobj, rec_header_fmt) |
59 | return get_record(edict, rechdr, fobj) # return tuple of record elements | |
26f7227b | 60 | |
15327c3d SH |
61 | def read_trace_header(fobj): |
62 | """Read and verify trace file header""" | |
90a147a2 | 63 | header = read_header(fobj, log_header_fmt) |
26f7227b SH |
64 | if header is None or \ |
65 | header[0] != header_event_id or \ | |
90a147a2 HPB |
66 | header[1] != header_magic: |
67 | raise ValueError('Not a valid trace file!') | |
90a147a2 HPB |
68 | |
69 | log_version = header[2] | |
ef0bd3bb LV |
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) | |
26f7227b | 75 | |
15327c3d SH |
76 | def read_trace_records(edict, fobj): |
77 | """Deserialize trace records from a file, yielding record tuples (event_num, timestamp, pid, arg1, ..., arg6).""" | |
26f7227b | 78 | while True: |
90a147a2 | 79 | rec = read_record(edict, fobj) |
26f7227b SH |
80 | if rec is None: |
81 | break | |
82 | ||
83 | yield rec | |
84 | ||
59da6684 SH |
85 | class Analyzer(object): |
86 | """A trace file analyzer which processes trace records. | |
87 | ||
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. | |
91 | ||
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.""" | |
94 | ||
95 | def begin(self): | |
96 | """Called at the start of the trace.""" | |
97 | pass | |
98 | ||
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 | ||
15327c3d | 107 | def process(events, log, analyzer, read_header=True): |
59da6684 SH |
108 | """Invoke an analyzer on each event in a log.""" |
109 | if isinstance(events, str): | |
90a147a2 | 110 | events = _read_events(open(events, 'r')) |
59da6684 SH |
111 | if isinstance(log, str): |
112 | log = open(log, 'rb') | |
113 | ||
15327c3d SH |
114 | if read_header: |
115 | read_trace_header(log) | |
116 | ||
90a147a2 HPB |
117 | dropped_event = Event.build("Dropped_Event(uint64_t num_events_dropped)") |
118 | edict = {dropped_event_id: dropped_event} | |
119 | ||
1dad2ce9 | 120 | for num, event in enumerate(events): |
90a147a2 HPB |
121 | edict[num] = event |
122 | ||
59da6684 | 123 | def build_fn(analyzer, event): |
90a147a2 HPB |
124 | if isinstance(event, str): |
125 | return analyzer.catchall | |
126 | ||
127 | fn = getattr(analyzer, event.name, None) | |
59da6684 SH |
128 | if fn is None: |
129 | return analyzer.catchall | |
130 | ||
90a147a2 | 131 | event_argcount = len(event.args) |
59da6684 SH |
132 | fn_argcount = len(inspect.getargspec(fn)[0]) - 1 |
133 | if fn_argcount == event_argcount + 1: | |
134 | # Include timestamp as first argument | |
80ff35cd SH |
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]) | |
59da6684 | 139 | else: |
80ff35cd SH |
140 | # Just arguments, no timestamp or pid |
141 | return lambda _, rec: fn(*rec[3:3 + event_argcount]) | |
59da6684 SH |
142 | |
143 | analyzer.begin() | |
144 | fn_cache = {} | |
15327c3d | 145 | for rec in read_trace_records(edict, log): |
59da6684 | 146 | event_num = rec[0] |
90a147a2 | 147 | event = edict[event_num] |
59da6684 SH |
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 | ||
15327c3d SH |
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]) | |
59da6684 SH |
167 | sys.exit(1) |
168 | ||
90a147a2 | 169 | events = _read_events(open(sys.argv[1], 'r')) |
15327c3d | 170 | process(events, sys.argv[2], analyzer, read_header=read_header) |
59da6684 SH |
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 | ||
80ff35cd SH |
184 | fields = [event.name, '%0.3f' % (delta_ns / 1000.0), |
185 | 'pid=%d' % rec[2]] | |
186 | i = 3 | |
90a147a2 HPB |
187 | for type, name in event.args: |
188 | if is_string(type): | |
80ff35cd | 189 | fields.append('%s=%s' % (name, rec[i])) |
90a147a2 | 190 | else: |
80ff35cd | 191 | fields.append('%s=0x%x' % (name, rec[i])) |
90a147a2 | 192 | i += 1 |
59da6684 SH |
193 | print ' '.join(fields) |
194 | ||
195 | run(Formatter()) |