Bazaar

Merge lp:~lifeless/bzr/test-speed into lp:~bzr/bzr/trunk-old

  1. test-speed
  2. Merge into trunk-old
Proposed by Robert Collins
Status: Merged
Merged at revision: not available
Proposed branch: lp:~lifeless/bzr/test-speed
Merge into: lp:~bzr/bzr/trunk-old
Diff against target: 466 lines
To merge this branch: bzr merge lp:~lifeless/bzr/test-speed
Reviewer Review Type Date Requested Status
Andrew Bennetts Approve
Review via email: mp+10633@code.launchpad.net
To post a comment you must log in.
Revision history for this message
Robert Collins (lifeless) wrote :

This little branch makes it possible to lsprof exactly what a single
test is doing; this can be very useful without requiring the use of a
time() section - though those sections are still supported.

-Rob

Revision history for this message
Andrew Bennetts (spiv) wrote :

Looks fine.

bzrlib/tests/__init__.py
------------------------

ProfileResult's docstring has a typo: "be be" should be "it be".

review: Approve
Revision history for this message
John A Meinel (jameinel) wrote :

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

Robert Collins wrote:
> Robert Collins has proposed merging lp:~lifeless/bzr/test-speed into lp:bzr.
>
> Requested reviews:
> bzr-core (bzr-core)
>
> This little branch makes it possible to lsprof exactly what a single
> test is doing; this can be very useful without requiring the use of a
> time() section - though those sections are still supported.
>
> -Rob
>
>

I don't really like this as an overload on top of 'lsprof-timed'. I
realize why you might want it, so I wouldn't really block it. But it
does seem like we are getting a few too many options:

bzr --lsprof --lsprof-file foo selftest --lsprof-timed --lsprof-tests -v
...

I personally understand the difference between all of them, but maybe it
would be better to have it as a data field.

bzr --lsprof=filename,overall
bzr --lsprof=filename,tests
bzr --lsprof=filename,benchmark

...

I haven't worked out a great name, but the current situation seems
pretty ad-hoc and not really where we want to be.

I also would say that writing to a file should be the preferred method,
and you can set '-' as the file if you want to write to the screen. It
seems like it would help reduce clutter.

Of course, I should also say that our option parsing is a bit weak as:
  bzr --lsprof-file foo
works, but
  bzr --lsprof-file=foo
does not.

Anyway, if you find this helpful, I would be okay having it. I just
think it takes us down the road of clutter.

(I did not review the actual content, so I'm not voting yet.)

John
=:->
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.9 (Cygwin)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org/

iEYEARECAAYFAkqT6ZwACgkQJdeBCYSNAANMWgCgxa9cIJnDbdG3B6IpQpV8mpRN
5dMAoL3MxE5LCkEgfu2yDCT7Yk5Zth3x
=g0Zd
-----END PGP SIGNATURE-----

Revision history for this message
Robert Collins (lifeless) wrote :

Hi John, I totally agree with all your comments.

In my brain-food slices I'm working on test infrastructure to fix the
test suite performance - its got to get fixed if we're to be productive.

So this branch was aimed towards that goal.

I think there are a few other issues :- namely that it would be good to
output kcachegrind files, it might be good to spin on tests (make
identical scenarios for say 100 copies) to get more timing data, it
would be good to be able to remote this, to have ec2 generate the
traces; and it would be great to fold this into test-coverage maps as
well.

Some of these are just glue, others need more thought because we don't
have canned approaches to solving them and I'd like to fit in with
python's core unittest values and facilities more (though that does
require fixing them upstream as well).

Cheers,
Rob

Preview Diff

[H/L] Next/Prev Comment, [J/K] Next/Prev File, [N/P] Next/Prev Hunk
1=== modified file 'NEWS'
2--- NEWS 2009-08-24 18:28:46 +0000
3+++ NEWS 2009-08-24 23:35:12 +0000
4@@ -67,9 +67,16 @@
5 Internals
6 *********
7
8+* The ``bzrlib.lsprof`` module has a new class ``BzrProfiler`` which makes
9+ profiling in some situations like callbacks and generators easier.
10+ (Robert Collins)
11+
12 Testing
13 *******
14
15+* Passing ``--lsprof-tests -v`` to bzr selftest will cause lsprof output to
16+ be output for every test. Note that this is very verbose! (Robert Collins)
17+
18 bzr 1.18
19 ########
20
21
22=== modified file 'bzrlib/builtins.py'
23--- bzrlib/builtins.py 2009-08-11 18:00:37 +0000
24+++ bzrlib/builtins.py 2009-08-24 23:35:12 +0000
25@@ -3369,6 +3369,8 @@
26 Option('lsprof-timed',
27 help='Generate lsprof output for benchmarked'
28 ' sections of code.'),
29+ Option('lsprof-tests',
30+ help='Generate lsprof output for each test.'),
31 Option('cache-dir', type=str,
32 help='Cache intermediate benchmark output in this '
33 'directory.'),
34@@ -3415,7 +3417,7 @@
35 first=False, list_only=False,
36 randomize=None, exclude=None, strict=False,
37 load_list=None, debugflag=None, starting_with=None, subunit=False,
38- parallel=None):
39+ parallel=None, lsprof_tests=False):
40 from bzrlib.tests import selftest
41 import bzrlib.benchmarks as benchmarks
42 from bzrlib.benchmarks import tree_creator
43@@ -3455,6 +3457,7 @@
44 "transport": transport,
45 "test_suite_factory": test_suite_factory,
46 "lsprof_timed": lsprof_timed,
47+ "lsprof_tests": lsprof_tests,
48 "bench_history": benchfile,
49 "matching_tests_first": first,
50 "list_only": list_only,
51
52=== modified file 'bzrlib/lsprof.py'
53--- bzrlib/lsprof.py 2009-03-08 06:18:06 +0000
54+++ bzrlib/lsprof.py 2009-08-24 23:35:12 +0000
55@@ -13,45 +13,74 @@
56
57 __all__ = ['profile', 'Stats']
58
59-_g_threadmap = {}
60-
61-
62-def _thread_profile(f, *args, **kwds):
63- # we lose the first profile point for a new thread in order to trampoline
64- # a new Profile object into place
65- global _g_threadmap
66- thr = thread.get_ident()
67- _g_threadmap[thr] = p = Profiler()
68- # this overrides our sys.setprofile hook:
69- p.enable(subcalls=True, builtins=True)
70-
71-
72 def profile(f, *args, **kwds):
73 """Run a function profile.
74
75 Exceptions are not caught: If you need stats even when exceptions are to be
76- raised, passing in a closure that will catch the exceptions and transform
77- them appropriately for your driver function.
78+ raised, pass in a closure that will catch the exceptions and transform them
79+ appropriately for your driver function.
80
81 :return: The functions return value and a stats object.
82 """
83- global _g_threadmap
84- p = Profiler()
85- p.enable(subcalls=True)
86- threading.setprofile(_thread_profile)
87+ profiler = BzrProfiler()
88+ profiler.start()
89 try:
90 ret = f(*args, **kwds)
91 finally:
92- p.disable()
93- for pp in _g_threadmap.values():
94+ stats = profiler.stop()
95+ return ret, stats
96+
97+
98+class BzrProfiler(object):
99+ """Bzr utility wrapper around Profiler.
100+
101+ For most uses the module level 'profile()' function will be suitable.
102+ However profiling when a simple wrapped function isn't available may
103+ be easier to accomplish using this class.
104+
105+ To use it, create a BzrProfiler and call start() on it. Some arbitrary
106+ time later call stop() to stop profiling and retrieve the statistics
107+ from the code executed in the interim.
108+ """
109+
110+ def start(self):
111+ """Start profiling.
112+
113+ This hooks into threading and will record all calls made until
114+ stop() is called.
115+ """
116+ self._g_threadmap = {}
117+ self.p = Profiler()
118+ self.p.enable(subcalls=True)
119+ threading.setprofile(self._thread_profile)
120+
121+ def stop(self):
122+ """Stop profiling.
123+
124+ This unhooks from threading and cleans up the profiler, returning
125+ the gathered Stats object.
126+
127+ :return: A bzrlib.lsprof.Stats object.
128+ """
129+ self.p.disable()
130+ for pp in self._g_threadmap.values():
131 pp.disable()
132 threading.setprofile(None)
133+ p = self.p
134+ self.p = None
135+ threads = {}
136+ for tid, pp in self._g_threadmap.items():
137+ threads[tid] = Stats(pp.getstats(), {})
138+ self._g_threadmap = None
139+ return Stats(p.getstats(), threads)
140
141- threads = {}
142- for tid, pp in _g_threadmap.items():
143- threads[tid] = Stats(pp.getstats(), {})
144- _g_threadmap = {}
145- return ret, Stats(p.getstats(), threads)
146+ def _thread_profile(self, f, *args, **kwds):
147+ # we lose the first profile point for a new thread in order to
148+ # trampoline a new Profile object into place
149+ thr = thread.get_ident()
150+ self._g_threadmap[thr] = p = Profiler()
151+ # this overrides our sys.setprofile hook:
152+ p.enable(subcalls=True, builtins=True)
153
154
155 class Stats(object):
156
157=== modified file 'bzrlib/tests/__init__.py'
158--- bzrlib/tests/__init__.py 2009-08-24 05:23:11 +0000
159+++ bzrlib/tests/__init__.py 2009-08-24 23:35:12 +0000
160@@ -579,13 +579,22 @@
161 bench_history=None,
162 list_only=False,
163 strict=False,
164+ result_decorators=None,
165 ):
166+ """Create a TextTestRunner.
167+
168+ :param result_decorators: An optional list of decorators to apply
169+ to the result object being used by the runner. Decorators are
170+ applied left to right - the first element in the list is the
171+ innermost decorator.
172+ """
173 self.stream = unittest._WritelnDecorator(stream)
174 self.descriptions = descriptions
175 self.verbosity = verbosity
176 self._bench_history = bench_history
177 self.list_only = list_only
178 self._strict = strict
179+ self._result_decorators = result_decorators or []
180
181 def run(self, test):
182 "Run the given test case or test suite."
183@@ -600,6 +609,9 @@
184 bench_history=self._bench_history,
185 strict=self._strict,
186 )
187+ run_result = result
188+ for decorator in self._result_decorators:
189+ run_result = decorator(run_result)
190 result.stop_early = self.stop_on_failure
191 result.report_starting()
192 if self.list_only:
193@@ -614,13 +626,13 @@
194 try:
195 import testtools
196 except ImportError:
197- test.run(result)
198+ test.run(run_result)
199 else:
200 if isinstance(test, testtools.ConcurrentTestSuite):
201 # We need to catch bzr specific behaviors
202- test.run(BZRTransformingResult(result))
203+ test.run(BZRTransformingResult(run_result))
204 else:
205- test.run(result)
206+ test.run(run_result)
207 run = result.testsRun
208 actionTaken = "Ran"
209 stopTime = time.time()
210@@ -2762,7 +2774,9 @@
211 strict=False,
212 runner_class=None,
213 suite_decorators=None,
214- stream=None):
215+ stream=None,
216+ result_decorators=None,
217+ ):
218 """Run a test suite for bzr selftest.
219
220 :param runner_class: The class of runner to use. Must support the
221@@ -2785,6 +2799,7 @@
222 bench_history=bench_history,
223 list_only=list_only,
224 strict=strict,
225+ result_decorators=result_decorators,
226 )
227 runner.stop_on_failure=stop_on_failure
228 # built in decorator factories:
229@@ -3131,7 +3146,7 @@
230 return result
231
232
233-class BZRTransformingResult(unittest.TestResult):
234+class ForwardingResult(unittest.TestResult):
235
236 def __init__(self, target):
237 unittest.TestResult.__init__(self)
238@@ -3143,6 +3158,21 @@
239 def stopTest(self, test):
240 self.result.stopTest(test)
241
242+ def addSkip(self, test, reason):
243+ self.result.addSkip(test, reason)
244+
245+ def addSuccess(self, test):
246+ self.result.addSuccess(test)
247+
248+ def addError(self, test, err):
249+ self.result.addError(test, err)
250+
251+ def addFailure(self, test, err):
252+ self.result.addFailure(test, err)
253+
254+
255+class BZRTransformingResult(ForwardingResult):
256+
257 def addError(self, test, err):
258 feature = self._error_looks_like('UnavailableFeature: ', err)
259 if feature is not None:
260@@ -3158,12 +3188,6 @@
261 else:
262 self.result.addFailure(test, err)
263
264- def addSkip(self, test, reason):
265- self.result.addSkip(test, reason)
266-
267- def addSuccess(self, test):
268- self.result.addSuccess(test)
269-
270 def _error_looks_like(self, prefix, err):
271 """Deserialize exception and returns the stringify value."""
272 import subunit
273@@ -3181,6 +3205,38 @@
274 return value
275
276
277+class ProfileResult(ForwardingResult):
278+ """Generate profiling data for all activity between start and success.
279+
280+ The profile data is appended to the test's _benchcalls attribute and can
281+ be accessed by the forwarded-to TestResult.
282+
283+ While it might be cleaner do accumulate this in stopTest, addSuccess is
284+ where our existing output support for lsprof is, and this class aims to
285+ fit in with that: while it could be moved it's not necessary to accomplish
286+ test profiling, nor would be be dramatically cleaner.
287+ """
288+
289+ def startTest(self, test):
290+ self.profiler = bzrlib.lsprof.BzrProfiler()
291+ self.profiler.start()
292+ ForwardingResult.startTest(self, test)
293+
294+ def addSuccess(self, test):
295+ stats = self.profiler.stop()
296+ try:
297+ calls = test._benchcalls
298+ except AttributeError:
299+ test._benchcalls = []
300+ calls = test._benchcalls
301+ calls.append(((test.id(), "", ""), stats))
302+ ForwardingResult.addSuccess(self, test)
303+
304+ def stopTest(self, test):
305+ ForwardingResult.stopTest(self, test)
306+ self.profiler = None
307+
308+
309 # Controlled by "bzr selftest -E=..." option
310 # Currently supported:
311 # -Eallow_debug Will no longer clear debug.debug_flags() so it
312@@ -3208,6 +3264,7 @@
313 runner_class=None,
314 suite_decorators=None,
315 stream=None,
316+ lsprof_tests=False,
317 ):
318 """Run the whole test suite under the enhanced runner"""
319 # XXX: Very ugly way to do this...
320@@ -3239,6 +3296,9 @@
321 if starting_with:
322 # But always filter as requested.
323 suite = filter_suite_by_id_startswith(suite, starting_with)
324+ result_decorators = []
325+ if lsprof_tests:
326+ result_decorators.append(ProfileResult)
327 return run_suite(suite, 'testbzr', verbose=verbose, pattern=pattern,
328 stop_on_failure=stop_on_failure,
329 transport=transport,
330@@ -3252,6 +3312,7 @@
331 runner_class=runner_class,
332 suite_decorators=suite_decorators,
333 stream=stream,
334+ result_decorators=result_decorators,
335 )
336 finally:
337 default_transport = old_transport
338
339=== modified file 'bzrlib/tests/blackbox/test_selftest.py'
340--- bzrlib/tests/blackbox/test_selftest.py 2009-08-24 05:23:11 +0000
341+++ bzrlib/tests/blackbox/test_selftest.py 2009-08-24 23:35:12 +0000
342@@ -172,3 +172,7 @@
343 outputs_nothing(['selftest', '--list-only', '--exclude', 'selftest'])
344 finally:
345 tests.selftest = original_selftest
346+
347+ def test_lsprof_tests(self):
348+ params = self.get_params_passed_to_core('selftest --lsprof-tests')
349+ self.assertEqual(True, params[1]["lsprof_tests"])
350
351=== modified file 'bzrlib/tests/test_lsprof.py'
352--- bzrlib/tests/test_lsprof.py 2009-03-23 14:59:43 +0000
353+++ bzrlib/tests/test_lsprof.py 2009-08-24 23:35:12 +0000
354@@ -92,3 +92,22 @@
355 self.stats.save(f)
356 data1 = cPickle.load(open(f))
357 self.assertEqual(type(data1), bzrlib.lsprof.Stats)
358+
359+
360+class TestBzrProfiler(tests.TestCase):
361+
362+ _test_needs_features = [LSProfFeature]
363+
364+ def test_start_call_stuff_stop(self):
365+ profiler = bzrlib.lsprof.BzrProfiler()
366+ profiler.start()
367+ try:
368+ def a_function():
369+ pass
370+ a_function()
371+ finally:
372+ stats = profiler.stop()
373+ stats.freeze()
374+ lines = [str(data) for data in stats.data]
375+ lines = [line for line in lines if 'a_function' in line]
376+ self.assertLength(1, lines)
377
378=== modified file 'bzrlib/tests/test_selftest.py'
379--- bzrlib/tests/test_selftest.py 2009-08-24 05:35:28 +0000
380+++ bzrlib/tests/test_selftest.py 2009-08-24 23:35:12 +0000
381@@ -687,6 +687,25 @@
382 self.assertEqual(url, t.clone('..').base)
383
384
385+class TestProfileResult(tests.TestCase):
386+
387+ def test_profiles_tests(self):
388+ terminal = unittest.TestResult()
389+ result = tests.ProfileResult(terminal)
390+ class Sample(tests.TestCase):
391+ def a(self):
392+ self.sample_function()
393+ def sample_function(self):
394+ pass
395+ test = Sample("a")
396+ test.attrs_to_keep = test.attrs_to_keep + ('_benchcalls',)
397+ test.run(result)
398+ self.assertLength(1, test._benchcalls)
399+ # We must be able to unpack it as the test reporting code wants
400+ (_, _, _), stats = test._benchcalls[0]
401+ self.assertTrue(callable(stats.pprint))
402+
403+
404 class TestTestResult(tests.TestCase):
405
406 def check_timing(self, test_case, expected_re):
407@@ -1031,6 +1050,20 @@
408 '\n'
409 'OK \\(known_failures=1\\)\n')
410
411+ def test_result_decorator(self):
412+ # decorate results
413+ calls = []
414+ class LoggingDecorator(tests.ForwardingResult):
415+ def startTest(self, test):
416+ tests.ForwardingResult.startTest(self, test)
417+ calls.append('start')
418+ test = unittest.FunctionTestCase(lambda:None)
419+ stream = StringIO()
420+ runner = tests.TextTestRunner(stream=stream,
421+ result_decorators=[LoggingDecorator])
422+ result = self.run_test_runner(runner, test)
423+ self.assertLength(1, calls)
424+
425 def test_skipped_test(self):
426 # run a test that is skipped, and check the suite as a whole still
427 # succeeds.
428@@ -1103,10 +1136,6 @@
429 self.assertContainsRe(out.getvalue(),
430 r'(?m)^ this test never runs')
431
432- def test_not_applicable_demo(self):
433- # just so you can see it in the test output
434- raise tests.TestNotApplicable('this test is just a demonstation')
435-
436 def test_unsupported_features_listed(self):
437 """When unsupported features are encountered they are detailed."""
438 class Feature1(tests.Feature):
439@@ -1480,6 +1509,7 @@
440 self.assertEqual((time.sleep, (0.003,), {}), self._benchcalls[1][0])
441 self.assertIsInstance(self._benchcalls[0][1], bzrlib.lsprof.Stats)
442 self.assertIsInstance(self._benchcalls[1][1], bzrlib.lsprof.Stats)
443+ del self._benchcalls[:]
444
445 def test_knownFailure(self):
446 """Self.knownFailure() should raise a KnownFailure exception."""
447@@ -1817,6 +1847,19 @@
448 self.assertNotContainsRe("Test.b", output.getvalue())
449 self.assertLength(2, output.readlines())
450
451+ def test_lsprof_tests(self):
452+ calls = []
453+ class Test(object):
454+ def __call__(test, result):
455+ test.run(result)
456+ def run(test, result):
457+ self.assertIsInstance(result, tests.ForwardingResult)
458+ calls.append("called")
459+ def countTestCases(self):
460+ return 1
461+ self.run_selftest(test_suite_factory=Test, lsprof_tests=True)
462+ self.assertLength(1, calls)
463+
464 def test_random(self):
465 # test randomising by listing a number of tests.
466 output_123 = self.run_selftest(test_suite_factory=self.factory,