bpo-4080: unittest durations (#12271)

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)
 
-.. class:: TextTestResult(stream, descriptions, verbosity)
+      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, *, 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()
 

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
 ----
 

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

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)
 

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
 

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

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,
+from test.test_unittest.support import (
-                                   ResultWithNoStartTestRunStopTestRun)
+    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()

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:

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,

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

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))

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)