diff --git a/core/src/session_types.cpp b/core/src/session_types.cpp index 7d3bac8..8ca8e28 100644 --- a/core/src/session_types.cpp +++ b/core/src/session_types.cpp @@ -14,10 +14,6 @@ You may obtain a copy of the License at // 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 { @@ -223,23 +219,6 @@ 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_) @@ -274,10 +253,6 @@ 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 e63c6a6..a20a7e7 100644 --- a/core/tests/test_session.cpp +++ b/core/tests/test_session.cpp @@ -27,6 +27,7 @@ You may obtain a copy of the License at #include #include +#include #include #include #include @@ -370,6 +371,119 @@ void testStallWatchdogBacksOffRatherThanLooping() ST_ASSERT_EQ(w.attemptsThisStall(), 1); } + +// TEMPORARY DEBUG -- remove before merge. Same sequence as the test above, +// but every number is RECORDED into plain locals and printed only after the +// loop finishes, so the loop body stays as close to the original as +// possible (an fprintf inside poll() made this pass on Windows, so the +// observation itself perturbs the thing being observed). +void testStallWatchdogTrace() +{ + struct Rec { + long long now_ns; + long long next_ns; + long long base_ns; + long long backoff_ms; + int attempts; + int early; // result of poll(now + 29999) -- expected 0 + int fire; // result of poll(now) -- expected 1 + }; + Rec recs[16]; + int n = 0; + + const auto t0 = std::chrono::steady_clock::now(); + StallWatchdog w(std::chrono::milliseconds(2000), std::chrono::milliseconds(30000)); + w.setExpectingFrames(true, t0); + + auto rel = [t0](std::chrono::steady_clock::time_point tp) { + return (long long)std::chrono::duration_cast(tp - t0).count(); + }; + auto rec = [&](std::chrono::steady_clock::time_point now, int early, int fire) { + if (n < 16) { + recs[n].now_ns = rel(now); + recs[n].next_ns = rel(w.dbgNextAllowed()); + recs[n].base_ns = rel(w.dbgBaseline()); + recs[n].backoff_ms = w.dbgBackoffMs(); + recs[n].attempts = w.attemptsThisStall(); + recs[n].early = early; + recs[n].fire = fire; + ++n; + } + }; + + auto now = t0 + std::chrono::milliseconds(2000); + int f = w.poll(now) ? 1 : 0; + rec(now, -1, f); + + const int gaps[] = {2000, 4000, 8000, 16000}; + for (int i = 0; i < 4; ++i) { + now += std::chrono::milliseconds(gaps[i]); + f = w.poll(now) ? 1 : 0; + rec(now, -1, f); + } + + for (int i = 0; i < 6; ++i) { + const int e = w.poll(now + std::chrono::milliseconds(29999)) ? 1 : 0; + now += std::chrono::milliseconds(30000); + f = w.poll(now) ? 1 : 0; + rec(now, e, f); + } + + std::fprintf(stderr, "WDTRACE t0_ns=%lld timeout_ms=%lld max_ms=%lld tick_num=%lld tick_den=%lld rep_bytes=%d\n", + (long long)std::chrono::duration_cast(t0.time_since_epoch()).count(), + w.dbgTimeoutMs(), w.dbgMaxBackoffMs(), + (long long)std::chrono::steady_clock::period::num, + (long long)std::chrono::steady_clock::period::den, + (int)sizeof(std::chrono::steady_clock::rep)); + for (int i = 0; i < n; ++i) { + std::fprintf(stderr, + "WDTRACE step=%2d now_rel_ns=%lld next_rel_ns=%lld base_rel_ns=%lld backoff_ms=%lld attempts=%d early=%d fire=%d\n", + i, recs[i].now_ns, recs[i].next_ns, recs[i].base_ns, + recs[i].backoff_ms, recs[i].attempts, recs[i].early, recs[i].fire); + } +} + +// 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. +void testStallWatchdogQuiet() +{ + int early[6] = {0}; + int fire[6] = {0}; + + const auto t0 = std::chrono::steady_clock::now(); + StallWatchdog w(std::chrono::milliseconds(2000), std::chrono::milliseconds(30000)); + w.setExpectingFrames(true, t0); + + 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(); + + 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; + } + + 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); + } +} + // The ceiling has to engage on the FIRST attempt whose doubled backoff would // exceed it, not one attempt later -- a Windows release build got exactly // that step wrong (it waited 32s once before settling at the 30s ceiling), @@ -528,6 +642,8 @@ int main() testStallWatchdogFiresAfterThreshold(); testStallWatchdogDoesNotFireWhenNotExpectingFrames(); testStallWatchdogBacksOffRatherThanLooping(); + testStallWatchdogTrace(); + testStallWatchdogQuiet(); testStallWatchdogNeverWaitsLongerThanTheCeiling(); LiveKitSession::globalInitialize();