« back to all changes in this revision
Viewing changes to utilities/top-tests.py
- browse files at revision 9265.1.1
- compare with another revision
- compare with revision 14612.2.4
- download diff
- download tarball
- view history from revision 9265.1.1
- Committer: Jonathan Lange
- Date: 2009-08-31 05:15:30 UTC
- mto: This revision was merged to the branch mainline in revision 9271.
- Revision ID: jml@canonical.com-20090831051530-pex7jge5d54ixay2
Add lp-dev-tools that lack license confusion, changing the license to match
the rest of the Launchpad source tree.
the rest of the Launchpad source tree.
added
removed
utilities/top-tests.py
1
#!/usr/bin/python2.4
2
#
3
# Copyright 2009 Canonical Ltd. This software is licensed under the
4
# GNU Affero General Public License version 3 (see the file LICENSE).
5
6
"""top-tests.py - Report about slowest tests in the test suite.
7
8
It parses the output of the testrunner run with -vvv and collects
9
statistics about the test run.
10
"""
11
12
__metaclass__ = type
13
14
import re
15
import operator
16
import os
17
import sys
18
19
LEN = 20
20
21
class ParseException(Exception):
22
"""Exception raised when there is an error while parsing a log file."""
23
24
25
class TestRunnerStats:
26
"""Encapsulates information about the time it took to run a testsuite."""
27
28
LAYER_STARTS_RE = re.compile(r'Running (.+) tests:')
29
30
LAYER_ENDS_RE = re.compile(
31
r' Ran (\d+) tests with (\d+) failures and (\d+) errors in ([\d.]+) '
32
'seconds.')
33
34
SETUP_RE = re.compile(r' Set up ([\w.]+) in ([\d.]+) seconds.')
35
36
TEARDOWN_RE = re.compile(r' Tear down ([\w.]+) in ([\d.]+) seconds.')
37
38
UNSUPPORTED_TEARDOWN_RE = re.compile(
39
r' Tear down ([\w.]+) ... not supported')
40
41
# We are not restricting this to the standard python identifiers because
42
# some doctest unittest or generated tests could contain funky names.
43
PYTHON_TEST_RE = re.compile(r'([^\( ]+) ?\(([^\)]+)\)')
44
45
MS_RE = re.compile(r'\s*\(([\d.]+) ms\)$')
46
47
TOTAL_RE = re.compile(r'Total: (\d+) tests, (\d+) failures, (\d+) errors')
48
49
# List of strings/patterns to attempt at matching.
50
# The second element in the tuple is the method to call when the start of
51
# the current line matches the string or the pattern.
52
MATCH_LIST = [
53
('Running tests at level', 'handleStartTestRunner'),
54
(LAYER_STARTS_RE, 'handleLayerStart'),
55
(LAYER_ENDS_RE, 'handleLayerEnd'),
56
(SETUP_RE, 'handleLayerSetUp'),
57
(TEARDOWN_RE, 'handleLayerTearDown'),
58
(UNSUPPORTED_TEARDOWN_RE, 'handleUnsupportedTearDown'),
59
(' Running:', None),
60
('Tearing down left over layers:', 'handleFinalTearDown'),
61
(MS_RE, 'handleTestRuntime'),
62
(LAYER_ENDS_RE, 'handleLayerEnd'),
63
(TEARDOWN_RE, 'handleLayerTearDown'),
64
(TOTAL_RE, 'handleTotal'),
65
(' ', 'handleTestRun'),
66
(None, 'handleGarbage'),
67
]
68
69
def __init__(self, logfile):
70
"""Create a new TestRunnerStats from a log file.
71
72
:param logfile: Open file-like object containing the log of the test
73
suite. That should have been generated at -vvv for maximum
74
information.
75
:raise ParseException: when the log file doesn't contain a testrunner
76
log, or couldn't be parsed for some other reasons.
77
"""
78
self.logfile = logfile
79
self._parse()
80
81
def _parse(self):
82
"""Extract timing information from the log file."""
83
self.layers = {}
84
self.ignored_lines = []
85
self.current_layer = None
86
self.last_test = None
87
88
end_of_tests = False
89
while not end_of_tests:
90
line = self.logfile.readline()
91
if not line:
92
break
93
for match, action in self.MATCH_LIST:
94
found = False
95
if isinstance(match, basestring):
96
if line.startswith(match):
97
found = True
98
elif match is None:
99
# None indicates the default action.
100
found = True
101
elif getattr(match, 'match', None):
102
found = match.match(line)
103
if found:
104
# Action is the name of the method to call.
105
# If it returns False, stop parsing.
106
if action is not None:
107
end_of_tests = getattr(self, action)(line, found)
108
break
109
110
if not end_of_tests:
111
raise ParseException('End of file before end of test run.')
112
113
def handleStartTestRunner(self, line, ignored):
114
"""Switch the the layer state."""
115
116
def handleLayerStart(self, line, match):
117
"""Create a new stats container for the layer."""
118
layer_name = match.group(1)
119
self.current_layer = self.getLayer(layer_name)
120
121
def handleLayerEnd(self, line, match):
122
"""Collect the total runtime for the layer tests."""
123
tests_run = match.group(1)
124
runtime = match.group(4)
125
self.current_layer.collectEndResults(tests_run, runtime)
126
127
def handleLayerSetUp(self, line, match):
128
"""Collect the runtime for the layer set up."""
129
layer_name = match.group(1)
130
runtime = float(match.group(2))
131
self.getLayer(layer_name).collectSetUp(runtime)
132
133
def handleLayerTearDown(self, line, match):
134
"""Collect the runtime for the layer tear down."""
135
layer_name = match.group(1)
136
runtime = float(match.group(2))
137
self.getLayer(layer_name).collectTearDown(runtime)
138
139
def handleUnsupportedTearDown(self, line, match):
140
"""Flag that tear down was unsupported."""
141
layer_name = match.group(1)
142
self.getLayer(layer_name).collectUnsupportedTearDown()
143
144
def handleFinalTearDown(self, line, match):
145
"""Switch to teardown state."""
146
147
def handleTestRun(self, line, ignored):
148
"""Collect that a test was run."""
149
# If we didn't saw the last test runtime, we are probably
150
# in a stack trace or something like that. So treat it as garbage.
151
if self.last_test is not None and not self.last_test_complete:
152
if self.MS_RE.search(line) is None:
153
self.handleGarbage(line, ignored)
154
return
155
else:
156
# It happens that a test doesn't output timing information.
157
# But other tests after that will.
158
# We are probably encountering such a case.
159
pass
160
line = line[4:]
161
if '/' in line:
162
if ' ' in line:
163
doctest, line = line.split(' ', 1)
164
else:
165
doctest = line
166
line = '\n'
167
self.last_test = DocTestStats(doctest)
168
else:
169
match = self.PYTHON_TEST_RE.match(line)
170
if match:
171
self.last_test = PythonTestStats(
172
match.group(1), match.group(2))
173
else:
174
raise ParseException("can't parse test name: %s" % line)
175
line = line[match.end():]
176
self.current_layer.collectTest(self.last_test)
177
178
# If the runtime isn't on this line, it means that there was output
179
# by the test, so we'll find the runtime info later on.
180
match = self.MS_RE.search(line)
181
if match:
182
self.last_test_complete = True
183
self.last_test.runtime = float(match.group(1))
184
else:
185
self.last_test_complete = False
186
self.last_test.collectGarbage(line)
187
188
def handleGarbage(self, line, ignored):
189
"""Save the log output by the test."""
190
if self.last_test is not None:
191
self.last_test.collectGarbage(line)
192
else:
193
self.ignored_lines.append(line)
194
195
def handleTestRuntime(self, line, match):
196
"""Collect the broken test runtime."""
197
if self.last_test is not None:
198
self.last_test.runtime = float(match.group(1))
199
self.last_test_complete = True
200
else:
201
self.ignored_lines.append(line)
202
203
def handleTotal(self, line, match):
204
"""Action invoked when the final line is encountered."""
205
self.current_layer = None
206
self.last_test = None
207
return True
208
209
def getLayer(self, layer_name):
210
"""Return the layer with name.
211
212
Create and return an empty layer if it doesn't exists.
213
"""
214
if layer_name not in self.layers:
215
self.layers[layer_name] = TestLayerStats(layer_name)
216
return self.layers[layer_name]
217
218
def getTestsIter(self):
219
"""Return an iterator over all tests."""
220
for layer in self.layers.values():
221
for test in layer.tests:
222
yield test
223
224
@property
225
def total_runtime(self):
226
"""Number of seconds used to run the whole test suite."""
227
return sum([layer.total_runtime for layer in self.layers.values()])
228
229
@property
230
def tests_count(self):
231
"""Number of tests in the test suite."""
232
return sum([len(layer.tests) for layer in self.layers.values()])
233
234
235
class TestLayerStats:
236
"""Contain all the tests that were run in the layer."""
237
238
name = None
239
unsupported_tear_downs = 0
240
241
tests_runtime = 0
242
243
def __init__(self, name):
244
"""Create a new stats container."""
245
self.name = name
246
self.tests = []
247
self.set_ups = []
248
self.tear_downs = []
249
250
@property
251
def total_runtime(self):
252
"""Return the runtime (including fixture) in this layer."""
253
return self.tests_runtime + sum(self.set_ups) + sum(self.tear_downs)
254
255
def collectTest(self, test):
256
"""Call when a test was run in the layer."""
257
self.tests.append(test)
258
259
def collectEndResults(self, tests_run, runtime):
260
"""Called when all the tests in the layer were run."""
261
self.tests_runtime = float(runtime)
262
self.tests_count = int(tests_run)
263
264
def collectSetUp(self, runtime):
265
"""Called when the layer was set up."""
266
self.set_ups.append(runtime)
267
268
def collectTearDown(self, runtime):
269
"""Called when the layer was torn down."""
270
self.tear_downs.append(runtime)
271
272
def collectUnsupportedTearDown(self):
273
"""Called when the layer couldn't be torn down."""
274
self.unsupported_tear_downs += 1
275
276
def __iter__(self):
277
"""Return an iterator over the tests run in this layer."""
278
return iter(self.tests)
279
280
281
class TestStats:
282
"""Base class for a test stats."""
283
284
name = None
285
runtime = 0
286
287
def __init__(self):
288
self._garbage = []
289
290
@property
291
def garbage(self):
292
"""Return the garbage output by the test."""
293
return "".join(self._garbage)
294
295
def collectGarbage(self, line):
296
self._garbage.append(line)
297
298
299
class PythonTestStats(TestStats):
300
"""Stats for a regular python unit test."""
301
302
def __init__(self, method, module):
303
super(PythonTestStats, self).__init__()
304
self.method = method
305
self.module = module
306
307
@property
308
def name(self):
309
"""Return the full name of the test."""
310
return "%s.%s" % (self.module, self.method)
311
312
313
class DocTestStats(TestStats):
314
"""Stats for a doctest."""
315
316
def __init__(self, filename):
317
super(DocTestStats, self).__init__()
318
self.filename = filename
319
320
@property
321
def name(self):
322
"""Remove the PQM directory from the name."""
323
index = self.filename.find("lib/canonical")
324
if index != -1:
325
filename = self.filename[index:]
326
else:
327
filename = self.filename
328
return os.path.normpath(filename)
329
330
331
class PQMLog:
332
"""Encapsulates information about a PQM log."""
333
334
def __init__(self, logfile):
335
"""Create a new PQMLog instance.
336
337
:param logfile: Path to the PQM log.
338
"""
339
self.logfile = logfile
340
self.fixtures_profile = []
341
342
self._parse()
343
344
def _parse(self):
345
"""Parse a PQM log file.
346
347
Extract the branch name, the time each tests took as well as the
348
time spent in the layers.
349
"""
350
self.branch = "Unknown"
351
profile = self.fixtures_profile
352
353
logfile = open(self.logfile)
354
while True:
355
line = logfile.readline()
356
if not line:
357
break
358
line = line.strip()
359
if not line:
360
continue
361
if line.startswith("Executing star-merge"):
362
self.branch = line.split(" ")[2]
363
elif " calls taking " in line:
364
if "s." not in line:
365
continue
366
values = line.split(" ")
367
runtime = float(values[-1][:-2])
368
profile.append((runtime, values[0]))
369
elif line.startswith("Executing pre-commit hook"):
370
self.testrunner_stats = TestRunnerStats(logfile)
371
372
373
def main(argv):
374
"""Parse a PQM log file."""
375
if len(sys.argv) > 1:
376
logfile = sys.argv[1]
377
else:
378
logfile = find_latest_successful_merge()
379
print_report(PQMLog(logfile))
380
381
382
def find_latest_successful_merge():
383
"""Return the latest PQM log that contain a successful merge.
384
385
Look into the current directory for the log files.
386
"""
387
cmd = "ls -at | head -10 | xargs grep -l 'star-merge succeeded'"
388
p = os.popen(cmd)
389
logfile_name = p.readlines()[0].strip()
390
p.close()
391
return logfile_name
392
393
394
def print_report(pqm_log, out=sys.stdout):
395
"""Print the report on STDOUT."""
396
397
print >>out, "Log: %s" % pqm_log.logfile
398
print >>out, "Branch: %s" % pqm_log.branch
399
400
stats = pqm_log.testrunner_stats
401
402
top_tests = list(stats.getTestsIter())
403
top_tests.sort(key=operator.attrgetter('runtime'), reverse=True)
404
405
total_runtime = stats.total_runtime
406
tests_count = stats.tests_count
407
408
print >>out
409
print >>out, "Top %d tests taking the longest time" % LEN
410
print >>out, "===================================="
411
print
412
top_runtime = 0.0
413
for test in top_tests[:LEN]:
414
percent = test.runtime / total_runtime * 100
415
top_runtime += test.runtime
416
print >>out, "%6.2f (%.1f%%) %s" % (test.runtime, percent, test.name)
417
print >>out
418
test_percent = LEN / float(tests_count) * 100
419
time_percent = top_runtime / total_runtime * 100
420
print >>out, (
421
"Top %s of %s (%.1f%%) tests taking %ss of %ss (%.1f%%)"
422
% (LEN, tests_count, test_percent, top_runtime, total_runtime,
423
time_percent))
424
print >>out
425
426
print >>out, "Tests and runtime by layer"
427
print >>out, "=========================="
428
print >>out
429
430
layers = stats.layers.values()
431
layers.sort(key=operator.attrgetter('total_runtime'), reverse=True)
432
for layer in layers:
433
if len(layer.tests) == 0:
434
continue
435
runtime_percent = layer.tests_runtime / total_runtime * 100
436
layer_name = layer.name.split('.')[-1]
437
print "%7.2f (%4.1f%%) %4d tests (%5.2fs/t) %s" % (
438
layer.tests_runtime, runtime_percent, len(layer.tests),
439
layer.tests_runtime / len(layer.tests), layer_name)
440
441
442
print >>out
443
print >>out, "Slowest fixture methods"
444
print >>out, "======================="
445
print >>out
446
447
profile = list(pqm_log.fixtures_profile)
448
profile.sort(reverse=True)
449
print >>out
450
fixture_runtime = 0
451
for runtime, method in profile:
452
runtime_percent = runtime / total_runtime * 100
453
print >>out, "%7.2f (%4.1f%%) %s" % (runtime, runtime_percent, method)
454
fixture_runtime += runtime
455
456
print >>out
457
print >>out, "Fixture overhead %ss (%.1f%%)" % (
458
fixture_runtime, fixture_runtime / total_runtime * 100)
459
print >>out
460
461
tests_with_garbage = 0
462
garbage_lines_count = 0
463
for test in stats.getTestsIter():
464
if len(test.garbage):
465
tests_with_garbage += 1
466
garbage_lines_count += test.garbage.strip().count('\n')+1
467
468
print >>out, "%d tests output %d warning lines." % (
469
tests_with_garbage, garbage_lines_count)
470
print >>out, "Ignored %d lines in the testrunner output." % len(
471
stats.ignored_lines)
472
print >>out
473
474
475
if __name__ == '__main__':
476
main(sys.argv)
Loggerhead is a web-based interface for Breezy
Version: 2.0.1