xref: /qemu/scripts/simpletrace.py (revision 15327c3d)
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):
3480ff35cdSStefan 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
3780ff35cdSStefan 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):
5780ff35cdSStefan 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
61*15327c3dSStefan Hajnoczidef read_trace_header(fobj):
62*15327c3dSStefan Hajnoczi    """Read and verify trace file header"""
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
76*15327c3dSStefan Hajnoczidef read_trace_records(edict, fobj):
77*15327c3dSStefan Hajnoczi    """Deserialize trace records from a file, yielding record tuples (event_num, timestamp, pid, arg1, ..., arg6)."""
784c3b5a48SBlue Swirl    while True:
7990a147a2SHarsh Prateek Bora        rec = read_record(edict, fobj)
804c3b5a48SBlue Swirl        if rec is None:
814c3b5a48SBlue Swirl            break
824c3b5a48SBlue Swirl
834c3b5a48SBlue Swirl        yield rec
844c3b5a48SBlue Swirl
8559da6684SStefan Hajnocziclass Analyzer(object):
8659da6684SStefan Hajnoczi    """A trace file analyzer which processes trace records.
8759da6684SStefan Hajnoczi
8859da6684SStefan Hajnoczi    An analyzer can be passed to run() or process().  The begin() method is
8959da6684SStefan Hajnoczi    invoked, then each trace record is processed, and finally the end() method
9059da6684SStefan Hajnoczi    is invoked.
9159da6684SStefan Hajnoczi
9259da6684SStefan Hajnoczi    If a method matching a trace event name exists, it is invoked to process
9359da6684SStefan Hajnoczi    that trace record.  Otherwise the catchall() method is invoked."""
9459da6684SStefan Hajnoczi
9559da6684SStefan Hajnoczi    def begin(self):
9659da6684SStefan Hajnoczi        """Called at the start of the trace."""
9759da6684SStefan Hajnoczi        pass
9859da6684SStefan Hajnoczi
9959da6684SStefan Hajnoczi    def catchall(self, event, rec):
10059da6684SStefan Hajnoczi        """Called if no specific method for processing a trace event has been found."""
10159da6684SStefan Hajnoczi        pass
10259da6684SStefan Hajnoczi
10359da6684SStefan Hajnoczi    def end(self):
10459da6684SStefan Hajnoczi        """Called at the end of the trace."""
10559da6684SStefan Hajnoczi        pass
10659da6684SStefan Hajnoczi
107*15327c3dSStefan Hajnoczidef process(events, log, analyzer, read_header=True):
10859da6684SStefan Hajnoczi    """Invoke an analyzer on each event in a log."""
10959da6684SStefan Hajnoczi    if isinstance(events, str):
11090a147a2SHarsh Prateek Bora        events = _read_events(open(events, 'r'))
11159da6684SStefan Hajnoczi    if isinstance(log, str):
11259da6684SStefan Hajnoczi        log = open(log, 'rb')
11359da6684SStefan Hajnoczi
114*15327c3dSStefan Hajnoczi    if read_header:
115*15327c3dSStefan Hajnoczi        read_trace_header(log)
116*15327c3dSStefan Hajnoczi
11790a147a2SHarsh Prateek Bora    dropped_event = Event.build("Dropped_Event(uint64_t num_events_dropped)")
11890a147a2SHarsh Prateek Bora    edict = {dropped_event_id: dropped_event}
11990a147a2SHarsh Prateek Bora
1201dad2ce9SLluís Vilanova    for num, event in enumerate(events):
12190a147a2SHarsh Prateek Bora        edict[num] = event
12290a147a2SHarsh Prateek Bora
12359da6684SStefan Hajnoczi    def build_fn(analyzer, event):
12490a147a2SHarsh Prateek Bora        if isinstance(event, str):
12590a147a2SHarsh Prateek Bora            return analyzer.catchall
12690a147a2SHarsh Prateek Bora
12790a147a2SHarsh Prateek Bora        fn = getattr(analyzer, event.name, None)
12859da6684SStefan Hajnoczi        if fn is None:
12959da6684SStefan Hajnoczi            return analyzer.catchall
13059da6684SStefan Hajnoczi
13190a147a2SHarsh Prateek Bora        event_argcount = len(event.args)
13259da6684SStefan Hajnoczi        fn_argcount = len(inspect.getargspec(fn)[0]) - 1
13359da6684SStefan Hajnoczi        if fn_argcount == event_argcount + 1:
13459da6684SStefan Hajnoczi            # Include timestamp as first argument
13580ff35cdSStefan Hajnoczi            return lambda _, rec: fn(*((rec[1:2],) + rec[3:3 + event_argcount]))
13680ff35cdSStefan Hajnoczi        elif fn_argcount == event_argcount + 2:
13780ff35cdSStefan Hajnoczi            # Include timestamp and pid
13880ff35cdSStefan Hajnoczi            return lambda _, rec: fn(*rec[1:3 + event_argcount])
13959da6684SStefan Hajnoczi        else:
14080ff35cdSStefan Hajnoczi            # Just arguments, no timestamp or pid
14180ff35cdSStefan Hajnoczi            return lambda _, rec: fn(*rec[3:3 + event_argcount])
14259da6684SStefan Hajnoczi
14359da6684SStefan Hajnoczi    analyzer.begin()
14459da6684SStefan Hajnoczi    fn_cache = {}
145*15327c3dSStefan Hajnoczi    for rec in read_trace_records(edict, log):
14659da6684SStefan Hajnoczi        event_num = rec[0]
14790a147a2SHarsh Prateek Bora        event = edict[event_num]
14859da6684SStefan Hajnoczi        if event_num not in fn_cache:
14959da6684SStefan Hajnoczi            fn_cache[event_num] = build_fn(analyzer, event)
15059da6684SStefan Hajnoczi        fn_cache[event_num](event, rec)
15159da6684SStefan Hajnoczi    analyzer.end()
15259da6684SStefan Hajnoczi
15359da6684SStefan Hajnoczidef run(analyzer):
15459da6684SStefan Hajnoczi    """Execute an analyzer on a trace file given on the command-line.
15559da6684SStefan Hajnoczi
15659da6684SStefan Hajnoczi    This function is useful as a driver for simple analysis scripts.  More
15759da6684SStefan Hajnoczi    advanced scripts will want to call process() instead."""
15859da6684SStefan Hajnoczi    import sys
15959da6684SStefan Hajnoczi
160*15327c3dSStefan Hajnoczi    read_header = True
161*15327c3dSStefan Hajnoczi    if len(sys.argv) == 4 and sys.argv[1] == '--no-header':
162*15327c3dSStefan Hajnoczi        read_header = False
163*15327c3dSStefan Hajnoczi        del sys.argv[1]
164*15327c3dSStefan Hajnoczi    elif len(sys.argv) != 3:
165*15327c3dSStefan Hajnoczi        sys.stderr.write('usage: %s [--no-header] <trace-events> ' \
166*15327c3dSStefan Hajnoczi                         '<trace-file>\n' % sys.argv[0])
16759da6684SStefan Hajnoczi        sys.exit(1)
16859da6684SStefan Hajnoczi
16990a147a2SHarsh Prateek Bora    events = _read_events(open(sys.argv[1], 'r'))
170*15327c3dSStefan Hajnoczi    process(events, sys.argv[2], analyzer, read_header=read_header)
17159da6684SStefan Hajnoczi
17259da6684SStefan Hajnocziif __name__ == '__main__':
17359da6684SStefan Hajnoczi    class Formatter(Analyzer):
17459da6684SStefan Hajnoczi        def __init__(self):
1754c3b5a48SBlue Swirl            self.last_timestamp = None
1764c3b5a48SBlue Swirl
17759da6684SStefan Hajnoczi        def catchall(self, event, rec):
17859da6684SStefan Hajnoczi            timestamp = rec[1]
1794c3b5a48SBlue Swirl            if self.last_timestamp is None:
18059da6684SStefan Hajnoczi                self.last_timestamp = timestamp
18159da6684SStefan Hajnoczi            delta_ns = timestamp - self.last_timestamp
18259da6684SStefan Hajnoczi            self.last_timestamp = timestamp
1834c3b5a48SBlue Swirl
18480ff35cdSStefan Hajnoczi            fields = [event.name, '%0.3f' % (delta_ns / 1000.0),
18580ff35cdSStefan Hajnoczi                      'pid=%d' % rec[2]]
18680ff35cdSStefan Hajnoczi            i = 3
18790a147a2SHarsh Prateek Bora            for type, name in event.args:
18890a147a2SHarsh Prateek Bora                if is_string(type):
18980ff35cdSStefan Hajnoczi                    fields.append('%s=%s' % (name, rec[i]))
19090a147a2SHarsh Prateek Bora                else:
19180ff35cdSStefan Hajnoczi                    fields.append('%s=0x%x' % (name, rec[i]))
19290a147a2SHarsh Prateek Bora                i += 1
19359da6684SStefan Hajnoczi            print ' '.join(fields)
1944c3b5a48SBlue Swirl
19559da6684SStefan Hajnoczi    run(Formatter())
196