diff --git a/core/include/stplugin/session_types.h b/core/include/stplugin/session_types.h index f21dee8..e7c544d 100644 --- a/core/include/stplugin/session_types.h +++ b/core/include/stplugin/session_types.h @@ -202,13 +202,6 @@ 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 8ca8e28..3db4387 100644 --- a/core/src/session_types.cpp +++ b/core/src/session_types.cpp @@ -11,10 +11,6 @@ You may obtain a copy of the License at #include "stplugin/session_types.h" -// TEMPORARY DEBUG -- remove before merge. -#include -#include - namespace stplugin { const char *describePixelFormat(PixelFormat format) diff --git a/core/tests/test_session.cpp b/core/tests/test_session.cpp index 903b4eb..97481c2 100644 --- a/core/tests/test_session.cpp +++ b/core/tests/test_session.cpp @@ -26,8 +26,6 @@ You may obtain a copy of the License at // manual-sign-off bucket. #include -#include -#include #include #include #include @@ -280,71 +278,81 @@ void testStallWatchdogDoesNotFireWhenNotExpectingFrames() ST_ASSERT(w.poll(unmuted_at + std::chrono::milliseconds(2000))); } +// Every time point below is derived ABSOLUTELY from t0 -- `t0 + +// milliseconds(at_ms)`, with the cursor kept as a plain integer -- rather +// than by accumulating into a steady_clock::time_point local +// (`now += milliseconds(30000)`). That is not a style preference; it is +// load-bearing on Windows. +// +// The MSVC 19.44 (VS 2022 BuildTools 14.44.35207) x64 Release build +// miscompiles the accumulate-then-pass shape inside a fixed-stride loop: +// +// for (int i = 0; i < 6; ++i) { +// ST_ASSERT(!w.poll(now + milliseconds(29999))); +// now += milliseconds(30000); +// ST_ASSERT(w.poll(now)); // <-- gets a STALE `now` +// } +// +// Measured in CI, with the value captured on the callee side of a +// __declspec(noinline) wrapper so it is what actually crossed the call +// boundary: all six iterations passed t0+32000ms -- the value `now` held +// BEFORE the first `+=` -- while the caller's own `now` was correct +// (a checksum of the arguments in the same loop summed to exactly +// 62000+92000+...+212000). The argument was hoisted out of the loop as if +// it were loop-invariant. Linux and macOS pass 62000, 92000, ... 212000 for +// the same source. +// +// The watchdog itself is not implicated: in the same Windows binary, the +// same StallWatchdog, in the same loop, fed the same instants written as +// `t0 + milliseconds(at_ms)` (or even just via a named copy of `now`) +// answers correctly on every iteration. Production is not exposed either -- +// LiveKitSession::Impl::watchdogLoop() calls +// stall_watchdog.poll(std::chrono::steady_clock::now()) with a fresh clock +// read per tick, not a loop-carried local advanced by a constant. +// +// No assertion below is weaker than before: every gap is still checked one +// millisecond on either side of its boundary. void testStallWatchdogBacksOffRatherThanLooping() { const auto t0 = std::chrono::steady_clock::now(); 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); + // Milliseconds since t0. A plain integer cursor, advanced explicitly. + long long at_ms = 2000; // 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(w.poll(t0 + std::chrono::milliseconds(at_ms))); ST_ASSERT_EQ(w.attemptsThisStall(), 1); // A genuinely gone publisher: no frame ever comes back. Immediately // asking again (the naive "retry every poll interval forever" a // watchdog without backoff would do) must NOT fire -- that is precisely // the "hammered every 2 seconds forever" this backoff exists to avoid. - ST_ASSERT(!w.poll(now + std::chrono::milliseconds(250))); - ST_ASSERT(!w.poll(now + std::chrono::milliseconds(1999))); + ST_ASSERT(!w.poll(t0 + std::chrono::milliseconds(at_ms + 250))); + ST_ASSERT(!w.poll(t0 + std::chrono::milliseconds(at_ms + 1999))); // 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); + at_ms += 2000; + ST_ASSERT(w.poll(t0 + std::chrono::milliseconds(at_ms))); 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(!w.poll(t0 + std::chrono::milliseconds(at_ms + 3999))); + at_ms += 4000; + ST_ASSERT(w.poll(t0 + std::chrono::milliseconds(at_ms))); 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(!w.poll(t0 + std::chrono::milliseconds(at_ms + 7999))); + at_ms += 8000; + ST_ASSERT(w.poll(t0 + std::chrono::milliseconds(at_ms))); 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(!w.poll(t0 + std::chrono::milliseconds(at_ms + 15999))); + at_ms += 16000; + ST_ASSERT(w.poll(t0 + std::chrono::milliseconds(at_ms))); ST_ASSERT_EQ(w.attemptsThisStall(), 5); // The backoff is capped: doubling 16000ms would be 32000ms, but it @@ -352,219 +360,21 @@ 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); + ST_ASSERT(!w.poll(t0 + std::chrono::milliseconds(at_ms + 29999))); + at_ms += 30000; + ST_ASSERT(w.poll(t0 + std::chrono::milliseconds(at_ms))); } // A frame finally arrives: the stall is over, and the NEXT one (a fresh // stall, not a continuation) starts back at the base cadence rather // than staying parked at the 30s ceiling forever. - w.onFrameDelivered(now); + w.onFrameDelivered(t0 + std::chrono::milliseconds(at_ms)); ST_ASSERT_EQ(w.attemptsThisStall(), 0); - ST_ASSERT(!w.poll(now + std::chrono::milliseconds(1999))); - ST_ASSERT(w.poll(now + std::chrono::milliseconds(2000))); + ST_ASSERT(!w.poll(t0 + std::chrono::milliseconds(at_ms + 1999))); + ST_ASSERT(w.poll(t0 + std::chrono::milliseconds(at_ms + 2000))); 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 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 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 = 8; - Trial trials[kTrials]; - - for (int t = 0; t < kTrials; ++t) { - 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 fsum = 0; - long long recv[6] = {0, 0, 0, 0, 0, 0}; - - 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); - - if (mode == 0) { - 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; - } - } else if (mode == 1) { - 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 if (mode == 2) { - for (int i = 0; i < 6; ++i) { - 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].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(); - } - - for (int t = 0; t < kTrials; ++t) { - std::fprintf(stderr, - "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].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], - 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); - } - } -} - // 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), @@ -578,8 +388,10 @@ void testStallWatchdogNeverWaitsLongerThanTheCeiling() StallWatchdog w(std::chrono::milliseconds(1000), std::chrono::milliseconds(5000)); w.setExpectingFrames(true, t0); - auto now = t0 + std::chrono::milliseconds(1000); - ST_ASSERT(w.poll(now)); + // Absolute instants off t0, for the reason spelled out above + // testStallWatchdogBacksOffRatherThanLooping(). + long long at_ms = 1000; + ST_ASSERT(w.poll(t0 + std::chrono::milliseconds(at_ms))); // Expected gaps between consecutive attempts: 1000, 2000, 4000, then the // ceiling for good. Each gap is checked on both sides of its boundary, so @@ -587,9 +399,9 @@ void testStallWatchdogNeverWaitsLongerThanTheCeiling() const int expected_gaps[] = {1000, 2000, 4000, 5000, 5000, 5000, 5000}; int attempt = 1; for (int gap : expected_gaps) { - ST_ASSERT(!w.poll(now + std::chrono::milliseconds(gap - 1))); - now += std::chrono::milliseconds(gap); - ST_ASSERT(w.poll(now)); + ST_ASSERT(!w.poll(t0 + std::chrono::milliseconds(at_ms + gap - 1))); + at_ms += gap; + ST_ASSERT(w.poll(t0 + std::chrono::milliseconds(at_ms))); ST_ASSERT_EQ(w.attemptsThisStall(), ++attempt); } } @@ -723,8 +535,6 @@ int main() testStallWatchdogFiresAfterThreshold(); testStallWatchdogDoesNotFireWhenNotExpectingFrames(); testStallWatchdogBacksOffRatherThanLooping(); - testStallWatchdogTrace(); - testStallWatchdogQuiet(); testStallWatchdogNeverWaitsLongerThanTheCeiling(); LiveKitSession::globalInitialize();