From 91d3c7146e214c334e0de98e89d75e35c223bcbe Mon Sep 17 00:00:00 2001 From: Josh Knapp Date: Mon, 21 Sep 2026 10:45:53 -0700 Subject: [PATCH] debug: round 3 -- 12 independent quiet trials, varying t0 and now-arithmetic TEMPORARY. Co-Authored-By: Claude Opus 5 (1M context) --- core/tests/test_session.cpp | 125 +++++++++++++++++++++++++++--------- 1 file changed, 94 insertions(+), 31 deletions(-) diff --git a/core/tests/test_session.cpp b/core/tests/test_session.cpp index a20a7e7..29cf892 100644 --- a/core/tests/test_session.cpp +++ b/core/tests/test_session.cpp @@ -443,44 +443,107 @@ void testStallWatchdogTrace() } } -// TEMPORARY DEBUG -- remove before merge. A byte-for-byte quiet copy of the -// loop from testStallWatchdogBacksOffRatherThanLooping: no accessor calls, -// no printing inside the loop. Results are collected into an int array and -// reported afterwards, so if the loud trace above passes while this one -// fails, the observation is the cure and the fault is codegen, not data. +// TEMPORARY DEBUG -- remove before merge. The quiet sequence, run as N +// independent trials: a fresh steady_clock::now() per trial, plus trials +// with a synthetic fixed t0 and trials that compute `now` as an absolute +// offset from t0 instead of accumulating. Nothing is observed inside the +// loop; per-trial results are printed afterwards. If some trials pass and +// others fail in the same process, the absolute clock value -- not codegen +// -- is what the fault tracks. void testStallWatchdogQuiet() { - int early[6] = {0}; - int fire[6] = {0}; + struct Trial { + long long t0_ns; + int mode; + int early[6]; + int fire[6]; + long long next_rel_ns; + long long backoff_ms; + int attempts_before_loop; + int attempts_after; + }; + const int kTrials = 12; + Trial trials[kTrials]; - const auto t0 = std::chrono::steady_clock::now(); - StallWatchdog w(std::chrono::milliseconds(2000), std::chrono::milliseconds(30000)); - w.setExpectingFrames(true, t0); + for (int t = 0; t < kTrials; ++t) { + // mode 0: now() as t0, accumulate. mode 1: now() as t0, absolute + // offsets. mode 2: synthetic t0 (epoch + a fixed odd nanosecond + // count), accumulate. + const int mode = t % 3; + std::chrono::steady_clock::time_point t0; + if (mode == 2) + t0 = std::chrono::steady_clock::time_point(std::chrono::nanoseconds(1234567891011LL)); + else + t0 = std::chrono::steady_clock::now(); - auto now = t0 + std::chrono::milliseconds(2000); - (void)w.poll(now); - now += std::chrono::milliseconds(2000); - (void)w.poll(now); - now += std::chrono::milliseconds(4000); - (void)w.poll(now); - now += std::chrono::milliseconds(8000); - (void)w.poll(now); - now += std::chrono::milliseconds(16000); - (void)w.poll(now); - const int attempts_before_loop = w.attemptsThisStall(); + StallWatchdog w(std::chrono::milliseconds(2000), std::chrono::milliseconds(30000)); + w.setExpectingFrames(true, t0); - for (int i = 0; i < 6; ++i) { - early[i] = w.poll(now + std::chrono::milliseconds(29999)) ? 1 : 0; - now += std::chrono::milliseconds(30000); - fire[i] = w.poll(now) ? 1 : 0; + int early[6] = {0}; + int fire[6] = {0}; + int attempts_before = 0; + + if (mode == 1) { + (void)w.poll(t0 + std::chrono::milliseconds(2000)); + (void)w.poll(t0 + std::chrono::milliseconds(4000)); + (void)w.poll(t0 + std::chrono::milliseconds(8000)); + (void)w.poll(t0 + std::chrono::milliseconds(16000)); + (void)w.poll(t0 + std::chrono::milliseconds(32000)); + attempts_before = w.attemptsThisStall(); + long long at = 32000; + for (int i = 0; i < 6; ++i) { + early[i] = w.poll(t0 + std::chrono::milliseconds(at + 29999)) ? 1 : 0; + at += 30000; + fire[i] = w.poll(t0 + std::chrono::milliseconds(at)) ? 1 : 0; + } + } else { + auto now = t0 + std::chrono::milliseconds(2000); + (void)w.poll(now); + now += std::chrono::milliseconds(2000); + (void)w.poll(now); + now += std::chrono::milliseconds(4000); + (void)w.poll(now); + now += std::chrono::milliseconds(8000); + (void)w.poll(now); + now += std::chrono::milliseconds(16000); + (void)w.poll(now); + attempts_before = w.attemptsThisStall(); + for (int i = 0; i < 6; ++i) { + early[i] = w.poll(now + std::chrono::milliseconds(29999)) ? 1 : 0; + now += std::chrono::milliseconds(30000); + fire[i] = w.poll(now) ? 1 : 0; + } + } + + trials[t].t0_ns = + (long long)std::chrono::duration_cast(t0.time_since_epoch()).count(); + trials[t].mode = mode; + for (int i = 0; i < 6; ++i) { + trials[t].early[i] = early[i]; + trials[t].fire[i] = fire[i]; + } + trials[t].next_rel_ns = + (long long)std::chrono::duration_cast(w.dbgNextAllowed() - t0).count(); + trials[t].backoff_ms = w.dbgBackoffMs(); + trials[t].attempts_before_loop = attempts_before; + trials[t].attempts_after = w.attemptsThisStall(); } - std::fprintf(stderr, "WDQUIET attempts_before_loop=%d\n", attempts_before_loop); - for (int i = 0; i < 6; ++i) - std::fprintf(stderr, "WDQUIET i=%d early=%d(want 0) fire=%d(want 1)\n", i, early[i], fire[i]); - for (int i = 0; i < 6; ++i) { - ST_ASSERT(early[i] == 0); - ST_ASSERT(fire[i] == 1); + for (int t = 0; t < kTrials; ++t) { + std::fprintf(stderr, + "WDQUIET trial=%2d mode=%d t0_ns=%lld before=%d after=%d final_next_rel_ns=%lld backoff_ms=%lld early=%d%d%d%d%d%d fire=%d%d%d%d%d%d\n", + t, trials[t].mode, trials[t].t0_ns, trials[t].attempts_before_loop, + trials[t].attempts_after, trials[t].next_rel_ns, trials[t].backoff_ms, + trials[t].early[0], trials[t].early[1], trials[t].early[2], + trials[t].early[3], trials[t].early[4], trials[t].early[5], + trials[t].fire[0], trials[t].fire[1], trials[t].fire[2], + trials[t].fire[3], trials[t].fire[4], trials[t].fire[5]); + } + for (int t = 0; t < kTrials; ++t) { + for (int i = 0; i < 6; ++i) { + ST_ASSERT(trials[t].early[i] == 0); + ST_ASSERT(trials[t].fire[i] == 1); + } } }