Frames end with their own cycle's predicted display time; the mock checks it on the Frame's FOVs and display lead

H3: lane G's end-at-locate rule gave every set shown a refresh late (24 % of the race) a display
time one refresh older than its cycle's; SteamVR's mispresented frames rose from 116 to 1284 and
reused app frames from 0.2 to 4.4 %. Every xrEndFrame now carries its cycle's predicted time
(KARTFRAME_END_TIME=locate restores lane G's rule). The "vr display times" line counts sets shown a
refresh or more late apart from SteamVR's +-0.02 ms prediction jitter (which made nearly every set
"located for another time").

xrmock: the Frame's own per-eye FOVs by default, predictedDisplayTime 3 refreshes after the wake
(MOCK_XR_LEAD; SteamVR's lead was 25 to 27 ms), 0.02 ms prediction jitter by default, an ERROR for
every xrEndFrame whose display time is not its frame's predicted time ("xrmock: end times"), and
MOCK_XR_DUMP_STEP for full-resolution dumps. The GPU watcher publishes its thread id.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

frame/tools/mockrun.sh

@@ -129,7 +129,7 @@ HWATCH=$!
 wait $PID; RC=$?
 kill $WATCH $HWATCH 2>/dev/null
 echo "mockrun: game stopped (exit $RC; 143 is the stop signal)"
-grep -a 'xrmock: summary\|xrmock: frames\|xrmock: queue drain\|xrmock: exact\|xrmock: stamps\|vr pacing totals' "$LOG" || true
+grep -a 'xrmock: summary\|xrmock: end times\|xrmock: frames\|xrmock: queue drain\|xrmock: exact\|xrmock: stamps\|vr pacing totals' "$LOG" || true
 echo "mockrun: session states: $(grep -a 'session state -> ' "$LOG" | sed 's/.*session state -> //' | tr '\n' ' ')"
 FATAL=$(grep -a -c 'fatal dialog\|Signal 11' "$LOG")
 echo "mockrun: fatal lines: $FATAL"

frame/tools/xrmock/xrmock.c

@@ -44,17 +44,23 @@
 //   MOCK_XR_DUMP=<dir>        Vulkan: write released images as PPM files (every 4th pixel)
 //                             <dir>/t<seconds>-sc<id>-<n>.ppm: at the seconds in
 //                             MOCK_XR_DUMP_AT=<s>,<s>... (default every 10 s), the next
-//                             MOCK_XR_DUMP_FRAMES=<n> (1) releases of every swapchain
+//                             MOCK_XR_DUMP_FRAMES=<n> (1) releases of every swapchain;
+//                             MOCK_XR_DUMP_STEP=<n> every n-th pixel (4; 1: full resolution)
 //   MOCK_XR_STAMP=1           Vulkan, with KARTFRAME_FRAME_STAMP=1 in the app: every eye image a
 //                             projection layer submits carries the display time its poses were
 //                             located for (a block in its corner); compared with the locate the
 //                             layer's poses came from (summary line "stamps")
 //   MOCK_XR_PREDICT_JITTER=<ms>  predictedDisplayTime is off its refresh by up to +-<ms> (uniform,
-//                             at most 3), as SteamVR's prediction is not always exactly one period
-//                             after the last
+//                             at most 3; default 0.02, SteamVR's on the Frame in the third headset
+//                             session), as SteamVR's prediction is not always exactly one period
+//                             after the last; 0 turns it off
+//   MOCK_XR_LEAD=<refreshes>  predictedDisplayTime this many refreshes after xrWaitFrame's wake-up
+//                             (default 3: SteamVR's lead on the Frame was 25 to 27 ms at 120 Hz)
 //   MOCK_XR_FOV=<l>,<r>,<u>,<d>  the left eye's field of view in degrees (the right eye mirrors it);
-//                             default an asymmetric one like the Frame's (-52,44,48,-52), "sym"
-//                             the old symmetric +-48.1
+//                             default the Frame's own, per eye (left -59.08,50.39,49.47,-60.00, right
+//                             -50.29,59.16,49.88,-59.55), "sym" the old symmetric +-48.1
+// Every xrEndFrame must carry the predictedDisplayTime of the xrWaitFrame its xrBeginFrame followed
+// (ERROR otherwise; summary line "end times").
 //   MOCK_XR_HANDS=1           controllers held in front of the player (left and right action
 //                             spaces at chest height, pointing ahead), instead of all at the head
 //   MOCK_XR_PRESS=<path>@<start s>/<every s>[;...]  scripted presses for the current profile
@@ -142,9 +148,15 @@ static int64_t gNextBlip = 0, gRefocusAt = 0;
 static int gFocused = 0, gBlips = 0, gProfileSent = 0;
 static const char* gProfile = NULL;
 static int64_t gT0 = 0, gPeriod = 8333333, gEndAt = 0;
-static int64_t gJitterNs = 0;  // MOCK_XR_PREDICT_JITTER
-// MOCK_XR_FOV: the left eye's angles in degrees (left, right, up, down); the right eye mirrors it.
-static float gFovDeg[4] = {-52.0f, 44.0f, 48.0f, -52.0f};
+static int64_t gJitterNs = 20000;  // MOCK_XR_PREDICT_JITTER
+static int64_t gLead = 3;         // MOCK_XR_LEAD (refreshes)
+// xrEndFrame against the frame's predicted display time (the one its xrBeginFrame followed).
+static XrTime gWaitPredicted = 0, gBegunPredicted = 0;
+static int gEndTimeMatch = 0, gEndTimeOff = 0, gEndTimeOffPeriods[3];  // [0] within a refresh, [1] a refresh earlier or more, [2] later
+static double gEndTimeOffWorstMs = 0.0;
+// The eyes' angles in degrees (left, right, up, down): the Frame's (its OpenXR eye fields of view, logged
+// in the third headset session). MOCK_XR_FOV sets the left eye's; the right eye then mirrors it.
+static float gFovDeg[2][4] = {{-59.08f, 50.39f, 49.47f, -60.00f}, {-50.29f, 59.16f, 49.88f, -59.55f}};
 static int gQuitSent = 0;
 
 static void pushState(int s) {
@@ -440,7 +452,7 @@ static XrResult XRAPI_CALL mWaitImage(XrSwapchain sc, const XrSwapchainImageWait
 static void maybeDump(Chain* c, XrSwapchain sc) {
     static const char* dir = NULL;
     static double at[64];
-    static int atCount = -1, frames = 1;
+    static int atCount = -1, frames = 1, step = 4;
     if (atCount < 0) {
         dir = getenv("MOCK_XR_DUMP");
         atCount = 0;
@@ -453,6 +465,7 @@ static void maybeDump(Chain* c, XrSwapchain sc) {
         if (!atCount)
             for (; atCount < 64; atCount++) at[atCount] = 10.0 * (atCount + 1);
         if (getenv("MOCK_XR_DUMP_FRAMES")) frames = atoi(getenv("MOCK_XR_DUMP_FRAMES"));
+        if (getenv("MOCK_XR_DUMP_STEP") && atoi(getenv("MOCK_XR_DUMP_STEP")) >= 1) step = atoi(getenv("MOCK_XR_DUMP_STEP"));
     }
     if (!dir || !gGfx || !gGfx->dump_image || !gT0) return;
     double t = (double)(nowNs() - gT0) / 1e9;
@@ -467,7 +480,7 @@ static void maybeDump(Chain* c, XrSwapchain sc) {
     int idx = ((c->next - c->acquired) % c->count + c->count) % c->count;
     char path[512];
     snprintf(path, sizeof(path), "%s/t%03d-sc%d-%02d.ppm", dir, (int)at[mark - 1], chainId(sc), c->dumped);
-    if (gGfx->dump_image(c->images, idx, c->w, c->h, c->format, 4, path)) trace("dump sc%d %s", chainId(sc), path);
+    if (gGfx->dump_image(c->images, idx, c->w, c->h, c->format, step, path)) trace("dump sc%d %s", chainId(sc), path);
     c->dumped++;
 }
 
@@ -550,6 +563,10 @@ static XrResult XRAPI_CALL mEndSession(XrSession s) {
             "%d projection layers: eyes from one locate for the display time submitted %d, for an earlier one %d, a later one %d; eyes from "
             "different locates %d, poses not from a locate %d\n",
             gErrors, gReleases, gBusyReleases, gBusyMaxMs, gPoseSets, gPoseSameTime, gPoseEarlier, gPoseLater, gPoseSplit, gPoseUnknown);
+    fprintf(stderr,
+            "xrmock: end times: %d frames ended with their predicted display time, %d with another (within a refresh %d, a refresh or more "
+            "earlier %d, later %d; worst %.3f ms)\n",
+            gEndTimeMatch, gEndTimeOff, gEndTimeOffPeriods[0], gEndTimeOffPeriods[1], gEndTimeOffPeriods[2], gEndTimeOffWorstMs);
     fprintf(stderr, "xrmock: projection layers by refreshes from the locate to the display time: later %d, 0: %d, 1: %d, 2: %d, 3: %d, more %d\n", gPoseAge[0],
             gPoseAge[1], gPoseAge[2], gPoseAge[3], gPoseAge[4], gPoseAge[5]);
     fprintf(stderr,
@@ -639,7 +656,7 @@ static XrResult XRAPI_CALL mWaitFrame(XrSession s, const XrFrameWaitInfo* wi, Xr
         struct timespec ts = {(time_t)((wake - now) / 1000000000ll), (long)((wake - now) % 1000000000ll)};
         nanosleep(&ts, NULL);
     }
-    fs->predictedDisplayTime = wake + 2 * gPeriod + gTimeOffset;
+    fs->predictedDisplayTime = wake + gLead * gPeriod + gTimeOffset;
     if (gJitterNs > 0) {
         // Deterministic: the same sequence every run.
         static uint64_t lcg = 0x2545F4914F6CDD1Dull;
@@ -649,6 +666,7 @@ static XrResult XRAPI_CALL mWaitFrame(XrSession s, const XrFrameWaitInfo* wi, Xr
     }
     fs->predictedDisplayPeriod = gPeriod;
     fs->shouldRender = XR_TRUE;
+    gWaitPredicted = fs->predictedDisplayTime;
     gWaits++;
     if (gEndAt && nowNs() > gEndAt && !gQuitSent) {
         gQuitSent = 1;
@@ -670,6 +688,7 @@ static XrResult XRAPI_CALL mWaitFrame(XrSession s, const XrFrameWaitInfo* wi, Xr
 static XrResult XRAPI_CALL mBeginFrame(XrSession s, const XrFrameBeginInfo* bi) {
     (void)s;
     (void)bi;
+    gBegunPredicted = gWaitPredicted;
     trace("beginFrame");
     return XR_SUCCESS;
 }
@@ -736,6 +755,19 @@ static XrResult XRAPI_CALL mEndFrame(XrSession s, const XrFrameEndInfo* ei) {
         gErrors++;
     }
     lastDisplay = ei->displayTime;
+    // The frame's own predicted time: SteamVR matches a frame to its refresh by it; an older time showed
+    // as mispresented frames and reused app frames on the headset.
+    if (gBegunPredicted && ei->displayTime != gBegunPredicted) {
+        const double ms = (double)(ei->displayTime - gBegunPredicted) / 1e6;
+        gEndTimeOff++;
+        gEndTimeOffPeriods[ms > 0 ? 2 : -ms * 1e6 >= 0.5 * (double)gPeriod ? 1 : 0]++;
+        if (fabs(ms) > fabs(gEndTimeOffWorstMs)) gEndTimeOffWorstMs = ms;
+        trace("ERROR endFrame display time %.3f ms off the frame's predicted time", ms);
+        gErrors++;
+    } else if (gBegunPredicted) {
+        gEndTimeMatch++;
+    }
+    gBegunPredicted = 0;
     gEnds++;
     if (ei->layerCount == 0) gEmptyEnds++;
     else if (ei->layers[0]->type == XR_TYPE_COMPOSITION_LAYER_QUAD) gQuadEnds++;
@@ -763,9 +795,7 @@ static XrResult XRAPI_CALL mLocateViews(XrSession s, const XrViewLocateInfo* li,
         v[e].pose.orientation = (XrQuaternionf){0, sinf(yaw * 0.5f), 0, cosf(yaw * 0.5f)};
         v[e].pose.position = (XrVector3f){x * c, 1.6f, -x * sn};
         const float rad = 3.14159265f / 180.0f;
-        // The right eye mirrors the left (its outer side is on the right).
-        v[e].fov = e ? (XrFovf){-gFovDeg[1] * rad, -gFovDeg[0] * rad, gFovDeg[2] * rad, gFovDeg[3] * rad}
-                     : (XrFovf){gFovDeg[0] * rad, gFovDeg[1] * rad, gFovDeg[2] * rad, gFovDeg[3] * rad};
+        v[e].fov = (XrFovf){gFovDeg[e][0] * rad, gFovDeg[e][1] * rad, gFovDeg[e][2] * rad, gFovDeg[e][3] * rad};
         gLocates[gLocateNext].pose[e] = v[e].pose;
     }
     gLocates[gLocateNext].time = li->displayTime;
@@ -1069,14 +1099,21 @@ static void init(void) {
     const char* jitter = getenv("MOCK_XR_PREDICT_JITTER");
     if (jitter) {
         double ms = atof(jitter);
+        gJitterNs = 0;
         gJitterNs = (int64_t)((ms < 0 ? 0 : ms > 3 ? 3 : ms) * 1e6);
     }
     const char* fov = getenv("MOCK_XR_FOV");
     if (fov && !strcmp(fov, "sym")) {
-        gFovDeg[0] = -48.13f, gFovDeg[1] = 48.13f, gFovDeg[2] = 48.13f, gFovDeg[3] = -48.13f;
+        gFovDeg[0][0] = -48.13f, gFovDeg[0][1] = 48.13f, gFovDeg[0][2] = 48.13f, gFovDeg[0][3] = -48.13f;
     } else if (fov) {
-        sscanf(fov, "%f,%f,%f,%f", &gFovDeg[0], &gFovDeg[1], &gFovDeg[2], &gFovDeg[3]);
+        sscanf(fov, "%f,%f,%f,%f", &gFovDeg[0][0], &gFovDeg[0][1], &gFovDeg[0][2], &gFovDeg[0][3]);
     }
+    if (fov) {
+        // The right eye mirrors the left (its outer side is on the right).
+        gFovDeg[1][0] = -gFovDeg[0][1], gFovDeg[1][1] = -gFovDeg[0][0], gFovDeg[1][2] = gFovDeg[0][2], gFovDeg[1][3] = gFovDeg[0][3];
+    }
+    const char* lead = getenv("MOCK_XR_LEAD");
+    if (lead && atoi(lead) >= 1) gLead = atoi(lead);
     const char* list = getenv("MOCK_XR_EXTENSIONS");
     if (list) {
         char* copy = strdup(list);

runtime/include/vr/openxr_vulkan_win32.h

@@ -132,6 +132,9 @@ private:
     std::unique_ptr<Impl> m_impl;
 };
 
+// The Linux thread id of the thread that waits for the GPU to finish eye sets (0 until it runs).
+uint32_t OpenXRVulkanGpuWatcherThreadId() noexcept;
+
 } // namespace mkw::vr
 
 #endif // defined(MKW_ENABLE_OPENXR) && defined(_WIN32)

runtime/src/vr/openxr_diagnostics.cpp

@@ -630,7 +630,7 @@ struct State {
     // OnCycleTimes / OnSetShown, summed up every 10 s.
     int64_t times_start_ns = 0;
     std::vector<float> step_error_ms, lead_ms;
-    uint32_t shown = 0, shown_other = 0;
+    uint32_t shown = 0, shown_other = 0, shown_late = 0;  // late: a refresh or more after its locate time
     float shown_min_ms = 0.0f, shown_max_ms = 0.0f;
 };
 State& S() {
@@ -694,7 +694,7 @@ void Reset() {
         s.times_start_ns = 0;
         s.step_error_ms.clear();
         s.lead_ms.clear();
-        s.shown = s.shown_other = 0;
+        s.shown = s.shown_other = s.shown_late = 0;
         sink = s.sink;
         // t=0 of the "vr pacing:" lines on the steady clock (CLOCK_MONOTONIC), so other logs can be
         // lined up with them (aurora's "hitch:" lines carry mono=).
@@ -762,6 +762,9 @@ void OnSetShown(int64_t locate_minus_cycle_ns) {
     ++s.shown;
     if (locate_minus_cycle_ns == 0) return;
     const float ms = static_cast<float>(static_cast<double>(locate_minus_cycle_ns) / 1e6);
+    // SteamVR's predictions jitter by +-0.02 ms: a set located for "this prediction + one period" is
+    // off its showing cycle's by that much. Half a refresh or more is a set shown a refresh late.
+    if (ms <= -4.0f) ++s.shown_late;
     if (s.shown_other++ == 0) s.shown_min_ms = s.shown_max_ms = ms;
     s.shown_min_ms = std::min(s.shown_min_ms, ms);
     s.shown_max_ms = std::max(s.shown_max_ms, ms);
@@ -776,17 +779,18 @@ std::string DisplayTimesLine(State& s, int64_t now) {
         const double low = *lo, high = *hi;  // before Percentile reorders the values
         std::snprintf(out, cap, "%.3f/%.3f/%.3f", static_cast<double>(Percentile(v, 0.5)), low, high);
     };
-    char step[64] = "-", lead[64] = "-", line[384];
+    char step[64] = "-", lead[64] = "-", line[512];
     if (!s.step_error_ms.empty()) range(s.step_error_ms, step, sizeof(step));
     range(s.lead_ms, lead, sizeof(lead));
     std::snprintf(line, sizeof(line),
                   "vr display times (10 s): predicted step minus period ms p50/min/max=%s, display lead ms "
-                  "p50/min/max=%s, sets shown %u, located for another time than their cycle's %u (ms %.3f..%.3f)",
+                  "p50/min/max=%s, sets shown %u, located for another time than their cycle's %u (ms %.3f..%.3f; a refresh "
+                  "or more earlier, shown late: %u)",
                   step, lead, s.shown, s.shown_other, static_cast<double>(s.shown_min_ms),
-                  static_cast<double>(s.shown_max_ms));
+                  static_cast<double>(s.shown_max_ms), s.shown_late);
     s.step_error_ms.clear();
     s.lead_ms.clear();
-    s.shown = s.shown_other = 0;
+    s.shown = s.shown_other = s.shown_late = 0;
     s.shown_min_ms = s.shown_max_ms = 0.0f;
     s.times_start_ns = now;
     return line;

runtime/src/vr/openxr_vulkan_win32.cpp

@@ -30,6 +30,10 @@
 #include <thread>
 #include <utility>
 #include <vector>
+#if defined(__linux__)
+#include <sys/syscall.h>
+#include <unistd.h>
+#endif
 
 namespace mkw::vr {
 namespace {
@@ -50,6 +54,8 @@ namespace {
 // records each set's submit-to-completion time. Without timeline semaphores the release
 // drains the queue instead (correct, slower; logged). KARTFRAME_NO_GPU_WAIT=1 skips the
 // wait: the negative test for the mock's MOCK_XR_BUSY_MS check.
+std::atomic<uint32_t> g_gpu_watcher_tid{0};
+
 class GpuCompletion {
 public:
     using Clock = std::chrono::steady_clock;
@@ -177,6 +183,9 @@ private:
     static constexpr uint64_t kRing = 64;
 
     void Watch() {
+#if defined(__linux__)
+        g_gpu_watcher_tid.store(static_cast<uint32_t>(syscall(SYS_gettid)), std::memory_order_release);
+#endif
         uint64_t next = 1;
         for (;;) {
             {
@@ -887,7 +896,7 @@ public:
         }
         OpenXRBackendFrame frame = set;
         frame.xr_frame.serial = active_frame_.serial;
-        // The layer is ended with the display time its poses were located for (EndFrameWithPanel).
+        // KARTFRAME_END_TIME=locate ends the layer with the time its poses were located for (EndFrameWithPanel).
         next_layer_locate_time_ = set.xr_frame.predicted_display_time;
         frame.xr_frame.predicted_display_time = active_frame_.predicted_display_time;
         frame.xr_frame.predicted_display_period = active_frame_.predicted_display_period;
@@ -1254,18 +1263,22 @@ public:
             panel_quad = OpenXRPanelQuadLayer(panel, runtime_->AppSpace(), retained_panel_swapchain_.handle);
             layers[count++] = reinterpret_cast<const XrCompositionLayerBaseHeader*>(&panel_quad);
         }
-        // A set's layer goes out with the display time its poses were located for, also when it is
-        // repeated or shown a refresh late: the poses and that time belong together, whatever
-        // this cycle's prediction says (SteamVR's is not always one period after the last).
-        // OpenXR allows any display time; the compositor reprojects. KARTFRAME_END_TIME=cycle:
-        // this cycle's predicted time instead (the behaviour before lane G).
-        static const bool end_at_cycle = [] {
+        // Every frame ends with its own cycle's predicted display time: SteamVR matches a frame to
+        // its refresh by that time. The layer's poses say where the images were rendered from; the
+        // compositor reprojects them to the head pose at display. A pipelined set is located for
+        // the next cycle's time (this cycle's prediction + one period, the same within SteamVR's
+        // +-0.02 ms jitter); a late set is shown a refresh after that. In the third headset session
+        // lane G's rule (end with the poses' locate time) gave every late set (24 % of the race)
+        // a time one refresh older than its cycle's; SteamVR's mispresented frames went from 116
+        // to 1284 and reused app frames from 0.2 to 4.4 %. KARTFRAME_END_TIME=locate restores it
+        // (the mock's end-time check counts each such frame as an error).
+        static const bool end_at_locate = [] {
             const char* env = std::getenv("KARTFRAME_END_TIME");
-            return env != nullptr && std::string_view(env) == "cycle";
+            return env != nullptr && std::string_view(env) == "locate";
         }();
         // Display times stay increasing from one xrEndFrame to the next: a layer shown again (or a
         // late set whose time an earlier frame already used) goes out at this cycle's time.
-        if (!end_at_cycle && retained_locate_time_ != 0 && retained_locate_time_ > last_end_display_time_ &&
+        if (end_at_locate && retained_locate_time_ != 0 && retained_locate_time_ > last_end_display_time_ &&
             retained_locate_time_ != active_frame_.predicted_display_time) {
             OpenXRFrame located = active_frame_;
             located.predicted_display_time = retained_locate_time_;
@@ -1837,6 +1850,8 @@ int64_t OpenXRWindowsVulkanBackend::SwapchainFormat() const { return m_impl->Swa
 
 const std::string& OpenXRWindowsVulkanBackend::LastError() const { return m_impl->LastError(); }
 
+uint32_t OpenXRVulkanGpuWatcherThreadId() noexcept { return g_gpu_watcher_tid.load(std::memory_order_acquire); }
+
 } // namespace mkw::vr
 
 #endif // defined(MKW_ENABLE_OPENXR) && defined(_WIN32)