From 95fadd5740d05fda9c525e1e7d8e75b60ad1b143 Mon Sep 17 00:00:00 2001 From: smarie Date: Sun, 29 Mar 2020 14:20:09 +0200 Subject: [PATCH] Improved time counter used to compute test durations. (#6939) Co-authored-by: Sylvain MARIE Co-authored-by: Ran Benita Co-authored-by: Bruno Oliveira --- AUTHORS | 1 + changelog/4391.improvement.rst | 1 + changelog/6940.improvement.rst | 1 + src/_pytest/reports.py | 2 +- src/_pytest/runner.py | 45 ++++++++++++++++++++++++++-------- testing/acceptance_test.py | 44 ++++++++++++++++++++++++--------- 6 files changed, 71 insertions(+), 23 deletions(-) create mode 100644 changelog/4391.improvement.rst create mode 100644 changelog/6940.improvement.rst diff --git a/AUTHORS b/AUTHORS index af0dc62c4d8..7c791cde8ca 100644 --- a/AUTHORS +++ b/AUTHORS @@ -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 00000000000..e7e4090f1dd --- /dev/null +++ b/changelog/4391.improvement.rst @@ -0,0 +1 @@ +Improved precision of test durations measurement. ``CallInfo`` items now have a new ``.duration`` attribute, created using ``time.perf_counter()``. This attribute is used to fill the ``.duration`` attribute, which is more accurate than the previous ``.stop - .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 00000000000..ab5fc0d49bf --- /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 dfda7f0e382..8459c1cb9e4 100644 --- a/src/_pytest/reports.py +++ b/src/_pytest/reports.py @@ -273,7 +273,7 @@ def from_item_and_call(cls, item, call) -> "TestReport": 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 7124996c8ff..c13dff711a1 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 @@ def result(self): 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 @@ def from_call(cls, func, when, reraise=None) -> "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 1bfdeed380e..c28c35b8621 100644 --- a/testing/acceptance_test.py +++ b/testing/acceptance_test.py @@ -896,26 +896,42 @@ def test_has_plugin(self, request): 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 @@ def test_calls_showall(self, testdir): 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 @@ def test_calls_showall_verbose(self, testdir): 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():