From c72fb5580de4857357ad234fb090330ccdc1bc5d Mon Sep 17 00:00:00 2001 From: Alexy Khrabrov Date: Sun, 20 Sep 2026 19:17:59 +0000 Subject: [PATCH] lsqb: give supervision waits room above scheduler noise The observation-worker tests assert how the coordinator reacts inside wall-clock windows of tens of milliseconds. On a starved host a process can be descheduled for longer than the window, and the test reports a supervision failure that did not happen: four such failures are recorded in docs/LSQB_RUNNER_TIMING_FLAKES.md, three of them in one run on a documentation-only commit. Waits that mean this bounded wait ends now get an order of magnitude over scheduler noise, named once as READY_AND_REAP_MS and REAP_GRACE_MS rather than repeated as literals. Three numbers stay small because they are the scenario rather than the tolerance: the 25 ms deadline whose test asserts the deadline fires, the 50 ms reap whose test asserts the reap gives up, and the 200 ms query deadline against a 300 ms cleanup, whose point is that cleanup is not query time. Every run() in plan_tests reports through unwrap_or_else rather than unwrap, so the next failure names its cause instead of printing Err. Co-Authored-By: Claude Opus 5 (1M context) --- .../src/observation_process/cleanup_tests.rs | 37 +++++++++++++++-- .../src/observation_process/plan_tests.rs | 40 ++++++++++++++----- 2 files changed, 63 insertions(+), 14 deletions(-) diff --git a/benchmarks/lsqb/src/observation_process/cleanup_tests.rs b/benchmarks/lsqb/src/observation_process/cleanup_tests.rs index 7609c39e..27571fda 100644 --- a/benchmarks/lsqb/src/observation_process/cleanup_tests.rs +++ b/benchmarks/lsqb/src/observation_process/cleanup_tests.rs @@ -16,9 +16,24 @@ printf '{{"protocol":"grust-lsqb-observation-worker-v1","event":"result","token" command } +/// See `plan_tests.rs` and `docs/LSQB_RUNNER_TIMING_FLAKES.md`: waits that are +/// expected to end get an order of magnitude over scheduler noise. +const READY_AND_REAP_MS: u64 = 10_000; +const REAP_GRACE_MS: u64 = 1_000; +/// Deliberately short: this one asserts that the reap gives up. +const HUNG_REAP_MS: u64 = 50; + #[test] fn post_result_cleanup_is_recovery_not_query_time() { - let result = run(&mut worker("sleep 0.3"), "cleanup", 200, 10, 1000, 1000).unwrap(); + let result = run( + &mut worker("sleep 0.3"), + "cleanup", + 200, + REAP_GRACE_MS, + READY_AND_REAP_MS, + READY_AND_REAP_MS, + ) + .unwrap_or_else(|error| panic!("supervision failed: {error}")); assert_eq!(result.outcome, WorkerOutcome::Pass); assert!(result.elapsed_ns < 200_000_000); assert!(result.recovery_ns >= 250_000_000); @@ -26,14 +41,30 @@ fn post_result_cleanup_is_recovery_not_query_time() { #[test] fn failed_cleanup_invalidates_an_already_emitted_result() { - let error = run(&mut worker("exit 1"), "cleanup", 500, 10, 500, 500).unwrap_err(); + let error = run( + &mut worker("exit 1"), + "cleanup", + READY_AND_REAP_MS, + REAP_GRACE_MS, + READY_AND_REAP_MS, + READY_AND_REAP_MS, + ) + .unwrap_err(); assert!(error.contains("failed after writing its result"), "{error}"); } #[test] fn hung_cleanup_cannot_hold_the_coordinator_indefinitely() { let started = Instant::now(); - let error = run(&mut worker("sleep 10"), "cleanup", 500, 10, 50, 500).unwrap_err(); + let error = run( + &mut worker("sleep 10"), + "cleanup", + READY_AND_REAP_MS, + REAP_GRACE_MS, + HUNG_REAP_MS, + READY_AND_REAP_MS, + ) + .unwrap_err(); assert!( error.contains("did not exit within the reap grace"), "{error}" diff --git a/benchmarks/lsqb/src/observation_process/plan_tests.rs b/benchmarks/lsqb/src/observation_process/plan_tests.rs index d1d8d201..3a55b991 100644 --- a/benchmarks/lsqb/src/observation_process/plan_tests.rs +++ b/benchmarks/lsqb/src/observation_process/plan_tests.rs @@ -9,6 +9,16 @@ fn ready_record(plan: Option) -> Vec { bytes } +/// Windows for waits that are expected to end. A descheduled process on a +/// starved host can miss a window of tens of milliseconds without anything +/// being wrong, and these tests are about supervision, not about how fast the +/// host is: see `docs/LSQB_RUNNER_TIMING_FLAKES.md`. Production defaults stay +/// tight; only the tests are generous. +const READY_AND_REAP_MS: u64 = 10_000; +const REAP_GRACE_MS: u64 = 1_000; +/// Deliberately short: this one asserts that the deadline fires. +const HARD_DEADLINE_MS: u64 = 25; + #[test] fn execution_plan_ready_is_additive_and_native_ready_bytes_stay_unchanged() { let legacy = ready_record(None); @@ -97,12 +107,12 @@ fn ready_execution_plan_survives_success_error_and_backend_timeout() { let observation = run( &mut worker(Some(plan), outcome), "plan-test", - 500, - 10, - 1000, - 1000, + READY_AND_REAP_MS, + REAP_GRACE_MS, + READY_AND_REAP_MS, + READY_AND_REAP_MS, ) - .unwrap(); + .unwrap_or_else(|error| panic!("supervision failed: {error}")); assert_eq!(observation.outcome, expected); assert_eq!(observation.require_declared_plan().unwrap(), plan); } @@ -114,12 +124,12 @@ fn ready_execution_plan_survives_hard_timeout_without_a_result_record() { let observation = run( &mut worker(Some(ExecutionPlan::CountFactorized), "hang"), "plan-test", - 25, - 10, - 1000, - 1000, + HARD_DEADLINE_MS, + REAP_GRACE_MS, + READY_AND_REAP_MS, + READY_AND_REAP_MS, ) - .unwrap(); + .unwrap_or_else(|error| panic!("supervision failed: {error}")); assert_eq!(observation.outcome, WorkerOutcome::Timeout); assert_eq!( observation.termination, @@ -135,7 +145,15 @@ fn ready_execution_plan_survives_hard_timeout_without_a_result_record() { #[test] #[cfg(unix)] fn legacy_worker_is_supported_but_cannot_supply_a_new_matrix_plan() { - let observation = run(&mut worker(None, "pass"), "plan-test", 500, 10, 1000, 1000).unwrap(); + let observation = run( + &mut worker(None, "pass"), + "plan-test", + READY_AND_REAP_MS, + REAP_GRACE_MS, + READY_AND_REAP_MS, + READY_AND_REAP_MS, + ) + .unwrap_or_else(|error| panic!("supervision failed: {error}")); assert_eq!(observation.outcome, WorkerOutcome::Pass); assert_eq!(observation.plan, None); assert!(