Skip to content
Open
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
1 change: 1 addition & 0 deletions changelog.d/19929.misc
Original file line number Diff line number Diff line change
@@ -0,0 +1 @@
Fix `test_lock_contention` being flaky when running against PostgreSQL by budgeting CPU time rather than wall-clock time.
37 changes: 10 additions & 27 deletions tests/handlers/test_worker_lock.py
Original file line number Diff line number Diff line change
Expand Up @@ -19,9 +19,6 @@
#
#

import logging
import platform

from twisted.internet import defer
from twisted.internet.testing import MemoryReactor

Expand All @@ -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(
Expand Down Expand Up @@ -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 = [
Expand Down
34 changes: 29 additions & 5 deletions tests/utils.py
Original file line number Diff line number Diff line change
Expand Up @@ -318,25 +318,49 @@ 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,
exc_type: type[BaseException] | None,
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)
Loading