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# 1087e0331cSPhilippe Mathieu-Daudé# For help see docs/devel/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]) 45249e9f79SJose Ricardo Ziviani try: 467f1b588fSDaniel P. Berrange event = edict[name] 47249e9f79SJose Ricardo Ziviani except KeyError, e: 48249e9f79SJose Ricardo Ziviani import sys 49249e9f79SJose Ricardo Ziviani sys.stderr.write('%s event is logged but is not declared ' \ 50249e9f79SJose Ricardo Ziviani 'in the trace events file, try using ' \ 51249e9f79SJose Ricardo Ziviani 'trace-events-all instead.\n' % str(e)) 52249e9f79SJose Ricardo Ziviani sys.exit(1) 53249e9f79SJose 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 100840d8351SStefan Hajnoczidef read_trace_records(edict, idtoname, fobj): 101840d8351SStefan Hajnoczi """Deserialize trace records from a file, yielding record tuples (event_num, timestamp, pid, arg1, ..., arg6). 102840d8351SStefan Hajnoczi 103840d8351SStefan Hajnoczi Note that `idtoname` is modified if the file contains mapping records. 104840d8351SStefan Hajnoczi 105840d8351SStefan Hajnoczi Args: 106840d8351SStefan Hajnoczi edict (str -> Event): events dict, indexed by name 107840d8351SStefan Hajnoczi idtoname (int -> str): event names dict, indexed by event ID 108840d8351SStefan Hajnoczi fobj (file): input file 109840d8351SStefan Hajnoczi 110840d8351SStefan Hajnoczi """ 1114c3b5a48SBlue Swirl while True: 1127f1b588fSDaniel P. Berrange t = fobj.read(8) 1137f1b588fSDaniel P. Berrange if len(t) == 0: 1144c3b5a48SBlue Swirl break 1154c3b5a48SBlue Swirl 1167f1b588fSDaniel P. Berrange (rectype, ) = struct.unpack('=Q', t) 1177f1b588fSDaniel P. Berrange if rectype == record_type_mapping: 1187f1b588fSDaniel P. Berrange event_id, name = get_mapping(fobj) 1197f1b588fSDaniel P. Berrange idtoname[event_id] = name 1207f1b588fSDaniel P. Berrange else: 1217f1b588fSDaniel P. Berrange rec = read_record(edict, idtoname, fobj) 1227f1b588fSDaniel P. Berrange 1234c3b5a48SBlue Swirl yield rec 1244c3b5a48SBlue Swirl 12559da6684SStefan Hajnocziclass Analyzer(object): 12659da6684SStefan Hajnoczi """A trace file analyzer which processes trace records. 12759da6684SStefan Hajnoczi 12859da6684SStefan Hajnoczi An analyzer can be passed to run() or process(). The begin() method is 12959da6684SStefan Hajnoczi invoked, then each trace record is processed, and finally the end() method 13059da6684SStefan Hajnoczi is invoked. 13159da6684SStefan Hajnoczi 13259da6684SStefan Hajnoczi If a method matching a trace event name exists, it is invoked to process 133659370f7SStefan Hajnoczi that trace record. Otherwise the catchall() method is invoked. 134659370f7SStefan Hajnoczi 135659370f7SStefan Hajnoczi Example: 136659370f7SStefan Hajnoczi The following method handles the runstate_set(int new_state) trace event:: 137659370f7SStefan Hajnoczi 138659370f7SStefan Hajnoczi def runstate_set(self, new_state): 139659370f7SStefan Hajnoczi ... 140659370f7SStefan Hajnoczi 141659370f7SStefan Hajnoczi The method can also take a timestamp argument before the trace event 142659370f7SStefan Hajnoczi arguments:: 143659370f7SStefan Hajnoczi 144659370f7SStefan Hajnoczi def runstate_set(self, timestamp, new_state): 145659370f7SStefan Hajnoczi ... 146659370f7SStefan Hajnoczi 147659370f7SStefan Hajnoczi Timestamps have the uint64_t type and are in nanoseconds. 148659370f7SStefan Hajnoczi 149659370f7SStefan Hajnoczi The pid can be included in addition to the timestamp and is useful when 150659370f7SStefan Hajnoczi dealing with traces from multiple processes:: 151659370f7SStefan Hajnoczi 152659370f7SStefan Hajnoczi def runstate_set(self, timestamp, pid, new_state): 153659370f7SStefan Hajnoczi ... 154659370f7SStefan Hajnoczi """ 15559da6684SStefan Hajnoczi 15659da6684SStefan Hajnoczi def begin(self): 15759da6684SStefan Hajnoczi """Called at the start of the trace.""" 15859da6684SStefan Hajnoczi pass 15959da6684SStefan Hajnoczi 16059da6684SStefan Hajnoczi def catchall(self, event, rec): 16159da6684SStefan Hajnoczi """Called if no specific method for processing a trace event has been found.""" 16259da6684SStefan Hajnoczi pass 16359da6684SStefan Hajnoczi 16459da6684SStefan Hajnoczi def end(self): 16559da6684SStefan Hajnoczi """Called at the end of the trace.""" 16659da6684SStefan Hajnoczi pass 16759da6684SStefan Hajnoczi 16815327c3dSStefan Hajnoczidef process(events, log, analyzer, read_header=True): 16959da6684SStefan Hajnoczi """Invoke an analyzer on each event in a log.""" 17059da6684SStefan Hajnoczi if isinstance(events, str): 171d1b97bceSDaniel P. Berrange events = read_events(open(events, 'r')) 17259da6684SStefan Hajnoczi if isinstance(log, str): 17359da6684SStefan Hajnoczi log = open(log, 'rb') 17459da6684SStefan Hajnoczi 17515327c3dSStefan Hajnoczi if read_header: 17615327c3dSStefan Hajnoczi read_trace_header(log) 17715327c3dSStefan Hajnoczi 17890a147a2SHarsh Prateek Bora dropped_event = Event.build("Dropped_Event(uint64_t num_events_dropped)") 1797f1b588fSDaniel P. Berrange edict = {"dropped": dropped_event} 180840d8351SStefan Hajnoczi idtoname = {dropped_event_id: "dropped"} 18190a147a2SHarsh Prateek Bora 1827f1b588fSDaniel P. Berrange for event in events: 1837f1b588fSDaniel P. Berrange edict[event.name] = event 18490a147a2SHarsh Prateek Bora 185840d8351SStefan Hajnoczi # If there is no header assume event ID mapping matches events list 186840d8351SStefan Hajnoczi if not read_header: 187840d8351SStefan Hajnoczi for event_id, event in enumerate(events): 188840d8351SStefan Hajnoczi idtoname[event_id] = event.name 189840d8351SStefan Hajnoczi 19059da6684SStefan Hajnoczi def build_fn(analyzer, event): 19190a147a2SHarsh Prateek Bora if isinstance(event, str): 19290a147a2SHarsh Prateek Bora return analyzer.catchall 19390a147a2SHarsh Prateek Bora 19490a147a2SHarsh Prateek Bora fn = getattr(analyzer, event.name, None) 19559da6684SStefan Hajnoczi if fn is None: 19659da6684SStefan Hajnoczi return analyzer.catchall 19759da6684SStefan Hajnoczi 19890a147a2SHarsh Prateek Bora event_argcount = len(event.args) 19959da6684SStefan Hajnoczi fn_argcount = len(inspect.getargspec(fn)[0]) - 1 20059da6684SStefan Hajnoczi if fn_argcount == event_argcount + 1: 20159da6684SStefan Hajnoczi # Include timestamp as first argument 202*e42860aeSStefan Hajnoczi return lambda _, rec: fn(*(rec[1:2] + rec[3:3 + event_argcount])) 20380ff35cdSStefan Hajnoczi elif fn_argcount == event_argcount + 2: 20480ff35cdSStefan Hajnoczi # Include timestamp and pid 20580ff35cdSStefan Hajnoczi return lambda _, rec: fn(*rec[1:3 + event_argcount]) 20659da6684SStefan Hajnoczi else: 20780ff35cdSStefan Hajnoczi # Just arguments, no timestamp or pid 20880ff35cdSStefan Hajnoczi return lambda _, rec: fn(*rec[3:3 + event_argcount]) 20959da6684SStefan Hajnoczi 21059da6684SStefan Hajnoczi analyzer.begin() 21159da6684SStefan Hajnoczi fn_cache = {} 212840d8351SStefan Hajnoczi for rec in read_trace_records(edict, idtoname, log): 21359da6684SStefan Hajnoczi event_num = rec[0] 21490a147a2SHarsh Prateek Bora event = edict[event_num] 21559da6684SStefan Hajnoczi if event_num not in fn_cache: 21659da6684SStefan Hajnoczi fn_cache[event_num] = build_fn(analyzer, event) 21759da6684SStefan Hajnoczi fn_cache[event_num](event, rec) 21859da6684SStefan Hajnoczi analyzer.end() 21959da6684SStefan Hajnoczi 22059da6684SStefan Hajnoczidef run(analyzer): 22159da6684SStefan Hajnoczi """Execute an analyzer on a trace file given on the command-line. 22259da6684SStefan Hajnoczi 22359da6684SStefan Hajnoczi This function is useful as a driver for simple analysis scripts. More 22459da6684SStefan Hajnoczi advanced scripts will want to call process() instead.""" 22559da6684SStefan Hajnoczi import sys 22659da6684SStefan Hajnoczi 22715327c3dSStefan Hajnoczi read_header = True 22815327c3dSStefan Hajnoczi if len(sys.argv) == 4 and sys.argv[1] == '--no-header': 22915327c3dSStefan Hajnoczi read_header = False 23015327c3dSStefan Hajnoczi del sys.argv[1] 23115327c3dSStefan Hajnoczi elif len(sys.argv) != 3: 23215327c3dSStefan Hajnoczi sys.stderr.write('usage: %s [--no-header] <trace-events> ' \ 23315327c3dSStefan Hajnoczi '<trace-file>\n' % sys.argv[0]) 23459da6684SStefan Hajnoczi sys.exit(1) 23559da6684SStefan Hajnoczi 236d1b97bceSDaniel P. Berrange events = read_events(open(sys.argv[1], 'r')) 23715327c3dSStefan Hajnoczi process(events, sys.argv[2], analyzer, read_header=read_header) 23859da6684SStefan Hajnoczi 23959da6684SStefan Hajnocziif __name__ == '__main__': 24059da6684SStefan Hajnoczi class Formatter(Analyzer): 24159da6684SStefan Hajnoczi def __init__(self): 2424c3b5a48SBlue Swirl self.last_timestamp = None 2434c3b5a48SBlue Swirl 24459da6684SStefan Hajnoczi def catchall(self, event, rec): 24559da6684SStefan Hajnoczi timestamp = rec[1] 2464c3b5a48SBlue Swirl if self.last_timestamp is None: 24759da6684SStefan Hajnoczi self.last_timestamp = timestamp 24859da6684SStefan Hajnoczi delta_ns = timestamp - self.last_timestamp 24959da6684SStefan Hajnoczi self.last_timestamp = timestamp 2504c3b5a48SBlue Swirl 25180ff35cdSStefan Hajnoczi fields = [event.name, '%0.3f' % (delta_ns / 1000.0), 25280ff35cdSStefan Hajnoczi 'pid=%d' % rec[2]] 25380ff35cdSStefan Hajnoczi i = 3 25490a147a2SHarsh Prateek Bora for type, name in event.args: 25590a147a2SHarsh Prateek Bora if is_string(type): 25680ff35cdSStefan Hajnoczi fields.append('%s=%s' % (name, rec[i])) 25790a147a2SHarsh Prateek Bora else: 25880ff35cdSStefan Hajnoczi fields.append('%s=0x%x' % (name, rec[i])) 25990a147a2SHarsh Prateek Bora i += 1 26059da6684SStefan Hajnoczi print ' '.join(fields) 2614c3b5a48SBlue Swirl 26259da6684SStefan Hajnoczi run(Formatter()) 263