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 15*d1b97bceSDaniel 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]) 457f1b588fSDaniel P. Berrange event = edict[name] 4690a147a2SHarsh Prateek Bora for type, name in event.args: 4790a147a2SHarsh Prateek Bora if is_string(type): 4890a147a2SHarsh Prateek Bora l = fobj.read(4) 4990a147a2SHarsh Prateek Bora (len,) = struct.unpack('=L', l) 5090a147a2SHarsh Prateek Bora s = fobj.read(len) 5190a147a2SHarsh Prateek Bora rec = rec + (s,) 5290a147a2SHarsh Prateek Bora else: 5390a147a2SHarsh Prateek Bora (value,) = struct.unpack('=Q', fobj.read(8)) 5490a147a2SHarsh Prateek Bora rec = rec + (value,) 5590a147a2SHarsh Prateek Bora else: 567f1b588fSDaniel P. Berrange rec = ("dropped", rechdr[1], rechdr[3]) 5790a147a2SHarsh Prateek Bora (value,) = struct.unpack('=Q', fobj.read(8)) 5890a147a2SHarsh Prateek Bora rec = rec + (value,) 5990a147a2SHarsh Prateek Bora return rec 6090a147a2SHarsh Prateek Bora 617f1b588fSDaniel P. Berrangedef get_mapping(fobj): 627f1b588fSDaniel P. Berrange (event_id, ) = struct.unpack('=Q', fobj.read(8)) 637f1b588fSDaniel P. Berrange (len, ) = struct.unpack('=L', fobj.read(4)) 647f1b588fSDaniel P. Berrange name = fobj.read(len) 6590a147a2SHarsh Prateek Bora 667f1b588fSDaniel P. Berrange return (event_id, name) 677f1b588fSDaniel P. Berrange 687f1b588fSDaniel P. Berrangedef read_record(edict, idtoname, fobj): 6980ff35cdSStefan Hajnoczi """Deserialize a trace record from a file into a tuple (event_num, timestamp, pid, arg1, ..., arg6).""" 7090a147a2SHarsh Prateek Bora rechdr = read_header(fobj, rec_header_fmt) 717f1b588fSDaniel P. Berrange return get_record(edict, idtoname, rechdr, fobj) 7290a147a2SHarsh Prateek Bora 7315327c3dSStefan Hajnoczidef read_trace_header(fobj): 7415327c3dSStefan Hajnoczi """Read and verify trace file header""" 7590a147a2SHarsh Prateek Bora header = read_header(fobj, log_header_fmt) 764c3b5a48SBlue Swirl if header is None or \ 774c3b5a48SBlue Swirl header[0] != header_event_id or \ 7890a147a2SHarsh Prateek Bora header[1] != header_magic: 7990a147a2SHarsh Prateek Bora raise ValueError('Not a valid trace file!') 8090a147a2SHarsh Prateek Bora 8190a147a2SHarsh Prateek Bora log_version = header[2] 827f1b588fSDaniel P. Berrange if log_version not in [0, 2, 3, 4]: 83ef0bd3bbSLluís Vilanova raise ValueError('Unknown version of tracelog format!') 847f1b588fSDaniel P. Berrange if log_version != 4: 85ef0bd3bbSLluís Vilanova raise ValueError('Log format %d not supported with this QEMU release!' 86ef0bd3bbSLluís Vilanova % log_version) 874c3b5a48SBlue Swirl 8815327c3dSStefan Hajnoczidef read_trace_records(edict, fobj): 8915327c3dSStefan Hajnoczi """Deserialize trace records from a file, yielding record tuples (event_num, timestamp, pid, arg1, ..., arg6).""" 907f1b588fSDaniel P. Berrange idtoname = { 917f1b588fSDaniel P. Berrange dropped_event_id: "dropped" 927f1b588fSDaniel P. Berrange } 934c3b5a48SBlue Swirl while True: 947f1b588fSDaniel P. Berrange t = fobj.read(8) 957f1b588fSDaniel P. Berrange if len(t) == 0: 964c3b5a48SBlue Swirl break 974c3b5a48SBlue Swirl 987f1b588fSDaniel P. Berrange (rectype, ) = struct.unpack('=Q', t) 997f1b588fSDaniel P. Berrange if rectype == record_type_mapping: 1007f1b588fSDaniel P. Berrange event_id, name = get_mapping(fobj) 1017f1b588fSDaniel P. Berrange idtoname[event_id] = name 1027f1b588fSDaniel P. Berrange else: 1037f1b588fSDaniel P. Berrange rec = read_record(edict, idtoname, fobj) 1047f1b588fSDaniel P. Berrange 1054c3b5a48SBlue Swirl yield rec 1064c3b5a48SBlue Swirl 10759da6684SStefan Hajnocziclass Analyzer(object): 10859da6684SStefan Hajnoczi """A trace file analyzer which processes trace records. 10959da6684SStefan Hajnoczi 11059da6684SStefan Hajnoczi An analyzer can be passed to run() or process(). The begin() method is 11159da6684SStefan Hajnoczi invoked, then each trace record is processed, and finally the end() method 11259da6684SStefan Hajnoczi is invoked. 11359da6684SStefan Hajnoczi 11459da6684SStefan Hajnoczi If a method matching a trace event name exists, it is invoked to process 11559da6684SStefan Hajnoczi that trace record. Otherwise the catchall() method is invoked.""" 11659da6684SStefan Hajnoczi 11759da6684SStefan Hajnoczi def begin(self): 11859da6684SStefan Hajnoczi """Called at the start of the trace.""" 11959da6684SStefan Hajnoczi pass 12059da6684SStefan Hajnoczi 12159da6684SStefan Hajnoczi def catchall(self, event, rec): 12259da6684SStefan Hajnoczi """Called if no specific method for processing a trace event has been found.""" 12359da6684SStefan Hajnoczi pass 12459da6684SStefan Hajnoczi 12559da6684SStefan Hajnoczi def end(self): 12659da6684SStefan Hajnoczi """Called at the end of the trace.""" 12759da6684SStefan Hajnoczi pass 12859da6684SStefan Hajnoczi 12915327c3dSStefan Hajnoczidef process(events, log, analyzer, read_header=True): 13059da6684SStefan Hajnoczi """Invoke an analyzer on each event in a log.""" 13159da6684SStefan Hajnoczi if isinstance(events, str): 132*d1b97bceSDaniel P. Berrange events = read_events(open(events, 'r')) 13359da6684SStefan Hajnoczi if isinstance(log, str): 13459da6684SStefan Hajnoczi log = open(log, 'rb') 13559da6684SStefan Hajnoczi 13615327c3dSStefan Hajnoczi if read_header: 13715327c3dSStefan Hajnoczi read_trace_header(log) 13815327c3dSStefan Hajnoczi 13990a147a2SHarsh Prateek Bora dropped_event = Event.build("Dropped_Event(uint64_t num_events_dropped)") 1407f1b588fSDaniel P. Berrange edict = {"dropped": dropped_event} 14190a147a2SHarsh Prateek Bora 1427f1b588fSDaniel P. Berrange for event in events: 1437f1b588fSDaniel P. Berrange edict[event.name] = event 14490a147a2SHarsh Prateek Bora 14559da6684SStefan Hajnoczi def build_fn(analyzer, event): 14690a147a2SHarsh Prateek Bora if isinstance(event, str): 14790a147a2SHarsh Prateek Bora return analyzer.catchall 14890a147a2SHarsh Prateek Bora 14990a147a2SHarsh Prateek Bora fn = getattr(analyzer, event.name, None) 15059da6684SStefan Hajnoczi if fn is None: 15159da6684SStefan Hajnoczi return analyzer.catchall 15259da6684SStefan Hajnoczi 15390a147a2SHarsh Prateek Bora event_argcount = len(event.args) 15459da6684SStefan Hajnoczi fn_argcount = len(inspect.getargspec(fn)[0]) - 1 15559da6684SStefan Hajnoczi if fn_argcount == event_argcount + 1: 15659da6684SStefan Hajnoczi # Include timestamp as first argument 15780ff35cdSStefan Hajnoczi return lambda _, rec: fn(*((rec[1:2],) + rec[3:3 + event_argcount])) 15880ff35cdSStefan Hajnoczi elif fn_argcount == event_argcount + 2: 15980ff35cdSStefan Hajnoczi # Include timestamp and pid 16080ff35cdSStefan Hajnoczi return lambda _, rec: fn(*rec[1:3 + event_argcount]) 16159da6684SStefan Hajnoczi else: 16280ff35cdSStefan Hajnoczi # Just arguments, no timestamp or pid 16380ff35cdSStefan Hajnoczi return lambda _, rec: fn(*rec[3:3 + event_argcount]) 16459da6684SStefan Hajnoczi 16559da6684SStefan Hajnoczi analyzer.begin() 16659da6684SStefan Hajnoczi fn_cache = {} 16715327c3dSStefan Hajnoczi for rec in read_trace_records(edict, log): 16859da6684SStefan Hajnoczi event_num = rec[0] 16990a147a2SHarsh Prateek Bora event = edict[event_num] 17059da6684SStefan Hajnoczi if event_num not in fn_cache: 17159da6684SStefan Hajnoczi fn_cache[event_num] = build_fn(analyzer, event) 17259da6684SStefan Hajnoczi fn_cache[event_num](event, rec) 17359da6684SStefan Hajnoczi analyzer.end() 17459da6684SStefan Hajnoczi 17559da6684SStefan Hajnoczidef run(analyzer): 17659da6684SStefan Hajnoczi """Execute an analyzer on a trace file given on the command-line. 17759da6684SStefan Hajnoczi 17859da6684SStefan Hajnoczi This function is useful as a driver for simple analysis scripts. More 17959da6684SStefan Hajnoczi advanced scripts will want to call process() instead.""" 18059da6684SStefan Hajnoczi import sys 18159da6684SStefan Hajnoczi 18215327c3dSStefan Hajnoczi read_header = True 18315327c3dSStefan Hajnoczi if len(sys.argv) == 4 and sys.argv[1] == '--no-header': 18415327c3dSStefan Hajnoczi read_header = False 18515327c3dSStefan Hajnoczi del sys.argv[1] 18615327c3dSStefan Hajnoczi elif len(sys.argv) != 3: 18715327c3dSStefan Hajnoczi sys.stderr.write('usage: %s [--no-header] <trace-events> ' \ 18815327c3dSStefan Hajnoczi '<trace-file>\n' % sys.argv[0]) 18959da6684SStefan Hajnoczi sys.exit(1) 19059da6684SStefan Hajnoczi 191*d1b97bceSDaniel P. Berrange events = read_events(open(sys.argv[1], 'r')) 19215327c3dSStefan Hajnoczi process(events, sys.argv[2], analyzer, read_header=read_header) 19359da6684SStefan Hajnoczi 19459da6684SStefan Hajnocziif __name__ == '__main__': 19559da6684SStefan Hajnoczi class Formatter(Analyzer): 19659da6684SStefan Hajnoczi def __init__(self): 1974c3b5a48SBlue Swirl self.last_timestamp = None 1984c3b5a48SBlue Swirl 19959da6684SStefan Hajnoczi def catchall(self, event, rec): 20059da6684SStefan Hajnoczi timestamp = rec[1] 2014c3b5a48SBlue Swirl if self.last_timestamp is None: 20259da6684SStefan Hajnoczi self.last_timestamp = timestamp 20359da6684SStefan Hajnoczi delta_ns = timestamp - self.last_timestamp 20459da6684SStefan Hajnoczi self.last_timestamp = timestamp 2054c3b5a48SBlue Swirl 20680ff35cdSStefan Hajnoczi fields = [event.name, '%0.3f' % (delta_ns / 1000.0), 20780ff35cdSStefan Hajnoczi 'pid=%d' % rec[2]] 20880ff35cdSStefan Hajnoczi i = 3 20990a147a2SHarsh Prateek Bora for type, name in event.args: 21090a147a2SHarsh Prateek Bora if is_string(type): 21180ff35cdSStefan Hajnoczi fields.append('%s=%s' % (name, rec[i])) 21290a147a2SHarsh Prateek Bora else: 21380ff35cdSStefan Hajnoczi fields.append('%s=0x%x' % (name, rec[i])) 21490a147a2SHarsh Prateek Bora i += 1 21559da6684SStefan Hajnoczi print ' '.join(fields) 2164c3b5a48SBlue Swirl 21759da6684SStefan Hajnoczi run(Formatter()) 218