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/devel/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, idtoname, fobj): 101 """Deserialize trace records from a file, yielding record tuples (event_num, timestamp, pid, arg1, ..., arg6). 102 103 Note that `idtoname` is modified if the file contains mapping records. 104 105 Args: 106 edict (str -> Event): events dict, indexed by name 107 idtoname (int -> str): event names dict, indexed by event ID 108 fobj (file): input file 109 110 """ 111 while True: 112 t = fobj.read(8) 113 if len(t) == 0: 114 break 115 116 (rectype, ) = struct.unpack('=Q', t) 117 if rectype == record_type_mapping: 118 event_id, name = get_mapping(fobj) 119 idtoname[event_id] = name 120 else: 121 rec = read_record(edict, idtoname, fobj) 122 123 yield rec 124 125class Analyzer(object): 126 """A trace file analyzer which processes trace records. 127 128 An analyzer can be passed to run() or process(). The begin() method is 129 invoked, then each trace record is processed, and finally the end() method 130 is invoked. 131 132 If a method matching a trace event name exists, it is invoked to process 133 that trace record. Otherwise the catchall() method is invoked. 134 135 Example: 136 The following method handles the runstate_set(int new_state) trace event:: 137 138 def runstate_set(self, new_state): 139 ... 140 141 The method can also take a timestamp argument before the trace event 142 arguments:: 143 144 def runstate_set(self, timestamp, new_state): 145 ... 146 147 Timestamps have the uint64_t type and are in nanoseconds. 148 149 The pid can be included in addition to the timestamp and is useful when 150 dealing with traces from multiple processes:: 151 152 def runstate_set(self, timestamp, pid, new_state): 153 ... 154 """ 155 156 def begin(self): 157 """Called at the start of the trace.""" 158 pass 159 160 def catchall(self, event, rec): 161 """Called if no specific method for processing a trace event has been found.""" 162 pass 163 164 def end(self): 165 """Called at the end of the trace.""" 166 pass 167 168def process(events, log, analyzer, read_header=True): 169 """Invoke an analyzer on each event in a log.""" 170 if isinstance(events, str): 171 events = read_events(open(events, 'r')) 172 if isinstance(log, str): 173 log = open(log, 'rb') 174 175 if read_header: 176 read_trace_header(log) 177 178 dropped_event = Event.build("Dropped_Event(uint64_t num_events_dropped)") 179 edict = {"dropped": dropped_event} 180 idtoname = {dropped_event_id: "dropped"} 181 182 for event in events: 183 edict[event.name] = event 184 185 # If there is no header assume event ID mapping matches events list 186 if not read_header: 187 for event_id, event in enumerate(events): 188 idtoname[event_id] = event.name 189 190 def build_fn(analyzer, event): 191 if isinstance(event, str): 192 return analyzer.catchall 193 194 fn = getattr(analyzer, event.name, None) 195 if fn is None: 196 return analyzer.catchall 197 198 event_argcount = len(event.args) 199 fn_argcount = len(inspect.getargspec(fn)[0]) - 1 200 if fn_argcount == event_argcount + 1: 201 # Include timestamp as first argument 202 return lambda _, rec: fn(*((rec[1:2],) + rec[3:3 + event_argcount])) 203 elif fn_argcount == event_argcount + 2: 204 # Include timestamp and pid 205 return lambda _, rec: fn(*rec[1:3 + event_argcount]) 206 else: 207 # Just arguments, no timestamp or pid 208 return lambda _, rec: fn(*rec[3:3 + event_argcount]) 209 210 analyzer.begin() 211 fn_cache = {} 212 for rec in read_trace_records(edict, idtoname, log): 213 event_num = rec[0] 214 event = edict[event_num] 215 if event_num not in fn_cache: 216 fn_cache[event_num] = build_fn(analyzer, event) 217 fn_cache[event_num](event, rec) 218 analyzer.end() 219 220def run(analyzer): 221 """Execute an analyzer on a trace file given on the command-line. 222 223 This function is useful as a driver for simple analysis scripts. More 224 advanced scripts will want to call process() instead.""" 225 import sys 226 227 read_header = True 228 if len(sys.argv) == 4 and sys.argv[1] == '--no-header': 229 read_header = False 230 del sys.argv[1] 231 elif len(sys.argv) != 3: 232 sys.stderr.write('usage: %s [--no-header] <trace-events> ' \ 233 '<trace-file>\n' % sys.argv[0]) 234 sys.exit(1) 235 236 events = read_events(open(sys.argv[1], 'r')) 237 process(events, sys.argv[2], analyzer, read_header=read_header) 238 239if __name__ == '__main__': 240 class Formatter(Analyzer): 241 def __init__(self): 242 self.last_timestamp = None 243 244 def catchall(self, event, rec): 245 timestamp = rec[1] 246 if self.last_timestamp is None: 247 self.last_timestamp = timestamp 248 delta_ns = timestamp - self.last_timestamp 249 self.last_timestamp = timestamp 250 251 fields = [event.name, '%0.3f' % (delta_ns / 1000.0), 252 'pid=%d' % rec[2]] 253 i = 3 254 for type, name in event.args: 255 if is_string(type): 256 fields.append('%s=%s' % (name, rec[i])) 257 else: 258 fields.append('%s=0x%x' % (name, rec[i])) 259 i += 1 260 print ' '.join(fields) 261 262 run(Formatter()) 263