From 53960ecb1bf9516883236e49c096598baf77ed55 Mon Sep 17 00:00:00 2001 From: Yaraslau Tamashevich Date: Wed, 23 Sep 2026 15:02:18 +0200 Subject: [PATCH] tests: give the strand-race case a budget sized from what it actually costs, instead of the blanket 120 s it was never measured against (fixes #760) `catch_discover_tests(morph_tests ... PROPERTIES TIMEOUT 120)` applied one ceiling to all 2966 cases in the binary. The longest, most load-sensitive case in it was governed by the same number as the cheapest, and that number was chosen against "every test is sub-second in practice" -- true of the other 2965. The case is not slow because it computes anything. It serialises 3200 tasks per iteration through one strand, and every handoff is a thread wakeup that has to wait its turn on the run queue, so its cost is set by how contended the host is. Measured on this tree, 12 cores, clang 22.1.8 Release, load generated with plain spin loops, whole-case wall clock, one run each: run queue 1 (idle) -> 0.136 s run queue 14 -> 23.8 s run queue 27 -> 170.5 s run queue 38 -> 396.4 s (load average 31-38 at measurement) Steeply superlinear -- 12 spin loops to 24 costs 7.2x, 24 to 36 another 2.3x -- and **every one of those runs passed**: 40 assertions, `inFlight 1, maxInFlight 1` throughout. The invariant the case exists for never wavered at any load. The 120 s ceiling was killing a passing test, which is a false red and, on shared hardware, eventually a false red on somebody else's PR. The same measurement with a 120 s cap, for the control: load36 run 1: rc=124 wall=120.014 s last watchdog: iteration 5, phase 'draining (~StrandExecutor)', 10 s into the iteration, completed 1975/3200, inFlight 1, maxInFlight 1 load36 run 2: rc=124 wall=120.018 s (reached iteration 6) load36 run 3: rc=124 wall=120.021 s (reached iteration 6) morph#760 reported four iterations in at 120 s under load average 29-48; six here at 26-38. Same shape. ## What was not done `kIterations` is untouched at 20. It is this case's detection power for a rare interleaving, not a duration knob, and cutting it to fit a ceiling would make the case cheaper and worse at the only thing it is for. The budget moved instead. Both constants now say so in the source. ## The budget `[slow]` is excluded from the blanket and registered again at `TIMEOUT 900` -- the mechanism #589/#590 already established here, because `DISCOVERY_MODE PRE_TEST` defers discovery to ctest invocation time and `set_tests_properties()` has nothing to name at configure time. 900 s is ~2.3x the measured 396 s. Extrapolating the curve to a run queue of ~50 -- the top of morph#760's reported load average -- gives roughly 730 s, so it is ~1.2x that too. It is also the number this same file already uses for its other load-sensitive case, `forms_schema_generation_is_not_route_count_ sensitive`, chosen there for the same reason. It is a ceiling, not immunity: past roughly 4.5x oversubscription this will exceed 900 s as well. What it still catches is a *deadlock*, which is unbounded rather than merely large -- in 15 minutes instead of 2, for one test out of 3044. ## Verified The tag is load-bearing, not decorative. `ctest --show-only=json-v1`: with [slow]: 3044 tests, {120.0: 2966, 900.0: 2, 300.0: 2, 60.0: 2}, strand case TIMEOUT 900.0 without [slow]: 3044 tests, {120.0: 2967, 900.0: 1, 300.0: 2, 60.0: 2}, strand case TIMEOUT 120.0 Same total either way and zero duplicate names, so splitting the discovery call in two neither drops a test nor registers one twice. Its neighbour in the same file, `StrandExecutor keeps one strand per key when a post races the drain`, stays at 120. Catch2 tags are never translated into ctest labels anywhere in this repository (no `catch_discover_tests` call passes `ADD_TAGS_AS_LABELS`; ci.yml says so at the TSan leg), so `[slow]` cannot change what any `-L`/`-LE` filter selects. ## The budget proved where it has to hold Full `ctest -j 12` with 24 spin loops competing for the same 12 cores, in four foreground ranges, load average 17 -> 37 across them: -I 1,1000 CTEST_EXIT=0 60 s 100% tests passed out of 1000 -I 1001,1800 CTEST_EXIT=0 274 s 100% tests passed out of 800 -I 1801,2600 CTEST_EXIT=0 233 s 100% tests passed out of 800 -I 2601,3044 CTEST_EXIT=0 30 s 100% tests passed out of 444 and in the range that holds it: 799/800 Test #1651: StrandExecutor never runs two tasks for one key concurrently under contention ... Passed 188.43 sec 188.43 s is a hard timeout at 120 and passes comfortably at 900 -- the defect and the fix in one line, under the load the issue asks the case to survive. Co-Authored-By: Claude Opus 5 (1M context) Claude-Session: https://claude.ai/code/session_01VptDWG2fKr2vBnLSJcgzgW --- tests/CMakeLists.txt | 56 +++++++++++++++++++++++++++++++++----- tests/test_strand_race.cpp | 29 +++++++++++++++++++- 2 files changed, 77 insertions(+), 8 deletions(-) diff --git a/tests/CMakeLists.txt b/tests/CMakeLists.txt index 2480ede19..f57393775 100644 --- a/tests/CMakeLists.txt +++ b/tests/CMakeLists.txt @@ -216,13 +216,55 @@ include(Catch) # test fails fast instead of stalling the whole CI job (observed: a single test # hanging blocked a Windows runner for over half an hour). # -# One test used to need an exception, registered separately by tag: the -# 70,000-node `equation()` depth test, whose O(n^2) string building cost 32.3s -# under ASan+UBSan and blew past 120s under TSan (#589, widened to 600s by -# #590). #582 made that rendering linear -- the same test now takes 0.11s under -# ASan+UBSan and 1.3s at -O0 under TSan -- so the exception, and the `[slow]` -# tag it keyed on, are gone again and every test is back under one cap. -catch_discover_tests(morph_tests DISCOVERY_MODE PRE_TEST PROPERTIES TIMEOUT 120) +# That number was never chosen with any particular test in mind, which is +# fine while every test is sub-second and wrong for the one that is not: the +# longest, most load-sensitive case in the binary was governed by the same +# ceiling as the cheapest (morph#760). So the blanket stays and `[slow]` is +# registered separately, exactly as it was for #589/#590 -- DISCOVERY_MODE +# PRE_TEST defers discovery to ctest invocation time, so a per-test TIMEOUT +# cannot be set with set_tests_properties() here (nothing is named that test +# yet at configure time); excluding a tag and giving it its own +# catch_discover_tests() call is the mechanism that is actually available. +# +# (#589's own use of `[slow]` is gone: the 70,000-node `equation()` depth test +# blew past 120s under TSan because of O(n^2) string building, #582 made that +# rendering linear, and it is back under the blanket cap. The tag is reused +# here for a different test and a different reason.) +catch_discover_tests(morph_tests DISCOVERY_MODE PRE_TEST TEST_SPEC "~[slow]" PROPERTIES TIMEOUT 120) + +# `[slow]` (morph#760): `StrandExecutor never runs two tasks for one key +# concurrently under contention`. Not slow because it computes anything -- +# 0.14 s on an idle box -- but because the strand serialises 3200 tasks per +# iteration and every handoff is a thread wakeup that has to wait its turn on +# the run queue. That cost is set by how contended the host is, and it climbs +# steeply. Measured on this tree, 12 cores, clang 22.1.8 Release, load made +# with plain spin loops, whole-case wall clock, one run each: +# +# run queue 1 (idle) -> 0.14 s +# run queue 14 -> 23.8 s +# run queue 27 -> 170.5 s +# run queue 38 -> 396.4 s <- load average 31-38 at measurement +# +# Every one of those runs *passed*: 40 assertions, `inFlight 1, maxInFlight 1` +# throughout. morph#760's report was this case being killed while passing, at +# load average 29-48 -- above the 38 measured here, and the curve is +# superlinear, so the fitted figure at a run queue of ~50 is roughly 730 s. +# +# 900 s is therefore ~2.3x the measured 396 s and ~1.2x that extrapolation. It +# is also the number this file already uses for its other load-sensitive case +# (`forms_schema_generation_is_not_route_count_sensitive`, below), chosen there +# for the same reason: a slow shared runner can be several times a workstation. +# +# What this deliberately does **not** do is reduce `kIterations`. Twenty +# iterations is this case's detection power for a rare interleaving; trading it +# away to fit a ceiling would make the case cheaper and worse at the only thing +# it exists for. See the comment on `kIterations` in test_strand_race.cpp. +# +# And what it does not buy is immunity: a host oversubscribed past roughly 4.5x +# will exceed 900 s too. The ceiling is here to catch a *deadlock* -- which is +# unbounded, not merely large -- and it still does, in 15 minutes instead of 2, +# for one test out of 3044. +catch_discover_tests(morph_tests DISCOVERY_MODE PRE_TEST TEST_SPEC "[slow]" PROPERTIES TIMEOUT 900) # ── Two-binary journal-path skew test (issue #246) ─────────────────────────── # The executable form of the journal's data-at-rest contract, which diff --git a/tests/test_strand_race.cpp b/tests/test_strand_race.cpp index 2719d6a96..2a586957d 100644 --- a/tests/test_strand_race.cpp +++ b/tests/test_strand_race.cpp @@ -168,9 +168,36 @@ class DrainWatchdog { } // namespace -TEST_CASE("StrandExecutor never runs two tasks for one key concurrently under contention", "[strand][race]") { +// `[slow]` (morph#760) is what gives this case its own ctest `TIMEOUT`; see +// tests/CMakeLists.txt, where the tag is excluded from the blanket 120 s and +// registered again with a budget sized from this case's measured loaded +// runtime. It is a *scheduling* budget, not a performance one -- see the note +// on `kIterations` below. +TEST_CASE("StrandExecutor never runs two tasks for one key concurrently under contention", "[strand][race][slow]") { constexpr int kThreads = 8; constexpr int kPostsPerThread = 400; + // Detection power, not a duration. Each iteration is one fresh + // pool/strand pair sampling the drain-and-re-arm interleaving once; twenty + // of them is how often this case gets to observe it. Cutting this number + // is the cheap way to fit a timeout and it makes the case worse at the one + // thing it exists for, so the budget was moved instead (morph#760). + // + // What the case actually costs is set by the *scheduler*, not by the work: + // the strand serialises `kThreads * kPostsPerThread` tasks, and each + // handoff is a wakeup that has to wait its turn on the run queue. Measured + // here, 12 cores, clang 22.1.8 Release, synthetic spin-loop load, whole + // case wall clock: + // + // run queue 1 (idle) -> 0.14 s + // run queue 14 -> 23.8 s + // run queue 27 -> 170.5 s + // run queue 38 -> 396.4 s + // + // Steeply superlinear in the oversubscription ratio, and the serialisation + // invariant held in every one of those runs -- `inFlight 1, maxInFlight 1` + // throughout, 40 assertions passed. A host busy enough will still exceed + // any fixed ceiling; that is a property of the measurement, not a defect + // this case can assert its way out of. constexpr int kIterations = 20; morph::exec::detail::ModelId const key{42};