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 12import struct 13import re 14import inspect 15from tracetool import read_events, Event 16from tracetool.backend.simple import is_string 17 18header_event_id = 0xffffffffffffffff 19header_magic = 0xf2b177cb0aa429b4 20dropped_event_id = 0xfffffffffffffffe 21 22record_type_mapping = 0 23record_type_event = 1 24 25log_header_fmt = '=QQQ' 26rec_header_fmt = '=QQII' 27 28def read_header(fobj, hfmt): 29 '''Read a trace record header''' 30 hlen = struct.calcsize(hfmt) 31 hdr = fobj.read(hlen) 32 if len(hdr) != hlen: 33 return None 34 return struct.unpack(hfmt, hdr) 35 36def get_record(edict, idtoname, rechdr, fobj): 37 """Deserialize a trace record from a file into a tuple 38 (name, timestamp, pid, arg1, ..., arg6).""" 39 if rechdr is None: 40 return None 41 if rechdr[0] != dropped_event_id: 42 event_id = rechdr[0] 43 name = idtoname[event_id] 44 rec = (name, rechdr[1], rechdr[3]) 45 try: 46 event = edict[name] 47 except KeyError, e: 48 import sys 49 sys.stderr.write('%s event is logged but is not declared ' \ 50 'in the trace events file, try using ' \ 51 'trace-events-all instead.\n' % str(e)) 52 sys.exit(1) 53 54 for type, name in event.args: 55 if is_string(type): 56 l = fobj.read(4) 57 (len,) = struct.unpack('=L', l) 58 s = fobj.read(len) 59 rec = rec + (s,) 60 else: 61 (value,) = struct.unpack('=Q', fobj.read(8)) 62 rec = rec + (value,) 63 else: 64 rec = ("dropped", rechdr[1], rechdr[3]) 65 (value,) = struct.unpack('=Q', fobj.read(8)) 66 rec = rec + (value,) 67 return rec 68 69def get_mapping(fobj): 70 (event_id, ) = struct.unpack('=Q', fobj.read(8)) 71 (len, ) = struct.unpack('=L', fobj.read(4)) 72 name = fobj.read(len) 73 74 return (event_id, name) 75 76def read_record(edict, idtoname, fobj): 77 """Deserialize a trace record from a file into a tuple (event_num, timestamp, pid, arg1, ..., arg6).""" 78 rechdr = read_header(fobj, rec_header_fmt) 79 return get_record(edict, idtoname, rechdr, fobj) 80 81def read_trace_header(fobj): 82 """Read and verify trace file header""" 83 header = read_header(fobj, log_header_fmt) 84 if header is None: 85 raise ValueError('Not a valid trace file!') 86 if header[0] != header_event_id: 87 raise ValueError('Not a valid trace file, header id %d != %d' % 88 (header[0], header_event_id)) 89 if header[1] != header_magic: 90 raise ValueError('Not a valid trace file, header magic %d != %d' % 91 (header[1], header_magic)) 92 93 log_version = header[2] 94 if log_version not in [0, 2, 3, 4]: 95 raise ValueError('Unknown version of tracelog format!') 96 if log_version != 4: 97 raise ValueError('Log format %d not supported with this QEMU release!' 98 % log_version) 99 100def read_trace_records(edict, fobj): 101 """Deserialize trace records from a file, yielding record tuples (event_num, timestamp, pid, arg1, ..., arg6).""" 102 idtoname = { 103 dropped_event_id: "dropped" 104 } 105 while True: 106 t = fobj.read(8) 107 if len(t) == 0: 108 break 109 110 (rectype, ) = struct.unpack('=Q', t) 111 if rectype == record_type_mapping: 112 event_id, name = get_mapping(fobj) 113 idtoname[event_id] = name 114 else: 115 rec = read_record(edict, idtoname, fobj) 116 117 yield rec 118 119class Analyzer(object): 120 """A trace file analyzer which processes trace records. 121 122 An analyzer can be passed to run() or process(). The begin() method is 123 invoked, then each trace record is processed, and finally the end() method 124 is invoked. 125 126 If a method matching a trace event name exists, it is invoked to process 127 that trace record. Otherwise the catchall() method is invoked. 128 129 Example: 130 The following method handles the runstate_set(int new_state) trace event:: 131 132 def runstate_set(self, new_state): 133 ... 134 135 The method can also take a timestamp argument before the trace event 136 arguments:: 137 138 def runstate_set(self, timestamp, new_state): 139 ... 140 141 Timestamps have the uint64_t type and are in nanoseconds. 142 143 The pid can be included in addition to the timestamp and is useful when 144 dealing with traces from multiple processes:: 145 146 def runstate_set(self, timestamp, pid, new_state): 147 ... 148 """ 149 150 def begin(self): 151 """Called at the start of the trace.""" 152 pass 153 154 def catchall(self, event, rec): 155 """Called if no specific method for processing a trace event has been found.""" 156 pass 157 158 def end(self): 159 """Called at the end of the trace.""" 160 pass 161 162def process(events, log, analyzer, read_header=True): 163 """Invoke an analyzer on each event in a log.""" 164 if isinstance(events, str): 165 events = read_events(open(events, 'r')) 166 if isinstance(log, str): 167 log = open(log, 'rb') 168 169 if read_header: 170 read_trace_header(log) 171 172 dropped_event = Event.build("Dropped_Event(uint64_t num_events_dropped)") 173 edict = {"dropped": dropped_event} 174 175 for event in events: 176 edict[event.name] = event 177 178 def build_fn(analyzer, event): 179 if isinstance(event, str): 180 return analyzer.catchall 181 182 fn = getattr(analyzer, event.name, None) 183 if fn is None: 184 return analyzer.catchall 185 186 event_argcount = len(event.args) 187 fn_argcount = len(inspect.getargspec(fn)[0]) - 1 188 if fn_argcount == event_argcount + 1: 189 # Include timestamp as first argument 190 return lambda _, rec: fn(*((rec[1:2],) + rec[3:3 + event_argcount])) 191 elif fn_argcount == event_argcount + 2: 192 # Include timestamp and pid 193 return lambda _, rec: fn(*rec[1:3 + event_argcount]) 194 else: 195 # Just arguments, no timestamp or pid 196 return lambda _, rec: fn(*rec[3:3 + event_argcount]) 197 198 analyzer.begin() 199 fn_cache = {} 200 for rec in read_trace_records(edict, log): 201 event_num = rec[0] 202 event = edict[event_num] 203 if event_num not in fn_cache: 204 fn_cache[event_num] = build_fn(analyzer, event) 205 fn_cache[event_num](event, rec) 206 analyzer.end() 207 208def run(analyzer): 209 """Execute an analyzer on a trace file given on the command-line. 210 211 This function is useful as a driver for simple analysis scripts. More 212 advanced scripts will want to call process() instead.""" 213 import sys 214 215 read_header = True 216 if len(sys.argv) == 4 and sys.argv[1] == '--no-header': 217 read_header = False 218 del sys.argv[1] 219 elif len(sys.argv) != 3: 220 sys.stderr.write('usage: %s [--no-header] <trace-events> ' \ 221 '<trace-file>\n' % sys.argv[0]) 222 sys.exit(1) 223 224 events = read_events(open(sys.argv[1], 'r')) 225 process(events, sys.argv[2], analyzer, read_header=read_header) 226 227if __name__ == '__main__': 228 class Formatter(Analyzer): 229 def __init__(self): 230 self.last_timestamp = None 231 232 def catchall(self, event, rec): 233 timestamp = rec[1] 234 if self.last_timestamp is None: 235 self.last_timestamp = timestamp 236 delta_ns = timestamp - self.last_timestamp 237 self.last_timestamp = timestamp 238 239 fields = [event.name, '%0.3f' % (delta_ns / 1000.0), 240 'pid=%d' % rec[2]] 241 i = 3 242 for type, name in event.args: 243 if is_string(type): 244 fields.append('%s=%s' % (name, rec[i])) 245 else: 246 fields.append('%s=0x%x' % (name, rec[i])) 247 i += 1 248 print ' '.join(fields) 249 250 run(Formatter()) 251