From 29bf205f3adf5884ad36fab9706792d98db69ac8 Mon Sep 17 00:00:00 2001 From: holger krekel Date: Tue, 8 Nov 2011 17:53:46 +0000 Subject: [PATCH] make --durations also show the execution times of setup/teardown calls. This requires a slight incompatibility - pytest_runtest_logreport now sees setup/teardown reports even if the tests passed. --- CHANGELOG | 4 ++-- _pytest/__init__.py | 2 +- _pytest/hookspec.py | 3 ++- _pytest/junitxml.py | 3 ++- _pytest/pytester.py | 4 ++-- _pytest/resultlog.py | 2 ++ _pytest/runner.py | 17 ++++++++++++++--- _pytest/terminal.py | 7 ++++--- doc/announce/release-2.2.0.txt | 15 ++++++++++++++- setup.py | 2 +- testing/acceptance_test.py | 25 +++++++++++++++++++++++++ testing/test_mark.py | 2 +- 12 files changed, 70 insertions(+), 16 deletions(-) diff --git a/CHANGELOG b/CHANGELOG index 80114ceb1..2c28ae2c8 100644 --- a/CHANGELOG +++ b/CHANGELOG @@ -1,8 +1,8 @@ -Changes between 2.1.3 and [next version] +Changes between 2.1.3 and XXX 2.2.0 ---------------------------------------- - new feature to help optimizing your tests: --durations=N option for - displaying N slowest test calls + displaying N slowest test calls and setup/teardown methods. - fix and cleanup pytest's own test suite to not leak FDs - fix issue83: link to generated funcarg list - fix issue74: pyarg module names are now checked against imp.find_module false positives diff --git a/_pytest/__init__.py b/_pytest/__init__.py index 94e47a012..6b2bfabb7 100644 --- a/_pytest/__init__.py +++ b/_pytest/__init__.py @@ -1,2 +1,2 @@ # -__version__ = '2.2.0.dev1' +__version__ = '2.2.0.dev2' diff --git a/_pytest/hookspec.py b/_pytest/hookspec.py index 580ab2799..c13fa180c 100644 --- a/_pytest/hookspec.py +++ b/_pytest/hookspec.py @@ -149,7 +149,8 @@ def pytest_runtest_makereport(item, call): pytest_runtest_makereport.firstresult = True def pytest_runtest_logreport(report): - """ process item test report. """ + """ process a test setup/call/teardown report relating to + the respective phase of executing a test. """ # special handling for final teardown - somewhat internal for now def pytest__teardown_final(session): diff --git a/_pytest/junitxml.py b/_pytest/junitxml.py index fa8b1c5ee..d781da1fb 100644 --- a/_pytest/junitxml.py +++ b/_pytest/junitxml.py @@ -166,7 +166,8 @@ class LogXML(object): def pytest_runtest_logreport(self, report): if report.passed: - self.append_pass(report) + if report.when == "call": # ignore setup/teardown + self.append_pass(report) elif report.failed: if report.when != "call": self.append_error(report) diff --git a/_pytest/pytester.py b/_pytest/pytester.py index 7ddb709d9..fb8adc50a 100644 --- a/_pytest/pytester.py +++ b/_pytest/pytester.py @@ -334,8 +334,8 @@ class TmpTestdir: l = list(args) + [p] reprec = self.inline_run(*l) reports = reprec.getreports("pytest_runtest_logreport") - assert len(reports) == 1, reports - return reports[0] + assert len(reports) == 3, reports # setup/call/teardown + return reports[1] def inline_genitems(self, *args): return self.inprocess_run(list(args) + ['--collectonly']) diff --git a/_pytest/resultlog.py b/_pytest/resultlog.py index 7f879cce5..02abe7659 100644 --- a/_pytest/resultlog.py +++ b/_pytest/resultlog.py @@ -63,6 +63,8 @@ class ResultLog(object): self.write_log_entry(testpath, lettercode, longrepr) def pytest_runtest_logreport(self, report): + if report.when != "call" and report.passed: + return res = self.config.hook.pytest_report_teststatus(report=report) code = res[1] if code == 'x': diff --git a/_pytest/runner.py b/_pytest/runner.py index f0f676215..6e19b0329 100644 --- a/_pytest/runner.py +++ b/_pytest/runner.py @@ -26,25 +26,36 @@ def pytest_terminal_summary(terminalreporter): return tr = terminalreporter duration2rep = {} + alldurations = 0.0 for key, replist in tr.stats.items(): if key == "deselected": continue for rep in replist: duration2rep[rep.duration] = rep + alldurations += rep.duration if not duration2rep: return - d2 = duration2rep.items() + d2 = remaining = duration2rep.items() d2.sort() d2.reverse() if not durations: tr.write_sep("=", "slowest test durations") else: tr.write_sep("=", "slowest %s test durations" % durations) + remaining = d2[durations:] d2 = d2[:durations] + assert (alldurations/100) > 0 for duration, rep in d2: nodeid = rep.nodeid.replace("::()::", "::") - tr.write_line("%2.2f %s %s" % (duration, rep.when, nodeid)) + percent = rep.duration / (alldurations / 100) + tr.write_line("%02.2fs %-02.2f%% %s %s" % + (duration, percent, rep.when, nodeid)) + if remaining: + remsum = sum(map(lambda x: x[0], remaining)) + tr.write_line("%02.2fs %-02.2f%% remaining in %d test phases" %( + remsum, remsum / (alldurations / 100), len(remaining))) + def pytest_sessionstart(session): session._setupstate = SetupState() @@ -110,7 +121,7 @@ def call_and_report(item, when, log=True): call = call_runtest_hook(item, when) hook = item.ihook report = hook.pytest_runtest_makereport(item=item, call=call) - if log and (when == "call" or not report.passed): + if log: hook.pytest_runtest_logreport(report=report) return report diff --git a/_pytest/terminal.py b/_pytest/terminal.py index 3b3e39e05..c8c399312 100644 --- a/_pytest/terminal.py +++ b/_pytest/terminal.py @@ -426,9 +426,10 @@ class TerminalReporter: keys.append(key) parts = [] for key in keys: - val = self.stats.get(key, None) - if val: - parts.append("%d %s" %(len(val), key)) + if key: # setup/teardown reports have an empty key, ignore them + val = self.stats.get(key, None) + if val: + parts.append("%d %s" %(len(val), key)) line = ", ".join(parts) # XXX coloring msg = "%s in %.2f seconds" %(line, session_duration) diff --git a/doc/announce/release-2.2.0.txt b/doc/announce/release-2.2.0.txt index 0b03beeaa..32ebdacd9 100644 --- a/doc/announce/release-2.2.0.txt +++ b/doc/announce/release-2.2.0.txt @@ -1,7 +1,7 @@ py.test 2.2.0: new test duration profiling and bug fixes =========================================================================== -pytest-2.2.0 is a backward compatible release of the popular +pytest-2.2.0 is a quite backward compatible release of the popular py.test testing tool. It introduces the new "--duration=N" option showing the N slowest test execution or setup/teardown calls. The release also contains a few fixes and some cleanup of pytest's own test @@ -16,6 +16,19 @@ If you want to install or upgrade pytest you might just type:: pip install -U pytest # or easy_install -U pytest +incompatible change +------------------------------------ + +* You need a new version of the pytest-xdist plugin (1.7) for distributing + test runs. + +* Also other plugins might need an upgrade if they implement + the ``pytest_runtest_logreport`` hook which now is called unconditionally + for the setup/teardown fixture phases of a test. You can just choose to + ignore them by inserting "if rep.when != 'call': return". Note that + most code probably "just" works because the hook was already called + for failing setup/teardown phases of a test. + best, holger krekel diff --git a/setup.py b/setup.py index 9f45274e4..0c3ac3213 100644 --- a/setup.py +++ b/setup.py @@ -24,7 +24,7 @@ def main(): name='pytest', description='py.test: simple powerful testing with Python', long_description = long_description, - version='2.2.0.dev1', + version='2.2.0.dev2', url='http://pytest.org', license='MIT license', platforms=['unix', 'linux', 'osx', 'cygwin', 'win32'], diff --git a/testing/acceptance_test.py b/testing/acceptance_test.py index 55a6effd1..66c6f8a00 100644 --- a/testing/acceptance_test.py +++ b/testing/acceptance_test.py @@ -484,12 +484,15 @@ def test_duration_test(testdir): "*call*test_2*", "*call*test_1*", ]) + assert "remaining in" not in result.stdout.str() + result = testdir.runpytest("--durations=2") assert result.ret == 0 result.stdout.fnmatch_lines([ "*durations*", "*call*test_3*", "*call*test_2*", + "*s*%*remaining in 7 test phases", ]) assert "test_1" not in result.stdout.str() result = testdir.runpytest("--durations=0") @@ -503,6 +506,28 @@ def test_duration_test(testdir): else: raise AssertionError("not found %s %s" % (x,y)) +def test_duration_test_with_fixture(testdir): + testdir.makepyfile(""" + import time + frag = 0.01 + def setup_function(func): + time.sleep(frag * 3) + + def test_1(): + time.sleep(frag*2) + def test_2(): + time.sleep(frag) + """) + result = testdir.runpytest("--durations=10") + assert result.ret == 0 + result.stdout.fnmatch_lines([ + "*durations*", + "*setup*test_1*", + "*setup*test_2*", + "*call*test_1*", + "*call*test_2*", + ]) + result = testdir.runpytest("--durations=2", "-k test_1") assert result.ret == 0 result.stdout.fnmatch_lines([ diff --git a/testing/test_mark.py b/testing/test_mark.py index d26132675..b0faca46f 100644 --- a/testing/test_mark.py +++ b/testing/test_mark.py @@ -77,7 +77,7 @@ class TestFunctional: assert hasattr(test_hello, 'hello') """) result = testdir.runpytest(p) - result.stdout.fnmatch_lines(["*passed*"]) + result.stdout.fnmatch_lines(["*1 passed*"]) def test_mark_per_module(self, testdir): item = testdir.getitem("""