print_stm_log.py 9.36 KB
Newer Older
Armin Rigo's avatar
Armin Rigo committed
1
#!/usr/bin/env pypy
2
import sys
3
import struct, re, linecache
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

# ____________________________________________________________

STM_TRANSACTION_START   = 0
STM_TRANSACTION_COMMIT  = 1
STM_TRANSACTION_ABORT   = 2

# contention; see details at the start of contention.c
STM_CONTENTION_WRITE_WRITE = 3   # markers: self loc / other written loc
STM_CONTENTION_WRITE_READ  = 4   # markers: self written loc / other missing
STM_CONTENTION_INEVITABLE  = 5   # markers: self loc / other inev loc

# following a contention, we get from the same thread one of
# STM_ABORTING_OTHER_CONTENTION, STM_TRANSACTION_ABORT (self-abort),
# or STM_WAIT_CONTENTION (self-wait).
STM_ABORTING_OTHER_CONTENTION = 6

# always one STM_WAIT_xxx followed later by STM_WAIT_DONE
STM_WAIT_FREE_SEGMENT  = 7
STM_WAIT_SYNC_PAUSE    = 8
STM_WAIT_CONTENTION    = 9
STM_WAIT_DONE          = 10

# start and end of GC cycles
STM_GC_MINOR_START  = 11
STM_GC_MINOR_DONE   = 12
STM_GC_MAJOR_START  = 13
STM_GC_MAJOR_DONE   = 14

33
34
_STM_EVENT_N  = 15

35
36
PAUSE_AFTER_ABORT   = 0.000001      # usleep(1) after every abort

37

38
39
40
41
42
43
44
45
46
47
event_name = {}
for _key, _value in globals().items():
    if _key.startswith('STM_'):
        event_name[_value] = _key

# ____________________________________________________________


class LogEntry(object):
    def __init__(self, timestamp, threadnum, otherthreadnum,
48
                 event, marker1, marker2, frac):
49
50
51
52
53
54
        self.timestamp = timestamp
        self.threadnum = threadnum
        self.otherthreadnum = otherthreadnum
        self.event = event
        self.marker1 = marker1
        self.marker2 = marker2
55
        self.frac = frac
56

57
58
59
60
61
62
63
64
65
66
    def __str__(self):
        s = '[%.3f][%s->%s]\t%s' % (
            self.timestamp, self.threadnum, self.otherthreadnum,
            event_name[self.event])
        if self.marker1:
            s += ':\n%s' % print_marker(self.marker1)
        if self.marker2:
            s += '\n%s' % print_marker(self.marker2)
        return s

67
68
69
70
71
72
73

def parse_log(filename):
    f = open(filename, 'rb')
    try:
        header = f.read(16)
        if header != "STMGC-C7-PROF01\n":
            raise ValueError("wrong format in file %r" % (filename,))
74
75
76
        f.seek(0, 2)
        frac = 1.0 / f.tell()
        f.seek(16, 0)
77
78
79
        result = []
        while True:
            packet = f.read(19)
Armin Rigo's avatar
Armin Rigo committed
80
            if len(packet) < 19: break
81
82
            sec, nsec, threadnum, otherthreadnum, event, len1, len2 = \
                  struct.unpack("IIIIBBB", packet)
83
            if event >= _STM_EVENT_N:
Armin Rigo's avatar
Fix    
Armin Rigo committed
84
                raise ValueError("the file %r appears corrupted" % (filename,))
85
86
            m1 = f.read(len1)
            m2 = f.read(len2)
87
88
89
            yield LogEntry(sec + 0.000000001 * nsec,
                           threadnum, otherthreadnum, event, m1, m2,
                           f.tell() * frac)
90
91
92
93
94
95
96
97
98
99
100
101
    finally:
        f.close()


class ThreadState(object):
    def __init__(self, threadnum):
        self.threadnum = threadnum
        self.cpu_time = 0.0

    def transaction_start(self, entry):
        self._start = entry
        self._conflict = None
102
103
        self._pause = None
        self._paused_time = 0.0
104
105
106

    def transaction_stop(self, entry):
        transaction_time = entry.timestamp - self._start.timestamp
107
108
        transaction_time -= self._paused_time
        assert transaction_time >= 0.0
109
110
        self.cpu_time += transaction_time
        self._start = None
111
        self._pause = None
112
113
114
        if self._conflict and entry.event == STM_TRANSACTION_ABORT:
            c = self._conflict[1]
            c.aborted_time += transaction_time
115
            c.paused_time += PAUSE_AFTER_ABORT
116
117
            self._conflict = None

118
119
120
121
122
123
124
125
126
127
128
129
130
131
    def transaction_pause(self, entry):
        self._pause = entry

    def transaction_unpause(self, entry):
        if self._pause is None:
            return
        pause_time = entry.timestamp - self._pause.timestamp
        self._paused_time += pause_time
        self._pause = None
        if self._conflict and self._conflict[0] == "local":
            c = self._conflict[1]
            c.paused_time += pause_time
            self._conflict = None

132
133
134
135
136
137
138
139
140
141
142
143
    def in_transaction(self):
        return self._start is not None


class ConflictSummary(object):
    def __init__(self, event, marker1, marker2):
        self.event = event
        self.marker1 = marker1
        self.marker2 = marker2
        self.aborted_time = 0.0
        self.paused_time = 0.0
        self.num_events = 0
144
        self.timestamps = []
145
146
147
148

    def sortkey(self):
        return self.aborted_time + self.paused_time

149
150
151
152
153
154
155
156
157
    def get_event_name(self):
        return event_name[self.event]

    def get_marker1(self):
        return print_marker(self.marker1)

    def get_marker2(self):
        return print_marker(self.marker2)

158
159
    def __str__(self):
        s = '%.3fs lost in aborts, %.3fs paused (%dx %s)\n' % (
160
161
            self.aborted_time, self.paused_time, self.num_events,
            self.get_event_name())
162
163
164
165
166
167
168
        s += print_marker(self.marker1)
        if self.marker2:
            s += '\n%s' % print_marker(self.marker2)
        return s



169

170
171
172
r_marker = re.compile(r'File "(.+)", line (\d+)')

def print_marker(marker):
173
    s = '  %s' % marker
174
175
176
177
178
    match = r_marker.match(marker)
    if match:
        line = linecache.getline(match.group(1), int(match.group(2)))
        line = line.strip()
        if line:
179
180
            s += '\n    %s' % line
    return s
181

182
183
184
185
186
187
def percent(fraction, total):
    r = '%.1f' % (fraction * 100.0 / total)
    if len(r) > 3:
        r = r.split('.')[0]
    return r + '%'

188
def summarize_log_entries(logentries, stmlog):
189
190
    threads = {}
    conflicts = {}
191
    cnt = 0
192
    for entry in logentries:
193
194
195
196
197
198
199
        if (cnt & 0x7ffff) == 0:
            if cnt == 0:
                start_time = entry.timestamp
            else:
                print >> sys.stderr, '%.0f%%' % (entry.frac * 100.0,),
        cnt += 1
        #
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
        if entry.event == STM_TRANSACTION_START:
            t = threads.get(entry.threadnum)
            if t is None:
                t = threads[entry.threadnum] = ThreadState(entry.threadnum)
            t.transaction_start(entry)
        elif (entry.event == STM_TRANSACTION_COMMIT or
              entry.event == STM_TRANSACTION_ABORT):
            t = threads.get(entry.threadnum)
            if t is not None and t.in_transaction():
                t.transaction_stop(entry)
        elif entry.event in (STM_CONTENTION_WRITE_WRITE,
                             STM_CONTENTION_WRITE_READ,
                             STM_CONTENTION_INEVITABLE):
            summary = (entry.event, entry.marker1, entry.marker2)
            c = conflicts.get(summary)
            if c is None:
                c = conflicts[summary] = ConflictSummary(*summary)
            c.num_events += 1
218
            c.timestamps.append(entry.timestamp)
219
220
221
222
223
224
225
226
227
228
229
            t = threads.get(entry.threadnum)
            if t is not None and t.in_transaction():
                t._conflict = ("local", c, entry)
        elif entry.event == STM_ABORTING_OTHER_CONTENTION:
            t = threads.get(entry.threadnum)
            if t is not None and t._conflict and t._conflict[0] == "local":
                _, c, entry = t._conflict
                t._conflict = None
                t2 = threads.get(entry.otherthreadnum)
                if t2 is not None and t2.in_transaction():
                    t2._conflict = ("remote", c, entry)
230
231
        elif entry.event in (STM_WAIT_SYNC_PAUSE, STM_WAIT_CONTENTION,
                             STM_WAIT_FREE_SEGMENT):
232
233
234
235
236
237
238
            t = threads.get(entry.threadnum)
            if t is not None and t.in_transaction():
                t.transaction_pause(entry)
        elif entry.event == STM_WAIT_DONE:
            t = threads.get(entry.threadnum)
            if t is not None and t.in_transaction():
                t.transaction_unpause(entry)
239
    #
240
241
242
243
    if cnt == 0:
        raise Exception("empty file")
    print >> sys.stderr
    stop_time = entry.timestamp
244
245
246
247
248
249
250
251
252
    stmlog.start_time = start_time
    stmlog.total_time = stop_time - start_time
    stmlog.threads = threads
    stmlog.conflicts = conflicts

def dump_summary(stmlog):
    start_time = stmlog.start_time
    total_time = stmlog.total_time
    print
253
254
    print 'Total real time:             %.3fs' % (total_time,)
    #
255
    total_cpu_time = stmlog.get_total_cpu_time()
256
257
258
259
    print 'Total CPU time in STM mode:  %.3fs (%s)' % (
        total_cpu_time, percent(total_cpu_time, total_time))
    print
    #
260
261
    values = stmlog.get_conflicts()
    for c in values[:15]:
262
263
264
265
266
267
        intervals = 48
        timeline = [0] * intervals
        for t in c.timestamps:
            idx = int((t - start_time) / total_time * intervals)
            timeline[idx] += 1

268
        print str(c)
269
        print "time line:", "".join(['x' if i else '.' for i in timeline])
270
271
272
        print


273
274
275
276
277
278
279
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
295
class StmLog(object):
    def __init__(self, filename):
        summarize_log_entries(parse_log(filename), self)

    def get_total_cpu_time(self):
        return sum([v.cpu_time for v in self.threads.values()])

    def get_conflicts(self):
        values = self.conflicts.values()
        values.sort(key=ConflictSummary.sortkey)
        values.reverse()
        return values

    def get_total_aborts_and_pauses(self):
        total = 0
        for c in self.conflicts.values():
            total += c.num_events
        return total

    def dump(self):
        dump_summary(self)


296
297
def main(argv):
    assert len(argv) == 1, "expected a filename argument"
298
    StmLog(argv[0]).dump()
299
300
301
302
    return 0

if __name__ == '__main__':
    sys.exit(main(sys.argv[1:]))