aboutsummaryrefslogtreecommitdiff
path: root/scripts/simpletrace.py
blob: 2658b5cc7ca96e6afcd00fc66953553356bedef6 (plain)
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
#!/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

from __future__ import print_function
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())