debug: round 5 -- capture the time point on the callee side

TEMPORARY.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>

core/tests/test_session.cpp

@@ -443,37 +443,53 @@ void testStallWatchdogTrace()
     }
 }
 
-// TEMPORARY DEBUG -- remove before merge. Five shapes of the same loop,
+// TEMPORARY DEBUG -- remove before merge.
-// each run twice. Nothing is printed until every trial is done.
+//
+// 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  absolute `t0 + milliseconds(offset)`               (known-good)
+//   mode 1  accumulate, pass a named copy of `now`         (known-good)
-//   mode 2  accumulate, and sum the ns actually handed to poll
+//   mode 2  accumulate, sum the ns the CALLER holds
-//   mode 3  accumulate, pass a named copy of `now`
+//   mode 3  accumulate, through st_dbg_poll (callee-side capture)
-//   mode 4  accumulate by a non-const step variable
 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<std::chrono::milliseconds>(e - t0).count();
-                early[i] = w.poll(e) ? 1 : 0;
-                now += std::chrono::milliseconds(30000);
-                fsum += std::chrono::duration_cast<std::chrono::milliseconds>(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 {
+        } else if (mode == 2) {
-            std::chrono::milliseconds step(30000);
-            std::chrono::milliseconds probe(29999);
             for (int i = 0; i < 6; ++i) {
-                early[i] = w.poll(now + probe) ? 1 : 0;
+                early[i] = w.poll(now + std::chrono::milliseconds(29999)) ? 1 : 0;
-                now += step;
+                now += std::chrono::milliseconds(30000);
+                fsum += std::chrono::duration_cast<std::chrono::milliseconds>(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<std::chrono::nanoseconds>(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],