bpo-4080: unittest durations

Doc/library/unittest.rst

@@ -239,6 +239,11 @@ Command-line options
 
    Show local variables in tracebacks.
 
+.. cmdoption:: --durations
+
+   Show the slowest test cases. If ``-v`` option is used also shows the
+   elapsed time of each individual test case.
+
 .. versionadded:: 3.2
    The command-line options ``-b``, ``-c`` and ``-f`` were added.
 
@@ -248,10 +253,12 @@ Command-line options
 .. versionadded:: 3.7
    The command-line option ``-k``.
 
+.. versionadded:: 3.8
+   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
@@ -1868,6 +1875,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.8
+
    .. attribute:: shouldStop
 
       Set to ``True`` when the execution of tests should stop by :meth:`stop`.
@@ -2019,16 +2033,25 @@ Loading and running tests
 
       .. versionadded:: 3.4
 
+   .. method:: addDuration(test, elapsed)
+
+      Called when the test case finishes. *elapsed* is the time represented
+      in seconds.
+
+      .. versionadded:: 3.8
 
-.. 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
       This class was previously named ``_TextTestResult``. The old name still
       exists as an alias but is deprecated.
 
+   .. versionadded:: 3.8
+      Added *durations* keyword argument.
 
 .. data:: defaultTestLoader
 
@@ -2038,7 +2061,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
@@ -2059,14 +2083,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.8
+      Added the *durations* parameter.
 
    .. method:: _makeResult()
 

Doc/whatsnew/3.8.rst

@@ -353,6 +353,25 @@ unittest
   :meth:`~unittest.TestCase.setUpClass()`.
   (Contributed by Lisa Roach in :issue:`24412`.)
 
+* Added ``--durations`` command line option, showing the slowest test cases.
+  If ``-v`` is used also shows the elapsed time of each individual test case::
+
+    python3 -m unittest --durations=3 lib.tests.test_threading
+    .....
+    Slowest test durations
+    ----------------------------------------------------------------------
+    0.518s     test_timeout (Lib.test.test_threading.EventTests)
+    1.003s     test_default_timeout (Lib.test.test_threading.BarrierTests)
+    1.010s     test_timeout (Lib.test.test_threading.BarrierTests)
+
+    (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`)
+
 venv
 ----
 
@@ -664,6 +683,12 @@ Changes in the Python API
   :exc:`dbm.gnu.error` or :exc:`dbm.ndbm.error`) instead of :exc:`KeyError`.
   (Contributed by Xiang Zhang in :issue:`33106`.)
 
+* :class:`unittest.TextTestRunner` and :class:`unittest.TextTestResult`
+  constructors have 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 in :issue:`4080`)
 
 CPython bytecode changes
 ------------------------

Lib/unittest/case.py

@@ -10,6 +10,7 @@
 import collections
 import contextlib
 import traceback
+import time
 
 from . import result
 from .util import (strclass, safe_repr, _count_diff_all_purpose,
@@ -604,6 +605,15 @@ def _addUnexpectedSuccess(self, result):
         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 run(self, result=None):
         orig_result = result
         if result is None:
@@ -631,6 +641,7 @@ def run(self, result=None):
                                           "__unittest_expecting_failure__", False)
         expecting_failure = expecting_failure_class or expecting_failure_method
         outcome = _Outcome(result)
+        start_time = time.perf_counter()
         try:
             self._outcome = outcome
 
@@ -645,6 +656,8 @@ def run(self, result=None):
                     self.tearDown()
 
             self.doCleanups()
+            self._addDuration(result, (time.perf_counter() - start_time))
+
             for test, reason in outcome.skipped:
                 self._addSkip(result, test, reason)
             self._feedErrorsToResult(result, outcome.errors)

Lib/unittest/main.py

@@ -65,7 +65,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:]:
@@ -81,6 +82,7 @@ def __init__(self, module='__main__', defaultTest=None, argv=None,
         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
@@ -175,6 +177,9 @@ def _getParentArgParser(self):
         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,
+                            help='Show test durations')
         if self.failfast is None:
             parser.add_argument('-f', '--failfast', dest='failfast',
                                 action='store_true',
@@ -195,7 +200,6 @@ def _getParentArgParser(self):
                                 action='append', type=_convert_select_pattern,
                                 help='Only run tests which match the given substring')
             self.testNamePatterns = []
-
         return parser
 
     def _getMainArgParser(self, parent):
@@ -255,9 +259,10 @@ def runTests(self):
                                                  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 @@ def __init__(self, stream=None, descriptions=None, verbosity=None):
         self.skipped = []
         self.expectedFailures = []
         self.unexpectedSuccesses = []
+        self.collectedDurations = []
         self.shouldStop = False
         self.buffer = False
         self.tb_locals = False
@@ -157,6 +158,10 @@ def addUnexpectedSuccess(self, test):
         """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."""
+        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

@@ -34,12 +34,22 @@ 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.durations = durations
+        self._lastDuration = None
+
+    def _formatDuration(self, s):
+        if self.durations is not None:
+            return "[%.3fs] %s" % (self._lastDuration, s)
+        else:
+            return s
 
     def getDescription(self, test):
         doc_first_line = test.shortDescription()
@@ -58,23 +68,23 @@ def startTest(self, test):
     def addSuccess(self, test):
         super(TextTestResult, self).addSuccess(test)
         if self.showAll:
-            self.stream.writeln("ok")
+            self.stream.writeln(self._formatDuration("ok"))
         elif self.dots:
             self.stream.write('.')
             self.stream.flush()
 
     def addError(self, test, err):
         super(TextTestResult, self).addError(test, err)
         if self.showAll:
-            self.stream.writeln("ERROR")
+            self.stream.writeln(self._formatDuration("ERROR"))
         elif self.dots:
             self.stream.write('E')
             self.stream.flush()
 
     def addFailure(self, test, err):
         super(TextTestResult, self).addFailure(test, err)
         if self.showAll:
-            self.stream.writeln("FAIL")
+            self.stream.writeln(self._formatDuration("FAIL"))
         elif self.dots:
             self.stream.write('F')
             self.stream.flush()
@@ -90,19 +100,23 @@ def addSkip(self, test, reason):
     def addExpectedFailure(self, test, err):
         super(TextTestResult, self).addExpectedFailure(test, err)
         if self.showAll:
-            self.stream.writeln("expected failure")
+            self.stream.writeln(self._formatDuration("expected failure"))
         elif self.dots:
             self.stream.write("x")
             self.stream.flush()
 
     def addUnexpectedSuccess(self, test):
         super(TextTestResult, self).addUnexpectedSuccess(test)
         if self.showAll:
-            self.stream.writeln("unexpected success")
+            self.stream.writeln(self._formatDuration("unexpected success"))
         elif self.dots:
             self.stream.write("u")
             self.stream.flush()
 
+    def addDuration(self, test, duration):
+        super(TextTestResult, self).addDuration(test, duration)
+        self._lastDuration = duration
+
     def printErrors(self):
         if self.dots or self.showAll:
             self.stream.writeln()
@@ -127,7 +141,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
@@ -141,12 +155,40 @@ def __init__(self, stream=None, descriptions=True, verbosity=1,
         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):
+        ls = sorted(result.collectedDurations, key=lambda x: x[1])
+        if self.durations > 0:
+            ls = ls[-self.durations:]
+        if not ls:
+            return
+        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(0.000 durations hidden.  Use -v to show these durations.)")
+        else:
+            self.stream.writeln("")
 
     def run(self, test):
         "Run the given test case or test suite."
@@ -181,8 +223,12 @@ def run(self, test):
             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))