blob: 3916c6d14ae80532cbc5e67d5cc29e9d115fa7c5 [file] [log] [blame]
Stefan Hajnoczi26f72272010-05-22 19:24:51 +01001#!/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 Hajnoczi26f72272010-05-22 19:24:51 +010012import struct
13import re
Stefan Hajnoczi59da6682011-02-22 13:59:41 +000014import inspect
Harsh Prateek Bora90a147a2012-07-18 15:16:00 +053015from tracetool import _read_events, Event
16from tracetool.backend.simple import is_string
Stefan Hajnoczi26f72272010-05-22 19:24:51 +010017
18header_event_id = 0xffffffffffffffff
19header_magic = 0xf2b177cb0aa429b4
Stefan Hajnoczi0b5538c2011-02-26 18:38:39 +000020dropped_event_id = 0xfffffffffffffffe
Stefan Hajnoczi26f72272010-05-22 19:24:51 +010021
Harsh Prateek Bora90a147a2012-07-18 15:16:00 +053022log_header_fmt = '=QQQ'
23rec_header_fmt = '=QQII'
Stefan Hajnoczi26f72272010-05-22 19:24:51 +010024
Harsh Prateek Bora90a147a2012-07-18 15:16:00 +053025def 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 Hajnoczi26f72272010-05-22 19:24:51 +010030 return None
Harsh Prateek Bora90a147a2012-07-18 15:16:00 +053031 return struct.unpack(hfmt, hdr)
Stefan Hajnoczi26f72272010-05-22 19:24:51 +010032
Harsh Prateek Bora90a147a2012-07-18 15:16:00 +053033def get_record(edict, rechdr, fobj):
Stefan Hajnoczi80ff35c2014-05-07 19:24:11 +020034 """Deserialize a trace record from a file into a tuple (event_num, timestamp, pid, arg1, ..., arg6)."""
Harsh Prateek Bora90a147a2012-07-18 15:16:00 +053035 if rechdr is None:
36 return None
Stefan Hajnoczi80ff35c2014-05-07 19:24:11 +020037 rec = (rechdr[0], rechdr[1], rechdr[3])
Harsh Prateek Bora90a147a2012-07-18 15:16:00 +053038 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
56def read_record(edict, fobj):
Stefan Hajnoczi80ff35c2014-05-07 19:24:11 +020057 """Deserialize a trace record from a file into a tuple (event_num, timestamp, pid, arg1, ..., arg6)."""
Harsh Prateek Bora90a147a2012-07-18 15:16:00 +053058 rechdr = read_header(fobj, rec_header_fmt)
59 return get_record(edict, rechdr, fobj) # return tuple of record elements
60
Stefan Hajnoczi15327c32014-06-22 21:46:06 +080061def read_trace_header(fobj):
62 """Read and verify trace file header"""
Harsh Prateek Bora90a147a2012-07-18 15:16:00 +053063 header = read_header(fobj, log_header_fmt)
Stefan Hajnoczi26f72272010-05-22 19:24:51 +010064 if header is None or \
65 header[0] != header_event_id or \
Harsh Prateek Bora90a147a2012-07-18 15:16:00 +053066 header[1] != header_magic:
67 raise ValueError('Not a valid trace file!')
Harsh Prateek Bora90a147a2012-07-18 15:16:00 +053068
69 log_version = header[2]
Lluís Vilanovaef0bd3b2014-02-23 20:37:35 +010070 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 Hajnoczi26f72272010-05-22 19:24:51 +010075
Stefan Hajnoczi15327c32014-06-22 21:46:06 +080076def read_trace_records(edict, fobj):
77 """Deserialize trace records from a file, yielding record tuples (event_num, timestamp, pid, arg1, ..., arg6)."""
Stefan Hajnoczi26f72272010-05-22 19:24:51 +010078 while True:
Harsh Prateek Bora90a147a2012-07-18 15:16:00 +053079 rec = read_record(edict, fobj)
Stefan Hajnoczi26f72272010-05-22 19:24:51 +010080 if rec is None:
81 break
82
83 yield rec
84
Stefan Hajnoczi59da6682011-02-22 13:59:41 +000085class Analyzer(object):
86 """A trace file analyzer which processes trace records.
Stefan Hajnoczi26f72272010-05-22 19:24:51 +010087
Stefan Hajnoczi59da6682011-02-22 13:59:41 +000088 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 Hajnoczi26f72272010-05-22 19:24:51 +010091
Stefan Hajnoczi59da6682011-02-22 13:59:41 +000092 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 Hajnoczi26f72272010-05-22 19:24:51 +010094
Stefan Hajnoczi59da6682011-02-22 13:59:41 +000095 def begin(self):
96 """Called at the start of the trace."""
97 pass
Stefan Hajnoczi26f72272010-05-22 19:24:51 +010098
Stefan Hajnoczi59da6682011-02-22 13:59:41 +000099 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 Hajnoczi15327c32014-06-22 21:46:06 +0800107def process(events, log, analyzer, read_header=True):
Stefan Hajnoczi59da6682011-02-22 13:59:41 +0000108 """Invoke an analyzer on each event in a log."""
109 if isinstance(events, str):
Harsh Prateek Bora90a147a2012-07-18 15:16:00 +0530110 events = _read_events(open(events, 'r'))
Stefan Hajnoczi59da6682011-02-22 13:59:41 +0000111 if isinstance(log, str):
112 log = open(log, 'rb')
113
Stefan Hajnoczi15327c32014-06-22 21:46:06 +0800114 if read_header:
115 read_trace_header(log)
116
Harsh Prateek Bora90a147a2012-07-18 15:16:00 +0530117 dropped_event = Event.build("Dropped_Event(uint64_t num_events_dropped)")
118 edict = {dropped_event_id: dropped_event}
119
Lluís Vilanova1dad2ce2014-02-23 20:37:40 +0100120 for num, event in enumerate(events):
Harsh Prateek Bora90a147a2012-07-18 15:16:00 +0530121 edict[num] = event
122
Stefan Hajnoczi59da6682011-02-22 13:59:41 +0000123 def build_fn(analyzer, event):
Harsh Prateek Bora90a147a2012-07-18 15:16:00 +0530124 if isinstance(event, str):
125 return analyzer.catchall
126
127 fn = getattr(analyzer, event.name, None)
Stefan Hajnoczi59da6682011-02-22 13:59:41 +0000128 if fn is None:
129 return analyzer.catchall
130
Harsh Prateek Bora90a147a2012-07-18 15:16:00 +0530131 event_argcount = len(event.args)
Stefan Hajnoczi59da6682011-02-22 13:59:41 +0000132 fn_argcount = len(inspect.getargspec(fn)[0]) - 1
133 if fn_argcount == event_argcount + 1:
134 # Include timestamp as first argument
Stefan Hajnoczi80ff35c2014-05-07 19:24:11 +0200135 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 Hajnoczi59da6682011-02-22 13:59:41 +0000139 else:
Stefan Hajnoczi80ff35c2014-05-07 19:24:11 +0200140 # Just arguments, no timestamp or pid
141 return lambda _, rec: fn(*rec[3:3 + event_argcount])
Stefan Hajnoczi59da6682011-02-22 13:59:41 +0000142
143 analyzer.begin()
144 fn_cache = {}
Stefan Hajnoczi15327c32014-06-22 21:46:06 +0800145 for rec in read_trace_records(edict, log):
Stefan Hajnoczi59da6682011-02-22 13:59:41 +0000146 event_num = rec[0]
Harsh Prateek Bora90a147a2012-07-18 15:16:00 +0530147 event = edict[event_num]
Stefan Hajnoczi59da6682011-02-22 13:59:41 +0000148 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
153def 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 Hajnoczi15327c32014-06-22 21:46:06 +0800160 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 Hajnoczi59da6682011-02-22 13:59:41 +0000167 sys.exit(1)
168
Harsh Prateek Bora90a147a2012-07-18 15:16:00 +0530169 events = _read_events(open(sys.argv[1], 'r'))
Stefan Hajnoczi15327c32014-06-22 21:46:06 +0800170 process(events, sys.argv[2], analyzer, read_header=read_header)
Stefan Hajnoczi59da6682011-02-22 13:59:41 +0000171
172if __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 Hajnoczi80ff35c2014-05-07 19:24:11 +0200184 fields = [event.name, '%0.3f' % (delta_ns / 1000.0),
185 'pid=%d' % rec[2]]
186 i = 3
Harsh Prateek Bora90a147a2012-07-18 15:16:00 +0530187 for type, name in event.args:
188 if is_string(type):
Stefan Hajnoczi80ff35c2014-05-07 19:24:11 +0200189 fields.append('%s=%s' % (name, rec[i]))
Harsh Prateek Bora90a147a2012-07-18 15:16:00 +0530190 else:
Stefan Hajnoczi80ff35c2014-05-07 19:24:11 +0200191 fields.append('%s=0x%x' % (name, rec[i]))
Harsh Prateek Bora90a147a2012-07-18 15:16:00 +0530192 i += 1
Stefan Hajnoczi59da6682011-02-22 13:59:41 +0000193 print ' '.join(fields)
194
195 run(Formatter())