14c3b5a48SBlue Swirl#!/usr/bin/env python 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# 104c3b5a48SBlue Swirl# For help see docs/tracing.txt 114c3b5a48SBlue Swirl 124c3b5a48SBlue Swirlimport struct 134c3b5a48SBlue Swirlimport re 1459da6684SStefan Hajnocziimport inspect 15d1b97bceSDaniel P. Berrangefrom tracetool import read_events, Event 1690a147a2SHarsh Prateek Borafrom tracetool.backend.simple import is_string 174c3b5a48SBlue Swirl 184c3b5a48SBlue Swirlheader_event_id = 0xffffffffffffffff 194c3b5a48SBlue Swirlheader_magic = 0xf2b177cb0aa429b4 200b5538c3SStefan Hajnoczidropped_event_id = 0xfffffffffffffffe 214c3b5a48SBlue Swirl 227f1b588fSDaniel P. Berrangerecord_type_mapping = 0 237f1b588fSDaniel P. Berrangerecord_type_event = 1 247f1b588fSDaniel P. Berrange 2590a147a2SHarsh Prateek Boralog_header_fmt = '=QQQ' 2690a147a2SHarsh Prateek Borarec_header_fmt = '=QQII' 274c3b5a48SBlue Swirl 2890a147a2SHarsh Prateek Boradef read_header(fobj, hfmt): 2990a147a2SHarsh Prateek Bora '''Read a trace record header''' 3090a147a2SHarsh Prateek Bora hlen = struct.calcsize(hfmt) 3190a147a2SHarsh Prateek Bora hdr = fobj.read(hlen) 3290a147a2SHarsh Prateek Bora if len(hdr) != hlen: 334c3b5a48SBlue Swirl return None 3490a147a2SHarsh Prateek Bora return struct.unpack(hfmt, hdr) 354c3b5a48SBlue Swirl 367f1b588fSDaniel P. Berrangedef get_record(edict, idtoname, rechdr, fobj): 377f1b588fSDaniel P. Berrange """Deserialize a trace record from a file into a tuple 387f1b588fSDaniel P. Berrange (name, timestamp, pid, arg1, ..., arg6).""" 3990a147a2SHarsh Prateek Bora if rechdr is None: 4090a147a2SHarsh Prateek Bora return None 4190a147a2SHarsh Prateek Bora if rechdr[0] != dropped_event_id: 4290a147a2SHarsh Prateek Bora event_id = rechdr[0] 437f1b588fSDaniel P. Berrange name = idtoname[event_id] 447f1b588fSDaniel P. Berrange rec = (name, rechdr[1], rechdr[3]) 45*249e9f79SJose Ricardo Ziviani try: 467f1b588fSDaniel P. Berrange event = edict[name] 47*249e9f79SJose Ricardo Ziviani except KeyError, e: 48*249e9f79SJose Ricardo Ziviani import sys 49*249e9f79SJose Ricardo Ziviani sys.stderr.write('%s event is logged but is not declared ' \ 50*249e9f79SJose Ricardo Ziviani 'in the trace events file, try using ' \ 51*249e9f79SJose Ricardo Ziviani 'trace-events-all instead.\n' % str(e)) 52*249e9f79SJose Ricardo Ziviani sys.exit(1) 53*249e9f79SJose Ricardo Ziviani 5490a147a2SHarsh Prateek Bora for type, name in event.args: 5590a147a2SHarsh Prateek Bora if is_string(type): 5690a147a2SHarsh Prateek Bora l = fobj.read(4) 5790a147a2SHarsh Prateek Bora (len,) = struct.unpack('=L', l) 5890a147a2SHarsh Prateek Bora s = fobj.read(len) 5990a147a2SHarsh Prateek Bora rec = rec + (s,) 6090a147a2SHarsh Prateek Bora else: 6190a147a2SHarsh Prateek Bora (value,) = struct.unpack('=Q', fobj.read(8)) 6290a147a2SHarsh Prateek Bora rec = rec + (value,) 6390a147a2SHarsh Prateek Bora else: 647f1b588fSDaniel P. Berrange rec = ("dropped", rechdr[1], rechdr[3]) 6590a147a2SHarsh Prateek Bora (value,) = struct.unpack('=Q', fobj.read(8)) 6690a147a2SHarsh Prateek Bora rec = rec + (value,) 6790a147a2SHarsh Prateek Bora return rec 6890a147a2SHarsh Prateek Bora 697f1b588fSDaniel P. Berrangedef get_mapping(fobj): 707f1b588fSDaniel P. Berrange (event_id, ) = struct.unpack('=Q', fobj.read(8)) 717f1b588fSDaniel P. Berrange (len, ) = struct.unpack('=L', fobj.read(4)) 727f1b588fSDaniel P. Berrange name = fobj.read(len) 7390a147a2SHarsh Prateek Bora 747f1b588fSDaniel P. Berrange return (event_id, name) 757f1b588fSDaniel P. Berrange 767f1b588fSDaniel P. Berrangedef read_record(edict, idtoname, fobj): 7780ff35cdSStefan Hajnoczi """Deserialize a trace record from a file into a tuple (event_num, timestamp, pid, arg1, ..., arg6).""" 7890a147a2SHarsh Prateek Bora rechdr = read_header(fobj, rec_header_fmt) 797f1b588fSDaniel P. Berrange return get_record(edict, idtoname, rechdr, fobj) 8090a147a2SHarsh Prateek Bora 8115327c3dSStefan Hajnoczidef read_trace_header(fobj): 8215327c3dSStefan Hajnoczi """Read and verify trace file header""" 8390a147a2SHarsh Prateek Bora header = read_header(fobj, log_header_fmt) 8425d54654SDaniel P. Berrange if header is None: 8590a147a2SHarsh Prateek Bora raise ValueError('Not a valid trace file!') 8625d54654SDaniel P. Berrange if header[0] != header_event_id: 8725d54654SDaniel P. Berrange raise ValueError('Not a valid trace file, header id %d != %d' % 8825d54654SDaniel P. Berrange (header[0], header_event_id)) 8925d54654SDaniel P. Berrange if header[1] != header_magic: 9025d54654SDaniel P. Berrange raise ValueError('Not a valid trace file, header magic %d != %d' % 9125d54654SDaniel P. Berrange (header[1], header_magic)) 9290a147a2SHarsh Prateek Bora 9390a147a2SHarsh Prateek Bora log_version = header[2] 947f1b588fSDaniel P. Berrange if log_version not in [0, 2, 3, 4]: 95ef0bd3bbSLluís Vilanova raise ValueError('Unknown version of tracelog format!') 967f1b588fSDaniel P. Berrange if log_version != 4: 97ef0bd3bbSLluís Vilanova raise ValueError('Log format %d not supported with this QEMU release!' 98ef0bd3bbSLluís Vilanova % log_version) 994c3b5a48SBlue Swirl 10015327c3dSStefan Hajnoczidef read_trace_records(edict, fobj): 10115327c3dSStefan Hajnoczi """Deserialize trace records from a file, yielding record tuples (event_num, timestamp, pid, arg1, ..., arg6).""" 1027f1b588fSDaniel P. Berrange idtoname = { 1037f1b588fSDaniel P. Berrange dropped_event_id: "dropped" 1047f1b588fSDaniel P. Berrange } 1054c3b5a48SBlue Swirl while True: 1067f1b588fSDaniel P. Berrange t = fobj.read(8) 1077f1b588fSDaniel P. Berrange if len(t) == 0: 1084c3b5a48SBlue Swirl break 1094c3b5a48SBlue Swirl 1107f1b588fSDaniel P. Berrange (rectype, ) = struct.unpack('=Q', t) 1117f1b588fSDaniel P. Berrange if rectype == record_type_mapping: 1127f1b588fSDaniel P. Berrange event_id, name = get_mapping(fobj) 1137f1b588fSDaniel P. Berrange idtoname[event_id] = name 1147f1b588fSDaniel P. Berrange else: 1157f1b588fSDaniel P. Berrange rec = read_record(edict, idtoname, fobj) 1167f1b588fSDaniel P. Berrange 1174c3b5a48SBlue Swirl yield rec 1184c3b5a48SBlue Swirl 11959da6684SStefan Hajnocziclass Analyzer(object): 12059da6684SStefan Hajnoczi """A trace file analyzer which processes trace records. 12159da6684SStefan Hajnoczi 12259da6684SStefan Hajnoczi An analyzer can be passed to run() or process(). The begin() method is 12359da6684SStefan Hajnoczi invoked, then each trace record is processed, and finally the end() method 12459da6684SStefan Hajnoczi is invoked. 12559da6684SStefan Hajnoczi 12659da6684SStefan Hajnoczi If a method matching a trace event name exists, it is invoked to process 127659370f7SStefan Hajnoczi that trace record. Otherwise the catchall() method is invoked. 128659370f7SStefan Hajnoczi 129659370f7SStefan Hajnoczi Example: 130659370f7SStefan Hajnoczi The following method handles the runstate_set(int new_state) trace event:: 131659370f7SStefan Hajnoczi 132659370f7SStefan Hajnoczi def runstate_set(self, new_state): 133659370f7SStefan Hajnoczi ... 134659370f7SStefan Hajnoczi 135659370f7SStefan Hajnoczi The method can also take a timestamp argument before the trace event 136659370f7SStefan Hajnoczi arguments:: 137659370f7SStefan Hajnoczi 138659370f7SStefan Hajnoczi def runstate_set(self, timestamp, new_state): 139659370f7SStefan Hajnoczi ... 140659370f7SStefan Hajnoczi 141659370f7SStefan Hajnoczi Timestamps have the uint64_t type and are in nanoseconds. 142659370f7SStefan Hajnoczi 143659370f7SStefan Hajnoczi The pid can be included in addition to the timestamp and is useful when 144659370f7SStefan Hajnoczi dealing with traces from multiple processes:: 145659370f7SStefan Hajnoczi 146659370f7SStefan Hajnoczi def runstate_set(self, timestamp, pid, new_state): 147659370f7SStefan Hajnoczi ... 148659370f7SStefan Hajnoczi """ 14959da6684SStefan Hajnoczi 15059da6684SStefan Hajnoczi def begin(self): 15159da6684SStefan Hajnoczi """Called at the start of the trace.""" 15259da6684SStefan Hajnoczi pass 15359da6684SStefan Hajnoczi 15459da6684SStefan Hajnoczi def catchall(self, event, rec): 15559da6684SStefan Hajnoczi """Called if no specific method for processing a trace event has been found.""" 15659da6684SStefan Hajnoczi pass 15759da6684SStefan Hajnoczi 15859da6684SStefan Hajnoczi def end(self): 15959da6684SStefan Hajnoczi """Called at the end of the trace.""" 16059da6684SStefan Hajnoczi pass 16159da6684SStefan Hajnoczi 16215327c3dSStefan Hajnoczidef process(events, log, analyzer, read_header=True): 16359da6684SStefan Hajnoczi """Invoke an analyzer on each event in a log.""" 16459da6684SStefan Hajnoczi if isinstance(events, str): 165d1b97bceSDaniel P. Berrange events = read_events(open(events, 'r')) 16659da6684SStefan Hajnoczi if isinstance(log, str): 16759da6684SStefan Hajnoczi log = open(log, 'rb') 16859da6684SStefan Hajnoczi 16915327c3dSStefan Hajnoczi if read_header: 17015327c3dSStefan Hajnoczi read_trace_header(log) 17115327c3dSStefan Hajnoczi 17290a147a2SHarsh Prateek Bora dropped_event = Event.build("Dropped_Event(uint64_t num_events_dropped)") 1737f1b588fSDaniel P. Berrange edict = {"dropped": dropped_event} 17490a147a2SHarsh Prateek Bora 1757f1b588fSDaniel P. Berrange for event in events: 1767f1b588fSDaniel P. Berrange edict[event.name] = event 17790a147a2SHarsh Prateek Bora 17859da6684SStefan Hajnoczi def build_fn(analyzer, event): 17990a147a2SHarsh Prateek Bora if isinstance(event, str): 18090a147a2SHarsh Prateek Bora return analyzer.catchall 18190a147a2SHarsh Prateek Bora 18290a147a2SHarsh Prateek Bora fn = getattr(analyzer, event.name, None) 18359da6684SStefan Hajnoczi if fn is None: 18459da6684SStefan Hajnoczi return analyzer.catchall 18559da6684SStefan Hajnoczi 18690a147a2SHarsh Prateek Bora event_argcount = len(event.args) 18759da6684SStefan Hajnoczi fn_argcount = len(inspect.getargspec(fn)[0]) - 1 18859da6684SStefan Hajnoczi if fn_argcount == event_argcount + 1: 18959da6684SStefan Hajnoczi # Include timestamp as first argument 19080ff35cdSStefan Hajnoczi return lambda _, rec: fn(*((rec[1:2],) + rec[3:3 + event_argcount])) 19180ff35cdSStefan Hajnoczi elif fn_argcount == event_argcount + 2: 19280ff35cdSStefan Hajnoczi # Include timestamp and pid 19380ff35cdSStefan Hajnoczi return lambda _, rec: fn(*rec[1:3 + event_argcount]) 19459da6684SStefan Hajnoczi else: 19580ff35cdSStefan Hajnoczi # Just arguments, no timestamp or pid 19680ff35cdSStefan Hajnoczi return lambda _, rec: fn(*rec[3:3 + event_argcount]) 19759da6684SStefan Hajnoczi 19859da6684SStefan Hajnoczi analyzer.begin() 19959da6684SStefan Hajnoczi fn_cache = {} 20015327c3dSStefan Hajnoczi for rec in read_trace_records(edict, log): 20159da6684SStefan Hajnoczi event_num = rec[0] 20290a147a2SHarsh Prateek Bora event = edict[event_num] 20359da6684SStefan Hajnoczi if event_num not in fn_cache: 20459da6684SStefan Hajnoczi fn_cache[event_num] = build_fn(analyzer, event) 20559da6684SStefan Hajnoczi fn_cache[event_num](event, rec) 20659da6684SStefan Hajnoczi analyzer.end() 20759da6684SStefan Hajnoczi 20859da6684SStefan Hajnoczidef run(analyzer): 20959da6684SStefan Hajnoczi """Execute an analyzer on a trace file given on the command-line. 21059da6684SStefan Hajnoczi 21159da6684SStefan Hajnoczi This function is useful as a driver for simple analysis scripts. More 21259da6684SStefan Hajnoczi advanced scripts will want to call process() instead.""" 21359da6684SStefan Hajnoczi import sys 21459da6684SStefan Hajnoczi 21515327c3dSStefan Hajnoczi read_header = True 21615327c3dSStefan Hajnoczi if len(sys.argv) == 4 and sys.argv[1] == '--no-header': 21715327c3dSStefan Hajnoczi read_header = False 21815327c3dSStefan Hajnoczi del sys.argv[1] 21915327c3dSStefan Hajnoczi elif len(sys.argv) != 3: 22015327c3dSStefan Hajnoczi sys.stderr.write('usage: %s [--no-header] <trace-events> ' \ 22115327c3dSStefan Hajnoczi '<trace-file>\n' % sys.argv[0]) 22259da6684SStefan Hajnoczi sys.exit(1) 22359da6684SStefan Hajnoczi 224d1b97bceSDaniel P. Berrange events = read_events(open(sys.argv[1], 'r')) 22515327c3dSStefan Hajnoczi process(events, sys.argv[2], analyzer, read_header=read_header) 22659da6684SStefan Hajnoczi 22759da6684SStefan Hajnocziif __name__ == '__main__': 22859da6684SStefan Hajnoczi class Formatter(Analyzer): 22959da6684SStefan Hajnoczi def __init__(self): 2304c3b5a48SBlue Swirl self.last_timestamp = None 2314c3b5a48SBlue Swirl 23259da6684SStefan Hajnoczi def catchall(self, event, rec): 23359da6684SStefan Hajnoczi timestamp = rec[1] 2344c3b5a48SBlue Swirl if self.last_timestamp is None: 23559da6684SStefan Hajnoczi self.last_timestamp = timestamp 23659da6684SStefan Hajnoczi delta_ns = timestamp - self.last_timestamp 23759da6684SStefan Hajnoczi self.last_timestamp = timestamp 2384c3b5a48SBlue Swirl 23980ff35cdSStefan Hajnoczi fields = [event.name, '%0.3f' % (delta_ns / 1000.0), 24080ff35cdSStefan Hajnoczi 'pid=%d' % rec[2]] 24180ff35cdSStefan Hajnoczi i = 3 24290a147a2SHarsh Prateek Bora for type, name in event.args: 24390a147a2SHarsh Prateek Bora if is_string(type): 24480ff35cdSStefan Hajnoczi fields.append('%s=%s' % (name, rec[i])) 24590a147a2SHarsh Prateek Bora else: 24680ff35cdSStefan Hajnoczi fields.append('%s=0x%x' % (name, rec[i])) 24790a147a2SHarsh Prateek Bora i += 1 24859da6684SStefan Hajnoczi print ' '.join(fields) 2494c3b5a48SBlue Swirl 25059da6684SStefan Hajnoczi run(Formatter()) 251