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 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 172c109f21SMads Ynddal__all__ = ['Analyzer', 'process', 'run'] 182c109f21SMads Ynddal 194c3b5a48SBlue Swirlheader_event_id = 0xffffffffffffffff 204c3b5a48SBlue Swirlheader_magic = 0xf2b177cb0aa429b4 210b5538c3SStefan Hajnoczidropped_event_id = 0xfffffffffffffffe 224c3b5a48SBlue Swirl 237f1b588fSDaniel P. Berrangerecord_type_mapping = 0 247f1b588fSDaniel P. Berrangerecord_type_event = 1 257f1b588fSDaniel P. Berrange 2690a147a2SHarsh Prateek Boralog_header_fmt = '=QQQ' 2790a147a2SHarsh Prateek Borarec_header_fmt = '=QQII' 284c3b5a48SBlue Swirl 2990a147a2SHarsh Prateek Boradef read_header(fobj, hfmt): 3090a147a2SHarsh Prateek Bora '''Read a trace record header''' 3190a147a2SHarsh Prateek Bora hlen = struct.calcsize(hfmt) 3290a147a2SHarsh Prateek Bora hdr = fobj.read(hlen) 3390a147a2SHarsh Prateek Bora if len(hdr) != hlen: 344c3b5a48SBlue Swirl return None 3590a147a2SHarsh Prateek Bora return struct.unpack(hfmt, hdr) 364c3b5a48SBlue Swirl 377f1b588fSDaniel P. Berrangedef get_record(edict, idtoname, rechdr, fobj): 387f1b588fSDaniel P. Berrange """Deserialize a trace record from a file into a tuple 397f1b588fSDaniel P. Berrange (name, timestamp, pid, arg1, ..., arg6).""" 4090a147a2SHarsh Prateek Bora if rechdr is None: 4190a147a2SHarsh Prateek Bora return None 4290a147a2SHarsh Prateek Bora if rechdr[0] != dropped_event_id: 4390a147a2SHarsh Prateek Bora event_id = rechdr[0] 447f1b588fSDaniel P. Berrange name = idtoname[event_id] 457f1b588fSDaniel P. Berrange rec = (name, rechdr[1], rechdr[3]) 46249e9f79SJose Ricardo Ziviani try: 477f1b588fSDaniel P. Berrange event = edict[name] 48bd228083SEduardo Habkost except KeyError as e: 49249e9f79SJose Ricardo Ziviani import sys 50249e9f79SJose Ricardo Ziviani sys.stderr.write('%s event is logged but is not declared ' \ 51249e9f79SJose Ricardo Ziviani 'in the trace events file, try using ' \ 52249e9f79SJose Ricardo Ziviani 'trace-events-all instead.\n' % str(e)) 53249e9f79SJose Ricardo Ziviani sys.exit(1) 54249e9f79SJose Ricardo Ziviani 5590a147a2SHarsh Prateek Bora for type, name in event.args: 5690a147a2SHarsh Prateek Bora if is_string(type): 5790a147a2SHarsh Prateek Bora l = fobj.read(4) 5890a147a2SHarsh Prateek Bora (len,) = struct.unpack('=L', l) 5990a147a2SHarsh Prateek Bora s = fobj.read(len) 6090a147a2SHarsh Prateek Bora rec = rec + (s,) 6190a147a2SHarsh Prateek Bora else: 6290a147a2SHarsh Prateek Bora (value,) = struct.unpack('=Q', fobj.read(8)) 6390a147a2SHarsh Prateek Bora rec = rec + (value,) 6490a147a2SHarsh Prateek Bora else: 657f1b588fSDaniel P. Berrange rec = ("dropped", rechdr[1], rechdr[3]) 6690a147a2SHarsh Prateek Bora (value,) = struct.unpack('=Q', fobj.read(8)) 6790a147a2SHarsh Prateek Bora rec = rec + (value,) 6890a147a2SHarsh Prateek Bora return rec 6990a147a2SHarsh Prateek Bora 707f1b588fSDaniel P. Berrangedef get_mapping(fobj): 717f1b588fSDaniel P. Berrange (event_id, ) = struct.unpack('=Q', fobj.read(8)) 727f1b588fSDaniel P. Berrange (len, ) = struct.unpack('=L', fobj.read(4)) 73749c1d8eSEduardo Habkost name = fobj.read(len).decode() 7490a147a2SHarsh Prateek Bora 757f1b588fSDaniel P. Berrange return (event_id, name) 767f1b588fSDaniel P. Berrange 777f1b588fSDaniel P. Berrangedef read_record(edict, idtoname, fobj): 7880ff35cdSStefan Hajnoczi """Deserialize a trace record from a file into a tuple (event_num, timestamp, pid, arg1, ..., arg6).""" 7990a147a2SHarsh Prateek Bora rechdr = read_header(fobj, rec_header_fmt) 807f1b588fSDaniel P. Berrange return get_record(edict, idtoname, rechdr, fobj) 8190a147a2SHarsh Prateek Bora 8215327c3dSStefan Hajnoczidef read_trace_header(fobj): 8315327c3dSStefan Hajnoczi """Read and verify trace file header""" 8490a147a2SHarsh Prateek Bora header = read_header(fobj, log_header_fmt) 8525d54654SDaniel P. Berrange if header is None: 8690a147a2SHarsh Prateek Bora raise ValueError('Not a valid trace file!') 8725d54654SDaniel P. Berrange if header[0] != header_event_id: 8825d54654SDaniel P. Berrange raise ValueError('Not a valid trace file, header id %d != %d' % 8925d54654SDaniel P. Berrange (header[0], header_event_id)) 9025d54654SDaniel P. Berrange if header[1] != header_magic: 9125d54654SDaniel P. Berrange raise ValueError('Not a valid trace file, header magic %d != %d' % 9225d54654SDaniel P. Berrange (header[1], header_magic)) 9390a147a2SHarsh Prateek Bora 9490a147a2SHarsh Prateek Bora log_version = header[2] 957f1b588fSDaniel P. Berrange if log_version not in [0, 2, 3, 4]: 96ef0bd3bbSLluís Vilanova raise ValueError('Unknown version of tracelog format!') 977f1b588fSDaniel P. Berrange if log_version != 4: 98ef0bd3bbSLluís Vilanova raise ValueError('Log format %d not supported with this QEMU release!' 99ef0bd3bbSLluís Vilanova % log_version) 1004c3b5a48SBlue Swirl 101840d8351SStefan Hajnoczidef read_trace_records(edict, idtoname, fobj): 102840d8351SStefan Hajnoczi """Deserialize trace records from a file, yielding record tuples (event_num, timestamp, pid, arg1, ..., arg6). 103840d8351SStefan Hajnoczi 104840d8351SStefan Hajnoczi Note that `idtoname` is modified if the file contains mapping records. 105840d8351SStefan Hajnoczi 106840d8351SStefan Hajnoczi Args: 107840d8351SStefan Hajnoczi edict (str -> Event): events dict, indexed by name 108840d8351SStefan Hajnoczi idtoname (int -> str): event names dict, indexed by event ID 109840d8351SStefan Hajnoczi fobj (file): input file 110840d8351SStefan Hajnoczi 111840d8351SStefan Hajnoczi """ 1124c3b5a48SBlue Swirl while True: 1137f1b588fSDaniel P. Berrange t = fobj.read(8) 1147f1b588fSDaniel P. Berrange if len(t) == 0: 1154c3b5a48SBlue Swirl break 1164c3b5a48SBlue Swirl 1177f1b588fSDaniel P. Berrange (rectype, ) = struct.unpack('=Q', t) 1187f1b588fSDaniel P. Berrange if rectype == record_type_mapping: 1197f1b588fSDaniel P. Berrange event_id, name = get_mapping(fobj) 1207f1b588fSDaniel P. Berrange idtoname[event_id] = name 1217f1b588fSDaniel P. Berrange else: 1227f1b588fSDaniel P. Berrange rec = read_record(edict, idtoname, fobj) 1237f1b588fSDaniel P. Berrange 1244c3b5a48SBlue Swirl yield rec 1254c3b5a48SBlue Swirl 12659da6684SStefan Hajnocziclass Analyzer(object): 12759da6684SStefan Hajnoczi """A trace file analyzer which processes trace records. 12859da6684SStefan Hajnoczi 12959da6684SStefan Hajnoczi An analyzer can be passed to run() or process(). The begin() method is 13059da6684SStefan Hajnoczi invoked, then each trace record is processed, and finally the end() method 13159da6684SStefan Hajnoczi is invoked. 13259da6684SStefan Hajnoczi 13359da6684SStefan Hajnoczi If a method matching a trace event name exists, it is invoked to process 134659370f7SStefan Hajnoczi that trace record. Otherwise the catchall() method is invoked. 135659370f7SStefan Hajnoczi 136659370f7SStefan Hajnoczi Example: 137659370f7SStefan Hajnoczi The following method handles the runstate_set(int new_state) trace event:: 138659370f7SStefan Hajnoczi 139659370f7SStefan Hajnoczi def runstate_set(self, new_state): 140659370f7SStefan Hajnoczi ... 141659370f7SStefan Hajnoczi 142659370f7SStefan Hajnoczi The method can also take a timestamp argument before the trace event 143659370f7SStefan Hajnoczi arguments:: 144659370f7SStefan Hajnoczi 145659370f7SStefan Hajnoczi def runstate_set(self, timestamp, new_state): 146659370f7SStefan Hajnoczi ... 147659370f7SStefan Hajnoczi 148659370f7SStefan Hajnoczi Timestamps have the uint64_t type and are in nanoseconds. 149659370f7SStefan Hajnoczi 150659370f7SStefan Hajnoczi The pid can be included in addition to the timestamp and is useful when 151659370f7SStefan Hajnoczi dealing with traces from multiple processes:: 152659370f7SStefan Hajnoczi 153659370f7SStefan Hajnoczi def runstate_set(self, timestamp, pid, new_state): 154659370f7SStefan Hajnoczi ... 155659370f7SStefan Hajnoczi """ 15659da6684SStefan Hajnoczi 15759da6684SStefan Hajnoczi def begin(self): 15859da6684SStefan Hajnoczi """Called at the start of the trace.""" 15959da6684SStefan Hajnoczi pass 16059da6684SStefan Hajnoczi 16159da6684SStefan Hajnoczi def catchall(self, event, rec): 16259da6684SStefan Hajnoczi """Called if no specific method for processing a trace event has been found.""" 16359da6684SStefan Hajnoczi pass 16459da6684SStefan Hajnoczi 16559da6684SStefan Hajnoczi def end(self): 16659da6684SStefan Hajnoczi """Called at the end of the trace.""" 16759da6684SStefan Hajnoczi pass 16859da6684SStefan Hajnoczi 16915327c3dSStefan Hajnoczidef process(events, log, analyzer, read_header=True): 17059da6684SStefan Hajnoczi """Invoke an analyzer on each event in a log.""" 17159da6684SStefan Hajnoczi if isinstance(events, str): 17286b5aacfSDaniel P. Berrangé events = read_events(open(events, 'r'), events) 17359da6684SStefan Hajnoczi if isinstance(log, str): 17459da6684SStefan Hajnoczi log = open(log, 'rb') 17559da6684SStefan Hajnoczi 17615327c3dSStefan Hajnoczi if read_header: 17715327c3dSStefan Hajnoczi read_trace_header(log) 17815327c3dSStefan Hajnoczi 179c6e93c9dSVolker Rümelin frameinfo = inspect.getframeinfo(inspect.currentframe()) 180c6e93c9dSVolker Rümelin dropped_event = Event.build("Dropped_Event(uint64_t num_events_dropped)", 181c6e93c9dSVolker Rümelin frameinfo.lineno + 1, frameinfo.filename) 1827f1b588fSDaniel P. Berrange edict = {"dropped": dropped_event} 183840d8351SStefan Hajnoczi idtoname = {dropped_event_id: "dropped"} 18490a147a2SHarsh Prateek Bora 1857f1b588fSDaniel P. Berrange for event in events: 1867f1b588fSDaniel P. Berrange edict[event.name] = event 18790a147a2SHarsh Prateek Bora 188840d8351SStefan Hajnoczi # If there is no header assume event ID mapping matches events list 189840d8351SStefan Hajnoczi if not read_header: 190840d8351SStefan Hajnoczi for event_id, event in enumerate(events): 191840d8351SStefan Hajnoczi idtoname[event_id] = event.name 192840d8351SStefan Hajnoczi 19359da6684SStefan Hajnoczi def build_fn(analyzer, event): 19490a147a2SHarsh Prateek Bora if isinstance(event, str): 19590a147a2SHarsh Prateek Bora return analyzer.catchall 19690a147a2SHarsh Prateek Bora 19790a147a2SHarsh Prateek Bora fn = getattr(analyzer, event.name, None) 19859da6684SStefan Hajnoczi if fn is None: 19959da6684SStefan Hajnoczi return analyzer.catchall 20059da6684SStefan Hajnoczi 20190a147a2SHarsh Prateek Bora event_argcount = len(event.args) 20259da6684SStefan Hajnoczi fn_argcount = len(inspect.getargspec(fn)[0]) - 1 20359da6684SStefan Hajnoczi if fn_argcount == event_argcount + 1: 20459da6684SStefan Hajnoczi # Include timestamp as first argument 205e42860aeSStefan Hajnoczi return lambda _, rec: fn(*(rec[1:2] + rec[3:3 + event_argcount])) 20680ff35cdSStefan Hajnoczi elif fn_argcount == event_argcount + 2: 20780ff35cdSStefan Hajnoczi # Include timestamp and pid 20880ff35cdSStefan Hajnoczi return lambda _, rec: fn(*rec[1:3 + event_argcount]) 20959da6684SStefan Hajnoczi else: 21080ff35cdSStefan Hajnoczi # Just arguments, no timestamp or pid 21180ff35cdSStefan Hajnoczi return lambda _, rec: fn(*rec[3:3 + event_argcount]) 21259da6684SStefan Hajnoczi 21359da6684SStefan Hajnoczi analyzer.begin() 21459da6684SStefan Hajnoczi fn_cache = {} 215840d8351SStefan Hajnoczi for rec in read_trace_records(edict, idtoname, log): 21659da6684SStefan Hajnoczi event_num = rec[0] 21790a147a2SHarsh Prateek Bora event = edict[event_num] 21859da6684SStefan Hajnoczi if event_num not in fn_cache: 21959da6684SStefan Hajnoczi fn_cache[event_num] = build_fn(analyzer, event) 22059da6684SStefan Hajnoczi fn_cache[event_num](event, rec) 22159da6684SStefan Hajnoczi analyzer.end() 22259da6684SStefan Hajnoczi 22359da6684SStefan Hajnoczidef run(analyzer): 22459da6684SStefan Hajnoczi """Execute an analyzer on a trace file given on the command-line. 22559da6684SStefan Hajnoczi 22659da6684SStefan Hajnoczi This function is useful as a driver for simple analysis scripts. More 22759da6684SStefan Hajnoczi advanced scripts will want to call process() instead.""" 22859da6684SStefan Hajnoczi import sys 22959da6684SStefan Hajnoczi 23015327c3dSStefan Hajnoczi read_header = True 23115327c3dSStefan Hajnoczi if len(sys.argv) == 4 and sys.argv[1] == '--no-header': 23215327c3dSStefan Hajnoczi read_header = False 23315327c3dSStefan Hajnoczi del sys.argv[1] 23415327c3dSStefan Hajnoczi elif len(sys.argv) != 3: 23515327c3dSStefan Hajnoczi sys.stderr.write('usage: %s [--no-header] <trace-events> ' \ 23615327c3dSStefan Hajnoczi '<trace-file>\n' % sys.argv[0]) 23759da6684SStefan Hajnoczi sys.exit(1) 23859da6684SStefan Hajnoczi 23986b5aacfSDaniel P. Berrangé events = read_events(open(sys.argv[1], 'r'), sys.argv[1]) 24015327c3dSStefan Hajnoczi process(events, sys.argv[2], analyzer, read_header=read_header) 24159da6684SStefan Hajnoczi 24259da6684SStefan Hajnocziif __name__ == '__main__': 24359da6684SStefan Hajnoczi class Formatter(Analyzer): 24459da6684SStefan Hajnoczi def __init__(self): 2454c3b5a48SBlue Swirl self.last_timestamp = None 2464c3b5a48SBlue Swirl 24759da6684SStefan Hajnoczi def catchall(self, event, rec): 24859da6684SStefan Hajnoczi timestamp = rec[1] 2494c3b5a48SBlue Swirl if self.last_timestamp is None: 25059da6684SStefan Hajnoczi self.last_timestamp = timestamp 25159da6684SStefan Hajnoczi delta_ns = timestamp - self.last_timestamp 25259da6684SStefan Hajnoczi self.last_timestamp = timestamp 2534c3b5a48SBlue Swirl 25480ff35cdSStefan Hajnoczi fields = [event.name, '%0.3f' % (delta_ns / 1000.0), 25580ff35cdSStefan Hajnoczi 'pid=%d' % rec[2]] 25680ff35cdSStefan Hajnoczi i = 3 25790a147a2SHarsh Prateek Bora for type, name in event.args: 25890a147a2SHarsh Prateek Bora if is_string(type): 25980ff35cdSStefan Hajnoczi fields.append('%s=%s' % (name, rec[i])) 26090a147a2SHarsh Prateek Bora else: 26180ff35cdSStefan Hajnoczi fields.append('%s=0x%x' % (name, rec[i])) 26290a147a2SHarsh Prateek Bora i += 1 263f03868bdSEduardo Habkost print(' '.join(fields)) 2644c3b5a48SBlue Swirl 26559da6684SStefan Hajnoczi run(Formatter()) 266