Improved time counter used to compute test durations. (#6939)

Co-authored-by: Sylvain MARIE <sylvain.marie@se.com>
Co-authored-by: Ran Benita <ran@unusedvar.com>
Co-authored-by: Bruno Oliveira <nicoddemus@gmail.com>

AUTHORS

@@ -254,6 +254,7 @@ Stefano Taschini
 Steffen Allner
 Stephan Obermann
 Sven-Hendrik Haase
+Sylvain Marié
 Tadek Teleżyński
 Takafumi Arakaki
 Tarcisio Fischer

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()``).

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.

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 = []

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()
+    start = attr.ib(type=float)
-    stop = attr.ib()
+    stop = attr.ib(type=float)
-    when = attr.ib()
+    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:

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