86b5aacfb9
Improves error messages from:
ValueError: Error on line 72: need more than 1 value to unpack
To
ValueError: Error at /home/berrange/src/virt/qemu/trace-events:72:
need more than 1 value to unpack
Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
Reviewed-by: Philippe Mathieu-Daudé <f4bug@amsat.org>
Message-id: 20180306154650.24075-1-berrange@redhat.com
Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>
263 lines
8.4 KiB
Python
Executable File
263 lines
8.4 KiB
Python
Executable File
#!/usr/bin/env python
|
|
#
|
|
# Pretty-printer for simple trace backend binary trace files
|
|
#
|
|
# Copyright IBM, Corp. 2010
|
|
#
|
|
# This work is licensed under the terms of the GNU GPL, version 2. See
|
|
# the COPYING file in the top-level directory.
|
|
#
|
|
# For help see docs/devel/tracing.txt
|
|
|
|
import struct
|
|
import re
|
|
import inspect
|
|
from tracetool import read_events, Event
|
|
from tracetool.backend.simple import is_string
|
|
|
|
header_event_id = 0xffffffffffffffff
|
|
header_magic = 0xf2b177cb0aa429b4
|
|
dropped_event_id = 0xfffffffffffffffe
|
|
|
|
record_type_mapping = 0
|
|
record_type_event = 1
|
|
|
|
log_header_fmt = '=QQQ'
|
|
rec_header_fmt = '=QQII'
|
|
|
|
def read_header(fobj, hfmt):
|
|
'''Read a trace record header'''
|
|
hlen = struct.calcsize(hfmt)
|
|
hdr = fobj.read(hlen)
|
|
if len(hdr) != hlen:
|
|
return None
|
|
return struct.unpack(hfmt, hdr)
|
|
|
|
def get_record(edict, idtoname, rechdr, fobj):
|
|
"""Deserialize a trace record from a file into a tuple
|
|
(name, timestamp, pid, arg1, ..., arg6)."""
|
|
if rechdr is None:
|
|
return None
|
|
if rechdr[0] != dropped_event_id:
|
|
event_id = rechdr[0]
|
|
name = idtoname[event_id]
|
|
rec = (name, rechdr[1], rechdr[3])
|
|
try:
|
|
event = edict[name]
|
|
except KeyError, e:
|
|
import sys
|
|
sys.stderr.write('%s event is logged but is not declared ' \
|
|
'in the trace events file, try using ' \
|
|
'trace-events-all instead.\n' % str(e))
|
|
sys.exit(1)
|
|
|
|
for type, name in event.args:
|
|
if is_string(type):
|
|
l = fobj.read(4)
|
|
(len,) = struct.unpack('=L', l)
|
|
s = fobj.read(len)
|
|
rec = rec + (s,)
|
|
else:
|
|
(value,) = struct.unpack('=Q', fobj.read(8))
|
|
rec = rec + (value,)
|
|
else:
|
|
rec = ("dropped", rechdr[1], rechdr[3])
|
|
(value,) = struct.unpack('=Q', fobj.read(8))
|
|
rec = rec + (value,)
|
|
return rec
|
|
|
|
def get_mapping(fobj):
|
|
(event_id, ) = struct.unpack('=Q', fobj.read(8))
|
|
(len, ) = struct.unpack('=L', fobj.read(4))
|
|
name = fobj.read(len)
|
|
|
|
return (event_id, name)
|
|
|
|
def read_record(edict, idtoname, fobj):
|
|
"""Deserialize a trace record from a file into a tuple (event_num, timestamp, pid, arg1, ..., arg6)."""
|
|
rechdr = read_header(fobj, rec_header_fmt)
|
|
return get_record(edict, idtoname, rechdr, fobj)
|
|
|
|
def read_trace_header(fobj):
|
|
"""Read and verify trace file header"""
|
|
header = read_header(fobj, log_header_fmt)
|
|
if header is None:
|
|
raise ValueError('Not a valid trace file!')
|
|
if header[0] != header_event_id:
|
|
raise ValueError('Not a valid trace file, header id %d != %d' %
|
|
(header[0], header_event_id))
|
|
if header[1] != header_magic:
|
|
raise ValueError('Not a valid trace file, header magic %d != %d' %
|
|
(header[1], header_magic))
|
|
|
|
log_version = header[2]
|
|
if log_version not in [0, 2, 3, 4]:
|
|
raise ValueError('Unknown version of tracelog format!')
|
|
if log_version != 4:
|
|
raise ValueError('Log format %d not supported with this QEMU release!'
|
|
% log_version)
|
|
|
|
def read_trace_records(edict, idtoname, fobj):
|
|
"""Deserialize trace records from a file, yielding record tuples (event_num, timestamp, pid, arg1, ..., arg6).
|
|
|
|
Note that `idtoname` is modified if the file contains mapping records.
|
|
|
|
Args:
|
|
edict (str -> Event): events dict, indexed by name
|
|
idtoname (int -> str): event names dict, indexed by event ID
|
|
fobj (file): input file
|
|
|
|
"""
|
|
while True:
|
|
t = fobj.read(8)
|
|
if len(t) == 0:
|
|
break
|
|
|
|
(rectype, ) = struct.unpack('=Q', t)
|
|
if rectype == record_type_mapping:
|
|
event_id, name = get_mapping(fobj)
|
|
idtoname[event_id] = name
|
|
else:
|
|
rec = read_record(edict, idtoname, fobj)
|
|
|
|
yield rec
|
|
|
|
class Analyzer(object):
|
|
"""A trace file analyzer which processes trace records.
|
|
|
|
An analyzer can be passed to run() or process(). The begin() method is
|
|
invoked, then each trace record is processed, and finally the end() method
|
|
is invoked.
|
|
|
|
If a method matching a trace event name exists, it is invoked to process
|
|
that trace record. Otherwise the catchall() method is invoked.
|
|
|
|
Example:
|
|
The following method handles the runstate_set(int new_state) trace event::
|
|
|
|
def runstate_set(self, new_state):
|
|
...
|
|
|
|
The method can also take a timestamp argument before the trace event
|
|
arguments::
|
|
|
|
def runstate_set(self, timestamp, new_state):
|
|
...
|
|
|
|
Timestamps have the uint64_t type and are in nanoseconds.
|
|
|
|
The pid can be included in addition to the timestamp and is useful when
|
|
dealing with traces from multiple processes::
|
|
|
|
def runstate_set(self, timestamp, pid, new_state):
|
|
...
|
|
"""
|
|
|
|
def begin(self):
|
|
"""Called at the start of the trace."""
|
|
pass
|
|
|
|
def catchall(self, event, rec):
|
|
"""Called if no specific method for processing a trace event has been found."""
|
|
pass
|
|
|
|
def end(self):
|
|
"""Called at the end of the trace."""
|
|
pass
|
|
|
|
def process(events, log, analyzer, read_header=True):
|
|
"""Invoke an analyzer on each event in a log."""
|
|
if isinstance(events, str):
|
|
events = read_events(open(events, 'r'), events)
|
|
if isinstance(log, str):
|
|
log = open(log, 'rb')
|
|
|
|
if read_header:
|
|
read_trace_header(log)
|
|
|
|
dropped_event = Event.build("Dropped_Event(uint64_t num_events_dropped)")
|
|
edict = {"dropped": dropped_event}
|
|
idtoname = {dropped_event_id: "dropped"}
|
|
|
|
for event in events:
|
|
edict[event.name] = event
|
|
|
|
# If there is no header assume event ID mapping matches events list
|
|
if not read_header:
|
|
for event_id, event in enumerate(events):
|
|
idtoname[event_id] = event.name
|
|
|
|
def build_fn(analyzer, event):
|
|
if isinstance(event, str):
|
|
return analyzer.catchall
|
|
|
|
fn = getattr(analyzer, event.name, None)
|
|
if fn is None:
|
|
return analyzer.catchall
|
|
|
|
event_argcount = len(event.args)
|
|
fn_argcount = len(inspect.getargspec(fn)[0]) - 1
|
|
if fn_argcount == event_argcount + 1:
|
|
# Include timestamp as first argument
|
|
return lambda _, rec: fn(*(rec[1:2] + rec[3:3 + event_argcount]))
|
|
elif fn_argcount == event_argcount + 2:
|
|
# Include timestamp and pid
|
|
return lambda _, rec: fn(*rec[1:3 + event_argcount])
|
|
else:
|
|
# Just arguments, no timestamp or pid
|
|
return lambda _, rec: fn(*rec[3:3 + event_argcount])
|
|
|
|
analyzer.begin()
|
|
fn_cache = {}
|
|
for rec in read_trace_records(edict, idtoname, log):
|
|
event_num = rec[0]
|
|
event = edict[event_num]
|
|
if event_num not in fn_cache:
|
|
fn_cache[event_num] = build_fn(analyzer, event)
|
|
fn_cache[event_num](event, rec)
|
|
analyzer.end()
|
|
|
|
def run(analyzer):
|
|
"""Execute an analyzer on a trace file given on the command-line.
|
|
|
|
This function is useful as a driver for simple analysis scripts. More
|
|
advanced scripts will want to call process() instead."""
|
|
import sys
|
|
|
|
read_header = True
|
|
if len(sys.argv) == 4 and sys.argv[1] == '--no-header':
|
|
read_header = False
|
|
del sys.argv[1]
|
|
elif len(sys.argv) != 3:
|
|
sys.stderr.write('usage: %s [--no-header] <trace-events> ' \
|
|
'<trace-file>\n' % sys.argv[0])
|
|
sys.exit(1)
|
|
|
|
events = read_events(open(sys.argv[1], 'r'), sys.argv[1])
|
|
process(events, sys.argv[2], analyzer, read_header=read_header)
|
|
|
|
if __name__ == '__main__':
|
|
class Formatter(Analyzer):
|
|
def __init__(self):
|
|
self.last_timestamp = None
|
|
|
|
def catchall(self, event, rec):
|
|
timestamp = rec[1]
|
|
if self.last_timestamp is None:
|
|
self.last_timestamp = timestamp
|
|
delta_ns = timestamp - self.last_timestamp
|
|
self.last_timestamp = timestamp
|
|
|
|
fields = [event.name, '%0.3f' % (delta_ns / 1000.0),
|
|
'pid=%d' % rec[2]]
|
|
i = 3
|
|
for type, name in event.args:
|
|
if is_string(type):
|
|
fields.append('%s=%s' % (name, rec[i]))
|
|
else:
|
|
fields.append('%s=0x%x' % (name, rec[i]))
|
|
i += 1
|
|
print ' '.join(fields)
|
|
|
|
run(Formatter())
|