13d004a37SPhilippe Mathieu-Daudé#!/usr/bin/env python3 24c3b5a48SBlue Swirl# 34c3b5a48SBlue Swirl# Pretty-printer for simple trace backend binary trace files 44c3b5a48SBlue Swirl# 54c3b5a48SBlue Swirl# Copyright IBM, Corp. 2010 64c3b5a48SBlue Swirl# 74c3b5a48SBlue Swirl# This work is licensed under the terms of the GNU GPL, version 2. See 84c3b5a48SBlue Swirl# the COPYING file in the top-level directory. 94c3b5a48SBlue Swirl# 10d0fb9657SStefano Garzarella# For help see docs/devel/tracing.rst 114c3b5a48SBlue Swirl 12f7bd4f02SMads Ynddalimport sys 134c3b5a48SBlue Swirlimport struct 1459da6684SStefan Hajnocziimport inspect 153470fef1SMads Ynddalimport warnings 16d1b97bceSDaniel P. Berrangefrom tracetool import read_events, Event 1790a147a2SHarsh Prateek Borafrom tracetool.backend.simple import is_string 184c3b5a48SBlue Swirl 193470fef1SMads Ynddal__all__ = ['Analyzer', 'Analyzer2', 'process', 'run'] 202c109f21SMads Ynddal 218405ec6aSMads Ynddal# This is the binary format that the QEMU "simple" trace backend 228405ec6aSMads Ynddal# emits. There is no specification documentation because the format is 238405ec6aSMads Ynddal# not guaranteed to be stable. Trace files must be parsed with the 248405ec6aSMads Ynddal# same trace-events-all file and the same simpletrace.py file that 258405ec6aSMads Ynddal# QEMU was built with. 264c3b5a48SBlue Swirlheader_event_id = 0xffffffffffffffff 274c3b5a48SBlue Swirlheader_magic = 0xf2b177cb0aa429b4 280b5538c3SStefan Hajnoczidropped_event_id = 0xfffffffffffffffe 294c3b5a48SBlue Swirl 307f1b588fSDaniel P. Berrangerecord_type_mapping = 0 317f1b588fSDaniel P. Berrangerecord_type_event = 1 327f1b588fSDaniel P. Berrange 3390a147a2SHarsh Prateek Boralog_header_fmt = '=QQQ' 3490a147a2SHarsh Prateek Borarec_header_fmt = '=QQII' 356f53641aSMads Ynddalrec_header_fmt_len = struct.calcsize(rec_header_fmt) 364c3b5a48SBlue Swirl 371990fb98SMads Ynddalclass SimpleException(Exception): 381990fb98SMads Ynddal pass 391990fb98SMads Ynddal 4090a147a2SHarsh Prateek Boradef read_header(fobj, hfmt): 4190a147a2SHarsh Prateek Bora '''Read a trace record header''' 4290a147a2SHarsh Prateek Bora hlen = struct.calcsize(hfmt) 4390a147a2SHarsh Prateek Bora hdr = fobj.read(hlen) 4490a147a2SHarsh Prateek Bora if len(hdr) != hlen: 451990fb98SMads Ynddal raise SimpleException('Error reading header. Wrong filetype provided?') 4690a147a2SHarsh Prateek Bora return struct.unpack(hfmt, hdr) 474c3b5a48SBlue Swirl 487f1b588fSDaniel P. Berrangedef get_mapping(fobj): 497f1b588fSDaniel P. Berrange (event_id, ) = struct.unpack('=Q', fobj.read(8)) 507f1b588fSDaniel P. Berrange (len, ) = struct.unpack('=L', fobj.read(4)) 51749c1d8eSEduardo Habkost name = fobj.read(len).decode() 5290a147a2SHarsh Prateek Bora 537f1b588fSDaniel P. Berrange return (event_id, name) 547f1b588fSDaniel P. Berrange 556f53641aSMads Ynddaldef read_record(fobj): 566f53641aSMads Ynddal """Deserialize a trace record from a file into a tuple (event_num, timestamp, pid, args).""" 576f53641aSMads Ynddal event_id, timestamp_ns, record_length, record_pid = read_header(fobj, rec_header_fmt) 586f53641aSMads Ynddal args_payload = fobj.read(record_length - rec_header_fmt_len) 596f53641aSMads Ynddal return (event_id, timestamp_ns, record_pid, args_payload) 6090a147a2SHarsh Prateek Bora 6115327c3dSStefan Hajnoczidef read_trace_header(fobj): 6215327c3dSStefan Hajnoczi """Read and verify trace file header""" 63d1f92590SMads Ynddal _header_event_id, _header_magic, log_version = read_header(fobj, log_header_fmt) 64d1f92590SMads Ynddal if _header_event_id != header_event_id: 65d1f92590SMads Ynddal raise ValueError(f'Not a valid trace file, header id {_header_event_id} != {header_event_id}') 66d1f92590SMads Ynddal if _header_magic != header_magic: 67d1f92590SMads Ynddal raise ValueError(f'Not a valid trace file, header magic {_header_magic} != {header_magic}') 6890a147a2SHarsh Prateek Bora 697f1b588fSDaniel P. Berrange if log_version not in [0, 2, 3, 4]: 70d1f92590SMads Ynddal raise ValueError(f'Unknown version {log_version} of tracelog format!') 717f1b588fSDaniel P. Berrange if log_version != 4: 72d1f92590SMads Ynddal raise ValueError(f'Log format {log_version} not supported with this QEMU release!') 734c3b5a48SBlue Swirl 746f53641aSMads Ynddaldef read_trace_records(events, fobj, read_header): 756f53641aSMads Ynddal """Deserialize trace records from a file, yielding record tuples (event, event_num, timestamp, pid, arg1, ..., arg6). 76840d8351SStefan Hajnoczi 77840d8351SStefan Hajnoczi Args: 783b71b61eSMads Ynddal event_mapping (str -> Event): events dict, indexed by name 79840d8351SStefan Hajnoczi fobj (file): input file 806f53641aSMads Ynddal read_header (bool): whether headers were read from fobj 81840d8351SStefan Hajnoczi 82840d8351SStefan Hajnoczi """ 836f53641aSMads Ynddal frameinfo = inspect.getframeinfo(inspect.currentframe()) 846f53641aSMads Ynddal dropped_event = Event.build("Dropped_Event(uint64_t num_events_dropped)", 856f53641aSMads Ynddal frameinfo.lineno + 1, frameinfo.filename) 866f53641aSMads Ynddal 876f53641aSMads Ynddal event_mapping = {e.name: e for e in events} 886f53641aSMads Ynddal event_mapping["dropped"] = dropped_event 896f53641aSMads Ynddal event_id_to_name = {dropped_event_id: "dropped"} 906f53641aSMads Ynddal 916f53641aSMads Ynddal # If there is no header assume event ID mapping matches events list 926f53641aSMads Ynddal if not read_header: 936f53641aSMads Ynddal for event_id, event in enumerate(events): 946f53641aSMads Ynddal event_id_to_name[event_id] = event.name 956f53641aSMads Ynddal 964c3b5a48SBlue Swirl while True: 977f1b588fSDaniel P. Berrange t = fobj.read(8) 987f1b588fSDaniel P. Berrange if len(t) == 0: 994c3b5a48SBlue Swirl break 1004c3b5a48SBlue Swirl 1017f1b588fSDaniel P. Berrange (rectype, ) = struct.unpack('=Q', t) 1027f1b588fSDaniel P. Berrange if rectype == record_type_mapping: 1036f53641aSMads Ynddal event_id, event_name = get_mapping(fobj) 1046f53641aSMads Ynddal event_id_to_name[event_id] = event_name 1057f1b588fSDaniel P. Berrange else: 1066f53641aSMads Ynddal event_id, timestamp_ns, pid, args_payload = read_record(fobj) 1076f53641aSMads Ynddal event_name = event_id_to_name[event_id] 1087f1b588fSDaniel P. Berrange 1096f53641aSMads Ynddal try: 1106f53641aSMads Ynddal event = event_mapping[event_name] 1116f53641aSMads Ynddal except KeyError as e: 1126f53641aSMads Ynddal raise SimpleException( 1136f53641aSMads Ynddal f'{e} event is logged but is not declared in the trace events' 1146f53641aSMads Ynddal 'file, try using trace-events-all instead.' 1156f53641aSMads Ynddal ) 1166f53641aSMads Ynddal 1176f53641aSMads Ynddal offset = 0 1186f53641aSMads Ynddal args = [] 1196f53641aSMads Ynddal for type, _ in event.args: 1206f53641aSMads Ynddal if is_string(type): 1216f53641aSMads Ynddal (length,) = struct.unpack_from('=L', args_payload, offset=offset) 1226f53641aSMads Ynddal offset += 4 1236f53641aSMads Ynddal s = args_payload[offset:offset+length] 1246f53641aSMads Ynddal offset += length 1256f53641aSMads Ynddal args.append(s) 1266f53641aSMads Ynddal else: 1276f53641aSMads Ynddal (value,) = struct.unpack_from('=Q', args_payload, offset=offset) 1286f53641aSMads Ynddal offset += 8 1296f53641aSMads Ynddal args.append(value) 1306f53641aSMads Ynddal 1316f53641aSMads Ynddal yield (event_mapping[event_name], event_name, timestamp_ns, pid) + tuple(args) 1324c3b5a48SBlue Swirl 13387617b9aSMads Ynddalclass Analyzer: 1343470fef1SMads Ynddal """[Deprecated. Refer to Analyzer2 instead.] 1353470fef1SMads Ynddal 1363470fef1SMads Ynddal A trace file analyzer which processes trace records. 13759da6684SStefan Hajnoczi 13859da6684SStefan Hajnoczi An analyzer can be passed to run() or process(). The begin() method is 13959da6684SStefan Hajnoczi invoked, then each trace record is processed, and finally the end() method 14087617b9aSMads Ynddal is invoked. When Analyzer is used as a context-manager (using the `with` 14187617b9aSMads Ynddal statement), begin() and end() are called automatically. 14259da6684SStefan Hajnoczi 14359da6684SStefan Hajnoczi If a method matching a trace event name exists, it is invoked to process 144659370f7SStefan Hajnoczi that trace record. Otherwise the catchall() method is invoked. 145659370f7SStefan Hajnoczi 146659370f7SStefan Hajnoczi Example: 147659370f7SStefan Hajnoczi The following method handles the runstate_set(int new_state) trace event:: 148659370f7SStefan Hajnoczi 149659370f7SStefan Hajnoczi def runstate_set(self, new_state): 150659370f7SStefan Hajnoczi ... 151659370f7SStefan Hajnoczi 152659370f7SStefan Hajnoczi The method can also take a timestamp argument before the trace event 153659370f7SStefan Hajnoczi arguments:: 154659370f7SStefan Hajnoczi 155659370f7SStefan Hajnoczi def runstate_set(self, timestamp, new_state): 156659370f7SStefan Hajnoczi ... 157659370f7SStefan Hajnoczi 158659370f7SStefan Hajnoczi Timestamps have the uint64_t type and are in nanoseconds. 159659370f7SStefan Hajnoczi 160659370f7SStefan Hajnoczi The pid can be included in addition to the timestamp and is useful when 161659370f7SStefan Hajnoczi dealing with traces from multiple processes:: 162659370f7SStefan Hajnoczi 163659370f7SStefan Hajnoczi def runstate_set(self, timestamp, pid, new_state): 164659370f7SStefan Hajnoczi ... 165659370f7SStefan Hajnoczi """ 16659da6684SStefan Hajnoczi 16759da6684SStefan Hajnoczi def begin(self): 16859da6684SStefan Hajnoczi """Called at the start of the trace.""" 16959da6684SStefan Hajnoczi pass 17059da6684SStefan Hajnoczi 17159da6684SStefan Hajnoczi def catchall(self, event, rec): 17259da6684SStefan Hajnoczi """Called if no specific method for processing a trace event has been found.""" 17359da6684SStefan Hajnoczi pass 17459da6684SStefan Hajnoczi 175d1f89c23SMads Ynddal def _build_fn(self, event): 176d1f89c23SMads Ynddal fn = getattr(self, event.name, None) 177d1f89c23SMads Ynddal if fn is None: 178d1f89c23SMads Ynddal # Return early to avoid costly call to inspect.getfullargspec 179d1f89c23SMads Ynddal return self.catchall 180d1f89c23SMads Ynddal 181d1f89c23SMads Ynddal event_argcount = len(event.args) 182d1f89c23SMads Ynddal fn_argcount = len(inspect.getfullargspec(fn)[0]) - 1 183d1f89c23SMads Ynddal if fn_argcount == event_argcount + 1: 184d1f89c23SMads Ynddal # Include timestamp as first argument 185d1f89c23SMads Ynddal return lambda _, rec: fn(*(rec[1:2] + rec[3:3 + event_argcount])) 186d1f89c23SMads Ynddal elif fn_argcount == event_argcount + 2: 187d1f89c23SMads Ynddal # Include timestamp and pid 188d1f89c23SMads Ynddal return lambda _, rec: fn(*rec[1:3 + event_argcount]) 189d1f89c23SMads Ynddal else: 190d1f89c23SMads Ynddal # Just arguments, no timestamp or pid 191d1f89c23SMads Ynddal return lambda _, rec: fn(*rec[3:3 + event_argcount]) 192d1f89c23SMads Ynddal 193d1f89c23SMads Ynddal def _process_event(self, rec_args, *, event, event_id, timestamp_ns, pid, **kwargs): 1943470fef1SMads Ynddal warnings.warn( 1953470fef1SMads Ynddal "Use of deprecated Analyzer class. Refer to Analyzer2 instead.", 1963470fef1SMads Ynddal DeprecationWarning, 1973470fef1SMads Ynddal ) 1983470fef1SMads Ynddal 199d1f89c23SMads Ynddal if not hasattr(self, '_fn_cache'): 200d1f89c23SMads Ynddal # NOTE: Cannot depend on downstream subclasses to have 201d1f89c23SMads Ynddal # super().__init__() because of legacy. 202d1f89c23SMads Ynddal self._fn_cache = {} 203d1f89c23SMads Ynddal 204d1f89c23SMads Ynddal rec = (event_id, timestamp_ns, pid, *rec_args) 205d1f89c23SMads Ynddal if event_id not in self._fn_cache: 206d1f89c23SMads Ynddal self._fn_cache[event_id] = self._build_fn(event) 207d1f89c23SMads Ynddal self._fn_cache[event_id](event, rec) 208d1f89c23SMads Ynddal 20959da6684SStefan Hajnoczi def end(self): 21059da6684SStefan Hajnoczi """Called at the end of the trace.""" 21159da6684SStefan Hajnoczi pass 21259da6684SStefan Hajnoczi 21387617b9aSMads Ynddal def __enter__(self): 21487617b9aSMads Ynddal self.begin() 21587617b9aSMads Ynddal return self 21687617b9aSMads Ynddal 21787617b9aSMads Ynddal def __exit__(self, exc_type, exc_val, exc_tb): 21887617b9aSMads Ynddal if exc_type is None: 21987617b9aSMads Ynddal self.end() 22087617b9aSMads Ynddal return False 22187617b9aSMads Ynddal 2223470fef1SMads Ynddalclass Analyzer2(Analyzer): 2233470fef1SMads Ynddal """A trace file analyzer which processes trace records. 2243470fef1SMads Ynddal 2253470fef1SMads Ynddal An analyzer can be passed to run() or process(). The begin() method is 2263470fef1SMads Ynddal invoked, then each trace record is processed, and finally the end() method 2273470fef1SMads Ynddal is invoked. When Analyzer is used as a context-manager (using the `with` 2283470fef1SMads Ynddal statement), begin() and end() are called automatically. 2293470fef1SMads Ynddal 2303470fef1SMads Ynddal If a method matching a trace event name exists, it is invoked to process 2313470fef1SMads Ynddal that trace record. Otherwise the catchall() method is invoked. 2323470fef1SMads Ynddal 2333470fef1SMads Ynddal The methods are called with a set of keyword-arguments. These can be ignored 2343470fef1SMads Ynddal using `**kwargs` or defined like any keyword-argument. 2353470fef1SMads Ynddal 2363470fef1SMads Ynddal The following keyword-arguments are available, but make sure to have an 2373470fef1SMads Ynddal **kwargs to allow for unmatched arguments in the future: 2383470fef1SMads Ynddal event: Event object of current trace 2393470fef1SMads Ynddal event_id: The id of the event in the current trace file 2403470fef1SMads Ynddal timestamp_ns: The timestamp in nanoseconds of the trace 2413470fef1SMads Ynddal pid: The process id recorded for the given trace 2423470fef1SMads Ynddal 2433470fef1SMads Ynddal Example: 2443470fef1SMads Ynddal The following method handles the runstate_set(int new_state) trace event:: 2453470fef1SMads Ynddal 2463470fef1SMads Ynddal def runstate_set(self, new_state, **kwargs): 2473470fef1SMads Ynddal ... 2483470fef1SMads Ynddal 2493470fef1SMads Ynddal The method can also explicitly take a timestamp keyword-argument with the 2503470fef1SMads Ynddal trace event arguments:: 2513470fef1SMads Ynddal 2523470fef1SMads Ynddal def runstate_set(self, new_state, *, timestamp_ns, **kwargs): 2533470fef1SMads Ynddal ... 2543470fef1SMads Ynddal 2553470fef1SMads Ynddal Timestamps have the uint64_t type and are in nanoseconds. 2563470fef1SMads Ynddal 2573470fef1SMads Ynddal The pid can be included in addition to the timestamp and is useful when 2583470fef1SMads Ynddal dealing with traces from multiple processes: 2593470fef1SMads Ynddal 2603470fef1SMads Ynddal def runstate_set(self, new_state, *, timestamp_ns, pid, **kwargs): 2613470fef1SMads Ynddal ... 2623470fef1SMads Ynddal """ 2633470fef1SMads Ynddal 2643470fef1SMads Ynddal def catchall(self, *rec_args, event, timestamp_ns, pid, event_id, **kwargs): 2653470fef1SMads Ynddal """Called if no specific method for processing a trace event has been found.""" 2663470fef1SMads Ynddal pass 2673470fef1SMads Ynddal 2683470fef1SMads Ynddal def _process_event(self, rec_args, *, event, **kwargs): 2693470fef1SMads Ynddal fn = getattr(self, event.name, self.catchall) 2703470fef1SMads Ynddal fn(*rec_args, event=event, **kwargs) 2713470fef1SMads Ynddal 27215327c3dSStefan Hajnoczidef process(events, log, analyzer, read_header=True): 273f7bd4f02SMads Ynddal """Invoke an analyzer on each event in a log. 274f7bd4f02SMads Ynddal Args: 275f7bd4f02SMads Ynddal events (file-object or list or str): events list or file-like object or file path as str to read event data from 276f7bd4f02SMads Ynddal log (file-object or str): file-like object or file path as str to read log data from 277f7bd4f02SMads Ynddal analyzer (Analyzer): Instance of Analyzer to interpret the event data 278f7bd4f02SMads Ynddal read_header (bool, optional): Whether to read header data from the log data. Defaults to True. 279f7bd4f02SMads Ynddal """ 280f7bd4f02SMads Ynddal 28159da6684SStefan Hajnoczi if isinstance(events, str): 282f7bd4f02SMads Ynddal with open(events, 'r') as f: 283f7bd4f02SMads Ynddal events_list = read_events(f, events) 284f7bd4f02SMads Ynddal elif isinstance(events, list): 285f7bd4f02SMads Ynddal # Treat as a list of events already produced by tracetool.read_events 286f7bd4f02SMads Ynddal events_list = events 287f7bd4f02SMads Ynddal else: 288f7bd4f02SMads Ynddal # Treat as an already opened file-object 289f7bd4f02SMads Ynddal events_list = read_events(events, events.name) 290f7bd4f02SMads Ynddal 29159da6684SStefan Hajnoczi if isinstance(log, str): 292b78234e6SMads Ynddal with open(log, 'rb') as log_fobj: 293b78234e6SMads Ynddal _process(events_list, log_fobj, analyzer, read_header) 294b78234e6SMads Ynddal else: 295b78234e6SMads Ynddal # Treat `log` as an already opened file-object. We will not close it, 296b78234e6SMads Ynddal # as we do not own it. 297b78234e6SMads Ynddal _process(events_list, log, analyzer, read_header) 298b78234e6SMads Ynddal 299b78234e6SMads Ynddaldef _process(events, log_fobj, analyzer, read_header=True): 300b78234e6SMads Ynddal """Internal function for processing 301b78234e6SMads Ynddal 302b78234e6SMads Ynddal Args: 303b78234e6SMads Ynddal events (list): list of events already produced by tracetool.read_events 304b78234e6SMads Ynddal log_fobj (file): file-object to read log data from 305b78234e6SMads Ynddal analyzer (Analyzer): the Analyzer to interpret the event data 306b78234e6SMads Ynddal read_header (bool, optional): Whether to read header data from the log data. Defaults to True. 307b78234e6SMads Ynddal """ 30859da6684SStefan Hajnoczi 30915327c3dSStefan Hajnoczi if read_header: 310b78234e6SMads Ynddal read_trace_header(log_fobj) 31115327c3dSStefan Hajnoczi 31287617b9aSMads Ynddal with analyzer: 313b78234e6SMads Ynddal for event, event_id, timestamp_ns, record_pid, *rec_args in read_trace_records(events, log_fobj, read_header): 314d1f89c23SMads Ynddal analyzer._process_event( 315d1f89c23SMads Ynddal rec_args, 316d1f89c23SMads Ynddal event=event, 317d1f89c23SMads Ynddal event_id=event_id, 318d1f89c23SMads Ynddal timestamp_ns=timestamp_ns, 319d1f89c23SMads Ynddal pid=record_pid, 320d1f89c23SMads Ynddal ) 32159da6684SStefan Hajnoczi 32259da6684SStefan Hajnoczidef run(analyzer): 32359da6684SStefan Hajnoczi """Execute an analyzer on a trace file given on the command-line. 32459da6684SStefan Hajnoczi 32559da6684SStefan Hajnoczi This function is useful as a driver for simple analysis scripts. More 32659da6684SStefan Hajnoczi advanced scripts will want to call process() instead.""" 32759da6684SStefan Hajnoczi 328f7bd4f02SMads Ynddal try: 329f7bd4f02SMads Ynddal # NOTE: See built-in `argparse` module for a more robust cli interface 330f7bd4f02SMads Ynddal *no_header, trace_event_path, trace_file_path = sys.argv[1:] 331f7bd4f02SMads Ynddal assert no_header == [] or no_header == ['--no-header'], 'Invalid no-header argument' 332f7bd4f02SMads Ynddal except (AssertionError, ValueError): 3331990fb98SMads Ynddal raise SimpleException(f'usage: {sys.argv[0]} [--no-header] <trace-events> <trace-file>\n') 33459da6684SStefan Hajnoczi 335f7bd4f02SMads Ynddal with open(trace_event_path, 'r') as events_fobj, open(trace_file_path, 'rb') as log_fobj: 336f7bd4f02SMads Ynddal process(events_fobj, log_fobj, analyzer, read_header=not no_header) 33759da6684SStefan Hajnoczi 33859da6684SStefan Hajnocziif __name__ == '__main__': 3393470fef1SMads Ynddal class Formatter2(Analyzer2): 34059da6684SStefan Hajnoczi def __init__(self): 3413470fef1SMads Ynddal self.last_timestamp_ns = None 3424c3b5a48SBlue Swirl 3433470fef1SMads Ynddal def catchall(self, *rec_args, event, timestamp_ns, pid, event_id): 3443470fef1SMads Ynddal if self.last_timestamp_ns is None: 3453470fef1SMads Ynddal self.last_timestamp_ns = timestamp_ns 3463470fef1SMads Ynddal delta_ns = timestamp_ns - self.last_timestamp_ns 3473470fef1SMads Ynddal self.last_timestamp_ns = timestamp_ns 3484c3b5a48SBlue Swirl 3493470fef1SMads Ynddal fields = [ 3503470fef1SMads Ynddal f'{name}={r}' if is_string(type) else f'{name}=0x{r:x}' 3513470fef1SMads Ynddal for r, (type, name) in zip(rec_args, event.args) 3523470fef1SMads Ynddal ] 3533470fef1SMads Ynddal print(f'{event.name} {delta_ns / 1000:0.3f} {pid=} ' + ' '.join(fields)) 3544c3b5a48SBlue Swirl 3551990fb98SMads Ynddal try: 3563470fef1SMads Ynddal run(Formatter2()) 3571990fb98SMads Ynddal except SimpleException as e: 3581990fb98SMads Ynddal sys.stderr.write(str(e) + "\n") 3591990fb98SMads Ynddal sys.exit(1) 360