diff options
| -rw-r--r-- | AUTHORS | 1 | ||||
| -rw-r--r-- | changelog/4391.improvement.rst | 1 | ||||
| -rw-r--r-- | changelog/6940.improvement.rst | 1 | ||||
| -rw-r--r-- | src/_pytest/reports.py | 2 | ||||
| -rw-r--r-- | src/_pytest/runner.py | 45 | ||||
| -rw-r--r-- | testing/acceptance_test.py | 44 |
6 files changed, 71 insertions, 23 deletions
@@ -254,6 +254,7 @@ Stefano Taschini Steffen Allner Stephan Obermann Sven-Hendrik Haase +Sylvain Marié Tadek Teleżyński Takafumi Arakaki Tarcisio Fischer diff --git a/changelog/4391.improvement.rst b/changelog/4391.improvement.rst new file mode 100644 index 000000000..e7e4090f1 --- /dev/null +++ b/changelog/4391.improvement.rst @@ -0,0 +1 @@ +Improved precision of test durations measurement. ``CallInfo`` items now have a new ``<CallInfo>.duration`` attribute, created using ``time.perf_counter()``. This attribute is used to fill the ``<TestReport>.duration`` attribute, which is more accurate than the previous ``<CallInfo>.stop - <CallInfo>.start`` (as these are based on ``time.time()``). diff --git a/changelog/6940.improvement.rst b/changelog/6940.improvement.rst new file mode 100644 index 000000000..ab5fc0d49 --- /dev/null +++ b/changelog/6940.improvement.rst @@ -0,0 +1 @@ +When using the ``--duration`` option, the terminal message output is now more precise about the number and durations of hidden items. diff --git a/src/_pytest/reports.py b/src/_pytest/reports.py index dfda7f0e3..8459c1cb9 100644 --- a/src/_pytest/reports.py +++ b/src/_pytest/reports.py @@ -273,7 +273,7 @@ class TestReport(BaseReport): Factory method to create and fill a TestReport with standard item and call info. """ when = call.when - duration = call.stop - call.start + duration = call.duration keywords = {x: 1 for x in item.keywords} excinfo = call.excinfo sections = [] diff --git a/src/_pytest/runner.py b/src/_pytest/runner.py index 7124996c8..c13dff711 100644 --- a/src/_pytest/runner.py +++ b/src/_pytest/runner.py @@ -2,6 +2,7 @@ import bdb import os import sys +from time import perf_counter from time import time from typing import Callable from typing import Dict @@ -59,15 +60,18 @@ def pytest_terminal_summary(terminalreporter): dlist.sort(key=lambda x: x.duration) dlist.reverse() if not durations: - tr.write_sep("=", "slowest test durations") + tr.write_sep("=", "slowest durations") else: - tr.write_sep("=", "slowest %s test durations" % durations) + tr.write_sep("=", "slowest %s durations" % durations) dlist = dlist[:durations] - for rep in dlist: + for i, rep in enumerate(dlist): if verbose < 2 and rep.duration < 0.005: tr.write_line("") - tr.write_line("(0.00 durations hidden. Use -vv to show these durations.)") + tr.write_line( + "(%s durations < 0.005s hidden. Use -vv to show these durations.)" + % (len(dlist) - i) + ) break tr.write_line("{:02.2f}s {:<8} {}".format(rep.duration, rep.when, rep.nodeid)) @@ -220,13 +224,23 @@ def call_runtest_hook(item, when: "Literal['setup', 'call', 'teardown']", **kwds @attr.s(repr=False) class CallInfo: - """ Result/Exception info a function invocation. """ + """ Result/Exception info a function invocation. + + :param result: The return value of the call, if it didn't raise. Can only be accessed + if excinfo is None. + :param Optional[ExceptionInfo] excinfo: The captured exception of the call, if it raised. + :param float start: The system time when the call started, in seconds since the epoch. + :param float stop: The system time when the call ended, in seconds since the epoch. + :param float duration: The call duration, in seconds. + :param str when: The context of invocation: "setup", "call", "teardown", ... + """ _result = attr.ib() excinfo = attr.ib(type=Optional[ExceptionInfo]) - start = attr.ib() - stop = attr.ib() - when = attr.ib() + start = attr.ib(type=float) + stop = attr.ib(type=float) + duration = attr.ib(type=float) + when = attr.ib(type=str) @property def result(self): @@ -238,8 +252,9 @@ class CallInfo: def from_call(cls, func, when, reraise=None) -> "CallInfo": #: context of invocation: one of "setup", "call", #: "teardown", "memocollect" - start = time() excinfo = None + start = time() + precise_start = perf_counter() try: result = func() except: # noqa @@ -247,8 +262,18 @@ class CallInfo: if reraise is not None and excinfo.errisinstance(reraise): raise result = None + # use the perf counter + precise_stop = perf_counter() + duration = precise_stop - precise_start stop = time() - return cls(start=start, stop=stop, when=when, result=result, excinfo=excinfo) + return cls( + start=start, + stop=stop, + duration=duration, + when=when, + result=result, + excinfo=excinfo, + ) def __repr__(self): if self.excinfo is None: diff --git a/testing/acceptance_test.py b/testing/acceptance_test.py index 1bfdeed38..c28c35b86 100644 --- a/testing/acceptance_test.py +++ b/testing/acceptance_test.py @@ -896,26 +896,42 @@ class TestInvocationVariants: class TestDurations: source = """ import time - frag = 0.002 + frag = 0.002 # 2 ms def test_something(): pass def test_2(): - time.sleep(frag*5) + time.sleep(frag*5) # 10 ms: on windows might sleep < 0.005s def test_1(): - time.sleep(frag) + time.sleep(frag) # 2 ms: on macOS/windows might sleep > 0.005s def test_3(): - time.sleep(frag*10) + time.sleep(frag*10) # 20 ms """ def test_calls(self, testdir): testdir.makepyfile(self.source) result = testdir.runpytest("--durations=10") assert result.ret == 0 - result.stdout.fnmatch_lines_random( - ["*durations*", "*call*test_3*", "*call*test_2*"] - ) + + # on Windows, test 2 (10ms) can actually sleep less than 5ms and become hidden + if sys.platform == "win32": + to_match = ["*durations*", "*call*test_3*"] + else: + to_match = ["*durations*", "*call*test_3*", "*call*test_2*"] + result.stdout.fnmatch_lines_random(to_match) + + # The number of hidden should be 8, but on macOS and windows it sometimes is 7 + # - on MacOS and Windows test 1 can last longer and appear in the list + # - on Windows test 2 can last less and disappear from the list + if sys.platform in ("win32", "darwin"): + nb_hidden = "*" + else: + nb_hidden = "8" + result.stdout.fnmatch_lines( - ["(0.00 durations hidden. Use -vv to show these durations.)"] + [ + "(%s durations < 0.005s hidden. Use -vv to show these durations.)" + % nb_hidden + ] ) def test_calls_show_2(self, testdir): @@ -929,7 +945,10 @@ class TestDurations: testdir.makepyfile(self.source) result = testdir.runpytest("--durations=0") assert result.ret == 0 - for x in "23": + + # on windows, test 2 (10ms) can actually sleep less than 5ms and become hidden + tested = "3" if sys.platform == "win32" else "23" + for x in tested: for y in ("call",): # 'setup', 'call', 'teardown': for line in result.stdout.lines: if ("test_%s" % x) in line and y in line: @@ -951,9 +970,10 @@ class TestDurations: def test_with_deselected(self, testdir): testdir.makepyfile(self.source) - result = testdir.runpytest("--durations=2", "-k test_2") + # on windows test 2 might sleep less than 0.005s and be hidden. Prefer test 3. + result = testdir.runpytest("--durations=2", "-k test_3") assert result.ret == 0 - result.stdout.fnmatch_lines(["*durations*", "*call*test_2*"]) + result.stdout.fnmatch_lines(["*durations*", "*call*test_3*"]) def test_with_failing_collection(self, testdir): testdir.makepyfile(self.source) @@ -975,7 +995,7 @@ class TestDurationWithFixture: source = """ import pytest import time - frag = 0.01 + frag = 0.02 # as on windows sleep(0.01) might take < 0.005s @pytest.fixture def setup_fixt(): |