debug: instrument StallWatchdog timing for a Windows CI trace
Build / macOS (macos-latest) (push) Successful in 56s
Build / Linux (ubuntu-24.04) (push) Successful in 1m11s
Build / Windows (windows-latest) (push) Successful in 6m28s

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) <noreply@anthropic.com>
This commit is contained in:
2026-09-21 10:30:41 -07:00
co-authored by Claude Opus 5
parent 352a843d93
commit 422d871cfe
3 changed files with 67 additions and 0 deletions
+31
View File
@@ -26,6 +26,7 @@ You may obtain a copy of the License at
// manual-sign-off bucket.
#include <atomic>
#include <cstdio>
#include <chrono>
#include <string>
#include <thread>
@@ -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<std::chrono::nanoseconds>(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<std::chrono::nanoseconds>(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