Launchpad itself

Merge lp:~jml/launchpad/remove-top-tests into lp:launchpad

  1. remove-top-tests
  2. Merge into devel
Proposed by Jonathan Lange
Status: Merged
Approved by: Steve Kowalik
Approved revision: no longer in the source branch.
Merged at revision: 15396
Proposed branch: lp:~jml/launchpad/remove-top-tests
Merge into: lp:launchpad
Diff against target: 481 lines (+0/-477)
1 file modified
utilities/top-tests.py (+0/-477)
To merge this branch: bzr merge lp:~jml/launchpad/remove-top-tests
Reviewer Review Type Date Requested Status
Steve Kowalik (community) code Approve
Review via email: mp+109664@code.launchpad.net

Description of the change

I find myself in need of LoC credit so I can merge my other branches.

./utilities/top-tests.py already exists in lp:lp-dev-utils. This branch removes it. (I also think it's a pointless script in lp:lp-dev-utils and would replace it with judicious use of 'testr slowest', but to each their own).

477 lines of code healed, I think you'll find.

To post a comment you must log in.
Revision history for this message
Steve Kowalik (stevenk) :
review: Approve (code)

Preview Diff

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