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