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 event = edict[name] 46 for type, name in event.args: 47 if is_string(type): 48 l = fobj.read(4) 49 (len,) = struct.unpack('=L', l) 50 s = fobj.read(len) 51 rec = rec + (s,) 52 else: 53 (value,) = struct.unpack('=Q', fobj.read(8)) 54 rec = rec + (value,) 55 else: 56 rec = ("dropped", rechdr[1], rechdr[3]) 57 (value,) = struct.unpack('=Q', fobj.read(8)) 58 rec = rec + (value,) 59 return rec 60 61def get_mapping(fobj): 62 (event_id, ) = struct.unpack('=Q', fobj.read(8)) 63 (len, ) = struct.unpack('=L', fobj.read(4)) 64 name = fobj.read(len) 65 66 return (event_id, name) 67 68def read_record(edict, idtoname, fobj): 69 """Deserialize a trace record from a file into a tuple (event_num, timestamp, pid, arg1, ..., arg6).""" 70 rechdr = read_header(fobj, rec_header_fmt) 71 return get_record(edict, idtoname, rechdr, fobj) 72 73def read_trace_header(fobj): 74 """Read and verify trace file header""" 75 header = read_header(fobj, log_header_fmt) 76 if header is None or \ 77 header[0] != header_event_id or \ 78 header[1] != header_magic: 79 raise ValueError('Not a valid trace file!') 80 81 log_version = header[2] 82 if log_version not in [0, 2, 3, 4]: 83 raise ValueError('Unknown version of tracelog format!') 84 if log_version != 4: 85 raise ValueError('Log format %d not supported with this QEMU release!' 86 % log_version) 87 88def read_trace_records(edict, fobj): 89 """Deserialize trace records from a file, yielding record tuples (event_num, timestamp, pid, arg1, ..., arg6).""" 90 idtoname = { 91 dropped_event_id: "dropped" 92 } 93 while True: 94 t = fobj.read(8) 95 if len(t) == 0: 96 break 97 98 (rectype, ) = struct.unpack('=Q', t) 99 if rectype == record_type_mapping: 100 event_id, name = get_mapping(fobj) 101 idtoname[event_id] = name 102 else: 103 rec = read_record(edict, idtoname, fobj) 104 105 yield rec 106 107class Analyzer(object): 108 """A trace file analyzer which processes trace records. 109 110 An analyzer can be passed to run() or process(). The begin() method is 111 invoked, then each trace record is processed, and finally the end() method 112 is invoked. 113 114 If a method matching a trace event name exists, it is invoked to process 115 that trace record. Otherwise the catchall() method is invoked.""" 116 117 def begin(self): 118 """Called at the start of the trace.""" 119 pass 120 121 def catchall(self, event, rec): 122 """Called if no specific method for processing a trace event has been found.""" 123 pass 124 125 def end(self): 126 """Called at the end of the trace.""" 127 pass 128 129def process(events, log, analyzer, read_header=True): 130 """Invoke an analyzer on each event in a log.""" 131 if isinstance(events, str): 132 events = read_events(open(events, 'r')) 133 if isinstance(log, str): 134 log = open(log, 'rb') 135 136 if read_header: 137 read_trace_header(log) 138 139 dropped_event = Event.build("Dropped_Event(uint64_t num_events_dropped)") 140 edict = {"dropped": dropped_event} 141 142 for event in events: 143 edict[event.name] = event 144 145 def build_fn(analyzer, event): 146 if isinstance(event, str): 147 return analyzer.catchall 148 149 fn = getattr(analyzer, event.name, None) 150 if fn is None: 151 return analyzer.catchall 152 153 event_argcount = len(event.args) 154 fn_argcount = len(inspect.getargspec(fn)[0]) - 1 155 if fn_argcount == event_argcount + 1: 156 # Include timestamp as first argument 157 return lambda _, rec: fn(*((rec[1:2],) + rec[3:3 + event_argcount])) 158 elif fn_argcount == event_argcount + 2: 159 # Include timestamp and pid 160 return lambda _, rec: fn(*rec[1:3 + event_argcount]) 161 else: 162 # Just arguments, no timestamp or pid 163 return lambda _, rec: fn(*rec[3:3 + event_argcount]) 164 165 analyzer.begin() 166 fn_cache = {} 167 for rec in read_trace_records(edict, log): 168 event_num = rec[0] 169 event = edict[event_num] 170 if event_num not in fn_cache: 171 fn_cache[event_num] = build_fn(analyzer, event) 172 fn_cache[event_num](event, rec) 173 analyzer.end() 174 175def run(analyzer): 176 """Execute an analyzer on a trace file given on the command-line. 177 178 This function is useful as a driver for simple analysis scripts. More 179 advanced scripts will want to call process() instead.""" 180 import sys 181 182 read_header = True 183 if len(sys.argv) == 4 and sys.argv[1] == '--no-header': 184 read_header = False 185 del sys.argv[1] 186 elif len(sys.argv) != 3: 187 sys.stderr.write('usage: %s [--no-header] <trace-events> ' \ 188 '<trace-file>\n' % sys.argv[0]) 189 sys.exit(1) 190 191 events = read_events(open(sys.argv[1], 'r')) 192 process(events, sys.argv[2], analyzer, read_header=read_header) 193 194if __name__ == '__main__': 195 class Formatter(Analyzer): 196 def __init__(self): 197 self.last_timestamp = None 198 199 def catchall(self, event, rec): 200 timestamp = rec[1] 201 if self.last_timestamp is None: 202 self.last_timestamp = timestamp 203 delta_ns = timestamp - self.last_timestamp 204 self.last_timestamp = timestamp 205 206 fields = [event.name, '%0.3f' % (delta_ns / 1000.0), 207 'pid=%d' % rec[2]] 208 i = 3 209 for type, name in event.args: 210 if is_string(type): 211 fields.append('%s=%s' % (name, rec[i])) 212 else: 213 fields.append('%s=0x%x' % (name, rec[i])) 214 i += 1 215 print ' '.join(fields) 216 217 run(Formatter()) 218