From 0839436fb81cfd2cdd1759dea911ce9d86d56d9e Mon Sep 17 00:00:00 2001 From: Bruno Oliveira Date: Wed, 10 May 2023 19:31:57 -0300 Subject: [PATCH] Make collection progress output less verbose Fix #555 --- changelog/555.improvement.rst | 1 + src/xdist/dsession.py | 94 ++++++++++++++++++++++++++++------- testing/acceptance_test.py | 36 +++++++++----- testing/test_dsession.py | 76 +++++++++++++++++++++++++++- 4 files changed, 175 insertions(+), 32 deletions(-) create mode 100644 changelog/555.improvement.rst diff --git a/changelog/555.improvement.rst b/changelog/555.improvement.rst new file mode 100644 index 00000000..f70ff53a --- /dev/null +++ b/changelog/555.improvement.rst @@ -0,0 +1 @@ +Improved progress output when collecting nodes to be less verbose. diff --git a/src/xdist/dsession.py b/src/xdist/dsession.py index a622b8bd..8ae59a4a 100644 --- a/src/xdist/dsession.py +++ b/src/xdist/dsession.py @@ -1,3 +1,7 @@ +import sys +from enum import Enum, auto +from typing import Sequence, Tuple, Dict + import pytest from xdist.remote import Producer @@ -251,14 +255,16 @@ def worker_collectionfinish(self, node, ids): self._session.testscollected = len(ids) self.sched.add_node_collection(node, ids) if self.terminal: - self.trdist.setstatus(node.gateway.spec, "[%d]" % (len(ids))) + self.trdist.setstatus( + node.gateway.spec, WorkerStatus.CollectionDone, tests_collected=len(ids) + ) if self.sched.collection_is_completed: if self.terminal and not self.sched.has_pending: self.trdist.ensure_show_status() self.terminal.write_line("") if self.config.option.verbose > 0: self.terminal.write_line( - "scheduling tests via %s" % (self.sched.__class__.__name__) + f"scheduling tests via {self.sched.__class__.__name__}" ) self.sched.schedule() @@ -345,7 +351,7 @@ def _handlefailures(self, rep): if rep.failed: self.countfailures += 1 if self.maxfail and self.countfailures >= self.maxfail: - self.shouldstop = "stopping after %d failures" % (self.countfailures) + self.shouldstop = f"stopping after {self.countfailures} failures" def triggershutdown(self): self.log("triggering shutdown") @@ -372,11 +378,27 @@ def handle_crashitem(self, nodeid, worker): self.config.hook.pytest_runtest_logreport(report=rep) +class WorkerStatus(Enum): + """Status of each worker during creation/collection.""" + + # Worker spec has just been created. + Created = auto() + + # Worker has been initialized. + Initialized = auto() + + # Worker is now ready for collection. + Ready = auto() + + # Worker has finished collection. + CollectionDone = auto() + + class TerminalDistReporter: def __init__(self, config): self.config = config self.tr = config.pluginmanager.getplugin("terminalreporter") - self._status = {} + self._status: Dict[str, Tuple[WorkerStatus, int]] = {} self._lastlen = 0 self._isatty = getattr(self.tr, "isatty", self.tr.hasmarkup) @@ -387,17 +409,20 @@ def ensure_show_status(self): if not self._isatty: self.write_line(self.getstatus()) - def setstatus(self, spec, status, show=True): - self._status[spec.id] = status + def setstatus( + self, spec, status: WorkerStatus, *, tests_collected: int, show: bool = True + ) -> None: + self._status[spec.id] = (status, tests_collected) if show and self._isatty: self.rewrite(self.getstatus()) def getstatus(self): if self.config.option.verbose >= 0: - parts = [f"{spec.id} {self._status[spec.id]}" for spec in self._specs] - return " / ".join(parts) - else: - return "bringing up nodes..." + line = get_workers_status_line(list(self._status.values())) + if line: + return line + + return "bringing up nodes..." def rewrite(self, line, newline=False): pline = line + " " * max(self._lastlen - len(line), 0) @@ -412,31 +437,33 @@ def rewrite(self, line, newline=False): def pytest_xdist_setupnodes(self, specs): self._specs = specs for spec in specs: - self.setstatus(spec, "I", show=False) - self.setstatus(spec, "I", show=True) + self.setstatus(spec, WorkerStatus.Created, tests_collected=0, show=False) + self.setstatus(spec, WorkerStatus.Created, tests_collected=0, show=True) self.ensure_show_status() @pytest.hookimpl def pytest_xdist_newgateway(self, gateway): - if self.config.option.verbose > 0: - rinfo = gateway._rinfo() + rinfo = gateway._rinfo() + is_local = rinfo.executable == sys.executable + if self.config.option.verbose > 0 and not is_local: version = "%s.%s.%s" % rinfo.version_info[:3] self.rewrite( "[%s] %s Python %s cwd: %s" % (gateway.id, rinfo.platform, version, rinfo.cwd), newline=True, ) - self.setstatus(gateway.spec, "C") + self.setstatus(gateway.spec, WorkerStatus.Initialized, tests_collected=0) @pytest.hookimpl def pytest_testnodeready(self, node): - if self.config.option.verbose > 0: - d = node.workerinfo + d = node.workerinfo + is_local = d.get("executable") == sys.executable + if self.config.option.verbose > 0 and not is_local: infoline = "[{}] Python {}".format( d["id"], d["version"].replace("\n", " -- ") ) self.rewrite(infoline, newline=True) - self.setstatus(node.gateway.spec, "ok") + self.setstatus(node.gateway.spec, WorkerStatus.Ready, tests_collected=0) @pytest.hookimpl def pytest_testnodedown(self, node, error): @@ -457,3 +484,34 @@ def get_default_max_worker_restart(config): # if --max-worker-restart was not provided, use a reasonable default (#226) result = config.option.numprocesses * 4 return result + + +def get_workers_status_line( + status_and_items: Sequence[Tuple[WorkerStatus, int]] +) -> str: + """ + Return the line to display during worker setup/collection based on the + status of the workers and number of tests collected for each. + """ + statuses = [s for s, c in status_and_items] + total_workers = len(statuses) + workers_noun = "worker" if total_workers == 1 else "workers" + if status_and_items and all(s == WorkerStatus.CollectionDone for s in statuses): + first = status_and_items[0] + status, tests_collected = first + tests_noun = "test" if tests_collected == 1 else "tests" + return f"{total_workers} {workers_noun} [{tests_collected} {tests_noun}]" + if WorkerStatus.CollectionDone in statuses: + done = sum(1 for s, c in status_and_items if c > 0) + return f"collecting: {done}/{total_workers} {workers_noun}" + if WorkerStatus.Ready in statuses: + ready = list(statuses).count(WorkerStatus.Ready) + return f"ready: {ready}/{total_workers} {workers_noun}" + if WorkerStatus.Initialized in statuses: + initialized = list(statuses).count(WorkerStatus.Initialized) + return f"initialized: {initialized}/{total_workers} {workers_noun}" + if WorkerStatus.Created in statuses: + created = list(statuses).count(WorkerStatus.Created) + return f"created: {created}/{total_workers} {workers_noun}" + + return "" diff --git a/testing/acceptance_test.py b/testing/acceptance_test.py index 1666ba03..faab899a 100644 --- a/testing/acceptance_test.py +++ b/testing/acceptance_test.py @@ -101,7 +101,12 @@ def test_skip(): """ ) result = pytester.runpytest(p1, "-v", "-d", "--tx=popen", "--tx=popen") - result.stdout.fnmatch_lines(["*1*Python*", "*2 failed, 1 passed, 1 skipped*"]) + result.stdout.fnmatch_lines( + [ + "created: 2/2 workers", + "*2 failed, 1 passed, 1 skipped*", + ] + ) assert result.ret == 1 def test_n1_fail_minus_x(self, pytester: pytest.Pytester) -> None: @@ -151,7 +156,12 @@ def test_skip(): """ ) result = pytester.runpytest(p1, "-d", "-v") - result.stdout.fnmatch_lines(["*2*Python*", "*2 failed, 1 passed, 1 skipped*"]) + result.stdout.fnmatch_lines( + [ + "created: 3/3 workers", + "*2 failed, 1 passed, 1 skipped*", + ] + ) assert result.ret == 1 def test_dist_tests_with_crash(self, pytester: pytest.Pytester) -> None: @@ -237,9 +247,6 @@ def pytest_load_initial_conftests(early_config): assert result.ret == 0 result.stdout.fnmatch_lines( [ - "*0* *cwd*", - # "RSyncStart: [G1]", - # "RSyncFinished: [G1]", "*1 passed*", ] ) @@ -276,7 +283,11 @@ def pytest_terminal_summary(terminalreporter): p1 = pytester.makepyfile("def test_func(): pass") result = pytester.runpytest("-v", p1, "-d", "--tx=popen") result.stdout.fnmatch_lines( - ["*0*Python*", "*calculated result is 49*", "*1 passed*"] + [ + "created: 1/1 worker", + "*calculated result is 49*", + "*1 passed*", + ] ) assert result.ret == 0 @@ -393,14 +404,14 @@ def test_ok(): out = result.stdout.str() if verbosity == "-v": assert "scheduling tests" in out - assert "gw" in out + assert "1 worker [1 test]" in out elif verbosity == "-q": assert "scheduling tests" not in out assert "gw" not in out assert "bringing up nodes..." in out else: assert "scheduling tests" not in out - assert "gw" in out + assert "1 worker [1 test]" in out def test_pass_skip_fail(self, pytester: pytest.Pytester) -> None: pytester.makepyfile( @@ -1099,8 +1110,9 @@ def test_this(i): result = pytester.runpytest(*args) assert "test session starts" in result.stdout.str() assert "\x1b[1m" in result.stdout.str() - assert "gw0 [10] / gw1 [10]" in result.stdout.str() - assert "gw0 C / gw1 C" not in result.stdout.str() + assert "created: 2/2 workers" in result.stdout.str() + assert "2 workers [10 tests]" in result.stdout.str() + assert "collecting:" not in result.stdout.str() def test_without_terminal_plugin(pytester, request) -> None: @@ -1554,8 +1566,8 @@ def test_collection_crash(testdir): assert result.ret == 1 result.stdout.fnmatch_lines( [ - "gw0 I", - "gw0 [[]0[]]", + "created: 1/1 worker", + "1 worker [[]0 tests[]]", "*_ ERROR collecting test_collection_crash.py _*", "E assert 0", "*= 1 error in *", diff --git a/testing/test_dsession.py b/testing/test_dsession.py index 20468e46..21257928 100644 --- a/testing/test_dsession.py +++ b/testing/test_dsession.py @@ -1,7 +1,12 @@ -from xdist.dsession import DSession, get_default_max_worker_restart +from xdist.dsession import ( + DSession, + get_default_max_worker_restart, + get_workers_status_line, + WorkerStatus, +) from xdist.report import report_collection_diff from xdist.scheduler import EachScheduling, LoadScheduling, WorkStealingScheduling -from typing import Optional +from typing import Optional, Sequence import pytest import execnet @@ -527,3 +532,70 @@ def test_2011_table(birth_year): reprec = pytester.inline_run("-n1") reprec.assertoutcome(passed=2) assert 0 + + +Created = WorkerStatus.Created +Initialized = WorkerStatus.Initialized +Ready = WorkerStatus.Ready +CollectionDone = WorkerStatus.CollectionDone + + +@pytest.mark.parametrize( + "status_and_items, expected", + [ + ( + [], + "", + ), + ( + [(Created, 0)], + "created: 1/1 worker", + ), + ( + [(Created, 0), (Created, 0)], + "created: 2/2 workers", + ), + ( + [(Initialized, 0), (Created, 0)], + "initialized: 1/2 workers", + ), + ( + [(Initialized, 0), (Initialized, 0)], + "initialized: 2/2 workers", + ), + ( + [(Ready, 0), (Created, 0)], + "ready: 1/2 workers", + ), + ( + [(Ready, 0), (Ready, 0)], + "ready: 2/2 workers", + ), + ( + [(CollectionDone, 12), (Created, 0)], + "collecting: 1/2 workers", + ), + ( + [(CollectionDone, 12), (CollectionDone, 12)], + "2 workers [12 tests]", + ), + ( + [(CollectionDone, 1), (CollectionDone, 1)], + "2 workers [1 test]", + ), + ( + [(CollectionDone, 1)], + "1 worker [1 test]", + ), + # Different number of tests collected will raise an error and should not happen in practice, + # but we test for it anyway. + ( + [(CollectionDone, 1), (CollectionDone, 12)], + "2 workers [1 test]", + ), + ], +) +def test_get_workers_status_line( + status_and_items: Sequence[tuple[WorkerStatus, int]], expected: str +) -> None: + assert get_workers_status_line(status_and_items) == expected