From cd8123a4ab17d90b527515554f183f90bb03a79b Mon Sep 17 00:00:00 2001 From: Josh Knapp Date: Mon, 21 Sep 2026 10:57:47 -0700 Subject: [PATCH] debug: round 5 -- capture the time point on the callee side TEMPORARY. Co-Authored-By: Claude Opus 5 (1M context) --- core/tests/test_session.cpp | 85 ++++++++++++++++++++----------------- 1 file changed, 45 insertions(+), 40 deletions(-) diff --git a/core/tests/test_session.cpp b/core/tests/test_session.cpp index 1a5b74a..903b4eb 100644 --- a/core/tests/test_session.cpp +++ b/core/tests/test_session.cpp @@ -443,37 +443,53 @@ void testStallWatchdogTrace() } } -// TEMPORARY DEBUG -- remove before merge. Five shapes of the same loop, -// each run twice. Nothing is printed until every trial is done. -// mode 0 accumulate `now += 30000ms`, pass `now` (known-bad) -// mode 1 absolute `t0 + milliseconds(offset)` (known-good) -// mode 2 accumulate, and sum the ns actually handed to poll -// mode 3 accumulate, pass a named copy of `now` -// mode 4 accumulate by a non-const step variable +// TEMPORARY DEBUG -- remove before merge. +// +// A non-inlined wrapper, so the time point can be read on the CALLEE side: +// whatever `received_ns` holds is what actually crossed the call boundary, +// independent of what the caller's abstract-machine value was. +#if defined(_MSC_VER) +#define ST_NOINLINE __declspec(noinline) +#else +#define ST_NOINLINE __attribute__((noinline)) +#endif +ST_NOINLINE bool st_dbg_poll(StallWatchdog &w, std::chrono::steady_clock::time_point n, + long long *received_ns) +{ + *received_ns = (long long)n.time_since_epoch().count(); + return w.poll(n); +} + +// Shapes, each run twice: +// mode 0 accumulate `now += 30000ms`, pass `now` (known-bad) +// mode 1 accumulate, pass a named copy of `now` (known-good) +// mode 2 accumulate, sum the ns the CALLER holds +// mode 3 accumulate, through st_dbg_poll (callee-side capture) void testStallWatchdogQuiet() { struct Trial { int mode; int early[6]; int fire[6]; - long long early_arg_sum_ms; long long fire_arg_sum_ms; + long long recv_rel_ms[6]; + long long t0_ns; long long next_rel_ns; int attempts_after; }; - const int kTrials = 10; + const int kTrials = 8; Trial trials[kTrials]; for (int t = 0; t < kTrials; ++t) { - const int mode = t % 5; + const int mode = t % 4; const auto t0 = std::chrono::steady_clock::now(); StallWatchdog w(std::chrono::milliseconds(2000), std::chrono::milliseconds(30000)); w.setExpectingFrames(true, t0); int early[6] = {0}; int fire[6] = {0}; - long long esum = 0; long long fsum = 0; + long long recv[6] = {0, 0, 0, 0, 0, 0}; auto now = t0 + std::chrono::milliseconds(2000); (void)w.poll(now); @@ -493,60 +509,49 @@ void testStallWatchdogQuiet() fire[i] = w.poll(now) ? 1 : 0; } } else if (mode == 1) { - 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 if (mode == 2) { - for (int i = 0; i < 6; ++i) { - const auto e = now + std::chrono::milliseconds(29999); - esum += std::chrono::duration_cast(e - t0).count(); - early[i] = w.poll(e) ? 1 : 0; - now += std::chrono::milliseconds(30000); - fsum += std::chrono::duration_cast(now - t0).count(); - fire[i] = w.poll(now) ? 1 : 0; - } - } else if (mode == 3) { for (int i = 0; i < 6; ++i) { early[i] = w.poll(now + std::chrono::milliseconds(29999)) ? 1 : 0; now += std::chrono::milliseconds(30000); const auto fire_arg = now; fire[i] = w.poll(fire_arg) ? 1 : 0; } - } else { - std::chrono::milliseconds step(30000); - std::chrono::milliseconds probe(29999); + } else if (mode == 2) { for (int i = 0; i < 6; ++i) { - early[i] = w.poll(now + probe) ? 1 : 0; - now += step; + early[i] = w.poll(now + std::chrono::milliseconds(29999)) ? 1 : 0; + now += std::chrono::milliseconds(30000); + fsum += std::chrono::duration_cast(now - t0).count(); fire[i] = w.poll(now) ? 1 : 0; } + } else { + for (int i = 0; i < 6; ++i) { + long long junk = 0; + early[i] = st_dbg_poll(w, now + std::chrono::milliseconds(29999), &junk) ? 1 : 0; + now += std::chrono::milliseconds(30000); + fire[i] = st_dbg_poll(w, now, &recv[i]) ? 1 : 0; + } } 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].recv_rel_ms[i] = + recv[i] ? (recv[i] - (long long)t0.time_since_epoch().count()) / 1000000LL : -1; } - trials[t].early_arg_sum_ms = esum; trials[t].fire_arg_sum_ms = fsum; + trials[t].t0_ns = (long long)t0.time_since_epoch().count(); trials[t].next_rel_ns = (long long)std::chrono::duration_cast(w.dbgNextAllowed() - t0).count(); trials[t].attempts_after = w.attemptsThisStall(); } - // Expected sums for mode 2: early args 61999..211999 step 30000, - // fire args 62000..212000 step 30000. - std::fprintf(stderr, "WDQUIET expect_early_sum=%lld expect_fire_sum=%lld\n", - (long long)(61999 + 91999 + 121999 + 151999 + 181999 + 211999), - (long long)(62000 + 92000 + 122000 + 152000 + 182000 + 212000)); for (int t = 0; t < kTrials; ++t) { std::fprintf(stderr, - "WDQUIET trial=%2d mode=%d after=%d final_next_rel_ns=%lld esum=%lld fsum=%lld early=%d%d%d%d%d%d fire=%d%d%d%d%d%d\n", + "WDQUIET trial=%d mode=%d after=%d next_rel_ns=%lld fsum=%lld(want 822000) recv_ms=%lld,%lld,%lld,%lld,%lld,%lld early=%d%d%d%d%d%d fire=%d%d%d%d%d%d\n", t, trials[t].mode, trials[t].attempts_after, trials[t].next_rel_ns, - trials[t].early_arg_sum_ms, trials[t].fire_arg_sum_ms, + trials[t].fire_arg_sum_ms, + trials[t].recv_rel_ms[0], trials[t].recv_rel_ms[1], trials[t].recv_rel_ms[2], + trials[t].recv_rel_ms[3], trials[t].recv_rel_ms[4], trials[t].recv_rel_ms[5], 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],