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.rst 11 12import sys 13import struct 14import inspect 15import warnings 16from tracetool import read_events, Event 17from tracetool.backend.simple import is_string 18 19__all__ = ['Analyzer', 'Analyzer2', 'process', 'run'] 20 21# This is the binary format that the QEMU "simple" trace backend 22# emits. There is no specification documentation because the format is 23# not guaranteed to be stable. Trace files must be parsed with the 24# same trace-events-all file and the same simpletrace.py file that 25# QEMU was built with. 26header_event_id = 0xffffffffffffffff 27header_magic = 0xf2b177cb0aa429b4 28dropped_event_id = 0xfffffffffffffffe 29 30record_type_mapping = 0 31record_type_event = 1 32 33log_header_fmt = '=QQQ' 34rec_header_fmt = '=QQII' 35rec_header_fmt_len = struct.calcsize(rec_header_fmt) 36 37class SimpleException(Exception): 38 pass 39 40def read_header(fobj, hfmt): 41 '''Read a trace record header''' 42 hlen = struct.calcsize(hfmt) 43 hdr = fobj.read(hlen) 44 if len(hdr) != hlen: 45 raise SimpleException('Error reading header. Wrong filetype provided?') 46 return struct.unpack(hfmt, hdr) 47 48def get_mapping(fobj): 49 (event_id, ) = struct.unpack('=Q', fobj.read(8)) 50 (len, ) = struct.unpack('=L', fobj.read(4)) 51 name = fobj.read(len).decode() 52 53 return (event_id, name) 54 55def read_record(fobj): 56 """Deserialize a trace record from a file into a tuple (event_num, timestamp, pid, args).""" 57 event_id, timestamp_ns, record_length, record_pid = read_header(fobj, rec_header_fmt) 58 args_payload = fobj.read(record_length - rec_header_fmt_len) 59 return (event_id, timestamp_ns, record_pid, args_payload) 60 61def read_trace_header(fobj): 62 """Read and verify trace file header""" 63 _header_event_id, _header_magic, log_version = read_header(fobj, log_header_fmt) 64 if _header_event_id != header_event_id: 65 raise ValueError(f'Not a valid trace file, header id {_header_event_id} != {header_event_id}') 66 if _header_magic != header_magic: 67 raise ValueError(f'Not a valid trace file, header magic {_header_magic} != {header_magic}') 68 69 if log_version not in [0, 2, 3, 4]: 70 raise ValueError(f'Unknown version {log_version} of tracelog format!') 71 if log_version != 4: 72 raise ValueError(f'Log format {log_version} not supported with this QEMU release!') 73 74def read_trace_records(events, fobj, read_header): 75 """Deserialize trace records from a file, yielding record tuples (event, event_num, timestamp, pid, arg1, ..., arg6). 76 77 Args: 78 event_mapping (str -> Event): events dict, indexed by name 79 fobj (file): input file 80 read_header (bool): whether headers were read from fobj 81 82 """ 83 frameinfo = inspect.getframeinfo(inspect.currentframe()) 84 dropped_event = Event.build("Dropped_Event(uint64_t num_events_dropped)", 85 frameinfo.lineno + 1, frameinfo.filename) 86 87 event_mapping = {e.name: e for e in events} 88 event_mapping["dropped"] = dropped_event 89 event_id_to_name = {dropped_event_id: "dropped"} 90 91 # If there is no header assume event ID mapping matches events list 92 if not read_header: 93 for event_id, event in enumerate(events): 94 event_id_to_name[event_id] = event.name 95 96 while True: 97 t = fobj.read(8) 98 if len(t) == 0: 99 break 100 101 (rectype, ) = struct.unpack('=Q', t) 102 if rectype == record_type_mapping: 103 event_id, event_name = get_mapping(fobj) 104 event_id_to_name[event_id] = event_name 105 else: 106 event_id, timestamp_ns, pid, args_payload = read_record(fobj) 107 event_name = event_id_to_name[event_id] 108 109 try: 110 event = event_mapping[event_name] 111 except KeyError as e: 112 raise SimpleException( 113 f'{e} event is logged but is not declared in the trace events' 114 'file, try using trace-events-all instead.' 115 ) 116 117 offset = 0 118 args = [] 119 for type, _ in event.args: 120 if is_string(type): 121 (length,) = struct.unpack_from('=L', args_payload, offset=offset) 122 offset += 4 123 s = args_payload[offset:offset+length] 124 offset += length 125 args.append(s) 126 else: 127 (value,) = struct.unpack_from('=Q', args_payload, offset=offset) 128 offset += 8 129 args.append(value) 130 131 yield (event_mapping[event_name], event_name, timestamp_ns, pid) + tuple(args) 132 133class Analyzer: 134 """[Deprecated. Refer to Analyzer2 instead.] 135 136 A trace file analyzer which processes trace records. 137 138 An analyzer can be passed to run() or process(). The begin() method is 139 invoked, then each trace record is processed, and finally the end() method 140 is invoked. When Analyzer is used as a context-manager (using the `with` 141 statement), begin() and end() are called automatically. 142 143 If a method matching a trace event name exists, it is invoked to process 144 that trace record. Otherwise the catchall() method is invoked. 145 146 Example: 147 The following method handles the runstate_set(int new_state) trace event:: 148 149 def runstate_set(self, new_state): 150 ... 151 152 The method can also take a timestamp argument before the trace event 153 arguments:: 154 155 def runstate_set(self, timestamp, new_state): 156 ... 157 158 Timestamps have the uint64_t type and are in nanoseconds. 159 160 The pid can be included in addition to the timestamp and is useful when 161 dealing with traces from multiple processes:: 162 163 def runstate_set(self, timestamp, pid, new_state): 164 ... 165 """ 166 167 def begin(self): 168 """Called at the start of the trace.""" 169 pass 170 171 def catchall(self, event, rec): 172 """Called if no specific method for processing a trace event has been found.""" 173 pass 174 175 def _build_fn(self, event): 176 fn = getattr(self, event.name, None) 177 if fn is None: 178 # Return early to avoid costly call to inspect.getfullargspec 179 return self.catchall 180 181 event_argcount = len(event.args) 182 fn_argcount = len(inspect.getfullargspec(fn)[0]) - 1 183 if fn_argcount == event_argcount + 1: 184 # Include timestamp as first argument 185 return lambda _, rec: fn(*(rec[1:2] + rec[3:3 + event_argcount])) 186 elif fn_argcount == event_argcount + 2: 187 # Include timestamp and pid 188 return lambda _, rec: fn(*rec[1:3 + event_argcount]) 189 else: 190 # Just arguments, no timestamp or pid 191 return lambda _, rec: fn(*rec[3:3 + event_argcount]) 192 193 def _process_event(self, rec_args, *, event, event_id, timestamp_ns, pid, **kwargs): 194 warnings.warn( 195 "Use of deprecated Analyzer class. Refer to Analyzer2 instead.", 196 DeprecationWarning, 197 ) 198 199 if not hasattr(self, '_fn_cache'): 200 # NOTE: Cannot depend on downstream subclasses to have 201 # super().__init__() because of legacy. 202 self._fn_cache = {} 203 204 rec = (event_id, timestamp_ns, pid, *rec_args) 205 if event_id not in self._fn_cache: 206 self._fn_cache[event_id] = self._build_fn(event) 207 self._fn_cache[event_id](event, rec) 208 209 def end(self): 210 """Called at the end of the trace.""" 211 pass 212 213 def __enter__(self): 214 self.begin() 215 return self 216 217 def __exit__(self, exc_type, exc_val, exc_tb): 218 if exc_type is None: 219 self.end() 220 return False 221 222class Analyzer2(Analyzer): 223 """A trace file analyzer which processes trace records. 224 225 An analyzer can be passed to run() or process(). The begin() method is 226 invoked, then each trace record is processed, and finally the end() method 227 is invoked. When Analyzer is used as a context-manager (using the `with` 228 statement), begin() and end() are called automatically. 229 230 If a method matching a trace event name exists, it is invoked to process 231 that trace record. Otherwise the catchall() method is invoked. 232 233 The methods are called with a set of keyword-arguments. These can be ignored 234 using `**kwargs` or defined like any keyword-argument. 235 236 The following keyword-arguments are available, but make sure to have an 237 **kwargs to allow for unmatched arguments in the future: 238 event: Event object of current trace 239 event_id: The id of the event in the current trace file 240 timestamp_ns: The timestamp in nanoseconds of the trace 241 pid: The process id recorded for the given trace 242 243 Example: 244 The following method handles the runstate_set(int new_state) trace event:: 245 246 def runstate_set(self, new_state, **kwargs): 247 ... 248 249 The method can also explicitly take a timestamp keyword-argument with the 250 trace event arguments:: 251 252 def runstate_set(self, new_state, *, timestamp_ns, **kwargs): 253 ... 254 255 Timestamps have the uint64_t type and are in nanoseconds. 256 257 The pid can be included in addition to the timestamp and is useful when 258 dealing with traces from multiple processes: 259 260 def runstate_set(self, new_state, *, timestamp_ns, pid, **kwargs): 261 ... 262 """ 263 264 def catchall(self, *rec_args, event, timestamp_ns, pid, event_id, **kwargs): 265 """Called if no specific method for processing a trace event has been found.""" 266 pass 267 268 def _process_event(self, rec_args, *, event, **kwargs): 269 fn = getattr(self, event.name, self.catchall) 270 fn(*rec_args, event=event, **kwargs) 271 272def process(events, log, analyzer, read_header=True): 273 """Invoke an analyzer on each event in a log. 274 Args: 275 events (file-object or list or str): events list or file-like object or file path as str to read event data from 276 log (file-object or str): file-like object or file path as str to read log data from 277 analyzer (Analyzer): Instance of Analyzer to interpret the event data 278 read_header (bool, optional): Whether to read header data from the log data. Defaults to True. 279 """ 280 281 if isinstance(events, str): 282 with open(events, 'r') as f: 283 events_list = read_events(f, events) 284 elif isinstance(events, list): 285 # Treat as a list of events already produced by tracetool.read_events 286 events_list = events 287 else: 288 # Treat as an already opened file-object 289 events_list = read_events(events, events.name) 290 291 if isinstance(log, str): 292 with open(log, 'rb') as log_fobj: 293 _process(events_list, log_fobj, analyzer, read_header) 294 else: 295 # Treat `log` as an already opened file-object. We will not close it, 296 # as we do not own it. 297 _process(events_list, log, analyzer, read_header) 298 299def _process(events, log_fobj, analyzer, read_header=True): 300 """Internal function for processing 301 302 Args: 303 events (list): list of events already produced by tracetool.read_events 304 log_fobj (file): file-object to read log data from 305 analyzer (Analyzer): the Analyzer to interpret the event data 306 read_header (bool, optional): Whether to read header data from the log data. Defaults to True. 307 """ 308 309 if read_header: 310 read_trace_header(log_fobj) 311 312 with analyzer: 313 for event, event_id, timestamp_ns, record_pid, *rec_args in read_trace_records(events, log_fobj, read_header): 314 analyzer._process_event( 315 rec_args, 316 event=event, 317 event_id=event_id, 318 timestamp_ns=timestamp_ns, 319 pid=record_pid, 320 ) 321 322def run(analyzer): 323 """Execute an analyzer on a trace file given on the command-line. 324 325 This function is useful as a driver for simple analysis scripts. More 326 advanced scripts will want to call process() instead.""" 327 328 try: 329 # NOTE: See built-in `argparse` module for a more robust cli interface 330 *no_header, trace_event_path, trace_file_path = sys.argv[1:] 331 assert no_header == [] or no_header == ['--no-header'], 'Invalid no-header argument' 332 except (AssertionError, ValueError): 333 raise SimpleException(f'usage: {sys.argv[0]} [--no-header] <trace-events> <trace-file>\n') 334 335 with open(trace_event_path, 'r') as events_fobj, open(trace_file_path, 'rb') as log_fobj: 336 process(events_fobj, log_fobj, analyzer, read_header=not no_header) 337 338if __name__ == '__main__': 339 class Formatter2(Analyzer2): 340 def __init__(self): 341 self.last_timestamp_ns = None 342 343 def catchall(self, *rec_args, event, timestamp_ns, pid, event_id): 344 if self.last_timestamp_ns is None: 345 self.last_timestamp_ns = timestamp_ns 346 delta_ns = timestamp_ns - self.last_timestamp_ns 347 self.last_timestamp_ns = timestamp_ns 348 349 fields = [ 350 f'{name}={r}' if is_string(type) else f'{name}=0x{r:x}' 351 for r, (type, name) in zip(rec_args, event.args) 352 ] 353 print(f'{event.name} {delta_ns / 1000:0.3f} {pid=} ' + ' '.join(fields)) 354 355 try: 356 run(Formatter2()) 357 except SimpleException as e: 358 sys.stderr.write(str(e) + "\n") 359 sys.exit(1) 360