Implement more detailed diagnostics for OpenXR stages

runtime/src/vr/openxr_d3d12.cpp

@@ -316,7 +316,9 @@ public:
             submission_success_ = false;
             submission_unsafe_ = false;
         }
-        if (!aurora_d3d12_set_stereo_targets(frame.xr_frame.serial, targets.data(), target_count)) {
+        if (!diagnostics::Measure(diagnostics::Stage::SetTargets, [&] {
+            return aurora_d3d12_set_stereo_targets(frame.xr_frame.serial, targets.data(), target_count);
+        })) {
             {
                 std::lock_guard lock(submission_mutex_);
                 awaiting_token_ = 0;

runtime/src/vr/openxr_diagnostics.cpp

@@ -14,6 +14,10 @@
 namespace mkw::vr::diagnostics {
 namespace {
 
+constexpr std::array<const char*, static_cast<size_t>(Stage::Count)> kStageNames{
+    "poll-events", "begin-call", "locate-views", "input-sync", "sync-actions",
+    "publish", "withdraw", "submission-wait", "cancel", "set-targets"};
+
 constexpr double kNanosecondsPerMillisecond = 1'000'000.0;
 
 double Milliseconds(int64_t nanoseconds) noexcept {
@@ -123,6 +127,7 @@ void FrameDiagnostics::Reset(int64_t now_ns) {
     Sink sink = std::move(sink_);
     *this = FrameDiagnostics(std::move(sink));
     window_start_ns_ = now_ns;
+    session_start_ns_ = now_ns;
     session_info_requested_ = true;
 }
 
@@ -136,6 +141,7 @@ void FrameDiagnostics::OnWaitFrame(int64_t now_ns, int64_t wait_ns, int64_t disp
         window_start_ns_ = now_ns;
     }
     ++cycles_;
+    ++cycle_sequence_;
     wait_frame_ms_.Add(Milliseconds(wait_ns));
     if (display_period > 0) {
         display_period_ = display_period;
@@ -280,14 +286,31 @@ void FrameDiagnostics::OnPacketPublished(int64_t now_ns) {
     published_ns_ = now_ns;
 }
 
-void FrameDiagnostics::OnPacketCanceled(int64_t consumed_ns) {
+void FrameDiagnostics::OnStage(Stage stage, int64_t ns, int64_t now_ns) {
+    if (ns < 0 || static_cast<size_t>(stage) >= stages_.size()) return;
+    auto& sample = stages_[static_cast<size_t>(stage)];
+    sample.samples.Add(Milliseconds(ns));
+    if (ns > sample.worst_ns) {
+        sample.worst_ns = ns;
+        sample.worst_at_ns = now_ns;
+        sample.cycle = cycle_sequence_;
+    }
+}
+
+void FrameDiagnostics::OnPacketCanceled(int64_t now_ns, int64_t consumed_ns) {
+    if (published_ns_ != 0 && now_ns >= published_ns_) {
+        cancel_age_ms_.Add(Milliseconds(now_ns - published_ns_));
+        if (consumed_ns >= published_ns_ && consumed_ns <= now_ns) {
+            cancel_pickup_ms_.Add(Milliseconds(consumed_ns - published_ns_));
+            cancel_after_pickup_ms_.Add(Milliseconds(now_ns - consumed_ns));
+        }
+    }
     if (consumed_ns == 0 || consumed_ns < published_ns_) {
         ++packet_unused_;
-        Event("stereo packet withdrawn: no game frame picked it up within 50 ms");
+        Event("stereo packet withdrawn: no game frame picked it up before cancellation");
     } else {
         ++packet_rejected_;
-        Event("stereo packet canceled: Aurora picked it up but rendered that frame without it "
-              "(content tag or transform check)");
+        Event("stereo packet canceled: Aurora picked it up but the bridge had not encoded it before cancellation");
     }
     published_ns_ = 0;
 }
@@ -355,8 +378,13 @@ void FrameDiagnostics::ClearWindow(int64_t now_ns) {
     keepalive_ = packet_unused_ = packet_rejected_ = submit_failed_ = interp_skip_ = 0;
     immersive_ = screen_ = not_rendered_ = no_orientation_ = no_position_ = 0;
     events_ = suppressed_ = 0;
+    for (auto& stage : stages_) {
+        stage.samples.Clear();
+        stage.worst_ns = -1;
+    }
     for (Samples* samples : {&wait_frame_ms_, &open_ms_, &margin_ms_, &end_gap_ms_, &end_call_ms_,
-                             &acquire_ms_, &release_ms_, &game_wait_ms_, &encode_ms_}) {
+                             &acquire_ms_, &release_ms_, &game_wait_ms_, &encode_ms_,
+                             &cancel_age_ms_, &cancel_pickup_ms_, &cancel_after_pickup_ms_}) {
         samples->Clear();
     }
 }
@@ -365,7 +393,7 @@ void FrameDiagnostics::EmitSummary(int64_t now_ns) {
     std::string text;
     AppendFormat(text, "%.2fs", Milliseconds(now_ns - window_start_ns_) / 1000.0);
     if (display_period_ > 0) {
-        AppendFormat(text, " %.1fHz", 1.0e9 / static_cast<double>(display_period_));
+        AppendFormat(text, " predicted-rate=%.1fHz", 1.0e9 / static_cast<double>(display_period_));
     }
     AppendFormat(text, " cycles=%u skipped-slots=%u late=%u", cycles_, skipped_slots_, late_);
     AppendFormat(text, " | layers new=%u repeat=%u empty=%u discarded=%u layer-rejected=%u", layers_new_,
@@ -384,8 +412,26 @@ void FrameDiagnostics::EmitSummary(int64_t now_ns) {
                  keepalive_, packet_unused_, packet_rejected_, submit_failed_, interp_skip_);
     AppendFormat(text, " | frames immersive=%u screen=%u not-rendered=%u no-orientation=%u no-position=%u",
                  immersive_, screen_, not_rendered_, no_orientation_, no_position_);
-    AppendFormat(text, " | suppressed=%u", suppressed_);
+    AppendFormat(text, " | suppressed=%u cycle=%llu t=%.3fs", suppressed_,
+                 static_cast<unsigned long long>(cycle_sequence_),
+                 static_cast<double>(now_ns - session_start_ns_) / 1.0e9);
     Info(text);
+    // Skipped-slot event spam must not suppress evidence of a blocking call.
+    std::string stages = "stages ms";
+    for (size_t i = 0; i < stages_.size(); ++i) {
+        auto& sample = stages_[i];
+        AppendStat(stages, kStageNames[i], sample.samples.values, false);
+        if (sample.worst_ns >= 0) {
+            AppendFormat(stages, "@cycle=%llu,t=%.3fs",
+                         static_cast<unsigned long long>(sample.cycle),
+                         static_cast<double>(sample.worst_at_ns - session_start_ns_) / 1.0e9);
+        }
+    }
+    AppendStat(stages, "cancel-age", cancel_age_ms_.values, false);
+    AppendStat(stages, "cancel-pickup", cancel_pickup_ms_.values, false);
+    AppendStat(stages, "cancel-after-pickup", cancel_after_pickup_ms_.values, false);
+    if (!cancel_age_ms_.values.empty() || std::any_of(stages_.begin(), stages_.end(),
+            [](const auto& stage) { return stage.worst_ns >= 0; })) Info(stages);
 }
 
 namespace {
@@ -473,6 +519,10 @@ void OnWaitFrame(int64_t wait_ns, int64_t display_time, int64_t display_period)
     collector.OnWaitFrame(NowNs(), wait_ns, display_time, display_period, ConvertDisplayTime(display_time));
 }
 
+void OnStage(Stage stage, int64_t ns) {
+    Collector().OnStage(stage, ns, NowNs());
+}
+
 void OnBeginFrame() {
     Collector().OnBeginFrame(NowNs());
 }
@@ -524,7 +574,7 @@ void OnPacketPublished() {
 }
 
 void OnPacketCanceled() {
-    Collector().OnPacketCanceled(g_packet_consumed_ns.load(std::memory_order_relaxed));
+    Collector().OnPacketCanceled(NowNs(), g_packet_consumed_ns.load(std::memory_order_relaxed));
 }
 
 void OnKeepaliveRepeat() {

runtime/src/vr/openxr_input.cpp

@@ -10,6 +10,7 @@
 #endif
 
 #include "vr/openxr_input.h"
+#include "vr/openxr_diagnostics.h"
 
 #include <SDL3/SDL_gamepad.h>
 #include <SDL3/SDL_joystick.h>
@@ -518,7 +519,9 @@ void OpenXRInput::Sync(XrTime predicted_display_time, const OpenXRPointerScreen&
     XrActionsSyncInfo sync{XR_TYPE_ACTIONS_SYNC_INFO};
     sync.countActiveActionSets = 1;
     sync.activeActionSets = &active;
-    const XrResult result = xrSyncActions(m_runtime->Session(), &sync);
+    const XrResult result = diagnostics::Measure(diagnostics::Stage::SyncActions, [&] {
+        return xrSyncActions(m_runtime->Session(), &sync);
+    });
     m_runtime->ObserveResult(result);
     if (XR_FAILED(result)) {
         if (!m_logged_sync_failure) {

runtime/src/vr/openxr_integration.cpp

@@ -736,7 +736,9 @@ private:
                 gx_registered = RegisterGxThread();
             }
 #endif
-            const OpenXREventStatus events = runtime_->PollEvents();
+            const OpenXREventStatus events = diagnostics::Measure(diagnostics::Stage::PollEvents, [&] {
+                return runtime_->PollEvents();
+            });
             const bool session_active = runtime_->IsSessionRunning();
             MkwVRPolicySetSessionActive(session_active);
             const uint64_t session_run_serial = runtime_->SessionRunSerial();
@@ -859,6 +861,7 @@ private:
             ServiceRecenterRequest();
             UpdateVirtualScreenPose(frame);
             if (input_ != nullptr) {
+                const diagnostics::ScopedStage input_timer(diagnostics::Stage::InputSync);
                 // After the screen is placed, so the pointer aims at this
                 // frame's screen rather than the previous one's.
                 input_->Sync(frame.xr_frame.predicted_display_time, PointerScreen(frame, policy, immersive),
@@ -876,7 +879,9 @@ private:
             if (aurora_get_stereo_frame_interpolation() &&
                 !interpolation_pacing_.ShouldRender(frame.xr_frame.predicted_display_time, interpolation_target)) {
                 diagnostics::OnInterpolationSkip();
-                if (!backend_->TryCancelPendingFrame(frame) || !backend_->FinishFrame(frame, false)) {
+                if (!diagnostics::Measure(diagnostics::Stage::Cancel, [&] {
+                    return backend_->TryCancelPendingFrame(frame);
+                }) || !backend_->FinishFrame(frame, false)) {
                     SetError(backend_->LastError());
                     fatal = true;
                 }
@@ -884,6 +889,7 @@ private:
             }
 
             {
+                const diagnostics::ScopedStage publish_timer(diagnostics::Stage::Publish);
                 std::lock_guard lock(published_mutex_);
                 // First person renders at life-size scale, third person at the
                 // configured diorama scale. Head translation and IPD are the
@@ -904,14 +910,18 @@ private:
                    submission == OpenXRSubmissionStatus::Timeout) {
                 // Fresh rendering wakes us immediately. A 50 ms keep-alive
                 // protects stalls without issuing eager repeats during GPU work.
-                submission = backend_->WaitForSubmission(frame, 50);
+                submission = diagnostics::Measure(diagnostics::Stage::SubmissionWait, [&] {
+                    return backend_->WaitForSubmission(frame, 50);
+                });
                 if (submission == OpenXRSubmissionStatus::Timeout) {
                     // A pause, minimized window, or guest stall may leave no GX
                     // frame to consume this packet. Withdraw it, then cancel the
                     // matching bridge target only if Encode has not taken ownership.
                     if (std::chrono::steady_clock::now() >= cancel_after) {
-                        WithdrawPublishedFrame();
-                        canceled_before_encode = backend_->TryCancelPendingFrame(frame);
+                        diagnostics::Measure(diagnostics::Stage::Withdraw, [&] { WithdrawPublishedFrame(); });
+                        canceled_before_encode = diagnostics::Measure(diagnostics::Stage::Cancel, [&] {
+                            return backend_->TryCancelPendingFrame(frame);
+                        });
                         if (canceled_before_encode) {
                             diagnostics::OnPacketCanceled();
                             break;
@@ -925,7 +935,7 @@ private:
                     }
                 }
             }
-            WithdrawPublishedFrame();
+            diagnostics::Measure(diagnostics::Stage::Withdraw, [&] { WithdrawPublishedFrame(); });
             if (stop_.load(std::memory_order_acquire)) {
                 // Aurora has been drained by Shutdown(); backend shutdown below
                 // cancels its pending target, then either safely releases the
@@ -1035,6 +1045,7 @@ private:
         ServiceRecenterRequest();
         UpdateVirtualScreenPose(packet);
         if (input_ != nullptr) {
+            const diagnostics::ScopedStage input_timer(diagnostics::Stage::InputSync);
             input_->Sync(packet.xr_frame.predicted_display_time, PointerScreen(packet, policy, immersive),
                          SettingsPanelScreen(packet, policy, immersive));
         }
@@ -1043,6 +1054,7 @@ private:
             return KeepAlive();
         }
         {
+            const diagnostics::ScopedStage publish_timer(diagnostics::Stage::Publish);
             std::lock_guard lock(published_mutex_);
             BuildPublishedFrame(packet, immersive, policy.EffectiveUnitsPerMeter(), policy.content_tag);
             diagnostics::OnPacketPublished();
@@ -1056,11 +1068,15 @@ private:
         bool canceled_before_encode = false;
         const auto cancel_after = std::chrono::steady_clock::now() + std::chrono::milliseconds(50);
         while (!stop_.load(std::memory_order_acquire) && submission == OpenXRSubmissionStatus::Timeout) {
-            submission = backend_->WaitForSubmission(packet, 50);
+            submission = diagnostics::Measure(diagnostics::Stage::SubmissionWait, [&] {
+                return backend_->WaitForSubmission(packet, 50);
+            });
             if (submission == OpenXRSubmissionStatus::Timeout) {
                 if (std::chrono::steady_clock::now() >= cancel_after) {
-                    WithdrawPublishedFrame();
-                    canceled_before_encode = backend_->TryCancelPendingPacket(packet);
+                    diagnostics::Measure(diagnostics::Stage::Withdraw, [&] { WithdrawPublishedFrame(); });
+                    canceled_before_encode = diagnostics::Measure(diagnostics::Stage::Cancel, [&] {
+                        return backend_->TryCancelPendingPacket(packet);
+                    });
                     if (canceled_before_encode) {
                         diagnostics::OnPacketCanceled();
                         break;
@@ -1072,7 +1088,7 @@ private:
                 }
             }
         }
-        WithdrawPublishedFrame();
+        diagnostics::Measure(diagnostics::Stage::Withdraw, [&] { WithdrawPublishedFrame(); });
         if (stop_.load(std::memory_order_acquire) || canceled_before_encode ||
             submission == OpenXRSubmissionStatus::ShuttingDown) {
             return true;

runtime/src/vr/openxr_runtime.cpp

@@ -723,7 +723,9 @@ bool OpenXRRuntime::BeginFrame(const OpenXRFrame& frame) {
     }
 
     XrFrameBeginInfo begin_info{XR_TYPE_FRAME_BEGIN_INFO};
-    const XrResult result = xrBeginFrame(m_session, &begin_info);
+    const XrResult result = diagnostics::Measure(diagnostics::Stage::BeginCall, [&] {
+        return xrBeginFrame(m_session, &begin_info);
+    });
     if (XR_FAILED(result)) {
         m_frame_phase = FramePhase::Idle;
         m_active_frame_serial = 0;
@@ -769,9 +771,11 @@ bool OpenXRRuntime::LocateViewsForFrame(OpenXRFrame& frame) {
     locate_info.space = m_app_space;
     XrViewState view_state{XR_TYPE_VIEW_STATE};
     uint32_t view_count = 0;
-    if (!Check(xrLocateViews(m_session, &locate_info, &view_state,
-                             kOpenXREyeCount, &view_count, frame.views.data()),
-               "xrLocateViews")) {
+    const XrResult locate_result = diagnostics::Measure(diagnostics::Stage::LocateViews, [&] {
+        return xrLocateViews(m_session, &locate_info, &view_state,
+                             kOpenXREyeCount, &view_count, frame.views.data());
+    });
+    if (!Check(locate_result, "xrLocateViews")) {
         return false;
     }
     if (view_count != kOpenXREyeCount) {