From cc45c55ed3556ff0a1be6c6e1e436c5164b34fb4 Mon Sep 17 00:00:00 2001 From: Joe Rivera Date: Thu, 3 Sep 2026 23:08:18 -0500 Subject: [PATCH] test(state): poll the published value, not the pump_cycles proxy StateSessionStatusTest.ConflictAutoPublish fails roughly one Windows run in ten. It has been the only failing check on PRs #315 and #318, and it cost #324 a CI round too. It is a test defect, not a race and not scheduler starvation. The evidence that settles it is the duration of the same test in PASSING windows-2022 jobs: #315 bc5b9c3 FAIL 1.61s #318 eb3ec7b pass 1.71s #318 (old) FAIL 1.59s #324 branch pass 1.60s #319 branch pass 1.59s Pass and fail are indistinguishable in wall time, and the test is scheduled last in every run -- it fails alone and passes alone. So RUN_SERIAL (the #121/#325 remedy for the fork+IPC suites) cannot separate the populations; this session is transport_kind::inproc, with no fork and no socket. Nor is it a replication race: ingest_remote fills the conflict ring synchronously under mutex, and the EXPECT_GT(total_conflicts_detected(), 0u) above passes in both failing jobs. The observed "" is an auto-vivified, never-written node. The bug is the premise in the test's own comment: "At 1ms interval, 100 cycles ~= 100ms". pump_interval_ms is a sleep FLOOR, not a rate. Windows' ~15.6ms scheduler tick stretches sleep_for(1ms) to a full tick, so 100 pump cycles takes ~1.55s; meanwhile sleep_for(20ms) costs two ticks, capping the 50-iteration wait at ~1.56s. The two deadlines land one tick apart, so a single preemption exhausts the loop and the value is read one tick early. Linux clears it in ~130ms and macOS in ~1.0s, which is why only the windows-2022 lane ever saw this. Poll the published value itself instead. That is correct on any timer granularity -- it returns as soon as the publish lands -- and the assertion is now fatal and prints pump_cycles, so a future timeout reports "never published, pump_cycles=N" instead of the misleading `"" != "conflict.key"` that sent this one to the wrong suspect. Verified on linux: suite 8/8; ConflictAutoPublish alone 0.13s over three runs (unchanged -- the larger budget only costs time when the publish is genuinely slow); 0 failures in 8 concurrent runs and 0 in 5 runs pinned to a single core. Deliberately not folded in, both real but separate: * _pump_cycles is stored/loaded memory_order_relaxed. Hygiene only; the per-node mutex supplies the real edge, and this fix stops the counter being load-bearing. * The publish cadence is counted in cycles, so on Windows conflict metrics publish ~15x less often than pump_interval_ms implies. If that is meant to be a wall-clock guarantee, pump_loop should compare elapsed time -- a product change deserving its own PR. --- src/cvc/tests/state_session_status_test.cpp | 34 ++++++++++++++++----- 1 file changed, 26 insertions(+), 8 deletions(-) diff --git a/src/cvc/tests/state_session_status_test.cpp b/src/cvc/tests/state_session_status_test.cpp index ae715c99..e5cbf6eb 100644 --- a/src/cvc/tests/state_session_status_test.cpp +++ b/src/cvc/tests/state_session_status_test.cpp @@ -136,18 +136,36 @@ TEST_F(StateSessionStatusTest, ConflictAutoPublish) { EXPECT_GT(session->shard().total_conflicts_detected(), 0u); - // Let pump run enough cycles for auto-publish (every 100 cycles). - // At 1ms interval, 100 cycles ≈ 100ms. Wait generously for CI. - for (int i = 0; i < 50; ++i) { - auto s = session->status(); - if (s.pump_cycles >= 110) + // Wait for the pump's periodic conflict publish (every 100 pump cycles). + // + // Poll the published value itself, NOT the pump_cycles proxy. The old wait + // was `pump_cycles >= 110` within 50 x 20ms, on the premise recorded in its + // comment: "At 1ms interval, 100 cycles ~= 100ms". That premise is wrong. + // pump_interval_ms is a sleep FLOOR, not a rate, and Windows' ~15.6ms + // scheduler tick stretches sleep_for(1ms) to a full tick -- so 100 cycles + // takes ~1.55s there, and sleep_for(20ms) costs two ticks, capping the loop + // at ~1.56s. The two deadlines land within one tick of each other, so the + // loop would exhaust, the value would be read one tick early, and the test + // failed on an auto-vivified empty node roughly one Windows run in ten. + // Linux exits here in ~130ms and macOS in ~1.0s, which is why only the + // windows-2022 lane ever saw it. + // + // Polling the value is correct on any timer granularity: it leaves as soon + // as the publish lands, so the common case is no slower than before. + const std::string prefix = "__system.distributed.test_cluster.conflicts.recent.0.path"; + std::string val; + for (int i = 0; i < 400; ++i) { + val = cvc::state::instance(ctx)(prefix).value(); + if (!val.empty()) break; std::this_thread::sleep_for(std::chrono::milliseconds(20)); } - // Verify conflict metrics appear in the state tree. - std::string prefix = "__system.distributed.test_cluster.conflicts.recent.0.path"; - std::string val = cvc::state::instance(ctx)(prefix).value(); + // Fatal, and it reports the pump counter: a future timeout should say + // "never published, pump_cycles=N" rather than the misleading + // `"" != "conflict.key"` that sent this one to the wrong suspect. + ASSERT_FALSE(val.empty()) << "conflict metrics never auto-published; pump_cycles=" + << session->status().pump_cycles; EXPECT_EQ(val, "conflict.key"); session->stop();