From 6883007a86bdf0d7cf4560b949fd5e577dab1013 Mon Sep 17 00:00:00 2001 From: Giampaolo Rodola Date: Mon, 3 Apr 2023 00:12:51 +0200 Subject: bpo-4080: unittest durations (#12271) --- Doc/library/unittest.rst | 42 ++++++++++++-- Doc/whatsnew/3.12.rst | 21 +++++++ Lib/test/test_unittest/support.py | 16 ++++++ Lib/test/test_unittest/test_break.py | 7 ++- Lib/test/test_unittest/test_program.py | 9 ++- Lib/test/test_unittest/test_result.py | 18 +----- Lib/test/test_unittest/test_runner.py | 67 +++++++++++++++++++++- Lib/unittest/case.py | 12 ++++ Lib/unittest/main.py | 12 +++- Lib/unittest/result.py | 7 +++ Lib/unittest/runner.py | 42 +++++++++++++- .../2022-11-24-13-23-07.gh-issue-48330.6uAX9F.rst | 8 +++ 12 files changed, 227 insertions(+), 34 deletions(-) create mode 100644 Misc/NEWS.d/next/Library/2022-11-24-13-23-07.gh-issue-48330.6uAX9F.rst diff --git a/Doc/library/unittest.rst b/Doc/library/unittest.rst index 1577149..d1a977f 100644 --- a/Doc/library/unittest.rst +++ b/Doc/library/unittest.rst @@ -244,6 +244,10 @@ Command-line options Show local variables in tracebacks. +.. cmdoption:: --durations N + + Show the N slowest test cases (N=0 for all). + .. versionadded:: 3.2 The command-line options ``-b``, ``-c`` and ``-f`` were added. @@ -253,10 +257,12 @@ Command-line options .. versionadded:: 3.7 The command-line option ``-k``. +.. versionadded:: 3.12 + The command-line option ``--durations``. + The command line can also be used for test discovery, for running all of the tests in a project or just a subset. - .. _unittest-test-discovery: Test Discovery @@ -2009,6 +2015,13 @@ Loading and running tests A list containing :class:`TestCase` instances that were marked as expected failures, but succeeded. + .. attribute:: collectedDurations + + A list containing 2-tuples of :class:`TestCase` instances and floats + representing the elapsed time of each test which was run. + + .. versionadded:: 3.12 + .. attribute:: shouldStop Set to ``True`` when the execution of tests should stop by :meth:`stop`. @@ -2160,14 +2173,27 @@ Loading and running tests .. versionadded:: 3.4 + .. method:: addDuration(test, elapsed) + + Called when the test case finishes. *elapsed* is the time represented in + seconds, and it includes the execution of cleanup functions. + + .. versionadded:: 3.12 -.. class:: TextTestResult(stream, descriptions, verbosity) +.. class:: TextTestResult(stream, descriptions, verbosity, *, durations=None) A concrete implementation of :class:`TestResult` used by the - :class:`TextTestRunner`. + :class:`TextTestRunner`. Subclasses should accept ``**kwargs`` to ensure + compatibility as the interface changes. .. versionadded:: 3.2 + .. versionadded:: 3.12 + Added *durations* keyword argument. + + .. versionchanged:: 3.12 + Subclasses should accept ``**kwargs`` to ensure compatibility as the + interface changes. .. data:: defaultTestLoader @@ -2177,7 +2203,8 @@ Loading and running tests .. class:: TextTestRunner(stream=None, descriptions=True, verbosity=1, failfast=False, \ - buffer=False, resultclass=None, warnings=None, *, tb_locals=False) + buffer=False, resultclass=None, warnings=None, *, \ + tb_locals=False, durations=None) A basic test runner implementation that outputs results to a stream. If *stream* is ``None``, the default, :data:`sys.stderr` is used as the output stream. This class @@ -2195,14 +2222,17 @@ Loading and running tests *warnings* to ``None``. .. versionchanged:: 3.2 - Added the ``warnings`` argument. + Added the *warnings* parameter. .. versionchanged:: 3.2 The default stream is set to :data:`sys.stderr` at instantiation time rather than import time. .. versionchanged:: 3.5 - Added the tb_locals parameter. + Added the *tb_locals* parameter. + + .. versionchanged:: 3.12 + Added the *durations* parameter. .. method:: _makeResult() diff --git a/Doc/whatsnew/3.12.rst b/Doc/whatsnew/3.12.rst index 93543cb..3df3ef7 100644 --- a/Doc/whatsnew/3.12.rst +++ b/Doc/whatsnew/3.12.rst @@ -371,6 +371,27 @@ unicodedata * The Unicode database has been updated to version 15.0.0. (Contributed by Benjamin Peterson in :gh:`96734`). +unittest +-------- + +Added ``--durations`` command line option, showing the N slowest test cases:: + + python3 -m unittest --durations=3 lib.tests.test_threading + ..... + Slowest test durations + ---------------------------------------------------------------------- + 1.210s test_timeout (Lib.test.test_threading.BarrierTests) + 1.003s test_default_timeout (Lib.test.test_threading.BarrierTests) + 0.518s test_timeout (Lib.test.test_threading.EventTests) + + (0.000 durations hidden. Use -v to show these durations.) + ---------------------------------------------------------------------- + Ran 158 tests in 9.869s + + OK (skipped=3) + +(Contributed by Giampaolo Rodola in :issue:`4080`) + uuid ---- diff --git a/Lib/test/test_unittest/support.py b/Lib/test/test_unittest/support.py index 5292653..8c97bf5 100644 --- a/Lib/test/test_unittest/support.py +++ b/Lib/test/test_unittest/support.py @@ -136,3 +136,19 @@ class ResultWithNoStartTestRunStopTestRun(object): def wasSuccessful(self): return True + + +class BufferedWriter: + def __init__(self): + self.result = '' + self.buffer = '' + + def write(self, arg): + self.buffer += arg + + def flush(self): + self.result += self.buffer + self.buffer = '' + + def getvalue(self): + return self.result diff --git a/Lib/test/test_unittest/test_break.py b/Lib/test/test_unittest/test_break.py index 33cbdd2..1da98af 100644 --- a/Lib/test/test_unittest/test_break.py +++ b/Lib/test/test_unittest/test_break.py @@ -236,6 +236,7 @@ class TestBreak(unittest.TestCase): self.testRunner = FakeRunner self.test = test self.result = None + self.durations = None p = Program(False) p.runTests() @@ -244,7 +245,8 @@ class TestBreak(unittest.TestCase): 'verbosity': verbosity, 'failfast': failfast, 'tb_locals': False, - 'warnings': None})]) + 'warnings': None, + 'durations': None})]) self.assertEqual(FakeRunner.runArgs, [test]) self.assertEqual(p.result, result) @@ -259,7 +261,8 @@ class TestBreak(unittest.TestCase): 'verbosity': verbosity, 'failfast': failfast, 'tb_locals': False, - 'warnings': None})]) + 'warnings': None, + 'durations': None})]) self.assertEqual(FakeRunner.runArgs, [test]) self.assertEqual(p.result, result) diff --git a/Lib/test/test_unittest/test_program.py b/Lib/test/test_unittest/test_program.py index 3645bcf..f138f68 100644 --- a/Lib/test/test_unittest/test_program.py +++ b/Lib/test/test_unittest/test_program.py @@ -284,6 +284,7 @@ class TestCommandLineArgs(unittest.TestCase): program.failfast = 'failfast' program.buffer = 'buffer' program.warnings = 'warnings' + program.durations = '5' program.runTests() @@ -291,7 +292,8 @@ class TestCommandLineArgs(unittest.TestCase): 'failfast': 'failfast', 'buffer': 'buffer', 'tb_locals': False, - 'warnings': 'warnings'}) + 'warnings': 'warnings', + 'durations': '5'}) self.assertEqual(FakeRunner.test, 'test') self.assertIs(program.result, RESULT) @@ -320,7 +322,8 @@ class TestCommandLineArgs(unittest.TestCase): 'failfast': False, 'tb_locals': True, 'verbosity': 1, - 'warnings': None}) + 'warnings': None, + 'durations': None}) def testRunTestsOldRunnerClass(self): program = self.program @@ -333,6 +336,7 @@ class TestCommandLineArgs(unittest.TestCase): program.failfast = 'failfast' program.buffer = 'buffer' program.test = 'test' + program.durations = '0' program.runTests() @@ -356,6 +360,7 @@ class TestCommandLineArgs(unittest.TestCase): program = self.program program.catchbreak = True + program.durations = None program.testRunner = FakeRunner diff --git a/Lib/test/test_unittest/test_result.py b/Lib/test/test_unittest/test_result.py index efd9c90..37d0fe1 100644 --- a/Lib/test/test_unittest/test_result.py +++ b/Lib/test/test_unittest/test_result.py @@ -6,7 +6,9 @@ from test.support import warnings_helper, captured_stdout import traceback import unittest +from unittest import mock from unittest.util import strclass +from test.test_unittest.support import BufferedWriter class MockTraceback(object): @@ -33,22 +35,6 @@ def bad_cleanup2(): raise ValueError('bad cleanup2') -class BufferedWriter: - def __init__(self): - self.result = '' - self.buffer = '' - - def write(self, arg): - self.buffer += arg - - def flush(self): - self.result += self.buffer - self.buffer = '' - - def getvalue(self): - return self.result - - class Test_TestResult(unittest.TestCase): # Note: there are not separate tests for TestResult.wasSuccessful(), # TestResult.errors, TestResult.failures, TestResult.testsRun or diff --git a/Lib/test/test_unittest/test_runner.py b/Lib/test/test_unittest/test_runner.py index df584b7..1ce42a1 100644 --- a/Lib/test/test_unittest/test_runner.py +++ b/Lib/test/test_unittest/test_runner.py @@ -8,8 +8,11 @@ from test import support import unittest from unittest.case import _Outcome -from test.test_unittest.support import (LoggingResult, - ResultWithNoStartTestRunStopTestRun) +from test.test_unittest.support import ( + BufferedWriter, + LoggingResult, + ResultWithNoStartTestRunStopTestRun, +) def resultFactory(*_): @@ -1176,6 +1179,7 @@ class Test_TextTestRunner(unittest.TestCase): self.assertTrue(runner.descriptions) self.assertEqual(runner.resultclass, unittest.TextTestResult) self.assertFalse(runner.tb_locals) + self.assertIsNone(runner.durations) def test_multiple_inheritance(self): class AResult(unittest.TestResult): @@ -1362,6 +1366,65 @@ class Test_TextTestRunner(unittest.TestCase): runner = unittest.TextTestRunner(f) self.assertTrue(runner.stream.stream is f) + def test_durations(self): + def run(test, expect_durations): + stream = BufferedWriter() + runner = unittest.TextTestRunner(stream=stream, durations=5, verbosity=2) + result = runner.run(test) + self.assertEqual(result.durations, 5) + stream.flush() + text = stream.getvalue() + regex = r"\n\d+.\d\d\ds" + if expect_durations: + self.assertEqual(len(result.collectedDurations), 1) + self.assertIn('Slowest test durations', text) + self.assertRegex(text, regex) + else: + self.assertEqual(len(result.collectedDurations), 0) + self.assertNotIn('Slowest test durations', text) + self.assertNotRegex(text, regex) + + # success + class Foo(unittest.TestCase): + def test_1(self): + pass + + run(Foo('test_1'), True) + + # failure + class Foo(unittest.TestCase): + def test_1(self): + self.assertEqual(0, 1) + + run(Foo('test_1'), True) + + # error + class Foo(unittest.TestCase): + def test_1(self): + 1 / 0 + + run(Foo('test_1'), True) + + + # error in setUp and tearDown + class Foo(unittest.TestCase): + def setUp(self): + 1 / 0 + tearDown = setUp + def test_1(self): + pass + + run(Foo('test_1'), True) + + # skip (expect no durations) + class Foo(unittest.TestCase): + @unittest.skip("reason") + def test_1(self): + pass + + run(Foo('test_1'), False) + + if __name__ == "__main__": unittest.main() diff --git a/Lib/unittest/case.py b/Lib/unittest/case.py index 5167c5f..018f22e 100644 --- a/Lib/unittest/case.py +++ b/Lib/unittest/case.py @@ -9,6 +9,7 @@ import warnings import collections import contextlib import traceback +import time import types from . import result @@ -572,6 +573,15 @@ class TestCase(object): else: addUnexpectedSuccess(self) + def _addDuration(self, result, elapsed): + try: + addDuration = result.addDuration + except AttributeError: + warnings.warn("TestResult has no addDuration method", + RuntimeWarning) + else: + addDuration(self, elapsed) + def _callSetUp(self): self.setUp() @@ -612,6 +622,7 @@ class TestCase(object): getattr(testMethod, "__unittest_expecting_failure__", False) ) outcome = _Outcome(result) + start_time = time.perf_counter() try: self._outcome = outcome @@ -625,6 +636,7 @@ class TestCase(object): with outcome.testPartExecutor(self): self._callTearDown() self.doCleanups() + self._addDuration(result, (time.perf_counter() - start_time)) if outcome.success: if expecting_failure: diff --git a/Lib/unittest/main.py b/Lib/unittest/main.py index 046fbd3..0792750 100644 --- a/Lib/unittest/main.py +++ b/Lib/unittest/main.py @@ -66,7 +66,8 @@ class TestProgram(object): def __init__(self, module='__main__', defaultTest=None, argv=None, testRunner=None, testLoader=loader.defaultTestLoader, exit=True, verbosity=1, failfast=None, catchbreak=None, - buffer=None, warnings=None, *, tb_locals=False): + buffer=None, warnings=None, *, tb_locals=False, + durations=None): if isinstance(module, str): self.module = __import__(module) for part in module.split('.')[1:]: @@ -82,6 +83,7 @@ class TestProgram(object): self.verbosity = verbosity self.buffer = buffer self.tb_locals = tb_locals + self.durations = durations if warnings is None and not sys.warnoptions: # even if DeprecationWarnings are ignored by default # print them anyway unless other warnings settings are @@ -178,6 +180,9 @@ class TestProgram(object): parser.add_argument('--locals', dest='tb_locals', action='store_true', help='Show local variables in tracebacks') + parser.add_argument('--durations', dest='durations', type=int, + default=None, metavar="N", + help='Show the N slowest test cases (N=0 for all)') if self.failfast is None: parser.add_argument('-f', '--failfast', dest='failfast', action='store_true', @@ -258,9 +263,10 @@ class TestProgram(object): failfast=self.failfast, buffer=self.buffer, warnings=self.warnings, - tb_locals=self.tb_locals) + tb_locals=self.tb_locals, + durations=self.durations) except TypeError: - # didn't accept the tb_locals argument + # didn't accept the tb_locals or durations argument testRunner = self.testRunner(verbosity=self.verbosity, failfast=self.failfast, buffer=self.buffer, diff --git a/Lib/unittest/result.py b/Lib/unittest/result.py index 5ca4c23..fa9bea4 100644 --- a/Lib/unittest/result.py +++ b/Lib/unittest/result.py @@ -43,6 +43,7 @@ class TestResult(object): self.skipped = [] self.expectedFailures = [] self.unexpectedSuccesses = [] + self.collectedDurations = [] self.shouldStop = False self.buffer = False self.tb_locals = False @@ -157,6 +158,12 @@ class TestResult(object): """Called when a test was expected to fail, but succeed.""" self.unexpectedSuccesses.append(test) + def addDuration(self, test, elapsed): + """Called when a test finished to run, regardless of its outcome.""" + # support for a TextTestRunner using an old TestResult class + if hasattr(self, "collectedDurations"): + self.collectedDurations.append((test, elapsed)) + def wasSuccessful(self): """Tells whether or not this result was a success.""" # The hasattr check is for test_result's OldResult test. That diff --git a/Lib/unittest/runner.py b/Lib/unittest/runner.py index 6678adb..a51c5c5 100644 --- a/Lib/unittest/runner.py +++ b/Lib/unittest/runner.py @@ -35,13 +35,16 @@ class TextTestResult(result.TestResult): separator1 = '=' * 70 separator2 = '-' * 70 - def __init__(self, stream, descriptions, verbosity): + def __init__(self, stream, descriptions, verbosity, *, durations=None): + """Construct a TextTestResult. Subclasses should accept **kwargs + to ensure compatibility as the interface changes.""" super(TextTestResult, self).__init__(stream, descriptions, verbosity) self.stream = stream self.showAll = verbosity > 1 self.dots = verbosity == 1 self.descriptions = descriptions self._newline = True + self.durations = durations def getDescription(self, test): doc_first_line = test.shortDescription() @@ -168,7 +171,7 @@ class TextTestRunner(object): def __init__(self, stream=None, descriptions=True, verbosity=1, failfast=False, buffer=False, resultclass=None, warnings=None, - *, tb_locals=False): + *, tb_locals=False, durations=None): """Construct a TextTestRunner. Subclasses should accept **kwargs to ensure compatibility as the @@ -182,12 +185,41 @@ class TextTestRunner(object): self.failfast = failfast self.buffer = buffer self.tb_locals = tb_locals + self.durations = durations self.warnings = warnings if resultclass is not None: self.resultclass = resultclass def _makeResult(self): - return self.resultclass(self.stream, self.descriptions, self.verbosity) + try: + return self.resultclass(self.stream, self.descriptions, + self.verbosity, durations=self.durations) + except TypeError: + # didn't accept the durations argument + return self.resultclass(self.stream, self.descriptions, + self.verbosity) + + def _printDurations(self, result): + if not result.collectedDurations: + return + ls = sorted(result.collectedDurations, key=lambda x: x[1], + reverse=True) + if self.durations > 0: + ls = ls[:self.durations] + self.stream.writeln("Slowest test durations") + if hasattr(result, 'separator2'): + self.stream.writeln(result.separator2) + hidden = False + for test, elapsed in ls: + if self.verbosity < 2 and elapsed < 0.001: + hidden = True + continue + self.stream.writeln("%-10s %s" % ("%.3fs" % elapsed, test)) + if hidden: + self.stream.writeln("\n(durations < 0.001s were hidden; " + "use -v to show these durations)") + else: + self.stream.writeln("") def run(self, test): "Run the given test case or test suite." @@ -213,8 +245,12 @@ class TextTestRunner(object): stopTime = time.perf_counter() timeTaken = stopTime - startTime result.printErrors() + if self.durations is not None: + self._printDurations(result) + if hasattr(result, 'separator2'): self.stream.writeln(result.separator2) + run = result.testsRun self.stream.writeln("Ran %d test%s in %.3fs" % (run, run != 1 and "s" or "", timeTaken)) diff --git a/Misc/NEWS.d/next/Library/2022-11-24-13-23-07.gh-issue-48330.6uAX9F.rst b/Misc/NEWS.d/next/Library/2022-11-24-13-23-07.gh-issue-48330.6uAX9F.rst new file mode 100644 index 0000000..5b63a0a --- /dev/null +++ b/Misc/NEWS.d/next/Library/2022-11-24-13-23-07.gh-issue-48330.6uAX9F.rst @@ -0,0 +1,8 @@ +Added ``--durations`` command line option, showing the N slowest test cases. +:class:`unittest.TextTestRunner` and :class:`unittest.TextTestResult` +constructors accept a new *durations* keyword argument. Subclasses should take +this into account or accept ``**kwargs``. Added +:meth:`unittest.TestResult.addDuration` method and +:attr:`unittest.TestResult.collectedDurations` attribute. + +(Contributed by Giampaolo Rodola) -- cgit v0.12