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# 1087e0331cSPhilippe Mathieu-Daudé# For help see docs/devel/tracing.txt 114c3b5a48SBlue Swirl 124c3b5a48SBlue Swirlimport struct 1359da6684SStefan Hajnocziimport inspect 14d1b97bceSDaniel P. Berrangefrom tracetool import read_events, Event 1590a147a2SHarsh Prateek Borafrom tracetool.backend.simple import is_string 164c3b5a48SBlue Swirl 174c3b5a48SBlue Swirlheader_event_id = 0xffffffffffffffff 184c3b5a48SBlue Swirlheader_magic = 0xf2b177cb0aa429b4 190b5538c3SStefan Hajnoczidropped_event_id = 0xfffffffffffffffe 204c3b5a48SBlue Swirl 217f1b588fSDaniel P. Berrangerecord_type_mapping = 0 227f1b588fSDaniel P. Berrangerecord_type_event = 1 237f1b588fSDaniel P. Berrange 2490a147a2SHarsh Prateek Boralog_header_fmt = '=QQQ' 2590a147a2SHarsh Prateek Borarec_header_fmt = '=QQII' 264c3b5a48SBlue Swirl 2790a147a2SHarsh Prateek Boradef read_header(fobj, hfmt): 2890a147a2SHarsh Prateek Bora '''Read a trace record header''' 2990a147a2SHarsh Prateek Bora hlen = struct.calcsize(hfmt) 3090a147a2SHarsh Prateek Bora hdr = fobj.read(hlen) 3190a147a2SHarsh Prateek Bora if len(hdr) != hlen: 324c3b5a48SBlue Swirl return None 3390a147a2SHarsh Prateek Bora return struct.unpack(hfmt, hdr) 344c3b5a48SBlue Swirl 357f1b588fSDaniel P. Berrangedef get_record(edict, idtoname, rechdr, fobj): 367f1b588fSDaniel P. Berrange """Deserialize a trace record from a file into a tuple 377f1b588fSDaniel P. Berrange (name, timestamp, pid, arg1, ..., arg6).""" 3890a147a2SHarsh Prateek Bora if rechdr is None: 3990a147a2SHarsh Prateek Bora return None 4090a147a2SHarsh Prateek Bora if rechdr[0] != dropped_event_id: 4190a147a2SHarsh Prateek Bora event_id = rechdr[0] 427f1b588fSDaniel P. Berrange name = idtoname[event_id] 437f1b588fSDaniel P. Berrange rec = (name, rechdr[1], rechdr[3]) 44249e9f79SJose Ricardo Ziviani try: 457f1b588fSDaniel P. Berrange event = edict[name] 46bd228083SEduardo Habkost except KeyError as e: 47249e9f79SJose Ricardo Ziviani import sys 48249e9f79SJose Ricardo Ziviani sys.stderr.write('%s event is logged but is not declared ' \ 49249e9f79SJose Ricardo Ziviani 'in the trace events file, try using ' \ 50249e9f79SJose Ricardo Ziviani 'trace-events-all instead.\n' % str(e)) 51249e9f79SJose Ricardo Ziviani sys.exit(1) 52249e9f79SJose Ricardo Ziviani 5390a147a2SHarsh Prateek Bora for type, name in event.args: 5490a147a2SHarsh Prateek Bora if is_string(type): 5590a147a2SHarsh Prateek Bora l = fobj.read(4) 5690a147a2SHarsh Prateek Bora (len,) = struct.unpack('=L', l) 5790a147a2SHarsh Prateek Bora s = fobj.read(len) 5890a147a2SHarsh Prateek Bora rec = rec + (s,) 5990a147a2SHarsh Prateek Bora else: 6090a147a2SHarsh Prateek Bora (value,) = struct.unpack('=Q', fobj.read(8)) 6190a147a2SHarsh Prateek Bora rec = rec + (value,) 6290a147a2SHarsh Prateek Bora else: 637f1b588fSDaniel P. Berrange rec = ("dropped", rechdr[1], rechdr[3]) 6490a147a2SHarsh Prateek Bora (value,) = struct.unpack('=Q', fobj.read(8)) 6590a147a2SHarsh Prateek Bora rec = rec + (value,) 6690a147a2SHarsh Prateek Bora return rec 6790a147a2SHarsh Prateek Bora 687f1b588fSDaniel P. Berrangedef get_mapping(fobj): 697f1b588fSDaniel P. Berrange (event_id, ) = struct.unpack('=Q', fobj.read(8)) 707f1b588fSDaniel P. Berrange (len, ) = struct.unpack('=L', fobj.read(4)) 71749c1d8eSEduardo Habkost name = fobj.read(len).decode() 7290a147a2SHarsh Prateek Bora 737f1b588fSDaniel P. Berrange return (event_id, name) 747f1b588fSDaniel P. Berrange 757f1b588fSDaniel P. Berrangedef read_record(edict, idtoname, fobj): 7680ff35cdSStefan Hajnoczi """Deserialize a trace record from a file into a tuple (event_num, timestamp, pid, arg1, ..., arg6).""" 7790a147a2SHarsh Prateek Bora rechdr = read_header(fobj, rec_header_fmt) 787f1b588fSDaniel P. Berrange return get_record(edict, idtoname, rechdr, fobj) 7990a147a2SHarsh Prateek Bora 8015327c3dSStefan Hajnoczidef read_trace_header(fobj): 8115327c3dSStefan Hajnoczi """Read and verify trace file header""" 8290a147a2SHarsh Prateek Bora header = read_header(fobj, log_header_fmt) 8325d54654SDaniel P. Berrange if header is None: 8490a147a2SHarsh Prateek Bora raise ValueError('Not a valid trace file!') 8525d54654SDaniel P. Berrange if header[0] != header_event_id: 8625d54654SDaniel P. Berrange raise ValueError('Not a valid trace file, header id %d != %d' % 8725d54654SDaniel P. Berrange (header[0], header_event_id)) 8825d54654SDaniel P. Berrange if header[1] != header_magic: 8925d54654SDaniel P. Berrange raise ValueError('Not a valid trace file, header magic %d != %d' % 9025d54654SDaniel P. Berrange (header[1], header_magic)) 9190a147a2SHarsh Prateek Bora 9290a147a2SHarsh Prateek Bora log_version = header[2] 937f1b588fSDaniel P. Berrange if log_version not in [0, 2, 3, 4]: 94ef0bd3bbSLluís Vilanova raise ValueError('Unknown version of tracelog format!') 957f1b588fSDaniel P. Berrange if log_version != 4: 96ef0bd3bbSLluís Vilanova raise ValueError('Log format %d not supported with this QEMU release!' 97ef0bd3bbSLluís Vilanova % log_version) 984c3b5a48SBlue Swirl 99840d8351SStefan Hajnoczidef read_trace_records(edict, idtoname, fobj): 100840d8351SStefan Hajnoczi """Deserialize trace records from a file, yielding record tuples (event_num, timestamp, pid, arg1, ..., arg6). 101840d8351SStefan Hajnoczi 102840d8351SStefan Hajnoczi Note that `idtoname` is modified if the file contains mapping records. 103840d8351SStefan Hajnoczi 104840d8351SStefan Hajnoczi Args: 105840d8351SStefan Hajnoczi edict (str -> Event): events dict, indexed by name 106840d8351SStefan Hajnoczi idtoname (int -> str): event names dict, indexed by event ID 107840d8351SStefan Hajnoczi fobj (file): input file 108840d8351SStefan Hajnoczi 109840d8351SStefan Hajnoczi """ 1104c3b5a48SBlue Swirl while True: 1117f1b588fSDaniel P. Berrange t = fobj.read(8) 1127f1b588fSDaniel P. Berrange if len(t) == 0: 1134c3b5a48SBlue Swirl break 1144c3b5a48SBlue Swirl 1157f1b588fSDaniel P. Berrange (rectype, ) = struct.unpack('=Q', t) 1167f1b588fSDaniel P. Berrange if rectype == record_type_mapping: 1177f1b588fSDaniel P. Berrange event_id, name = get_mapping(fobj) 1187f1b588fSDaniel P. Berrange idtoname[event_id] = name 1197f1b588fSDaniel P. Berrange else: 1207f1b588fSDaniel P. Berrange rec = read_record(edict, idtoname, fobj) 1217f1b588fSDaniel P. Berrange 1224c3b5a48SBlue Swirl yield rec 1234c3b5a48SBlue Swirl 12459da6684SStefan Hajnocziclass Analyzer(object): 12559da6684SStefan Hajnoczi """A trace file analyzer which processes trace records. 12659da6684SStefan Hajnoczi 12759da6684SStefan Hajnoczi An analyzer can be passed to run() or process(). The begin() method is 12859da6684SStefan Hajnoczi invoked, then each trace record is processed, and finally the end() method 12959da6684SStefan Hajnoczi is invoked. 13059da6684SStefan Hajnoczi 13159da6684SStefan Hajnoczi If a method matching a trace event name exists, it is invoked to process 132659370f7SStefan Hajnoczi that trace record. Otherwise the catchall() method is invoked. 133659370f7SStefan Hajnoczi 134659370f7SStefan Hajnoczi Example: 135659370f7SStefan Hajnoczi The following method handles the runstate_set(int new_state) trace event:: 136659370f7SStefan Hajnoczi 137659370f7SStefan Hajnoczi def runstate_set(self, new_state): 138659370f7SStefan Hajnoczi ... 139659370f7SStefan Hajnoczi 140659370f7SStefan Hajnoczi The method can also take a timestamp argument before the trace event 141659370f7SStefan Hajnoczi arguments:: 142659370f7SStefan Hajnoczi 143659370f7SStefan Hajnoczi def runstate_set(self, timestamp, new_state): 144659370f7SStefan Hajnoczi ... 145659370f7SStefan Hajnoczi 146659370f7SStefan Hajnoczi Timestamps have the uint64_t type and are in nanoseconds. 147659370f7SStefan Hajnoczi 148659370f7SStefan Hajnoczi The pid can be included in addition to the timestamp and is useful when 149659370f7SStefan Hajnoczi dealing with traces from multiple processes:: 150659370f7SStefan Hajnoczi 151659370f7SStefan Hajnoczi def runstate_set(self, timestamp, pid, new_state): 152659370f7SStefan Hajnoczi ... 153659370f7SStefan Hajnoczi """ 15459da6684SStefan Hajnoczi 15559da6684SStefan Hajnoczi def begin(self): 15659da6684SStefan Hajnoczi """Called at the start of the trace.""" 15759da6684SStefan Hajnoczi pass 15859da6684SStefan Hajnoczi 15959da6684SStefan Hajnoczi def catchall(self, event, rec): 16059da6684SStefan Hajnoczi """Called if no specific method for processing a trace event has been found.""" 16159da6684SStefan Hajnoczi pass 16259da6684SStefan Hajnoczi 16359da6684SStefan Hajnoczi def end(self): 16459da6684SStefan Hajnoczi """Called at the end of the trace.""" 16559da6684SStefan Hajnoczi pass 16659da6684SStefan Hajnoczi 16715327c3dSStefan Hajnoczidef process(events, log, analyzer, read_header=True): 16859da6684SStefan Hajnoczi """Invoke an analyzer on each event in a log.""" 16959da6684SStefan Hajnoczi if isinstance(events, str): 17086b5aacfSDaniel P. Berrangé events = read_events(open(events, 'r'), events) 17159da6684SStefan Hajnoczi if isinstance(log, str): 17259da6684SStefan Hajnoczi log = open(log, 'rb') 17359da6684SStefan Hajnoczi 17415327c3dSStefan Hajnoczi if read_header: 17515327c3dSStefan Hajnoczi read_trace_header(log) 17615327c3dSStefan Hajnoczi 177*c6e93c9dSVolker Rümelin frameinfo = inspect.getframeinfo(inspect.currentframe()) 178*c6e93c9dSVolker Rümelin dropped_event = Event.build("Dropped_Event(uint64_t num_events_dropped)", 179*c6e93c9dSVolker Rümelin frameinfo.lineno + 1, frameinfo.filename) 1807f1b588fSDaniel P. Berrange edict = {"dropped": dropped_event} 181840d8351SStefan Hajnoczi idtoname = {dropped_event_id: "dropped"} 18290a147a2SHarsh Prateek Bora 1837f1b588fSDaniel P. Berrange for event in events: 1847f1b588fSDaniel P. Berrange edict[event.name] = event 18590a147a2SHarsh Prateek Bora 186840d8351SStefan Hajnoczi # If there is no header assume event ID mapping matches events list 187840d8351SStefan Hajnoczi if not read_header: 188840d8351SStefan Hajnoczi for event_id, event in enumerate(events): 189840d8351SStefan Hajnoczi idtoname[event_id] = event.name 190840d8351SStefan Hajnoczi 19159da6684SStefan Hajnoczi def build_fn(analyzer, event): 19290a147a2SHarsh Prateek Bora if isinstance(event, str): 19390a147a2SHarsh Prateek Bora return analyzer.catchall 19490a147a2SHarsh Prateek Bora 19590a147a2SHarsh Prateek Bora fn = getattr(analyzer, event.name, None) 19659da6684SStefan Hajnoczi if fn is None: 19759da6684SStefan Hajnoczi return analyzer.catchall 19859da6684SStefan Hajnoczi 19990a147a2SHarsh Prateek Bora event_argcount = len(event.args) 20059da6684SStefan Hajnoczi fn_argcount = len(inspect.getargspec(fn)[0]) - 1 20159da6684SStefan Hajnoczi if fn_argcount == event_argcount + 1: 20259da6684SStefan Hajnoczi # Include timestamp as first argument 203e42860aeSStefan Hajnoczi return lambda _, rec: fn(*(rec[1:2] + rec[3:3 + event_argcount])) 20480ff35cdSStefan Hajnoczi elif fn_argcount == event_argcount + 2: 20580ff35cdSStefan Hajnoczi # Include timestamp and pid 20680ff35cdSStefan Hajnoczi return lambda _, rec: fn(*rec[1:3 + event_argcount]) 20759da6684SStefan Hajnoczi else: 20880ff35cdSStefan Hajnoczi # Just arguments, no timestamp or pid 20980ff35cdSStefan Hajnoczi return lambda _, rec: fn(*rec[3:3 + event_argcount]) 21059da6684SStefan Hajnoczi 21159da6684SStefan Hajnoczi analyzer.begin() 21259da6684SStefan Hajnoczi fn_cache = {} 213840d8351SStefan Hajnoczi for rec in read_trace_records(edict, idtoname, log): 21459da6684SStefan Hajnoczi event_num = rec[0] 21590a147a2SHarsh Prateek Bora event = edict[event_num] 21659da6684SStefan Hajnoczi if event_num not in fn_cache: 21759da6684SStefan Hajnoczi fn_cache[event_num] = build_fn(analyzer, event) 21859da6684SStefan Hajnoczi fn_cache[event_num](event, rec) 21959da6684SStefan Hajnoczi analyzer.end() 22059da6684SStefan Hajnoczi 22159da6684SStefan Hajnoczidef run(analyzer): 22259da6684SStefan Hajnoczi """Execute an analyzer on a trace file given on the command-line. 22359da6684SStefan Hajnoczi 22459da6684SStefan Hajnoczi This function is useful as a driver for simple analysis scripts. More 22559da6684SStefan Hajnoczi advanced scripts will want to call process() instead.""" 22659da6684SStefan Hajnoczi import sys 22759da6684SStefan Hajnoczi 22815327c3dSStefan Hajnoczi read_header = True 22915327c3dSStefan Hajnoczi if len(sys.argv) == 4 and sys.argv[1] == '--no-header': 23015327c3dSStefan Hajnoczi read_header = False 23115327c3dSStefan Hajnoczi del sys.argv[1] 23215327c3dSStefan Hajnoczi elif len(sys.argv) != 3: 23315327c3dSStefan Hajnoczi sys.stderr.write('usage: %s [--no-header] <trace-events> ' \ 23415327c3dSStefan Hajnoczi '<trace-file>\n' % sys.argv[0]) 23559da6684SStefan Hajnoczi sys.exit(1) 23659da6684SStefan Hajnoczi 23786b5aacfSDaniel P. Berrangé events = read_events(open(sys.argv[1], 'r'), sys.argv[1]) 23815327c3dSStefan Hajnoczi process(events, sys.argv[2], analyzer, read_header=read_header) 23959da6684SStefan Hajnoczi 24059da6684SStefan Hajnocziif __name__ == '__main__': 24159da6684SStefan Hajnoczi class Formatter(Analyzer): 24259da6684SStefan Hajnoczi def __init__(self): 2434c3b5a48SBlue Swirl self.last_timestamp = None 2444c3b5a48SBlue Swirl 24559da6684SStefan Hajnoczi def catchall(self, event, rec): 24659da6684SStefan Hajnoczi timestamp = rec[1] 2474c3b5a48SBlue Swirl if self.last_timestamp is None: 24859da6684SStefan Hajnoczi self.last_timestamp = timestamp 24959da6684SStefan Hajnoczi delta_ns = timestamp - self.last_timestamp 25059da6684SStefan Hajnoczi self.last_timestamp = timestamp 2514c3b5a48SBlue Swirl 25280ff35cdSStefan Hajnoczi fields = [event.name, '%0.3f' % (delta_ns / 1000.0), 25380ff35cdSStefan Hajnoczi 'pid=%d' % rec[2]] 25480ff35cdSStefan Hajnoczi i = 3 25590a147a2SHarsh Prateek Bora for type, name in event.args: 25690a147a2SHarsh Prateek Bora if is_string(type): 25780ff35cdSStefan Hajnoczi fields.append('%s=%s' % (name, rec[i])) 25890a147a2SHarsh Prateek Bora else: 25980ff35cdSStefan Hajnoczi fields.append('%s=0x%x' % (name, rec[i])) 26090a147a2SHarsh Prateek Bora i += 1 261f03868bdSEduardo Habkost print(' '.join(fields)) 2624c3b5a48SBlue Swirl 26359da6684SStefan Hajnoczi run(Formatter()) 264