ci(portability): cut the Windows Python suite time at its causes (#487) (#490)

* test: list the slowest tests on request and stop waiting 30 s on a held WAL (#487)

PM_TEST_SLOWEST=N makes tests/run_suite.py list the N slowest tests.
Three history tests restored while their own read held a snapshot, so
each publish sat out the 30 s WAL-truncate wait; they now use a short wait.
Temporary diagnostics for the Windows timings ride along in this commit.

* test(lora): check Windows folder rules without asking the network (#487)

On Windows ntpath.realpath looks up \\server\share and waited about 2.8 s
per test for a host that does not exist. The guard tests now use the
lexical NT path rules, which is what they already ran on Linux and macOS.

* ci(portability): keep Windows test files on the work disk (#487)

The Windows runner's TEMP is on C:, where a flush took about 6 ms and a test
database's create-to-delete about 111 ms; on D: the same took 0.5 ms and
23 ms. The job now points TEMP/TMP at RUNNER_TEMP and lists the 40 slowest
tests. The fake HTTPS handlers get a TLS context that reads no certificate
store, and the missing-share tests name localhost instead of an unknown
server. The temporary diagnostics are removed.

* ci(portability): spell the Windows test TEMP by its short name (#487)

The runner's own TEMP was C:\Users\RUNNER~1\..., so tests met 8.3 short
names in every temp path. The folder on D: keeps that when the disk has
short names, and the step logs which spelling it got. TESTING.md notes
that the slowest list is not printed when a job is cancelled.

* ci(portability): switch on 8.3 names for the Windows test TEMP (#487)

D: made no short names (run 40922502209 logged the long spelling), so
the step now switches them on for D: before it creates the folder, and
warns when the folder still has no short name.

.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

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\<missing share>`) 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

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:

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 = {

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
 

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)

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

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

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})