From 422d871cfedd4cea7380f15e4d75812c807d9a60 Mon Sep 17 00:00:00 2001 From: Josh Knapp Date: Mon, 21 Sep 2026 10:30:41 -0700 Subject: [PATCH] debug: instrument StallWatchdog timing for a Windows CI trace TEMPORARY. Prints the actual clock/backoff numbers on every poll so the Windows job's log can be compared against Linux's, instead of guessing. Co-Authored-By: Claude Opus 5 (1M context) --- core/include/stplugin/session_types.h | 7 ++++++ core/src/session_types.cpp | 29 +++++++++++++++++++++++++ core/tests/test_session.cpp | 31 +++++++++++++++++++++++++++ 3 files changed, 67 insertions(+) diff --git a/core/include/stplugin/session_types.h b/core/include/stplugin/session_types.h index e7c544d..f21dee8 100644 --- a/core/include/stplugin/session_types.h +++ b/core/include/stplugin/session_types.h @@ -202,6 +202,13 @@ public: /// onFrameDelivered and by setExpectingFrames. int attemptsThisStall() const { return attempts_; } + // TEMPORARY DEBUG ACCESSORS -- remove before merge. + long long dbgBackoffMs() const { return (long long)backoff_.count(); } + long long dbgTimeoutMs() const { return (long long)timeout_.count(); } + long long dbgMaxBackoffMs() const { return (long long)max_backoff_.count(); } + std::chrono::steady_clock::time_point dbgNextAllowed() const { return next_attempt_allowed_; } + std::chrono::steady_clock::time_point dbgBaseline() const { return baseline_; } + private: std::chrono::milliseconds timeout_; std::chrono::milliseconds max_backoff_; diff --git a/core/src/session_types.cpp b/core/src/session_types.cpp index 3db4387..7d3bac8 100644 --- a/core/src/session_types.cpp +++ b/core/src/session_types.cpp @@ -11,6 +11,14 @@ You may obtain a copy of the License at #include "stplugin/session_types.h" +// TEMPORARY DEBUG -- remove before merge. +#include +#include +namespace { long long dbg_ns(std::chrono::steady_clock::time_point tp) { + return (long long)std::chrono::duration_cast(tp.time_since_epoch()).count(); +} } + + namespace stplugin { const char *describePixelFormat(PixelFormat format) @@ -215,6 +223,23 @@ void StallWatchdog::onFrameDelivered(std::chrono::steady_clock::time_point now) bool StallWatchdog::poll(std::chrono::steady_clock::time_point now) { + // TEMPORARY DEBUG -- remove before merge. + std::fprintf(stderr, + "WDPOLL now_ns=%lld base_ns=%lld next_ns=%lld elapsed_ms=%lld " + "backoff_ms=%lld timeout_ms=%lld max_ms=%lld attempts=%d " + "expecting=%d have_base=%d c_elapsed_lt_timeout=%d c_now_lt_next=%d " + "tick_num=%lld tick_den=%lld sizeof_rep=%d\n", + dbg_ns(now), dbg_ns(baseline_), dbg_ns(next_attempt_allowed_), + (long long)std::chrono::duration_cast(now - baseline_).count(), + (long long)backoff_.count(), (long long)timeout_.count(), + (long long)max_backoff_.count(), attempts_, + expecting_ ? 1 : 0, have_baseline_ ? 1 : 0, + (now - baseline_ < timeout_) ? 1 : 0, + (now < next_attempt_allowed_) ? 1 : 0, + (long long)std::chrono::steady_clock::period::num, + (long long)std::chrono::steady_clock::period::den, + (int)sizeof(std::chrono::steady_clock::rep)); + if (!expecting_ || !have_baseline_) return false; if (now - baseline_ < timeout_) @@ -249,6 +274,10 @@ bool StallWatchdog::poll(std::chrono::steady_clock::time_point now) // doubling also means the product is computed only when it cannot // exceed max_backoff_, so no intermediate can overflow. backoff_ = (wait > max_backoff_ / 2) ? max_backoff_ : wait * 2; + // TEMPORARY DEBUG -- remove before merge. + std::fprintf(stderr, "WDFIRE attempts=%d wait_ms=%lld new_next_ns=%lld new_backoff_ms=%lld\n", + attempts_, (long long)wait.count(), dbg_ns(next_attempt_allowed_), + (long long)backoff_.count()); return true; } diff --git a/core/tests/test_session.cpp b/core/tests/test_session.cpp index e2bf809..e63c6a6 100644 --- a/core/tests/test_session.cpp +++ b/core/tests/test_session.cpp @@ -26,6 +26,7 @@ You may obtain a copy of the License at // manual-sign-off bucket. #include +#include #include #include #include @@ -284,9 +285,27 @@ void testStallWatchdogBacksOffRatherThanLooping() StallWatchdog w(std::chrono::milliseconds(2000), std::chrono::milliseconds(30000)); w.setExpectingFrames(true, t0); + // TEMPORARY DEBUG -- remove before merge. + auto rel = [t0](std::chrono::steady_clock::time_point tp) { + return (long long)std::chrono::duration_cast(tp - t0).count(); + }; + auto dump = [&](const char *tag, std::chrono::steady_clock::time_point n) { + std::fprintf(stderr, + "WDTEST %-16s now_rel_ns=%lld next_rel_ns=%lld base_rel_ns=%lld " + "backoff_ms=%lld attempts=%d\n", + tag, rel(n), rel(w.dbgNextAllowed()), rel(w.dbgBaseline()), + w.dbgBackoffMs(), w.attemptsThisStall()); + }; + std::fprintf(stderr, "WDTEST t0_ns=%lld timeout_ms=%lld max_ms=%lld\n", + (long long)std::chrono::duration_cast(t0.time_since_epoch()).count(), + w.dbgTimeoutMs(), w.dbgMaxBackoffMs()); + dump("init", t0); + // First attempt at the threshold. auto now = t0 + std::chrono::milliseconds(2000); + dump("pre-attempt1", now); ST_ASSERT(w.poll(now)); + dump("post-attempt1", now); ST_ASSERT_EQ(w.attemptsThisStall(), 1); // A genuinely gone publisher: no frame ever comes back. Immediately @@ -299,24 +318,32 @@ void testStallWatchdogBacksOffRatherThanLooping() // The backoff after attempt 1 is the base timeout (2000ms): the second // attempt is allowed at +2000ms from the first, not before. now += std::chrono::milliseconds(2000); + dump("pre-attempt2", now); ST_ASSERT(w.poll(now)); + dump("post-attempt2", now); ST_ASSERT_EQ(w.attemptsThisStall(), 2); // Backoff doubles: the third attempt needs a 4000ms gap, not 2000ms. ST_ASSERT(!w.poll(now + std::chrono::milliseconds(3999))); now += std::chrono::milliseconds(4000); + dump("pre-attempt3", now); ST_ASSERT(w.poll(now)); + dump("post-attempt3", now); ST_ASSERT_EQ(w.attemptsThisStall(), 3); // ... and again to 8000ms, and again to 16000ms. ST_ASSERT(!w.poll(now + std::chrono::milliseconds(7999))); now += std::chrono::milliseconds(8000); + dump("pre-attempt4", now); ST_ASSERT(w.poll(now)); + dump("post-attempt4", now); ST_ASSERT_EQ(w.attemptsThisStall(), 4); ST_ASSERT(!w.poll(now + std::chrono::milliseconds(15999))); now += std::chrono::milliseconds(16000); + dump("pre-attempt5", now); ST_ASSERT(w.poll(now)); + dump("post-attempt5", now); ST_ASSERT_EQ(w.attemptsThisStall(), 5); // The backoff is capped: doubling 16000ms would be 32000ms, but it @@ -324,9 +351,13 @@ void testStallWatchdogBacksOffRatherThanLooping() // failed, so a publisher that comes back after an hour is still // retried at a bounded cadence, not abandoned. for (int i = 0; i < 6; ++i) { + std::fprintf(stderr, "WDTEST ---- loop iteration %d ----\n", i); + dump("loop-pre-29999", now + std::chrono::milliseconds(29999)); ST_ASSERT(!w.poll(now + std::chrono::milliseconds(29999))); now += std::chrono::milliseconds(30000); + dump("loop-pre-fire", now); ST_ASSERT(w.poll(now)); + dump("loop-post-fire", now); } // A frame finally arrives: the stall is over, and the NEXT one (a fresh