From 04c5ca5fce3ab2b9f07c0b486d8f2cea4c11a1b0 Mon Sep 17 00:00:00 2001 From: Sylvain MARIE Date: Thu, 19 Mar 2020 15:08:18 +0100 Subject: [PATCH 01/38] Improved time counter used to compute test durations. `CallInfo.start` is now retro-computed as `CallInfo.stop - duration`, where `duration` is counted using `time.perf_counter()`. Fixes #4391 --- src/_pytest/runner.py | 9 +++++++-- 1 file changed, 7 insertions(+), 2 deletions(-) diff --git a/src/_pytest/runner.py b/src/_pytest/runner.py index 412ea44a87d..4a6535d4377 100644 --- a/src/_pytest/runner.py +++ b/src/_pytest/runner.py @@ -2,7 +2,7 @@ import bdb import os import sys -from time import time +from time import time, perf_counter from typing import Callable from typing import Dict from typing import List @@ -238,7 +238,8 @@ def result(self): def from_call(cls, func, when, reraise=None) -> "CallInfo": #: context of invocation: one of "setup", "call", #: "teardown", "memocollect" - start = time() + # start = time() # --> we rather retrocompute 'start' later, see below + precise_start = perf_counter() excinfo = None try: result = func() @@ -247,7 +248,11 @@ def from_call(cls, func, when, reraise=None) -> "CallInfo": if reraise is not None and excinfo.errisinstance(reraise): raise result = None + precise_stop = perf_counter() + precise_duration = precise_stop - precise_start + # fill start and stop (API), while keeping a precise duration (diff) stop = time() + start = stop - precise_duration return cls(start=start, stop=stop, when=when, result=result, excinfo=excinfo) def __repr__(self): From bf03b05c50c4610dfcd80b60dd9bdbfeb0a871f7 Mon Sep 17 00:00:00 2001 From: Sylvain MARIE Date: Thu, 19 Mar 2020 15:19:36 +0100 Subject: [PATCH 02/38] Added changelog and authors --- AUTHORS | 1 + changelog/4391.feature.rst | 1 + 2 files changed, 2 insertions(+) create mode 100644 changelog/4391.feature.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.feature.rst b/changelog/4391.feature.rst new file mode 100644 index 00000000000..55dc325effd --- /dev/null +++ b/changelog/4391.feature.rst @@ -0,0 +1 @@ +Improved time counter used to compute test durations. ``.start`` is now retro-computed as ``.stop - duration``, where ``duration`` is counted using ``time.perf_counter()``. From bdb0d19eda0a584e7a107aabbd83f3dfbb5c73ca Mon Sep 17 00:00:00 2001 From: Sylvain MARIE Date: Thu, 19 Mar 2020 15:28:07 +0100 Subject: [PATCH 03/38] Linter fix --- src/_pytest/runner.py | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/src/_pytest/runner.py b/src/_pytest/runner.py index 4a6535d4377..9b6a87aaaa4 100644 --- a/src/_pytest/runner.py +++ b/src/_pytest/runner.py @@ -2,7 +2,7 @@ import bdb import os import sys -from time import time, perf_counter +import time from typing import Callable from typing import Dict from typing import List @@ -238,8 +238,8 @@ def result(self): def from_call(cls, func, when, reraise=None) -> "CallInfo": #: context of invocation: one of "setup", "call", #: "teardown", "memocollect" - # start = time() # --> we rather retrocompute 'start' later, see below - precise_start = perf_counter() + # start = time.time() # --> we rather retrocompute it later, see below + precise_start = time.perf_counter() excinfo = None try: result = func() @@ -248,10 +248,10 @@ def from_call(cls, func, when, reraise=None) -> "CallInfo": if reraise is not None and excinfo.errisinstance(reraise): raise result = None - precise_stop = perf_counter() + precise_stop = time.perf_counter() precise_duration = precise_stop - precise_start # fill start and stop (API), while keeping a precise duration (diff) - stop = time() + stop = time.time() start = stop - precise_duration return cls(start=start, stop=stop, when=when, result=result, excinfo=excinfo) From 55d484c0c57739afeb27f8cdb18782466749cb47 Mon Sep 17 00:00:00 2001 From: Sylvain MARIE Date: Thu, 19 Mar 2020 15:29:23 +0100 Subject: [PATCH 04/38] Linter fix 2 --- src/_pytest/runner.py | 11 ++++++----- 1 file changed, 6 insertions(+), 5 deletions(-) diff --git a/src/_pytest/runner.py b/src/_pytest/runner.py index 9b6a87aaaa4..977809e7952 100644 --- a/src/_pytest/runner.py +++ b/src/_pytest/runner.py @@ -2,7 +2,8 @@ import bdb import os import sys -import time +from time import perf_counter +from time import time from typing import Callable from typing import Dict from typing import List @@ -238,8 +239,8 @@ def result(self): def from_call(cls, func, when, reraise=None) -> "CallInfo": #: context of invocation: one of "setup", "call", #: "teardown", "memocollect" - # start = time.time() # --> we rather retrocompute it later, see below - precise_start = time.perf_counter() + # start = time() # --> we rather retrocompute 'start' later, see below + precise_start = perf_counter() excinfo = None try: result = func() @@ -248,10 +249,10 @@ def from_call(cls, func, when, reraise=None) -> "CallInfo": if reraise is not None and excinfo.errisinstance(reraise): raise result = None - precise_stop = time.perf_counter() + precise_stop = perf_counter() precise_duration = precise_stop - precise_start # fill start and stop (API), while keeping a precise duration (diff) - stop = time.time() + stop = time() start = stop - precise_duration return cls(start=start, stop=stop, when=when, result=result, excinfo=excinfo) From 8c041d3e0adaef892af84a09a6f3171a46336f8d Mon Sep 17 00:00:00 2001 From: Sylvain MARIE Date: Thu, 19 Mar 2020 17:31:21 +0100 Subject: [PATCH 05/38] Improved terminal message when the `--duration` option is used so as to display the number of skipped items with small duration < 0.005s. Fixed #6940 --- src/_pytest/runner.py | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/src/_pytest/runner.py b/src/_pytest/runner.py index 977809e7952..dcdd81f5cfa 100644 --- a/src/_pytest/runner.py +++ b/src/_pytest/runner.py @@ -65,10 +65,11 @@ def pytest_terminal_summary(terminalreporter): tr.write_sep("=", "slowest %s test 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 items with duration < 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)) From 4d77bb2c9d6a695f701aadb6e62c2766f32c6122 Mon Sep 17 00:00:00 2001 From: Sylvain MARIE Date: Thu, 19 Mar 2020 17:51:04 +0100 Subject: [PATCH 06/38] Updated durations test to match the new terminal output --- testing/acceptance_test.py | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/testing/acceptance_test.py b/testing/acceptance_test.py index 861938617e8..b5d027ed3c2 100644 --- a/testing/acceptance_test.py +++ b/testing/acceptance_test.py @@ -915,7 +915,8 @@ def test_calls(self, testdir): ["*durations*", "*call*test_3*", "*call*test_2*"] ) result.stdout.fnmatch_lines( - ["(0.00 durations hidden. Use -vv to show these durations.)"] + ["(8 items with duration < 0.005s hidden. Use -vv to show these " + "durations.)"] ) def test_calls_show_2(self, testdir): From 1c50d3d9c681618cd44e08bede48604e98a341e9 Mon Sep 17 00:00:00 2001 From: Sylvain MARIE Date: Thu, 19 Mar 2020 17:59:31 +0100 Subject: [PATCH 07/38] make linter happy --- src/_pytest/runner.py | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/src/_pytest/runner.py b/src/_pytest/runner.py index dcdd81f5cfa..d007b68d3b4 100644 --- a/src/_pytest/runner.py +++ b/src/_pytest/runner.py @@ -68,8 +68,10 @@ def pytest_terminal_summary(terminalreporter): for i, rep in enumerate(dlist): if verbose < 2 and rep.duration < 0.005: tr.write_line("") - tr.write_line("(%s items with duration < 0.005s hidden. Use -vv to show these durations.)" - % (len(dlist) - i)) + tr.write_line( + "(%s items with duration < 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)) From 47de8b80d2b6d57ea9266bd4e6c2090b1e2e38f3 Mon Sep 17 00:00:00 2001 From: Sylvain MARIE Date: Fri, 20 Mar 2020 10:49:12 +0100 Subject: [PATCH 08/38] As per code review: renamed towncrier changelog file --- changelog/{4391.feature.rst => 4391.improvement.rst} | 0 1 file changed, 0 insertions(+), 0 deletions(-) rename changelog/{4391.feature.rst => 4391.improvement.rst} (100%) diff --git a/changelog/4391.feature.rst b/changelog/4391.improvement.rst similarity index 100% rename from changelog/4391.feature.rst rename to changelog/4391.improvement.rst From 23d7a6c11bc07995a1a8a6c8154163a1251de6f0 Mon Sep 17 00:00:00 2001 From: Sylvain MARIE Date: Fri, 20 Mar 2020 17:09:47 +0100 Subject: [PATCH 09/38] New when `time.perf_counter_ns` is available (python >= 3.7) it is used instead of `time.perf_counter` to measure execution time, and `CallInfo` and `TestReport` objects have an extra `duration_ns` attribute to store the highest-precision duration. --- src/_pytest/reports.py | 10 ++++++++- src/_pytest/runner.py | 50 +++++++++++++++++++++++++++++++++++------- 2 files changed, 51 insertions(+), 9 deletions(-) diff --git a/src/_pytest/reports.py b/src/_pytest/reports.py index 4fa465ea71c..76d615290a5 100644 --- a/src/_pytest/reports.py +++ b/src/_pytest/reports.py @@ -223,6 +223,7 @@ def __init__( when, sections=(), duration=0, + duration_ns=None, # python >= 3.7 user_properties=None, **extra ) -> None: @@ -259,6 +260,8 @@ def __init__( #: time it took to run just the test self.duration = duration + if duration_ns is not None: + self.duration_ns = duration_ns self.__dict__.update(extra) @@ -273,7 +276,11 @@ 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 + try: # python >= 3.7 + duration_ns = {'duration_ns': call.duration_ns} + except AttributeError: + duration_ns = dict() keywords = {x: 1 for x in item.keywords} excinfo = call.excinfo sections = [] @@ -308,6 +315,7 @@ def from_item_and_call(cls, item, call) -> "TestReport": sections, duration, user_properties=item.user_properties, + **duration_ns ) diff --git a/src/_pytest/runner.py b/src/_pytest/runner.py index d007b68d3b4..f55901c0a8c 100644 --- a/src/_pytest/runner.py +++ b/src/_pytest/runner.py @@ -2,6 +2,10 @@ import bdb import os import sys +try: + from time import perf_counter_ns +except ImportError: + perf_counter_ns = None from time import perf_counter from time import time from typing import Callable @@ -28,6 +32,8 @@ from typing import Type from typing_extensions import Literal +_USE_PY37_PERF_NS = perf_counter_ns is not None + # # pytest plugin hooks @@ -230,6 +236,9 @@ class CallInfo: excinfo = attr.ib(type=Optional[ExceptionInfo]) start = attr.ib() stop = attr.ib() + duration = attr.ib() + if _USE_PY37_PERF_NS: + duration_ns = attr.ib() when = attr.ib() @property @@ -242,8 +251,11 @@ def result(self): def from_call(cls, func, when, reraise=None) -> "CallInfo": #: context of invocation: one of "setup", "call", #: "teardown", "memocollect" - # start = time() # --> we rather retrocompute 'start' later, see below - precise_start = perf_counter() + start = time() + if _USE_PY37_PERF_NS: + precise_start = perf_counter_ns() + else: + precise_start = perf_counter() excinfo = None try: result = func() @@ -252,12 +264,34 @@ def from_call(cls, func, when, reraise=None) -> "CallInfo": if reraise is not None and excinfo.errisinstance(reraise): raise result = None - precise_stop = perf_counter() - precise_duration = precise_stop - precise_start - # fill start and stop (API), while keeping a precise duration (diff) - stop = time() - start = stop - precise_duration - return cls(start=start, stop=stop, when=when, result=result, excinfo=excinfo) + if _USE_PY37_PERF_NS: + # use the new nanosecond-accurate perf counter + precise_stop = perf_counter_ns() + duration_ns = precise_stop - precise_start + duration = duration_ns * 1e-9 + stop = time() + return cls( + start=start, + stop=stop, + duration=duration, + duration_ns=duration_ns, + when=when, + result=result, + excinfo=excinfo, + ) + else: + # use the legacy perf counter + precise_stop = perf_counter() + duration = precise_stop - precise_start + stop = time() + return cls( + start=start, + stop=stop, + duration=duration, + when=when, + result=result, + excinfo=excinfo, + ) def __repr__(self): if self.excinfo is None: From 481ba139eb493a3edc16f9f02e6eeaacb0221820 Mon Sep 17 00:00:00 2001 From: Sylvain MARIE Date: Fri, 20 Mar 2020 17:10:52 +0100 Subject: [PATCH 10/38] Edited changelog according to latest proposal --- changelog/4391.improvement.rst | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/changelog/4391.improvement.rst b/changelog/4391.improvement.rst index 55dc325effd..f16b69a8c96 100644 --- a/changelog/4391.improvement.rst +++ b/changelog/4391.improvement.rst @@ -1 +1 @@ -Improved time counter used to compute test durations. ``.start`` is now retro-computed as ``.stop - duration``, where ``duration`` is counted using ``time.perf_counter()``. +Improved time counter used to compute test durations. ``.start`` is now retro-computed as ``.stop - duration``, where ``duration`` is counted using ``time.perf_counter()``. When `time.perf_counter_ns` is available (python >= 3.7) it is used instead of ``time.perf_counter`` to measure execution time, and ``CallInfo`` and ``TestReport`` objects have an extra ``duration_ns`` attribute to store the highest-precision duration. From 1649820de85a5d287b7f3442822c0911740caaea Mon Sep 17 00:00:00 2001 From: Sylvain MARIE Date: Fri, 20 Mar 2020 17:14:26 +0100 Subject: [PATCH 11/38] Linter/black edit --- src/_pytest/reports.py | 4 ++-- src/_pytest/runner.py | 1 + testing/acceptance_test.py | 6 ++++-- 3 files changed, 7 insertions(+), 4 deletions(-) diff --git a/src/_pytest/reports.py b/src/_pytest/reports.py index 76d615290a5..df0bcc7d303 100644 --- a/src/_pytest/reports.py +++ b/src/_pytest/reports.py @@ -278,7 +278,7 @@ def from_item_and_call(cls, item, call) -> "TestReport": when = call.when duration = call.duration try: # python >= 3.7 - duration_ns = {'duration_ns': call.duration_ns} + duration_ns = {"duration_ns": call.duration_ns} except AttributeError: duration_ns = dict() keywords = {x: 1 for x in item.keywords} @@ -315,7 +315,7 @@ def from_item_and_call(cls, item, call) -> "TestReport": sections, duration, user_properties=item.user_properties, - **duration_ns + **duration_ns, ) diff --git a/src/_pytest/runner.py b/src/_pytest/runner.py index f55901c0a8c..3ef44e59481 100644 --- a/src/_pytest/runner.py +++ b/src/_pytest/runner.py @@ -2,6 +2,7 @@ import bdb import os import sys + try: from time import perf_counter_ns except ImportError: diff --git a/testing/acceptance_test.py b/testing/acceptance_test.py index b5d027ed3c2..78f3d2ea09a 100644 --- a/testing/acceptance_test.py +++ b/testing/acceptance_test.py @@ -915,8 +915,10 @@ def test_calls(self, testdir): ["*durations*", "*call*test_3*", "*call*test_2*"] ) result.stdout.fnmatch_lines( - ["(8 items with duration < 0.005s hidden. Use -vv to show these " - "durations.)"] + [ + "(8 items with duration < 0.005s hidden. Use -vv to show these " + "durations.)" + ] ) def test_calls_show_2(self, testdir): From e1eb12299eb196cd6d7287b6b0990357e320acc7 Mon Sep 17 00:00:00 2001 From: Sylvain MARIE Date: Fri, 20 Mar 2020 17:21:03 +0100 Subject: [PATCH 12/38] Made one test a little looser --- testing/acceptance_test.py | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/testing/acceptance_test.py b/testing/acceptance_test.py index 78f3d2ea09a..e7371d8eb7e 100644 --- a/testing/acceptance_test.py +++ b/testing/acceptance_test.py @@ -914,9 +914,10 @@ def test_calls(self, testdir): result.stdout.fnmatch_lines_random( ["*durations*", "*call*test_3*", "*call*test_2*"] ) + # note: the number should be 8, but on macOS and windows it sometimes is 7 (test 1 lasts longer) result.stdout.fnmatch_lines( [ - "(8 items with duration < 0.005s hidden. Use -vv to show these " + "(* items with duration < 0.005s hidden. Use -vv to show these " "durations.)" ] ) From 5373d181fcf9b589b62b23a9efc61c66047d610e Mon Sep 17 00:00:00 2001 From: Sylvain MARIE Date: Sat, 21 Mar 2020 13:57:40 +0100 Subject: [PATCH 13/38] Attempt to improve terminal reporting again --- src/_pytest/runner.py | 6 +++--- testing/acceptance_test.py | 3 +-- 2 files changed, 4 insertions(+), 5 deletions(-) diff --git a/src/_pytest/runner.py b/src/_pytest/runner.py index 3ef44e59481..963b11d3360 100644 --- a/src/_pytest/runner.py +++ b/src/_pytest/runner.py @@ -67,16 +67,16 @@ 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 i, rep in enumerate(dlist): if verbose < 2 and rep.duration < 0.005: tr.write_line("") tr.write_line( - "(%s items with duration < 0.005s hidden. Use -vv to show these durations.)" + "(%s durations < 0.005s hidden. Use -vv to show these durations.)" % (len(dlist) - i) ) break diff --git a/testing/acceptance_test.py b/testing/acceptance_test.py index e7371d8eb7e..da4096be9b0 100644 --- a/testing/acceptance_test.py +++ b/testing/acceptance_test.py @@ -917,8 +917,7 @@ def test_calls(self, testdir): # note: the number should be 8, but on macOS and windows it sometimes is 7 (test 1 lasts longer) result.stdout.fnmatch_lines( [ - "(* items with duration < 0.005s hidden. Use -vv to show these " - "durations.)" + "(* durations < 0.005s hidden. Use -vv to show these durations.)" ] ) From 70460b506ad03637d2c49ac2e92492a2b4831c01 Mon Sep 17 00:00:00 2001 From: Sylvain MARIE Date: Sat, 21 Mar 2020 14:22:10 +0100 Subject: [PATCH 14/38] Modified tests so that they now pass of windows --- testing/acceptance_test.py | 42 ++++++++++++++++++++++++++------------ 1 file changed, 29 insertions(+), 13 deletions(-) diff --git a/testing/acceptance_test.py b/testing/acceptance_test.py index da4096be9b0..05749194b3c 100644 --- a/testing/acceptance_test.py +++ b/testing/acceptance_test.py @@ -2,6 +2,7 @@ import sys import textwrap import types +from platform import system import attr import py @@ -896,28 +897,39 @@ 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.05s def test_1(): - time.sleep(frag) + time.sleep(frag) # 2 ms: on macOS/windows might sleep > 0.05s 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*"] - ) - # note: the number should be 8, but on macOS and windows it sometimes is 7 (test 1 lasts longer) + + # on Windows, test 2 (10ms) can actually sleep less than 5ms and become hidden + if system() == "Windows": + 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 system() == "Linux": + nb_hidden = '8' + else: + nb_hidden = '*' result.stdout.fnmatch_lines( [ - "(* durations < 0.005s hidden. Use -vv to show these durations.)" + "(%s durations < 0.005s hidden. Use -vv to show these durations.)" % nb_hidden ] ) @@ -932,7 +944,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 = "23" if system() == "Windows" else "3" + 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: @@ -954,9 +969,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.05s 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) @@ -978,7 +994,7 @@ class TestDurationWithFixture: source = """ import pytest import time - frag = 0.01 + frag = 0.02 # as on windows sleep(0.01) might take < 0.05s @pytest.fixture def setup_fixt(): From e060ee0fd8ec8b4ffd4ce38ed55c4ee581fd90d8 Mon Sep 17 00:00:00 2001 From: Sylvain MARIE Date: Sat, 21 Mar 2020 14:31:06 +0100 Subject: [PATCH 15/38] Fixed test mistake on windows --- testing/acceptance_test.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/testing/acceptance_test.py b/testing/acceptance_test.py index 05749194b3c..cc4a4e826ff 100644 --- a/testing/acceptance_test.py +++ b/testing/acceptance_test.py @@ -946,7 +946,7 @@ def test_calls_showall(self, testdir): assert result.ret == 0 # on windows, test 2 (10ms) can actually sleep less than 5ms and become hidden - tested = "23" if system() == "Windows" else "3" + tested = "3" if system() == "Windows" else "23" for x in tested: for y in ("call",): # 'setup', 'call', 'teardown': for line in result.stdout.lines: From 2450d0c6096c5f83f95c095c9d7714007c815b95 Mon Sep 17 00:00:00 2001 From: Sylvain MARIE Date: Sat, 21 Mar 2020 14:33:04 +0100 Subject: [PATCH 16/38] Linter fixes --- testing/acceptance_test.py | 7 ++++--- 1 file changed, 4 insertions(+), 3 deletions(-) diff --git a/testing/acceptance_test.py b/testing/acceptance_test.py index cc4a4e826ff..2b0bade3003 100644 --- a/testing/acceptance_test.py +++ b/testing/acceptance_test.py @@ -924,12 +924,13 @@ def test_calls(self, testdir): # - 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 system() == "Linux": - nb_hidden = '8' + nb_hidden = "8" else: - nb_hidden = '*' + nb_hidden = "*" result.stdout.fnmatch_lines( [ - "(%s durations < 0.005s hidden. Use -vv to show these durations.)" % nb_hidden + "(%s durations < 0.005s hidden. Use -vv to show these durations.)" + % nb_hidden ] ) From 79974365ce46d47e9e78602f31c0f2794344e6aa Mon Sep 17 00:00:00 2001 From: Sylvain MARIE Date: Sat, 21 Mar 2020 14:33:57 +0100 Subject: [PATCH 17/38] Flake8 fix --- src/_pytest/runner.py | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/src/_pytest/runner.py b/src/_pytest/runner.py index 963b11d3360..2466832d3ec 100644 --- a/src/_pytest/runner.py +++ b/src/_pytest/runner.py @@ -5,8 +5,10 @@ try: from time import perf_counter_ns + + _USE_PY37_PERF_NS = True except ImportError: - perf_counter_ns = None + _USE_PY37_PERF_NS = False from time import perf_counter from time import time from typing import Callable @@ -33,8 +35,6 @@ from typing import Type from typing_extensions import Literal -_USE_PY37_PERF_NS = perf_counter_ns is not None - # # pytest plugin hooks From 8099f02c9eecf0a5ef907e6cfe96913610ba1bd7 Mon Sep 17 00:00:00 2001 From: Sylvain MARIE Date: Sat, 21 Mar 2020 14:47:40 +0100 Subject: [PATCH 18/38] Code simplification for linter: `duration_ns` is now always present but is just `None` on python < 3.7 --- src/_pytest/reports.py | 7 ++----- src/_pytest/runner.py | 41 ++++++++++++++++------------------------- 2 files changed, 18 insertions(+), 30 deletions(-) diff --git a/src/_pytest/reports.py b/src/_pytest/reports.py index df0bcc7d303..bf9e416188e 100644 --- a/src/_pytest/reports.py +++ b/src/_pytest/reports.py @@ -277,10 +277,7 @@ def from_item_and_call(cls, item, call) -> "TestReport": """ when = call.when duration = call.duration - try: # python >= 3.7 - duration_ns = {"duration_ns": call.duration_ns} - except AttributeError: - duration_ns = dict() + duration_ns = call.duration_ns keywords = {x: 1 for x in item.keywords} excinfo = call.excinfo sections = [] @@ -314,8 +311,8 @@ def from_item_and_call(cls, item, call) -> "TestReport": when, sections, duration, + duration_ns, user_properties=item.user_properties, - **duration_ns, ) diff --git a/src/_pytest/runner.py b/src/_pytest/runner.py index 2466832d3ec..bf2eb8b2798 100644 --- a/src/_pytest/runner.py +++ b/src/_pytest/runner.py @@ -238,8 +238,7 @@ class CallInfo: start = attr.ib() stop = attr.ib() duration = attr.ib() - if _USE_PY37_PERF_NS: - duration_ns = attr.ib() + duration_ns = attr.ib() when = attr.ib() @property @@ -254,7 +253,7 @@ def from_call(cls, func, when, reraise=None) -> "CallInfo": #: "teardown", "memocollect" start = time() if _USE_PY37_PERF_NS: - precise_start = perf_counter_ns() + precise_start_ns = perf_counter_ns() else: precise_start = perf_counter() excinfo = None @@ -267,32 +266,24 @@ def from_call(cls, func, when, reraise=None) -> "CallInfo": result = None if _USE_PY37_PERF_NS: # use the new nanosecond-accurate perf counter - precise_stop = perf_counter_ns() - duration_ns = precise_stop - precise_start + precise_stop_ns = perf_counter_ns() + duration_ns = precise_stop_ns - precise_start_ns # noqa duration = duration_ns * 1e-9 - stop = time() - return cls( - start=start, - stop=stop, - duration=duration, - duration_ns=duration_ns, - when=when, - result=result, - excinfo=excinfo, - ) else: # use the legacy perf counter precise_stop = perf_counter() - duration = precise_stop - precise_start - stop = time() - return cls( - start=start, - stop=stop, - duration=duration, - when=when, - result=result, - excinfo=excinfo, - ) + duration = precise_stop - precise_start # noqa + duration_ns = None + stop = time() + return cls( + start=start, + stop=stop, + duration=duration, + duration_ns=duration_ns, + when=when, + result=result, + excinfo=excinfo, + ) def __repr__(self): if self.excinfo is None: From c828c0b9b38b8c62d120f25b989a5f1290feff8a Mon Sep 17 00:00:00 2001 From: Sylvain MARIE Date: Sat, 21 Mar 2020 14:48:36 +0100 Subject: [PATCH 19/38] Updated changelog --- changelog/4391.improvement.rst | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/changelog/4391.improvement.rst b/changelog/4391.improvement.rst index f16b69a8c96..36a9e9ed6e7 100644 --- a/changelog/4391.improvement.rst +++ b/changelog/4391.improvement.rst @@ -1 +1 @@ -Improved time counter used to compute test durations. ``.start`` is now retro-computed as ``.stop - duration``, where ``duration`` is counted using ``time.perf_counter()``. When `time.perf_counter_ns` is available (python >= 3.7) it is used instead of ``time.perf_counter`` to measure execution time, and ``CallInfo`` and ``TestReport`` objects have an extra ``duration_ns`` attribute to store the highest-precision duration. +Improved time counter used to compute test durations. ``.start`` is now retro-computed as ``.stop - duration``, where ``duration`` is counted using ``time.perf_counter()``. When `time.perf_counter_ns` is available (python >= 3.7) it is used instead of ``time.perf_counter`` to measure execution time. ``CallInfo`` and ``TestReport`` objects have an extra ``duration_ns`` attribute to store this highest-precision duration when available. From a94382f83ca1abf89e7d8bee0c146d8e15d930c8 Mon Sep 17 00:00:00 2001 From: Sylvain MARIE Date: Sat, 21 Mar 2020 14:57:05 +0100 Subject: [PATCH 20/38] mypy fix --- src/_pytest/runner.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/_pytest/runner.py b/src/_pytest/runner.py index bf2eb8b2798..2338d8b037b 100644 --- a/src/_pytest/runner.py +++ b/src/_pytest/runner.py @@ -251,12 +251,13 @@ def result(self): def from_call(cls, func, when, reraise=None) -> "CallInfo": #: context of invocation: one of "setup", "call", #: "teardown", "memocollect" + duration_ns = None + excinfo = None start = time() if _USE_PY37_PERF_NS: precise_start_ns = perf_counter_ns() else: precise_start = perf_counter() - excinfo = None try: result = func() except: # noqa @@ -273,7 +274,6 @@ def from_call(cls, func, when, reraise=None) -> "CallInfo": # use the legacy perf counter precise_stop = perf_counter() duration = precise_stop - precise_start # noqa - duration_ns = None stop = time() return cls( start=start, From 15d0a22588391b7912b882d797622fdd423c6296 Mon Sep 17 00:00:00 2001 From: Sylvain MARIE Date: Sat, 21 Mar 2020 15:03:51 +0100 Subject: [PATCH 21/38] Tiny fix: now `duration_ns` attribute is always available on `TestReport` --- src/_pytest/reports.py | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/src/_pytest/reports.py b/src/_pytest/reports.py index bf9e416188e..13066dc3cb1 100644 --- a/src/_pytest/reports.py +++ b/src/_pytest/reports.py @@ -260,8 +260,7 @@ def __init__( #: time it took to run just the test self.duration = duration - if duration_ns is not None: - self.duration_ns = duration_ns + self.duration_ns = duration_ns self.__dict__.update(extra) From 8455b07ae87597e58b39e3a03e254763d6ebd710 Mon Sep 17 00:00:00 2001 From: Sylvain MARIE Date: Sun, 22 Mar 2020 14:24:07 +0100 Subject: [PATCH 22/38] Fixed typos in comments --- testing/acceptance_test.py | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/testing/acceptance_test.py b/testing/acceptance_test.py index 2b0bade3003..f4526fffedd 100644 --- a/testing/acceptance_test.py +++ b/testing/acceptance_test.py @@ -901,9 +901,9 @@ class TestDurations: def test_something(): pass def test_2(): - time.sleep(frag*5) # 10 ms: on windows might sleep < 0.05s + time.sleep(frag*5) # 10 ms: on windows might sleep < 0.005s def test_1(): - time.sleep(frag) # 2 ms: on macOS/windows might sleep > 0.05s + time.sleep(frag) # 2 ms: on macOS/windows might sleep > 0.005s def test_3(): time.sleep(frag*10) # 20 ms """ @@ -970,7 +970,7 @@ def test_calls_showall_verbose(self, testdir): def test_with_deselected(self, testdir): testdir.makepyfile(self.source) - # on windows test 2 might sleep less than 0.05s and be hidden. Prefer test 3. + # 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_3*"]) @@ -995,7 +995,7 @@ class TestDurationWithFixture: source = """ import pytest import time - frag = 0.02 # as on windows sleep(0.01) might take < 0.05s + frag = 0.02 # as on windows sleep(0.01) might take < 0.005s @pytest.fixture def setup_fixt(): From 22c2dbc816df6139158a93b27c3a53b87bb099ac Mon Sep 17 00:00:00 2001 From: Sylvain MARIE Date: Fri, 27 Mar 2020 12:08:20 +0100 Subject: [PATCH 23/38] Added docstring for `CallInfo` --- src/_pytest/runner.py | 10 +++++++++- 1 file changed, 9 insertions(+), 1 deletion(-) diff --git a/src/_pytest/runner.py b/src/_pytest/runner.py index 2338d8b037b..a928b577c72 100644 --- a/src/_pytest/runner.py +++ b/src/_pytest/runner.py @@ -231,7 +231,15 @@ 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 excinfo: `ExceptionInfo` describing the captured exception if any + :param start: (float) The system time when the call started, in seconds since the epoch. + :param stop: (float) The system time when the call ended, in seconds since the epoch. + :param duration: (float) The call duration in seconds + :param duration_ns: (int) The call duration in nanoseconds. Only in python >= 3.7 + :param when: context of invocation: "setup", "call", "teardown"... + """ _result = attr.ib() excinfo = attr.ib(type=Optional[ExceptionInfo]) From 2f6ffde6d0c48b4caf93b1f43133757dab5149f0 Mon Sep 17 00:00:00 2001 From: smarie Date: Fri, 27 Mar 2020 16:35:12 +0100 Subject: [PATCH 24/38] Update src/_pytest/runner.py Co-Authored-By: Ran Benita --- src/_pytest/runner.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/_pytest/runner.py b/src/_pytest/runner.py index a928b577c72..cfeddd5fca9 100644 --- a/src/_pytest/runner.py +++ b/src/_pytest/runner.py @@ -238,7 +238,7 @@ class CallInfo: :param stop: (float) The system time when the call ended, in seconds since the epoch. :param duration: (float) The call duration in seconds :param duration_ns: (int) The call duration in nanoseconds. Only in python >= 3.7 - :param when: context of invocation: "setup", "call", "teardown"... + :param when: The context of invocation: "setup", "call", "teardown", ... """ _result = attr.ib() From 92017f6b758e8345db72c6e039834fc73ef97ae9 Mon Sep 17 00:00:00 2001 From: smarie Date: Fri, 27 Mar 2020 16:35:53 +0100 Subject: [PATCH 25/38] Update src/_pytest/runner.py Co-Authored-By: Ran Benita --- src/_pytest/runner.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/_pytest/runner.py b/src/_pytest/runner.py index cfeddd5fca9..27b30a12ff6 100644 --- a/src/_pytest/runner.py +++ b/src/_pytest/runner.py @@ -237,7 +237,7 @@ class CallInfo: :param start: (float) The system time when the call started, in seconds since the epoch. :param stop: (float) The system time when the call ended, in seconds since the epoch. :param duration: (float) The call duration in seconds - :param duration_ns: (int) The call duration in nanoseconds. Only in python >= 3.7 + :param duration_ns: (int) The call duration, in nanoseconds. Only available in Python >= 3.7. :param when: The context of invocation: "setup", "call", "teardown", ... """ From b8830d9c3a617f582173b935e38fb41c5205e711 Mon Sep 17 00:00:00 2001 From: smarie Date: Fri, 27 Mar 2020 16:36:03 +0100 Subject: [PATCH 26/38] Update src/_pytest/runner.py Co-Authored-By: Ran Benita --- src/_pytest/runner.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/_pytest/runner.py b/src/_pytest/runner.py index 27b30a12ff6..4c2f49111d6 100644 --- a/src/_pytest/runner.py +++ b/src/_pytest/runner.py @@ -236,7 +236,7 @@ class CallInfo: :param excinfo: `ExceptionInfo` describing the captured exception if any :param start: (float) The system time when the call started, in seconds since the epoch. :param stop: (float) The system time when the call ended, in seconds since the epoch. - :param duration: (float) The call duration in seconds + :param duration: (float) The call duration, in seconds. :param duration_ns: (int) The call duration, in nanoseconds. Only available in Python >= 3.7. :param when: The context of invocation: "setup", "call", "teardown", ... """ From 99b779e0f71acf3123674357fde0d3ab46b40538 Mon Sep 17 00:00:00 2001 From: Sylvain MARIE Date: Fri, 27 Mar 2020 16:45:54 +0100 Subject: [PATCH 27/38] Added type hints for `CallInfo` --- src/_pytest/runner.py | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/src/_pytest/runner.py b/src/_pytest/runner.py index ee84e82d253..d9fceddf8d4 100644 --- a/src/_pytest/runner.py +++ b/src/_pytest/runner.py @@ -243,11 +243,11 @@ class CallInfo: _result = attr.ib() excinfo = attr.ib(type=Optional[ExceptionInfo]) - start = attr.ib() - stop = attr.ib() - duration = attr.ib() - duration_ns = attr.ib() - when = attr.ib() + start = attr.ib(type=float) + stop = attr.ib(type=float) + duration = attr.ib(type=float) + duration_ns = attr.ib(type=Optional[int]) + when = attr.ib(type=str) @property def result(self): From a1e92e98e31630b72803ec728bd3ec970224bd1f Mon Sep 17 00:00:00 2001 From: Sylvain MARIE Date: Fri, 27 Mar 2020 16:56:49 +0100 Subject: [PATCH 28/38] as per code review using sys.platform instead of the platform module --- testing/acceptance_test.py | 12 ++++++------ 1 file changed, 6 insertions(+), 6 deletions(-) diff --git a/testing/acceptance_test.py b/testing/acceptance_test.py index f4526fffedd..c9746f47696 100644 --- a/testing/acceptance_test.py +++ b/testing/acceptance_test.py @@ -2,7 +2,6 @@ import sys import textwrap import types -from platform import system import attr import py @@ -914,7 +913,7 @@ def test_calls(self, testdir): assert result.ret == 0 # on Windows, test 2 (10ms) can actually sleep less than 5ms and become hidden - if system() == "Windows": + if sys.platform == "win32": to_match = ["*durations*", "*call*test_3*"] else: to_match = ["*durations*", "*call*test_3*", "*call*test_2*"] @@ -923,10 +922,11 @@ def test_calls(self, testdir): # 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 system() == "Linux": - nb_hidden = "8" - else: + if sys.platform in ('win32', 'darwin'): nb_hidden = "*" + else: + nb_hidden = "8" + result.stdout.fnmatch_lines( [ "(%s durations < 0.005s hidden. Use -vv to show these durations.)" @@ -947,7 +947,7 @@ def test_calls_showall(self, testdir): assert result.ret == 0 # on windows, test 2 (10ms) can actually sleep less than 5ms and become hidden - tested = "3" if system() == "Windows" else "23" + 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: From 7f37a4964b3f372e8af8bf4b2a16daffd7ad5f76 Mon Sep 17 00:00:00 2001 From: Sylvain MARIE Date: Fri, 27 Mar 2020 17:00:56 +0100 Subject: [PATCH 29/38] lint fix --- testing/acceptance_test.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/testing/acceptance_test.py b/testing/acceptance_test.py index c9746f47696..ed07fec11a1 100644 --- a/testing/acceptance_test.py +++ b/testing/acceptance_test.py @@ -922,7 +922,7 @@ def test_calls(self, testdir): # 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'): + if sys.platform in ("win32", "darwin"): nb_hidden = "*" else: nb_hidden = "8" From 9a33ef4c626a7df60b05c140cea4c1bd235f3247 Mon Sep 17 00:00:00 2001 From: Sylvain MARIE Date: Fri, 27 Mar 2020 17:23:21 +0100 Subject: [PATCH 30/38] Improved changelog --- changelog/4391.improvement.rst | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/changelog/4391.improvement.rst b/changelog/4391.improvement.rst index 36a9e9ed6e7..2ad7f953f6c 100644 --- a/changelog/4391.improvement.rst +++ b/changelog/4391.improvement.rst @@ -1 +1 @@ -Improved time counter used to compute test durations. ``.start`` is now retro-computed as ``.stop - duration``, where ``duration`` is counted using ``time.perf_counter()``. When `time.perf_counter_ns` is available (python >= 3.7) it is used instead of ``time.perf_counter`` to measure execution time. ``CallInfo`` and ``TestReport`` objects have an extra ``duration_ns`` attribute to store this highest-precision duration when available. +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``, which is more accurate than ``.stop - .start`` (as these are based on ``time.time()``). When ``time.perf_counter_ns`` is available (python >= 3.7) it is used instead of ``time.perf_counter`` to measure the duration. ``CallInfo`` and ``TestReport`` objects have an extra ``duration_ns`` attribute to store this highest-precision duration when available. From 51ebcba13fa8b0b1256e0f94e34a97f0faac7934 Mon Sep 17 00:00:00 2001 From: Sylvain MARIE Date: Fri, 27 Mar 2020 17:35:22 +0100 Subject: [PATCH 31/38] As per code review: removed duration_ns from the picture --- src/_pytest/reports.py | 4 ---- src/_pytest/runner.py | 28 ++++------------------------ 2 files changed, 4 insertions(+), 28 deletions(-) diff --git a/src/_pytest/reports.py b/src/_pytest/reports.py index 7988ec09d1c..8459c1cb9e4 100644 --- a/src/_pytest/reports.py +++ b/src/_pytest/reports.py @@ -223,7 +223,6 @@ def __init__( when, sections=(), duration=0, - duration_ns=None, # python >= 3.7 user_properties=None, **extra ) -> None: @@ -260,7 +259,6 @@ def __init__( #: time it took to run just the test self.duration = duration - self.duration_ns = duration_ns self.__dict__.update(extra) @@ -276,7 +274,6 @@ def from_item_and_call(cls, item, call) -> "TestReport": """ when = call.when duration = call.duration - duration_ns = call.duration_ns keywords = {x: 1 for x in item.keywords} excinfo = call.excinfo sections = [] @@ -310,7 +307,6 @@ def from_item_and_call(cls, item, call) -> "TestReport": when, sections, duration, - duration_ns, user_properties=item.user_properties, ) diff --git a/src/_pytest/runner.py b/src/_pytest/runner.py index d9fceddf8d4..28c67edc093 100644 --- a/src/_pytest/runner.py +++ b/src/_pytest/runner.py @@ -2,13 +2,6 @@ import bdb import os import sys - -try: - from time import perf_counter_ns - - _USE_PY37_PERF_NS = True -except ImportError: - _USE_PY37_PERF_NS = False from time import perf_counter from time import time from typing import Callable @@ -237,7 +230,6 @@ class CallInfo: :param start: (float) The system time when the call started, in seconds since the epoch. :param stop: (float) The system time when the call ended, in seconds since the epoch. :param duration: (float) The call duration, in seconds. - :param duration_ns: (int) The call duration, in nanoseconds. Only available in Python >= 3.7. :param when: The context of invocation: "setup", "call", "teardown", ... """ @@ -246,7 +238,6 @@ class CallInfo: start = attr.ib(type=float) stop = attr.ib(type=float) duration = attr.ib(type=float) - duration_ns = attr.ib(type=Optional[int]) when = attr.ib(type=str) @property @@ -259,13 +250,9 @@ def result(self): def from_call(cls, func, when, reraise=None) -> "CallInfo": #: context of invocation: one of "setup", "call", #: "teardown", "memocollect" - duration_ns = None excinfo = None start = time() - if _USE_PY37_PERF_NS: - precise_start_ns = perf_counter_ns() - else: - precise_start = perf_counter() + precise_start = perf_counter() try: result = func() except: # noqa @@ -273,21 +260,14 @@ def from_call(cls, func, when, reraise=None) -> "CallInfo": if reraise is not None and excinfo.errisinstance(reraise): raise result = None - if _USE_PY37_PERF_NS: - # use the new nanosecond-accurate perf counter - precise_stop_ns = perf_counter_ns() - duration_ns = precise_stop_ns - precise_start_ns # noqa - duration = duration_ns * 1e-9 - else: - # use the legacy perf counter - precise_stop = perf_counter() - duration = precise_stop - precise_start # noqa + # use the perf counter + precise_stop = perf_counter() + duration = precise_stop - precise_start stop = time() return cls( start=start, stop=stop, duration=duration, - duration_ns=duration_ns, when=when, result=result, excinfo=excinfo, From 4b2306116ecd0c073e20543a3da072e8d2b34b74 Mon Sep 17 00:00:00 2001 From: Sylvain MARIE Date: Fri, 27 Mar 2020 17:36:06 +0100 Subject: [PATCH 32/38] Final changelog update --- changelog/4391.improvement.rst | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/changelog/4391.improvement.rst b/changelog/4391.improvement.rst index 2ad7f953f6c..e7e4090f1dd 100644 --- a/changelog/4391.improvement.rst +++ b/changelog/4391.improvement.rst @@ -1 +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``, which is more accurate than ``.stop - .start`` (as these are based on ``time.time()``). When ``time.perf_counter_ns`` is available (python >= 3.7) it is used instead of ``time.perf_counter`` to measure the duration. ``CallInfo`` and ``TestReport`` objects have an extra ``duration_ns`` attribute to store this highest-precision duration when available. +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()``). From a2f682c051b8b0e9dc7fd7990836525b754d32a7 Mon Sep 17 00:00:00 2001 From: Sylvain MARIE Date: Fri, 27 Mar 2020 17:40:29 +0100 Subject: [PATCH 33/38] Added changelog for the terminal improvement --- changelog/6940.improvement.rst | 1 + 1 file changed, 1 insertion(+) create mode 100644 changelog/6940.improvement.rst 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. From c86a42b828935a71690a1f722f2f57611ed4ebfe Mon Sep 17 00:00:00 2001 From: Sylvain MARIE Date: Fri, 27 Mar 2020 17:48:28 +0100 Subject: [PATCH 34/38] Minor docstring edits --- src/_pytest/runner.py | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/src/_pytest/runner.py b/src/_pytest/runner.py index 28c67edc093..28f25745742 100644 --- a/src/_pytest/runner.py +++ b/src/_pytest/runner.py @@ -226,11 +226,11 @@ def call_runtest_hook(item, when: "Literal['setup', 'call', 'teardown']", **kwds class CallInfo: """ Result/Exception info a function invocation. - :param excinfo: `ExceptionInfo` describing the captured exception if any - :param start: (float) The system time when the call started, in seconds since the epoch. - :param stop: (float) The system time when the call ended, in seconds since the epoch. - :param duration: (float) The call duration, in seconds. - :param when: The context of invocation: "setup", "call", "teardown", ... + :param excinfo: (`ExceptionInfo`, optional) describing the captured exception if any + :param start: (`float`) The system time when the call started, in seconds since the epoch. + :param stop: (`float`) The system time when the call ended, in seconds since the epoch. + :param duration: (`float`) The call duration, in seconds. + :param when: (`str`) The context of invocation: "setup", "call", "teardown", ... """ _result = attr.ib() From 8a27c972e97d752e542d11839b35b07af05eb22f Mon Sep 17 00:00:00 2001 From: Sylvain MARIE Date: Fri, 27 Mar 2020 17:49:14 +0100 Subject: [PATCH 35/38] Minor docstring edits --- src/_pytest/runner.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/_pytest/runner.py b/src/_pytest/runner.py index 28f25745742..e95836a5be5 100644 --- a/src/_pytest/runner.py +++ b/src/_pytest/runner.py @@ -226,7 +226,7 @@ def call_runtest_hook(item, when: "Literal['setup', 'call', 'teardown']", **kwds class CallInfo: """ Result/Exception info a function invocation. - :param excinfo: (`ExceptionInfo`, optional) describing the captured exception if any + :param excinfo: (`ExceptionInfo`, optional) describing the captured exception if any. :param start: (`float`) The system time when the call started, in seconds since the epoch. :param stop: (`float`) The system time when the call ended, in seconds since the epoch. :param duration: (`float`) The call duration, in seconds. From daa588c2ad566ba8ad06f980f33575688340ca79 Mon Sep 17 00:00:00 2001 From: Sylvain MARIE Date: Sat, 28 Mar 2020 08:56:38 +0100 Subject: [PATCH 36/38] docstring update as per code review --- src/_pytest/runner.py | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/src/_pytest/runner.py b/src/_pytest/runner.py index e95836a5be5..3b4294fc034 100644 --- a/src/_pytest/runner.py +++ b/src/_pytest/runner.py @@ -226,11 +226,11 @@ def call_runtest_hook(item, when: "Literal['setup', 'call', 'teardown']", **kwds class CallInfo: """ Result/Exception info a function invocation. - :param excinfo: (`ExceptionInfo`, optional) describing the captured exception if any. - :param start: (`float`) The system time when the call started, in seconds since the epoch. - :param stop: (`float`) The system time when the call ended, in seconds since the epoch. - :param duration: (`float`) The call duration, in seconds. - :param when: (`str`) The context of invocation: "setup", "call", "teardown", ... + :param ExceptionInfo excinfo: (optional) describing the captured exception if any. + :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() From 533e5ec6833ab2df725de88e5f61859bd1f81614 Mon Sep 17 00:00:00 2001 From: Bruno Oliveira Date: Sat, 28 Mar 2020 11:04:00 -0300 Subject: [PATCH 37/38] Update docstring as per request in code review --- src/_pytest/runner.py | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/src/_pytest/runner.py b/src/_pytest/runner.py index 3b4294fc034..76513b36142 100644 --- a/src/_pytest/runner.py +++ b/src/_pytest/runner.py @@ -226,7 +226,9 @@ def call_runtest_hook(item, when: "Literal['setup', 'call', 'teardown']", **kwds class CallInfo: """ Result/Exception info a function invocation. - :param ExceptionInfo excinfo: (optional) describing the captured exception if any. + :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. From 57f8a41658407c6ac7b5747e59a540223580017d Mon Sep 17 00:00:00 2001 From: Bruno Oliveira Date: Sat, 28 Mar 2020 11:24:09 -0300 Subject: [PATCH 38/38] Fix linting --- src/_pytest/runner.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/_pytest/runner.py b/src/_pytest/runner.py index 76513b36142..c13dff711a1 100644 --- a/src/_pytest/runner.py +++ b/src/_pytest/runner.py @@ -226,7 +226,7 @@ def call_runtest_hook(item, when: "Literal['setup', 'call', 'teardown']", **kwds class CallInfo: """ Result/Exception info a function invocation. - :param result: The return value of the call, if it didn't raise. Can only be accessed + :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.