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