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 1590a147a2SHarsh Prateek Borafrom 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 2290a147a2SHarsh Prateek Boralog_header_fmt = '=QQQ' 2390a147a2SHarsh Prateek Borarec_header_fmt = '=QQII' 244c3b5a48SBlue Swirl 2590a147a2SHarsh Prateek Boradef read_header(fobj, hfmt): 2690a147a2SHarsh Prateek Bora '''Read a trace record header''' 2790a147a2SHarsh Prateek Bora hlen = struct.calcsize(hfmt) 2890a147a2SHarsh Prateek Bora hdr = fobj.read(hlen) 2990a147a2SHarsh Prateek Bora if len(hdr) != hlen: 304c3b5a48SBlue Swirl return None 3190a147a2SHarsh Prateek Bora return struct.unpack(hfmt, hdr) 324c3b5a48SBlue Swirl 3390a147a2SHarsh Prateek Boradef get_record(edict, rechdr, fobj): 34*80ff35cdSStefan Hajnoczi """Deserialize a trace record from a file into a tuple (event_num, timestamp, pid, arg1, ..., arg6).""" 3590a147a2SHarsh Prateek Bora if rechdr is None: 3690a147a2SHarsh Prateek Bora return None 37*80ff35cdSStefan Hajnoczi rec = (rechdr[0], rechdr[1], rechdr[3]) 3890a147a2SHarsh Prateek Bora if rechdr[0] != dropped_event_id: 3990a147a2SHarsh Prateek Bora event_id = rechdr[0] 4090a147a2SHarsh Prateek Bora event = edict[event_id] 4190a147a2SHarsh Prateek Bora for type, name in event.args: 4290a147a2SHarsh Prateek Bora if is_string(type): 4390a147a2SHarsh Prateek Bora l = fobj.read(4) 4490a147a2SHarsh Prateek Bora (len,) = struct.unpack('=L', l) 4590a147a2SHarsh Prateek Bora s = fobj.read(len) 4690a147a2SHarsh Prateek Bora rec = rec + (s,) 4790a147a2SHarsh Prateek Bora else: 4890a147a2SHarsh Prateek Bora (value,) = struct.unpack('=Q', fobj.read(8)) 4990a147a2SHarsh Prateek Bora rec = rec + (value,) 5090a147a2SHarsh Prateek Bora else: 5190a147a2SHarsh Prateek Bora (value,) = struct.unpack('=Q', fobj.read(8)) 5290a147a2SHarsh Prateek Bora rec = rec + (value,) 5390a147a2SHarsh Prateek Bora return rec 5490a147a2SHarsh Prateek Bora 5590a147a2SHarsh Prateek Bora 5690a147a2SHarsh Prateek Boradef read_record(edict, fobj): 57*80ff35cdSStefan Hajnoczi """Deserialize a trace record from a file into a tuple (event_num, timestamp, pid, arg1, ..., arg6).""" 5890a147a2SHarsh Prateek Bora rechdr = read_header(fobj, rec_header_fmt) 5990a147a2SHarsh Prateek Bora return get_record(edict, rechdr, fobj) # return tuple of record elements 6090a147a2SHarsh Prateek Bora 6190a147a2SHarsh Prateek Boradef read_trace_file(edict, fobj): 62*80ff35cdSStefan Hajnoczi """Deserialize trace records from a file, yielding record tuples (event_num, timestamp, pid, arg1, ..., arg6).""" 6390a147a2SHarsh Prateek Bora header = read_header(fobj, log_header_fmt) 644c3b5a48SBlue Swirl if header is None or \ 654c3b5a48SBlue Swirl header[0] != header_event_id or \ 6690a147a2SHarsh Prateek Bora header[1] != header_magic: 6790a147a2SHarsh Prateek Bora raise ValueError('Not a valid trace file!') 6890a147a2SHarsh Prateek Bora 6990a147a2SHarsh Prateek Bora log_version = header[2] 70ef0bd3bbSLluís Vilanova if log_version not in [0, 2, 3]: 71ef0bd3bbSLluís Vilanova raise ValueError('Unknown version of tracelog format!') 72ef0bd3bbSLluís Vilanova if log_version != 3: 73ef0bd3bbSLluís Vilanova raise ValueError('Log format %d not supported with this QEMU release!' 74ef0bd3bbSLluís Vilanova % log_version) 754c3b5a48SBlue Swirl 764c3b5a48SBlue Swirl while True: 7790a147a2SHarsh Prateek Bora rec = read_record(edict, fobj) 784c3b5a48SBlue Swirl if rec is None: 794c3b5a48SBlue Swirl break 804c3b5a48SBlue Swirl 814c3b5a48SBlue Swirl yield rec 824c3b5a48SBlue Swirl 8359da6684SStefan Hajnocziclass Analyzer(object): 8459da6684SStefan Hajnoczi """A trace file analyzer which processes trace records. 8559da6684SStefan Hajnoczi 8659da6684SStefan Hajnoczi An analyzer can be passed to run() or process(). The begin() method is 8759da6684SStefan Hajnoczi invoked, then each trace record is processed, and finally the end() method 8859da6684SStefan Hajnoczi is invoked. 8959da6684SStefan Hajnoczi 9059da6684SStefan Hajnoczi If a method matching a trace event name exists, it is invoked to process 9159da6684SStefan Hajnoczi that trace record. Otherwise the catchall() method is invoked.""" 9259da6684SStefan Hajnoczi 9359da6684SStefan Hajnoczi def begin(self): 9459da6684SStefan Hajnoczi """Called at the start of the trace.""" 9559da6684SStefan Hajnoczi pass 9659da6684SStefan Hajnoczi 9759da6684SStefan Hajnoczi def catchall(self, event, rec): 9859da6684SStefan Hajnoczi """Called if no specific method for processing a trace event has been found.""" 9959da6684SStefan Hajnoczi pass 10059da6684SStefan Hajnoczi 10159da6684SStefan Hajnoczi def end(self): 10259da6684SStefan Hajnoczi """Called at the end of the trace.""" 10359da6684SStefan Hajnoczi pass 10459da6684SStefan Hajnoczi 10559da6684SStefan Hajnoczidef process(events, log, analyzer): 10659da6684SStefan Hajnoczi """Invoke an analyzer on each event in a log.""" 10759da6684SStefan Hajnoczi if isinstance(events, str): 10890a147a2SHarsh Prateek Bora events = _read_events(open(events, 'r')) 10959da6684SStefan Hajnoczi if isinstance(log, str): 11059da6684SStefan Hajnoczi log = open(log, 'rb') 11159da6684SStefan Hajnoczi 11290a147a2SHarsh Prateek Bora dropped_event = Event.build("Dropped_Event(uint64_t num_events_dropped)") 11390a147a2SHarsh Prateek Bora edict = {dropped_event_id: dropped_event} 11490a147a2SHarsh Prateek Bora 1151dad2ce9SLluís Vilanova for num, event in enumerate(events): 11690a147a2SHarsh Prateek Bora edict[num] = event 11790a147a2SHarsh Prateek Bora 11859da6684SStefan Hajnoczi def build_fn(analyzer, event): 11990a147a2SHarsh Prateek Bora if isinstance(event, str): 12090a147a2SHarsh Prateek Bora return analyzer.catchall 12190a147a2SHarsh Prateek Bora 12290a147a2SHarsh Prateek Bora fn = getattr(analyzer, event.name, None) 12359da6684SStefan Hajnoczi if fn is None: 12459da6684SStefan Hajnoczi return analyzer.catchall 12559da6684SStefan Hajnoczi 12690a147a2SHarsh Prateek Bora event_argcount = len(event.args) 12759da6684SStefan Hajnoczi fn_argcount = len(inspect.getargspec(fn)[0]) - 1 12859da6684SStefan Hajnoczi if fn_argcount == event_argcount + 1: 12959da6684SStefan Hajnoczi # Include timestamp as first argument 130*80ff35cdSStefan Hajnoczi return lambda _, rec: fn(*((rec[1:2],) + rec[3:3 + event_argcount])) 131*80ff35cdSStefan Hajnoczi elif fn_argcount == event_argcount + 2: 132*80ff35cdSStefan Hajnoczi # Include timestamp and pid 133*80ff35cdSStefan Hajnoczi return lambda _, rec: fn(*rec[1:3 + event_argcount]) 13459da6684SStefan Hajnoczi else: 135*80ff35cdSStefan Hajnoczi # Just arguments, no timestamp or pid 136*80ff35cdSStefan Hajnoczi return lambda _, rec: fn(*rec[3:3 + event_argcount]) 13759da6684SStefan Hajnoczi 13859da6684SStefan Hajnoczi analyzer.begin() 13959da6684SStefan Hajnoczi fn_cache = {} 14090a147a2SHarsh Prateek Bora for rec in read_trace_file(edict, log): 14159da6684SStefan Hajnoczi event_num = rec[0] 14290a147a2SHarsh Prateek Bora event = edict[event_num] 14359da6684SStefan Hajnoczi if event_num not in fn_cache: 14459da6684SStefan Hajnoczi fn_cache[event_num] = build_fn(analyzer, event) 14559da6684SStefan Hajnoczi fn_cache[event_num](event, rec) 14659da6684SStefan Hajnoczi analyzer.end() 14759da6684SStefan Hajnoczi 14859da6684SStefan Hajnoczidef run(analyzer): 14959da6684SStefan Hajnoczi """Execute an analyzer on a trace file given on the command-line. 15059da6684SStefan Hajnoczi 15159da6684SStefan Hajnoczi This function is useful as a driver for simple analysis scripts. More 15259da6684SStefan Hajnoczi advanced scripts will want to call process() instead.""" 15359da6684SStefan Hajnoczi import sys 15459da6684SStefan Hajnoczi 15559da6684SStefan Hajnoczi if len(sys.argv) != 3: 15659da6684SStefan Hajnoczi sys.stderr.write('usage: %s <trace-events> <trace-file>\n' % sys.argv[0]) 15759da6684SStefan Hajnoczi sys.exit(1) 15859da6684SStefan Hajnoczi 15990a147a2SHarsh Prateek Bora events = _read_events(open(sys.argv[1], 'r')) 16059da6684SStefan Hajnoczi process(events, sys.argv[2], analyzer) 16159da6684SStefan Hajnoczi 16259da6684SStefan Hajnocziif __name__ == '__main__': 16359da6684SStefan Hajnoczi class Formatter(Analyzer): 16459da6684SStefan Hajnoczi def __init__(self): 1654c3b5a48SBlue Swirl self.last_timestamp = None 1664c3b5a48SBlue Swirl 16759da6684SStefan Hajnoczi def catchall(self, event, rec): 16859da6684SStefan Hajnoczi timestamp = rec[1] 1694c3b5a48SBlue Swirl if self.last_timestamp is None: 17059da6684SStefan Hajnoczi self.last_timestamp = timestamp 17159da6684SStefan Hajnoczi delta_ns = timestamp - self.last_timestamp 17259da6684SStefan Hajnoczi self.last_timestamp = timestamp 1734c3b5a48SBlue Swirl 174*80ff35cdSStefan Hajnoczi fields = [event.name, '%0.3f' % (delta_ns / 1000.0), 175*80ff35cdSStefan Hajnoczi 'pid=%d' % rec[2]] 176*80ff35cdSStefan Hajnoczi i = 3 17790a147a2SHarsh Prateek Bora for type, name in event.args: 17890a147a2SHarsh Prateek Bora if is_string(type): 179*80ff35cdSStefan Hajnoczi fields.append('%s=%s' % (name, rec[i])) 18090a147a2SHarsh Prateek Bora else: 181*80ff35cdSStefan Hajnoczi fields.append('%s=0x%x' % (name, rec[i])) 18290a147a2SHarsh Prateek Bora i += 1 18359da6684SStefan Hajnoczi print ' '.join(fields) 1844c3b5a48SBlue Swirl 18559da6684SStefan Hajnoczi run(Formatter()) 186