diff --git a/.github/workflows/portability.yml b/.github/workflows/portability.yml index 75122ab0..43782e03 100644 --- a/.github/workflows/portability.yml +++ b/.github/workflows/portability.yml @@ -51,5 +51,27 @@ jobs: python -m pip install --upgrade pip pip install -r requirements-dev.txt + # The runner's TEMP is on C:, the OS disk, where a flush took about 6 ms + # and a test database's create-to-delete about 111 ms; on the D: work + # disk the same took 0.5 ms and 23 ms (macOS: 19 ms). Tests write their + # databases under TEMP, so it moves to a folder on D: (measured in #487, + # run 40915866444). The runner's TEMP was an 8.3 short name + # (C:\Users\RUNNER~1\...), so the new one is spelled by its short name too + # and paths still have to be resolved. D: makes no short names by default + # (run 40922502209), so they are switched on for it first. + - name: Keep test files on the work disk (Windows) + if: runner.os == 'Windows' + shell: pwsh + run: | + fsutil 8dot3name set D: 0 + $folder = New-Item -ItemType Directory -Force -Path (Join-Path $env:RUNNER_TEMP "PromptManagerTests") + $short = (New-Object -ComObject Scripting.FileSystemObject).GetFolder($folder.FullName).ShortPath + Write-Output "test TEMP: $short (long name $($folder.FullName))" + if ($short -eq $folder.FullName) { Write-Output "::warning::D: gave the test TEMP no 8.3 short name" } + "TEMP=$short" >> $env:GITHUB_ENV + "TMP=$short" >> $env:GITHUB_ENV + - name: Run tests + env: + PM_TEST_SLOWEST: "40" run: python -m tests.run_suite -v diff --git a/TESTING.md b/TESTING.md index 96683564..7f140c1c 100644 --- a/TESTING.md +++ b/TESTING.md @@ -251,6 +251,21 @@ the process exits non-zero. stacks. - When the watchdog fires under coverage, that run's coverage data is lost; the job fails anyway and the dump is what matters. +- `PM_TEST_SLOWEST=N` (off by default) lists the N slowest tests after the + summary, each timed from its `start:` line to the next one like the hang + limit. The Windows and macOS jobs (`portability.yml`) set it to 40, so every + run shows where its time went (#487). The list prints only when the run + ends: a job GitHub cancels or a watchdog exit prints none, so read the + timestamps between `start:` lines instead. +- On the Windows runners `TEMP` sits on the OS disk C:, where a flush took about + 6 ms and a test database's create-to-delete about 111 ms (D: 0.5 ms and 23 ms, + macOS 19 ms). `portability.yml` points `TEMP`/`TMP` at a folder under + `RUNNER_TEMP` on D: before the suite. It switches 8.3 short names on for D: + and spells the folder by its short name, as the runner's own TEMP was + (`C:\Users\RUNNER~1\...`), logs it, and warns when there is none. + A test that waits on a fixed busy timeout, a network name (`\\server\share`: + use `\\localhost\`) or a default TLS context (it reads the + Windows certificate store) costs seconds there; the slowest list shows it. Every job in `test.yml`, `code-quality.yml` and `viewerjs-check.yml` has `timeout-minutes` (`tests/vendor/ci-workflow.test.mjs` checks it). The rule is diff --git a/tests/run_suite.py b/tests/run_suite.py index 9775d274..fc75199f 100644 --- a/tests/run_suite.py +++ b/tests/run_suite.py @@ -28,6 +28,10 @@ stack shows which). A dump after the summary is a hang at interpreter exit A limit is a measurement, not a dial: change it only with new measurements written next to it (TESTING.md "Time limits and hangs"). + +PM_TEST_SLOWEST=N (opt-in, #487) lists the N slowest tests after the summary. +A test's time runs from its ``start:`` line to the next one, so it includes +the class and module fixtures in between, like the hang limit. """ import argparse @@ -36,6 +40,7 @@ import os import shutil import sys import tempfile +import time import unittest from pathlib import Path @@ -63,23 +68,57 @@ def read_limit(name, default): return int(text) -def make_result_class(stream, per_test_limit, shutdown_limit): +class TestClock: + """Seconds from each test's start to the next start (or the run's end).""" + + def __init__(self, clock=time.perf_counter): + self._clock = clock + self._current = None + self._started = 0.0 + self.durations = [] + + def start(self, test_id): + self.stop() + self._current = test_id + self._started = self._clock() + + def stop(self): + if self._current is not None: + self.durations.append((self._clock() - self._started, self._current)) + self._current = None + + def report(self, count): + """Return the lines that list the ``count`` slowest tests.""" + slowest = sorted(self.durations, key=lambda item: item[0], reverse=True) + lines = [f"slowest {min(count, len(slowest))} of {len(slowest)} tests:"] + lines += [f"{seconds:8.2f}s {test_id}" for seconds, test_id in slowest[:count]] + return lines + + +def make_result_class(stream, per_test_limit, shutdown_limit, slowest=0): """Build a TextTestResult that names each test and re-arms the watchdog.""" def arm(seconds): faulthandler.dump_traceback_later(seconds, exit=True, file=stream) + clock = TestClock() + class WatchdogResult(unittest.TextTestResult): def startTest(self, test): # At default verbosity the progress dots share a line; start ours. prefix = "\n" if self.dots else "" stream.write(f"{prefix}start: {test.id()}\n") stream.flush() + clock.start(test.id()) super().startTest(test) arm(per_test_limit) def stopTestRun(self): + clock.stop() super().stopTestRun() + if slowest: + stream.write("\n".join(["", *clock.report(slowest), ""])) + stream.flush() arm(shutdown_limit) return WatchdogResult @@ -138,6 +177,7 @@ def main(argv=None): try: per_test_limit = read_limit("PM_TEST_HANG_LIMIT", DEFAULT_PER_TEST_LIMIT) shutdown_limit = read_limit("PM_TEST_SHUTDOWN_LIMIT", DEFAULT_SHUTDOWN_LIMIT) + slowest = read_limit("PM_TEST_SLOWEST", 0) except LimitError as error: stream.write(f"{error}\n") return USAGE_EXIT @@ -152,7 +192,9 @@ def main(argv=None): verbosity=args.verbosity, # As unittest.main does: show warnings unless -W/PYTHONWARNINGS set them. warnings=None if sys.warnoptions else "default", - resultclass=make_result_class(stream, per_test_limit, shutdown_limit), + resultclass=make_result_class( + stream, per_test_limit, shutdown_limit, slowest + ), ) result = runner.run(suite) finally: diff --git a/tests/test_api_diagnostics_report.py b/tests/test_api_diagnostics_report.py index 113d6c42..8b6ef318 100644 --- a/tests/test_api_diagnostics_report.py +++ b/tests/test_api_diagnostics_report.py @@ -45,7 +45,9 @@ SEEDED_PATHS = ( "/srv/someone/renders", "C:\\Users\\someone\\Documents\\renders", "D:/Users/someone/prompts.db", - "\\\\nas\\share\\someone\\renders", + # A share on this machine: on Windows the report resolves every source, + # and an unknown server name made that wait about 2.9 s (#487). + "\\\\localhost\\pm-no-such-share\\someone\\renders", ) _WINDOWS_ABSOLUTE = re.compile(r"^[A-Za-z]:[\\/]") TOP_KEYS = { diff --git a/tests/test_api_history.py b/tests/test_api_history.py index f42e4b60..9e1d8ceb 100644 --- a/tests/test_api_history.py +++ b/tests/test_api_history.py @@ -25,6 +25,7 @@ try: except ImportError: from tests.test_api_images import ImageAPITestCase +from database import restore_stage from database.operations import PromptDatabase from py.api.library import _encode, _scope from tests.test_execution_context_database import bundle, snapshot @@ -43,6 +44,21 @@ OTHER_SESSION = "aaaaaaaa-3333-4333-8333-333333333333" MISSING_RUN = "bbbbbbbb-4444-4444-8444-444444444444" +@contextmanager +def no_wal_truncate_wait(): + """Restore with the restore notification held back, as these tests need. + + The read under test keeps its snapshot open across the restore, so the + publish's WAL truncate can never succeed; without the short wait it would + sit out the full CHECKPOINT_BUSY_MS (30 s) each time (#487). + """ + with ( + patch("database.execution_history.notify_history_restore"), + patch.object(restore_stage, "CHECKPOINT_BUSY_MS", 50), + ): + yield + + class HistoryAPITests(ImageAPITestCase): async def tearDownAsync(self): if hasattr(self.api, "close_history_reads"): @@ -346,7 +362,7 @@ class HistoryAPITests(ImageAPITestCase): def during_snapshot(*args, **kwargs): result = original(*args, **kwargs) - with patch("database.execution_history.notify_history_restore"): + with no_wal_truncate_wait(): writer.model.restore_from_file(source) return result @@ -890,7 +906,7 @@ class HistoryAPITests(ImageAPITestCase): def during_snapshot(*args, **kwargs): result = original(*args, **kwargs) - with patch("database.execution_history.notify_history_restore"): + with no_wal_truncate_wait(): writer.model.restore_from_file(source) return result diff --git a/tests/test_history_read_fence.py b/tests/test_history_read_fence.py index 9e60dd5c..9b6f354f 100644 --- a/tests/test_history_read_fence.py +++ b/tests/test_history_read_fence.py @@ -7,6 +7,7 @@ from contextlib import closing from pathlib import Path from unittest.mock import patch +from database import restore_stage from database.execution_history import HistoryEpochChanged, notify_history_restore from tests import test_execution_history_database as history_tests @@ -41,7 +42,12 @@ class HistoryReadFenceTests(unittest.TestCase): generation = fence.begin() with reader.recorded_history_snapshot() as epoch: original = reader.get_history_run(start.run_id) - with patch("database.execution_history.notify_history_restore"): + # The open snapshot keeps the WAL from being truncated; do not + # sit out the full 30 s checkpoint wait for it (#487). + with ( + patch("database.execution_history.notify_history_restore"), + patch.object(restore_stage, "CHECKPOINT_BUSY_MS", 50), + ): writer.model.restore_from_file(source) self.assertEqual(reader.get_execution_epoch(), epoch) self.assertEqual(original["run"]["storage_epoch"], epoch) diff --git a/tests/test_lora_manager_layout.py b/tests/test_lora_manager_layout.py index 16c94cd2..8af50902 100644 --- a/tests/test_lora_manager_layout.py +++ b/tests/test_lora_manager_layout.py @@ -14,6 +14,7 @@ import sys import tempfile import unittest from pathlib import Path +from types import SimpleNamespace from unittest.mock import patch sys.path.insert(0, os.path.dirname(os.path.dirname(os.path.abspath(__file__)))) @@ -753,6 +754,17 @@ class LocalMediaTests(LayoutTestCase): self.assertEqual(layout_module.VIDEO_SUFFIXES, frozenset(VIDEO_EXTENSIONS)) +# Windows path rules without the filesystem. On Windows ntpath.realpath asks +# the network for \\server\share and waits seconds for a host that does not +# exist (#487); elsewhere ntpath.realpath already is ntpath.abspath. +LEXICAL_NT = SimpleNamespace( + normcase=ntpath.normcase, + realpath=ntpath.abspath, + dirname=ntpath.dirname, + sep=ntpath.sep, +) + + class FolderGuardTests(unittest.TestCase): """Portable path-flavor controls (TESTING.md Windows portability preflight).""" @@ -762,7 +774,7 @@ class FolderGuardTests(unittest.TestCase): def guard_nt(self, path, home="C:\\Users\\Vito"): return layout_module._guard_folder( - path, home, pathmod=ntpath, isdir=lambda _p: True + path, home, pathmod=LEXICAL_NT, isdir=lambda _p: True ) def test_filesystem_roots_and_home_are_rejected(self): @@ -832,8 +844,12 @@ class FolderGuardTests(unittest.TestCase): def test_missing_folders_add_nothing(self): self.assertIsNone(layout_module._guard_folder(str(self.tmp / "x"), "/home")) + # A missing share on this machine: an unknown server name made + # Windows wait about 2.8 s for the network (#487). self.assertIsNone( - layout_module._guard_folder("\\\\server\\share\\loras", str(self.tmp)) + layout_module._guard_folder( + "\\\\localhost\\pm-no-such-share\\loras", str(self.tmp) + ) ) self.assertEqual( layout_module._guard_folder(str(self.tmp), "/nonexistent-home"), @@ -843,17 +859,17 @@ class FolderGuardTests(unittest.TestCase): def test_windows_model_path_matches_a_lower_case_root(self): self.assertTrue( layout_module._inside( - "C:/Models/Loras/A.safetensors", ("c:\\models\\loras",), ntpath + "C:/Models/Loras/A.safetensors", ("c:\\models\\loras",), LEXICAL_NT ) ) self.assertFalse( layout_module._inside( - "C:/Models/LorasX/A.safetensors", ("c:\\models\\loras",), ntpath + "C:/Models/LorasX/A.safetensors", ("c:\\models\\loras",), LEXICAL_NT ) ) self.assertFalse( layout_module._inside( - "\\\\other\\share\\A.safetensors", ("c:\\models\\loras",), ntpath + "\\\\other\\share\\A.safetensors", ("c:\\models\\loras",), LEXICAL_NT ) ) diff --git a/tests/test_lora_utils.py b/tests/test_lora_utils.py index d271c771..18476cfd 100644 --- a/tests/test_lora_utils.py +++ b/tests/test_lora_utils.py @@ -9,6 +9,7 @@ import email import json import os import shutil +import ssl import sys import tempfile import threading @@ -669,6 +670,15 @@ class TestStaleDownloadSweep(unittest.TestCase): self.assertTrue(old.exists()) +def _unused_tls_context(): + """A TLS context for the fake handlers, which never open a connection. + + HTTPSHandler() builds a default context, and on Windows that reads the + system certificate store: about 0.14 s per handler (#487). + """ + return ssl.SSLContext(ssl.PROTOCOL_TLS_CLIENT) + + class _FakeHTTPSHandler(urllib.request.HTTPSHandler): """Serves canned responses through a real urllib opener, recording requests. @@ -677,7 +687,7 @@ class _FakeHTTPSHandler(urllib.request.HTTPSHandler): """ def __init__(self, redirect_to): - super().__init__() + super().__init__(context=_unused_tls_context()) self.redirect_to = redirect_to self.requests = [] @@ -745,7 +755,7 @@ class _ChainHTTPSHandler(urllib.request.HTTPSHandler): urllib opener, recording every request; an unknown URL answers 404.""" def __init__(self, routes): - super().__init__() + super().__init__(context=_unused_tls_context()) self.routes = routes self.requests = [] diff --git a/tests/test_run_suite.py b/tests/test_run_suite.py index b35fe567..0ea3f859 100644 --- a/tests/test_run_suite.py +++ b/tests/test_run_suite.py @@ -18,11 +18,13 @@ from pathlib import Path REPO_ROOT = Path(__file__).resolve().parent.parent SUBPROCESS_TIMEOUT = 60 WATCHDOG_ENV = ("PM_TEST_HANG_LIMIT", "PM_TEST_SHUTDOWN_LIMIT") +# Integer settings the runner reads; a bad value is a usage error. +RUNNER_ENV = (*WATCHDOG_ENV, "PM_TEST_SLOWEST") def run_suite(folder, extra_env=None, *args, verbosity=("-v",)): """Run the runner on ``folder`` and return the completed process.""" - env = {k: v for k, v in os.environ.items() if k not in WATCHDOG_ENV} + env = {k: v for k, v in os.environ.items() if k not in RUNNER_ENV} # Windows writes a piped stderr in the ANSI codepage; ask for the UTF-8 # this helper decodes, so non-ASCII values and paths survive. env["PYTHONIOENCODING"] = "utf-8" @@ -269,8 +271,57 @@ class RunSuiteTests(unittest.TestCase): self.assertIn("ok", result.stderr, detail) self.assertIn("Timeout (", result.stderr, detail) + def test_slowest_tests_are_listed_when_asked(self): + self.write( + "test_probe_slowest.py", + """ + import time + import unittest + + class Probe(unittest.TestCase): + def test_fast(self): + pass + + def test_slow(self): + time.sleep(0.3) + + def test_slower(self): + time.sleep(0.6) + """, + ) + result = run_suite(self.folder, {"PM_TEST_SLOWEST": "2"}) + self.assertEqual(result.returncode, 0, result.stderr) + report = result.stderr.split("slowest 2 of 3 tests:\n", 1) + self.assertEqual(len(report), 2, result.stderr) + lines = [line.split() for line in report[1].strip().splitlines()[:2]] + self.assertEqual( + [line[1] for line in lines], + [ + "test_probe_slowest.Probe.test_slower", + "test_probe_slowest.Probe.test_slow", + ], + result.stderr, + ) + self.assertGreaterEqual(float(lines[0][0].rstrip("s")), 0.6) + self.assertNotIn("test_fast", report[1]) + + def test_slowest_tests_are_not_listed_by_default(self): + self.write( + "test_probe_quiet.py", + """ + import unittest + + class Probe(unittest.TestCase): + def test_ok(self): + pass + """, + ) + result = run_suite(self.folder) + self.assertEqual(result.returncode, 0, result.stderr) + self.assertNotIn("slowest", result.stderr) + def test_invalid_limit_is_a_usage_error(self): - for name in WATCHDOG_ENV: + for name in RUNNER_ENV: for value in ("abc", "0", "-3", "1.5", "\u00b2"): with self.subTest(name=name, value=value): result = run_suite(self.folder, {name: value})