[Python-checkins] bpo-4080: unittest durations (#12271)
giampaolo
webhook-mailer at python.org
Sun Apr 2 18:12:58 EDT 2023
https://github.com/python/cpython/commit/6883007a86bdf0d7cf4560b949fd5e577dab1013
commit: 6883007a86bdf0d7cf4560b949fd5e577dab1013
branch: main
author: Giampaolo Rodola <g.rodola at gmail.com>
committer: giampaolo <g.rodola at gmail.com>
date: 2023-04-03T00:12:51+02:00
summary:
bpo-4080: unittest durations (#12271)
files:
A Misc/NEWS.d/next/Library/2022-11-24-13-23-07.gh-issue-48330.6uAX9F.rst
M Doc/library/unittest.rst
M Doc/whatsnew/3.12.rst
M Lib/test/test_unittest/support.py
M Lib/test/test_unittest/test_break.py
M Lib/test/test_unittest/test_program.py
M Lib/test/test_unittest/test_result.py
M Lib/test/test_unittest/test_runner.py
M Lib/unittest/case.py
M Lib/unittest/main.py
M Lib/unittest/result.py
M Lib/unittest/runner.py
diff --git a/Doc/library/unittest.rst b/Doc/library/unittest.rst
index 1577149e9764..d1a977fd7da6 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 93543cb0790f..3df3ef711a90 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 529265304f28..8c97bf5c7297 100644
--- a/Lib/test/test_unittest/support.py
+++ b/Lib/test/test_unittest/support.py
@@ -136,3 +136,19 @@ def addSuccess(self, test):
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 33cbdd2661c1..1da98af3e74d 100644
--- a/Lib/test/test_unittest/test_break.py
+++ b/Lib/test/test_unittest/test_break.py
@@ -236,6 +236,7 @@ def __init__(self, catchbreak):
self.testRunner = FakeRunner
self.test = test
self.result = None
+ self.durations = None
p = Program(False)
p.runTests()
@@ -244,7 +245,8 @@ def __init__(self, catchbreak):
'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 @@ def __init__(self, catchbreak):
'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 3645bcf4b435..f138f6836514 100644
--- a/Lib/test/test_unittest/test_program.py
+++ b/Lib/test/test_unittest/test_program.py
@@ -284,6 +284,7 @@ def testRunTestsRunnerClass(self):
program.failfast = 'failfast'
program.buffer = 'buffer'
program.warnings = 'warnings'
+ program.durations = '5'
program.runTests()
@@ -291,7 +292,8 @@ def testRunTestsRunnerClass(self):
'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 @@ def test_locals(self):
'failfast': False,
'tb_locals': True,
'verbosity': 1,
- 'warnings': None})
+ 'warnings': None,
+ 'durations': None})
def testRunTestsOldRunnerClass(self):
program = self.program
@@ -333,6 +336,7 @@ def testRunTestsOldRunnerClass(self):
program.failfast = 'failfast'
program.buffer = 'buffer'
program.test = 'test'
+ program.durations = '0'
program.runTests()
@@ -356,6 +360,7 @@ def fakeInstallHandler():
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 efd9c9023505..37d0fe12409e 100644
--- a/Lib/test/test_unittest/test_result.py
+++ b/Lib/test/test_unittest/test_result.py
@@ -6,7 +6,9 @@
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 df584b7620d0..1ce42a106c58 100644
--- a/Lib/test/test_unittest/test_runner.py
+++ b/Lib/test/test_unittest/test_runner.py
@@ -8,8 +8,11 @@
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 @@ def test_init(self):
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 @@ def testSpecifiedStreamUsed(self):
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 5167c5f843f0..018f22e7ce0c 100644
--- a/Lib/unittest/case.py
+++ b/Lib/unittest/case.py
@@ -9,6 +9,7 @@
import collections
import contextlib
import traceback
+import time
import types
from . import result
@@ -572,6 +573,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 _callSetUp(self):
self.setUp()
@@ -612,6 +622,7 @@ def run(self, result=None):
getattr(testMethod, "__unittest_expecting_failure__", False)
)
outcome = _Outcome(result)
+ start_time = time.perf_counter()
try:
self._outcome = outcome
@@ -625,6 +636,7 @@ def run(self, result=None):
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 046fbd3a45dc..0792750ffd9e 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 @@ 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
@@ -178,6 +180,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, 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 @@ 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,
diff --git a/Lib/unittest/result.py b/Lib/unittest/result.py
index 5ca4c23238b4..fa9bea47c888 100644
--- a/Lib/unittest/result.py
+++ b/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,12 @@ 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."""
+ # 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 6678adb6a7d8..a51c5c562df0 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 @@ 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):
+ 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 @@ 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))
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 000000000000..5b63a0a6b96d
--- /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)
More information about the Python-checkins
mailing list