Use a CPU-time budget for test_lock_contention to fix postgres flakiness (#19929)

`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)`](https://docs.python.org/3/library/signal.html#signal.setitimer),
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 <noreply@anthropic.com>
This commit is contained in:
Erik Johnston
2026-07-09 10:40:53 +01:00
committed by GitHub
parent c63d77a79d
commit b4deb24be6
3 changed files with 40 additions and 32 deletions
+1
View File
@@ -0,0 +1 @@
Fix `test_lock_contention` being flaky when running against PostgreSQL by budgeting CPU time rather than wall-clock time.
+10 -27
View File
@@ -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 import unittest
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 @@ class WorkerLockTestCase(unittest.HomeserverTestCase):
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(5, 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 = [
+29 -5
View File
@@ -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 @@ class test_timeout:
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)