From 10498d8b4a0e1b9a7d812e7196943a49d7162687 Mon Sep 17 00:00:00 2001 From: Erik Johnston Date: Wed, 8 Jul 2026 09:52:43 +0000 Subject: [PATCH 1/2] Use a CPU-time budget for test_lock_contention to fix postgres flakiness test_lock_contention is a performance-regression canary (#16840): the pathological behaviour it guards against spent ~30s spinning the CPU, vs ~0.5s when healthy. The 5s wall-clock alarm it used was calibrated on SQLite, but against PostgreSQL a healthy run already takes 3-4s of wall-clock time (500 sequential acquire/release cycles, each a real database round-trip), so any CI load pushed it over the limit. Add a cpu_time mode to tests/utils.py's test_timeout, implemented with setitimer(ITIMER_PROF), which budgets process CPU time instead of wall-clock time. Time spent blocked on the database or lost to a loaded CI runner no longer counts, while a regression to CPU-spinning still trips the alarm mid-spin. A healthy run costs <1s of CPU on either database engine; the budget is 10s. This also subsumes the RISC-V wall-clock carve-out from #18430, which is removed. Co-Authored-By: Claude Fable 5 Claude-Session: https://claude.ai/code/session_019ZdvuLkg7Lm7wDtPQzDnJx --- tests/handlers/test_worker_lock.py | 37 ++++++++---------------------- tests/utils.py | 34 +++++++++++++++++++++++---- 2 files changed, 39 insertions(+), 32 deletions(-) diff --git a/tests/handlers/test_worker_lock.py b/tests/handlers/test_worker_lock.py index a38adcd4d44..b517e935cdc 100644 --- a/tests/handlers/test_worker_lock.py +++ b/tests/handlers/test_worker_lock.py @@ -19,9 +19,6 @@ # # -import logging -import platform - from twisted.internet import defer from twisted.internet.testing import MemoryReactor @@ -39,8 +36,6 @@ from tests.replication._base import BaseMultiWorkerStreamTestCase from tests.utils import test_timeout -logger = logging.getLogger(__name__) - class WorkerLockTestCase(unittest.HomeserverTestCase): def prepare( @@ -152,28 +147,16 @@ def _pump_by( def test_lock_contention(self) -> None: """Test lock contention when a lot of locks wait on a single worker""" nb_locks_to_test = 500 - current_machine = platform.machine().lower() - if current_machine.startswith("riscv"): - # RISC-V specific settings - timeout_seconds = 15 # Increased timeout for RISC-V - # add a print or log statement here for visibility in CI logs - logger.info( # use logger.info - "Detected RISC-V architecture (%s). " - "Adjusting test_lock_contention: timeout=%ss", - current_machine, - timeout_seconds, - ) - else: - # Settings for other architectures - timeout_seconds = 5 - # It takes around 0.5s on a 5+ years old laptop - with test_timeout(timeout_seconds): # Use the dynamically set timeout - d = self._take_locks( - nb_locks_to_test - ) # Use the (potentially adjusted) number of locks - self.assertEqual( - self.get_success(d), nb_locks_to_test - ) # Assert against the used number of locks + + # This test is a performance-regression canary: before #16840 taking the + # locks below spent ~30s spinning the CPU, afterwards ~0.5s. We budget + # CPU time rather than wall-clock time so that time spent waiting on + # database round-trips (significant on PostgreSQL) or lost to a loaded + # CI machine doesn't make the test flaky: a healthy run costs well + # under 1s of CPU on either database engine. + with test_timeout(10, cpu_time=True): + d = self._take_locks(nb_locks_to_test) + self.assertEqual(self.get_success(d), nb_locks_to_test) async def _take_locks(self, nb_locks: int) -> int: locks = [ diff --git a/tests/utils.py b/tests/utils.py index f3d51290979..7ea3a2aded5 100644 --- a/tests/utils.py +++ b/tests/utils.py @@ -318,20 +318,44 @@ class test_timeout: my_checking_func() time.sleep(0.1) ``` + + Args: + seconds: How long to allow the block to run for before raising + `TestTimeout`. + error_message: Extra text to append to the `TestTimeout` message. + cpu_time: If `True`, `seconds` is a budget of CPU time (user + system, + across all threads) consumed by the process rather than wall-clock + time. Useful for performance-regression tests, as time spent + blocked on I/O (e.g. waiting on the database) or lost to a loaded + CI machine doesn't count against the budget. Note that a block + which hangs while consuming *no* CPU will never trip this variant. """ - def __init__(self, seconds: int, error_message: str | None = None) -> None: - self.error_message = f"Test timed out after {seconds}s" + def __init__( + self, + seconds: float, + error_message: str | None = None, + *, + cpu_time: bool = False, + ) -> None: + self.error_message = f"Test timed out after {seconds}s of {'CPU' if cpu_time else 'wall-clock'} time" if error_message is not None: self.error_message += f": {error_message}" self.seconds = seconds + self.cpu_time = cpu_time def handle_timeout(self, signum: int, frame: FrameType | None) -> None: raise TestTimeout(self.error_message) def __enter__(self) -> None: - signal.signal(signal.SIGALRM, self.handle_timeout) - signal.alarm(self.seconds) + if self.cpu_time: + # `ITIMER_PROF` counts down against process CPU time (user + + # system) and delivers `SIGPROF` when it expires. + signal.signal(signal.SIGPROF, self.handle_timeout) + signal.setitimer(signal.ITIMER_PROF, self.seconds) + else: + signal.signal(signal.SIGALRM, self.handle_timeout) + signal.setitimer(signal.ITIMER_REAL, self.seconds) def __exit__( self, @@ -339,4 +363,4 @@ def __exit__( exc_val: BaseException | None, exc_tb: TracebackType | None, ) -> None: - signal.alarm(0) + signal.setitimer(signal.ITIMER_PROF if self.cpu_time else signal.ITIMER_REAL, 0) From 2ce841ab8e7ff0cbbba59a00654b86ebe44702f4 Mon Sep 17 00:00:00 2001 From: Erik Johnston Date: Wed, 8 Jul 2026 11:08:55 +0100 Subject: [PATCH 2/2] Newsfile --- changelog.d/19929.misc | 1 + 1 file changed, 1 insertion(+) create mode 100644 changelog.d/19929.misc diff --git a/changelog.d/19929.misc b/changelog.d/19929.misc new file mode 100644 index 00000000000..4778f9fa32f --- /dev/null +++ b/changelog.d/19929.misc @@ -0,0 +1 @@ +Fix `test_lock_contention` being flaky when running against PostgreSQL by budgeting CPU time rather than wall-clock time.