diff --git a/frame/tools/mockrun.sh b/frame/tools/mockrun.sh index a7f89a6..ab04d82 100755 --- a/frame/tools/mockrun.sh +++ b/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" diff --git a/frame/tools/xrmock/xrmock.c b/frame/tools/xrmock/xrmock.c index 8186a85..8d05f3c 100644 --- a/frame/tools/xrmock/xrmock.c +++ b/frame/tools/xrmock/xrmock.c @@ -44,17 +44,23 @@ // MOCK_XR_DUMP= Vulkan: write released images as PPM files (every 4th pixel) // /t-sc-.ppm: at the seconds in // MOCK_XR_DUMP_AT=,... (default every 10 s), the next -// MOCK_XR_DUMP_FRAMES= (1) releases of every swapchain +// MOCK_XR_DUMP_FRAMES= (1) releases of every swapchain; +// MOCK_XR_DUMP_STEP= 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= predictedDisplayTime is off its refresh by up to +- (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= 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=,,, 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=@/[;...] 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); diff --git a/runtime/include/vr/openxr_vulkan_win32.h b/runtime/include/vr/openxr_vulkan_win32.h index 4cd9a18..52b229d 100644 --- a/runtime/include/vr/openxr_vulkan_win32.h +++ b/runtime/include/vr/openxr_vulkan_win32.h @@ -132,6 +132,9 @@ private: std::unique_ptr 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) diff --git a/runtime/src/vr/openxr_diagnostics.cpp b/runtime/src/vr/openxr_diagnostics.cpp index f9155f7..317bcd0 100644 --- a/runtime/src/vr/openxr_diagnostics.cpp +++ b/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 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(static_cast(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(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(s.shown_min_ms), - static_cast(s.shown_max_ms)); + static_cast(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; diff --git a/runtime/src/vr/openxr_vulkan_win32.cpp b/runtime/src/vr/openxr_vulkan_win32.cpp index f7de3eb..93af810 100644 --- a/runtime/src/vr/openxr_vulkan_win32.cpp +++ b/runtime/src/vr/openxr_vulkan_win32.cpp @@ -30,6 +30,10 @@ #include #include #include +#if defined(__linux__) +#include +#include +#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 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(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(&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)