Implement log export functionality and OpenXR diagnostics

runtime/src/vr/openxr_d3d12.cpp

@@ -9,6 +9,7 @@
 #endif
 
 #include "vr/openxr_d3d12.h"
+#include "vr/openxr_diagnostics.h"
 
 #include <aurora/d3d12_interop.h>
 
@@ -290,6 +291,7 @@ public:
         }
 
         std::array<AuroraD3D12StereoTarget, kOpenXREyeCount> targets{};
+        const diagnostics::Stopwatch acquire_timer;
         for (uint32_t eye = 0; eye < target_count; ++eye) {
             auto& swapchain = eye_swapchains_[eye];
             if (!AcquireSwapchain(swapchain)) {
@@ -304,6 +306,7 @@ public:
                 static_cast<int64_t>(swapchain_format_),
             };
         }
+        diagnostics::OnSwapchainAcquire(acquire_timer);
 
         {
             std::lock_guard lock(submission_mutex_);
@@ -387,7 +390,11 @@ public:
             AbandonAcquiredSwapchains();
             Fail("Aurora's D3D12 stereo submission failed after GPU work may have been queued");
         }
+        const diagnostics::Stopwatch release_timer;
         bool release_ok = ReleaseAcquiredSwapchains();
+        if (frame.xr_frame.should_render && frame.xr_frame.views_valid) {
+            diagnostics::OnSwapchainRelease(release_timer);
+        }
         const bool position_valid =
             (frame.xr_frame.view_state_flags & XR_VIEW_STATE_POSITION_VALID_BIT) != 0;
         const bool composition_pose_valid =
@@ -395,6 +402,10 @@ public:
         const bool can_submit = submit_layer && release_ok && frame.xr_frame.should_render &&
                                 frame.xr_frame.views_valid && frame.expects_gpu_submission &&
                                 composition_pose_valid;
+        if (submit_layer && !can_submit) {
+            diagnostics::OnLayerRejected(diagnostics::ClassifyRejectedLayer(
+                release_ok, frame.xr_frame.should_render, frame.xr_frame.views_valid));
+        }
         if (can_submit) {
             // xrEndFrame references the MOST RECENTLY RELEASED image of a
             // swapchain, not an explicit image index. Keep the displayed pair
@@ -405,7 +416,7 @@ public:
             retained_space_serial_ = render_space_serial_;
             have_retained_frame_ = true;
         }
-        const bool end_ok = EndRetainedFrame();
+        const bool end_ok = EndRetainedFrame(can_submit);
 
         frame_active_ = false;
         active_frame_serial_ = 0;
@@ -426,7 +437,7 @@ public:
             frame.xr_frame.serial != active_frame_serial_) {
             return Fail("RepeatFrame received a stale or inactive render token");
         }
-        const bool end_ok = EndRetainedFrame();
+        const bool end_ok = EndRetainedFrame(false);
         // EndFrame consumes the compositor token even when submission fails.
         // Teardown must not try to end that same token again.
         frame_active_ = false;
@@ -447,7 +458,8 @@ public:
         return true;
     }
 
-    bool EndRetainedFrame() {
+    // fresh: the retained layer was completed for this call rather than repeated.
+    bool EndRetainedFrame(bool fresh) {
         if (!runtime_->IsSessionRunning()) {
             // A session that is no longer running needs no compositor frame
             // completion call. Preserve the original backend failure instead
@@ -456,13 +468,21 @@ public:
         }
         // Old poses cannot be reused after the runtime changes their coordinate
         // system. Also discard content across session restarts.
-        if (retained_session_serial_ != runtime_->SessionRunSerial() ||
-            retained_space_serial_ != runtime_->LastReferenceSpaceChange().serial) {
+        const bool session_changed = retained_session_serial_ != runtime_->SessionRunSerial();
+        if (session_changed || retained_space_serial_ != runtime_->LastReferenceSpaceChange().serial) {
+            if (have_retained_frame_) {
+                diagnostics::OnRetainedLayerDiscarded(session_changed
+                                                          ? diagnostics::DiscardReason::SessionRestarted
+                                                          : diagnostics::DiscardReason::ReferenceSpaceChanged);
+            }
             have_retained_frame_ = false;
         }
         if (!have_retained_frame_ || !active_frame_.should_render) {
+            diagnostics::OnEmptyFrame(!active_frame_.should_render ? diagnostics::EmptyFrameReason::ShouldRenderOff
+                                                                    : diagnostics::EmptyFrameReason::NoRetainedLayer);
             return runtime_->EndFrameWithoutLayers(active_frame_);
         }
+        diagnostics::OnLayer(fresh);
         const auto& frame = retained_frame_;
         if (frame.presentation.mode == OpenXRD3D12FrameMode::VirtualScreen) {
             XrCompositionLayerQuad quad{XR_TYPE_COMPOSITION_LAYER_QUAD};

runtime/src/vr/openxr_diagnostics.cpp

@@ -0,0 +1,559 @@
+// SPDX-License-Identifier: GPL-3.0-or-later
+
+#include "vr/openxr_diagnostics.h"
+
+#include <algorithm>
+#include <chrono>
+#include <cmath>
+#include <cstdarg>
+#include <cstdio>
+#include <limits>
+#include <mutex>
+#include <utility>
+
+namespace mkw::vr::diagnostics {
+namespace {
+
+constexpr double kNanosecondsPerMillisecond = 1'000'000.0;
+
+double Milliseconds(int64_t nanoseconds) noexcept {
+    return static_cast<double>(nanoseconds) / kNanosecondsPerMillisecond;
+}
+
+// Appends printf-formatted text. Each call is one short field, so a fixed
+// buffer is enough; the summary is assembled from many of them.
+void AppendFormat(std::string& output, const char* format, ...) {
+    char buffer[256];
+    va_list arguments;
+    va_start(arguments, format);
+    const int length = std::vsnprintf(buffer, sizeof(buffer), format, arguments);
+    va_end(arguments);
+    if (length > 0) {
+        output.append(buffer, std::min(static_cast<size_t>(length), sizeof(buffer) - 1));
+    }
+}
+
+// "median/worst" in milliseconds, where worst is the maximum, or the minimum
+// for a quantity (the display-time margin) where smaller is worse.
+void AppendStat(std::string& output, const char* name, std::vector<float>& values, bool worst_is_min) {
+    if (values.empty()) {
+        AppendFormat(output, " %s=-", name);
+        return;
+    }
+    std::sort(values.begin(), values.end());
+    const float median = values[values.size() / 2];
+    const float worst = worst_is_min ? values.front() : values.back();
+    AppendFormat(output, " %s=%.1f/%.1f", name, median, worst);
+}
+
+const char* EmptyFrameText(EmptyFrameReason reason) noexcept {
+    switch (reason) {
+    case EmptyFrameReason::NoRetainedLayer:
+        return "no completed layer is retained, so the headset shows black";
+    case EmptyFrameReason::ShouldRenderOff:
+        return "the runtime set shouldRender to false";
+    }
+    return "unknown reason";
+}
+
+const char* DiscardText(DiscardReason reason) noexcept {
+    switch (reason) {
+    case DiscardReason::SessionRestarted:
+        return "the OpenXR session restarted";
+    case DiscardReason::ReferenceSpaceChanged:
+        return "the reference space changed";
+    }
+    return "unknown reason";
+}
+
+const char* RejectText(RejectReason reason) noexcept {
+    switch (reason) {
+    case RejectReason::ReleaseFailed:
+        return "releasing its swapchain images failed";
+    case RejectReason::ShouldRenderOff:
+        return "the runtime set shouldRender to false";
+    case RejectReason::ViewsInvalid:
+        return "its views were not valid";
+    case RejectReason::PositionInvalid:
+        return "the head position was not valid";
+    }
+    return "unknown reason";
+}
+
+bool GeometryChanged(const ViewGeometry& before, const ViewGeometry& after) noexcept {
+    constexpr float kAngleTolerance = 0.5f;
+    constexpr float kIpdTolerance = 0.5f;
+    for (size_t eye = 0; eye < 2; ++eye) {
+        for (size_t side = 0; side < 4; ++side) {
+            if (std::fabs(before.fov_degrees[eye][side] - after.fov_degrees[eye][side]) > kAngleTolerance) {
+                return true;
+            }
+        }
+        if (before.width[eye] != after.width[eye] || before.height[eye] != after.height[eye]) {
+            return true;
+        }
+    }
+    if (std::fabs(before.cant_degrees - after.cant_degrees) > kAngleTolerance) {
+        return true;
+    }
+    if ((before.ipd_millimeters < 0.0f) != (after.ipd_millimeters < 0.0f)) {
+        return true;
+    }
+    return after.ipd_millimeters >= 0.0f &&
+           std::fabs(before.ipd_millimeters - after.ipd_millimeters) > kIpdTolerance;
+}
+
+} // namespace
+
+FrameDiagnostics::FrameDiagnostics(Sink sink) : sink_(std::move(sink)) {}
+
+void FrameDiagnostics::SetSink(Sink sink) {
+    sink_ = std::move(sink);
+}
+
+void FrameDiagnostics::Samples::Add(double ms) {
+    // A window at a 144 Hz display holds a few hundred samples at most; the
+    // cap only guards a runaway caller.
+    if (values.size() < 4096) {
+        values.push_back(static_cast<float>(ms));
+    }
+}
+
+void FrameDiagnostics::Reset(int64_t now_ns) {
+    Sink sink = std::move(sink_);
+    *this = FrameDiagnostics(std::move(sink));
+    window_start_ns_ = now_ns;
+    session_info_requested_ = true;
+}
+
+bool FrameDiagnostics::ConsumeSessionInfoRequest() {
+    return std::exchange(session_info_requested_, false);
+}
+
+void FrameDiagnostics::OnWaitFrame(int64_t now_ns, int64_t wait_ns, int64_t display_time,
+                                   int64_t display_period, int64_t deadline_ns) {
+    if (window_start_ns_ == 0) {
+        window_start_ns_ = now_ns;
+    }
+    ++cycles_;
+    wait_frame_ms_.Add(Milliseconds(wait_ns));
+    if (display_period > 0) {
+        display_period_ = display_period;
+        if (last_display_time_ != 0 && display_time > last_display_time_) {
+            const int64_t advance = display_time - last_display_time_;
+            const int64_t slots = (advance + display_period / 2) / display_period;
+            if (slots > 1) {
+                skipped_slots_ += static_cast<uint32_t>(slots - 1);
+                std::string text;
+                AppendFormat(text,
+                             "compositor skipped %lld display slot(s): the predicted display time advanced "
+                             "%.1f ms at %.1f Hz",
+                             static_cast<long long>(slots - 1), Milliseconds(advance),
+                             1.0e9 / static_cast<double>(display_period));
+                Event(text);
+            }
+        }
+    }
+    last_display_time_ = display_time;
+    deadline_ns_ = deadline_ns;
+}
+
+void FrameDiagnostics::OnBeginFrame(int64_t now_ns) {
+    begin_ns_ = now_ns;
+}
+
+void FrameDiagnostics::OnEndFrame(int64_t submit_ns, int64_t call_ns) {
+    end_call_ms_.Add(Milliseconds(call_ns));
+    const double open_ms = begin_ns_ != 0 ? Milliseconds(submit_ns - begin_ns_) : -1.0;
+    if (open_ms >= 0.0) {
+        open_ms_.Add(open_ms);
+    }
+    if (deadline_ns_ != 0) {
+        const double margin_ms = Milliseconds(deadline_ns_ - submit_ns);
+        margin_ms_.Add(margin_ms);
+        if (margin_ms < 0.0) {
+            ++late_;
+            std::string text;
+            AppendFormat(text,
+                         "late frame: xrEndFrame came %.1f ms after the predicted display time "
+                         "(frame open %.1f ms)",
+                         -margin_ms, open_ms);
+            Event(text);
+        }
+    }
+    if (last_submit_ns_ != 0) {
+        const double gap_ms = Milliseconds(submit_ns - last_submit_ns_);
+        end_gap_ms_.Add(gap_ms);
+        const double stall_ms = std::max(25.0, 2.5 * Milliseconds(display_period_));
+        if (gap_ms > stall_ms) {
+            std::string text;
+            AppendFormat(text, "stall: %.1f ms since the previous xrEndFrame", gap_ms);
+            Event(text);
+        }
+    }
+    last_submit_ns_ = submit_ns;
+    begin_ns_ = 0;
+    deadline_ns_ = 0;
+    Tick(submit_ns + call_ns);
+}
+
+void FrameDiagnostics::OnFrameBegun(bool immersive, bool should_render, bool views_valid,
+                                    bool orientation_valid, bool position_valid) {
+    ++(immersive ? immersive_ : screen_);
+    if (!should_render || !views_valid) {
+        ++not_rendered_;
+    }
+    if (!should_render) {
+        // Views are only located when the runtime wants rendering.
+        return;
+    }
+    no_orientation_ += orientation_valid ? 0 : 1;
+    no_position_ += position_valid ? 0 : 1;
+    if (tracking_known_ && orientation_valid != orientation_valid_) {
+        Event(orientation_valid ? "tracking: head orientation regained" : "tracking: head orientation lost");
+    }
+    if (tracking_known_ && position_valid != position_valid_) {
+        Event(position_valid ? "tracking: head position regained" : "tracking: head position lost");
+    }
+    tracking_known_ = true;
+    orientation_valid_ = orientation_valid;
+    position_valid_ = position_valid;
+}
+
+void FrameDiagnostics::OnViewGeometry(const ViewGeometry& geometry) {
+    if (geometry_logged_ && !GeometryChanged(geometry_, geometry)) {
+        return;
+    }
+    geometry_logged_ = true;
+    geometry_ = geometry;
+    std::string text = "view geometry: swapchains";
+    AppendFormat(text, " %ux%u / %ux%u", geometry.width[0], geometry.height[0], geometry.width[1],
+                 geometry.height[1]);
+    for (size_t eye = 0; eye < 2; ++eye) {
+        const auto& fov = geometry.fov_degrees[eye];
+        AppendFormat(text, " | %s eye fov left %+.1f right %+.1f up %+.1f down %+.1f deg",
+                     eye == 0 ? "left" : "right", fov[0], fov[1], fov[2], fov[3]);
+    }
+    AppendFormat(text, " | eye cant %.1f deg (%s)", geometry.cant_degrees,
+                 geometry.cant_degrees > 1.0f ? "canted displays" : "parallel");
+    if (geometry.ipd_millimeters >= 0.0f) {
+        AppendFormat(text, " | ipd %.1f mm", geometry.ipd_millimeters);
+    } else {
+        text += " | ipd unknown";
+    }
+    Info(text);
+}
+
+void FrameDiagnostics::OnSwapchainAcquire(int64_t ns) {
+    acquire_ms_.Add(Milliseconds(ns));
+}
+
+void FrameDiagnostics::OnSwapchainRelease(int64_t ns) {
+    release_ms_.Add(Milliseconds(ns));
+}
+
+void FrameDiagnostics::OnLayer(bool fresh) {
+    ++(fresh ? layers_new_ : layers_repeat_);
+}
+
+void FrameDiagnostics::OnEmptyFrame(EmptyFrameReason reason) {
+    ++empty_;
+    Event(std::string("empty frame submitted (no layers): ") +
+          EmptyFrameText(reason));
+}
+
+void FrameDiagnostics::OnRetainedLayerDiscarded(DiscardReason reason) {
+    ++discarded_;
+    Event(std::string("retained layer discarded: ") + DiscardText(reason));
+}
+
+void FrameDiagnostics::OnLayerRejected(RejectReason reason) {
+    ++layer_rejected_;
+    Event(std::string("rendered layer not submitted: ") + RejectText(reason));
+}
+
+void FrameDiagnostics::OnInterpolationSkip() {
+    ++interp_skip_;
+}
+
+void FrameDiagnostics::OnPacketPublished(int64_t now_ns) {
+    published_ns_ = now_ns;
+}
+
+void FrameDiagnostics::OnPacketCanceled(int64_t 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");
+    } else {
+        ++packet_rejected_;
+        Event("stereo packet canceled: Aurora picked it up but rendered that frame without it "
+              "(content tag or transform check)");
+    }
+    published_ns_ = 0;
+}
+
+void FrameDiagnostics::OnKeepaliveRepeat() {
+    ++keepalive_;
+}
+
+void FrameDiagnostics::OnSubmission(int64_t now_ns, int64_t consumed_ns, bool success) {
+    if (!success) {
+        ++submit_failed_;
+        Event("stereo submission failed");
+    }
+    if (published_ns_ != 0 && consumed_ns >= published_ns_) {
+        game_wait_ms_.Add(Milliseconds(consumed_ns - published_ns_));
+        encode_ms_.Add(Milliseconds(now_ns - consumed_ns));
+    }
+    published_ns_ = 0;
+}
+
+void FrameDiagnostics::OnReferenceSpaceChange(std::string_view space, bool pose_valid, bool effective_known,
+                                              double effective_in_ms) {
+    std::string text = "reference space change pending: ";
+    text.append(space);
+    text += pose_valid ? ", previous pose valid" : ", previous pose not valid";
+    if (effective_known) {
+        AppendFormat(text, ", takes effect in %.1f ms", effective_in_ms);
+    }
+    Info(text);
+}
+
+void FrameDiagnostics::Info(std::string_view text) {
+    if (!sink_) {
+        return;
+    }
+    std::string line = "[xr-diag] ";
+    line.append(text);
+    sink_(line);
+}
+
+void FrameDiagnostics::Event(std::string_view text) {
+    if (events_ >= kMaxEventsPerWindow) {
+        ++suppressed_;
+        return;
+    }
+    ++events_;
+    Info(text);
+}
+
+void FrameDiagnostics::Tick(int64_t now_ns) {
+    if (window_start_ns_ == 0) {
+        window_start_ns_ = now_ns;
+        return;
+    }
+    if (now_ns - window_start_ns_ >= kWindowNs) {
+        EmitSummary(now_ns);
+        ClearWindow(now_ns);
+    }
+}
+
+void FrameDiagnostics::ClearWindow(int64_t now_ns) {
+    window_start_ns_ = now_ns;
+    cycles_ = skipped_slots_ = late_ = 0;
+    layers_new_ = layers_repeat_ = empty_ = discarded_ = layer_rejected_ = 0;
+    keepalive_ = packet_unused_ = packet_rejected_ = submit_failed_ = interp_skip_ = 0;
+    immersive_ = screen_ = not_rendered_ = no_orientation_ = no_position_ = 0;
+    events_ = suppressed_ = 0;
+    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_}) {
+        samples->Clear();
+    }
+}
+
+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, " 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_,
+                 layers_repeat_, empty_, discarded_, layer_rejected_);
+    text += " | ms";
+    AppendStat(text, "wait-frame", wait_frame_ms_.values, false);
+    AppendStat(text, "open", open_ms_.values, false);
+    AppendStat(text, "end-margin", margin_ms_.values, true);
+    AppendStat(text, "end-gap", end_gap_ms_.values, false);
+    AppendStat(text, "end-call", end_call_ms_.values, false);
+    AppendStat(text, "pickup", game_wait_ms_.values, false);
+    AppendStat(text, "render", encode_ms_.values, false);
+    AppendStat(text, "acquire", acquire_ms_.values, false);
+    AppendStat(text, "release", release_ms_.values, false);
+    AppendFormat(text, " | keepalive=%u packet-unused=%u packet-rejected=%u submit-failed=%u interp-skip=%u",
+                 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_);
+    Info(text);
+}
+
+namespace {
+
+struct GlobalDiagnostics {
+    std::mutex sink_mutex;
+    FrameDiagnostics::Sink sink;
+    std::function<int64_t(int64_t)> converter;
+    FrameDiagnostics collector{[](std::string_view line) {
+        auto& state = Global();
+        std::lock_guard lock(state.sink_mutex);
+        if (state.sink) {
+            state.sink(line);
+        }
+    }};
+
+    static GlobalDiagnostics& Global() {
+        static GlobalDiagnostics state;
+        return state;
+    }
+};
+
+std::atomic_bool g_reset_pending{true};
+
+void WriteLine(std::string_view line) {
+    auto& state = GlobalDiagnostics::Global();
+    std::lock_guard lock(state.sink_mutex);
+    if (state.sink) {
+        state.sink(line);
+    }
+}
+
+// The pacing thread's view of the collector. A switch-on made elsewhere is
+// applied here, on the owning thread, before the next measurement.
+FrameDiagnostics& Collector() {
+    auto& collector = GlobalDiagnostics::Global().collector;
+    if (g_reset_pending.exchange(false, std::memory_order_acq_rel)) {
+        collector.Reset(detail::NowNs());
+    }
+    return collector;
+}
+
+int64_t ConvertDisplayTime(int64_t xr_time) {
+    const auto& converter = GlobalDiagnostics::Global().converter;
+    return converter ? converter(xr_time) : 0;
+}
+
+} // namespace
+
+void SetEnabled(bool enabled) noexcept {
+    const bool was_enabled = detail::g_enabled.exchange(enabled, std::memory_order_acq_rel);
+    if (enabled == was_enabled) {
+        return;
+    }
+    if (enabled) {
+        g_reset_pending.store(true, std::memory_order_release);
+    }
+    try {
+        WriteLine(enabled ? "[xr-diag] logging enabled" : "[xr-diag] logging disabled");
+    } catch (...) {
+        // A diagnostic line must never take the settings path down.
+    }
+}
+
+void SetLogSink(FrameDiagnostics::Sink sink) {
+    auto& state = GlobalDiagnostics::Global();
+    std::lock_guard lock(state.sink_mutex);
+    state.sink = std::move(sink);
+}
+
+void SetDisplayTimeConverter(std::function<int64_t(int64_t xr_time)> converter) {
+    GlobalDiagnostics::Global().converter = std::move(converter);
+}
+
+namespace detail {
+
+int64_t NowNs() noexcept {
+    return std::chrono::duration_cast<std::chrono::nanoseconds>(
+               std::chrono::steady_clock::now().time_since_epoch())
+        .count();
+}
+
+void OnWaitFrame(int64_t wait_ns, int64_t display_time, int64_t display_period) {
+    auto& collector = Collector();
+    collector.OnWaitFrame(NowNs(), wait_ns, display_time, display_period, ConvertDisplayTime(display_time));
+}
+
+void OnBeginFrame() {
+    Collector().OnBeginFrame(NowNs());
+}
+
+void OnEndFrame(int64_t submit_ns, int64_t call_ns) {
+    Collector().OnEndFrame(submit_ns, call_ns);
+}
+
+void OnFrameBegun(bool immersive, bool should_render, bool views_valid, bool orientation_valid,
+                  bool position_valid) {
+    Collector().OnFrameBegun(immersive, should_render, views_valid, orientation_valid, position_valid);
+}
+
+void OnViewGeometry(const ViewGeometry& geometry) {
+    Collector().OnViewGeometry(geometry);
+}
+
+void OnSwapchainAcquire(int64_t ns) {
+    Collector().OnSwapchainAcquire(ns);
+}
+
+void OnSwapchainRelease(int64_t ns) {
+    Collector().OnSwapchainRelease(ns);
+}
+
+void OnLayer(bool fresh) {
+    Collector().OnLayer(fresh);
+}
+
+void OnEmptyFrame(EmptyFrameReason reason) {
+    Collector().OnEmptyFrame(reason);
+}
+
+void OnRetainedLayerDiscarded(DiscardReason reason) {
+    Collector().OnRetainedLayerDiscarded(reason);
+}
+
+void OnLayerRejected(RejectReason reason) {
+    Collector().OnLayerRejected(reason);
+}
+
+void OnInterpolationSkip() {
+    Collector().OnInterpolationSkip();
+}
+
+void OnPacketPublished() {
+    g_packet_consumed_ns.store(0, std::memory_order_relaxed);
+    Collector().OnPacketPublished(NowNs());
+}
+
+void OnPacketCanceled() {
+    Collector().OnPacketCanceled(g_packet_consumed_ns.load(std::memory_order_relaxed));
+}
+
+void OnKeepaliveRepeat() {
+    Collector().OnKeepaliveRepeat();
+}
+
+void OnSubmission(bool success) {
+    Collector().OnSubmission(NowNs(), g_packet_consumed_ns.load(std::memory_order_relaxed), success);
+}
+
+void OnReferenceSpaceChange(std::string_view space, bool pose_valid, int64_t change_time) {
+    // The runtime reports 0 when the change applies immediately; the converter
+    // returns 0 when it has no clock to convert with.
+    const int64_t effective_ns = change_time != 0 ? ConvertDisplayTime(change_time) : 0;
+    const double effective_in_ms = effective_ns != 0 ? Milliseconds(effective_ns - NowNs()) : 0.0;
+    Collector().OnReferenceSpaceChange(space, pose_valid, effective_ns != 0, effective_in_ms);
+}
+
+void OnSessionStarted() {
+    g_reset_pending.store(true, std::memory_order_release);
+}
+
+bool ConsumeSessionInfoRequest() {
+    return Collector().ConsumeSessionInfoRequest();
+}
+
+void Info(std::string_view text) {
+    Collector().Info(text);
+}
+
+} // namespace detail
+} // namespace mkw::vr::diagnostics

runtime/src/vr/openxr_integration.cpp

@@ -11,6 +11,7 @@
 #include "vr/mkw_vr_first_person.h"
 #include "vr/mkw_vr_policy.h"
 #include "vr/mkw_vr_instrumentation.h"
+#include "vr/openxr_diagnostics.h"
 #include <aurora/gfx.h>
 
 #include <algorithm>
@@ -23,6 +24,7 @@
 #include <cstring>
 #include <memory>
 #include <mutex>
+#include <sstream>
 #include <string>
 #include <thread>
 
@@ -254,6 +256,64 @@ void ViewFromBase(const XrPosef& eye_pose, const std::array<float, 3>& base_posi
     output[11] = translation[2] * units_per_meter;
 }
 
+// Distinct names from openxr_runtime.cpp's helpers: both files can share a
+// unity-build translation unit and the same anonymous namespace.
+const char* DiagnosticSpaceName(XrReferenceSpaceType type) noexcept {
+    switch (type) {
+    case XR_REFERENCE_SPACE_TYPE_VIEW:
+        return "VIEW";
+    case XR_REFERENCE_SPACE_TYPE_LOCAL:
+        return "LOCAL";
+    case XR_REFERENCE_SPACE_TYPE_STAGE:
+        return "STAGE";
+    default:
+        return "OTHER";
+    }
+}
+
+const char* DiagnosticBlendModeName(XrEnvironmentBlendMode mode) noexcept {
+    switch (mode) {
+    case XR_ENVIRONMENT_BLEND_MODE_OPAQUE:
+        return "OPAQUE";
+    case XR_ENVIRONMENT_BLEND_MODE_ADDITIVE:
+        return "ADDITIVE";
+    case XR_ENVIRONMENT_BLEND_MODE_ALPHA_BLEND:
+        return "ALPHA_BLEND";
+    default:
+        return "OTHER";
+    }
+}
+
+// What the runtime reported about the eyes this frame. The cant is the angle
+// between the two eyes' forward axes: zero for parallel displays, and the
+// headset's display tilt on canted ones (Pimax) unless the runtime is asked for
+// parallel projections.
+diagnostics::ViewGeometry DiagnosticViewGeometry(const OpenXRBackendFrame& frame) noexcept {
+    constexpr float kRadiansToDegrees = 57.29577951f;
+    diagnostics::ViewGeometry geometry{};
+    std::array<std::array<float, 3>, kOpenXREyeCount> forward{};
+    for (uint32_t eye = 0; eye < kOpenXREyeCount; ++eye) {
+        const XrView& view = frame.xr_frame.views[eye];
+        geometry.fov_degrees[eye] = {view.fov.angleLeft * kRadiansToDegrees, view.fov.angleRight * kRadiansToDegrees,
+                                     view.fov.angleUp * kRadiansToDegrees, view.fov.angleDown * kRadiansToDegrees};
+        const auto& q = view.pose.orientation;
+        forward[eye] = Rotate(Normalize({q.x, q.y, q.z, q.w}), {0.0f, 0.0f, -1.0f});
+        geometry.width[eye] = frame.render_width[eye];
+        geometry.height[eye] = frame.render_height[eye];
+    }
+    const float dot = forward[0][0] * forward[1][0] + forward[0][1] * forward[1][1] + forward[0][2] * forward[1][2];
+    geometry.cant_degrees = std::acos(std::clamp(dot, -1.0f, 1.0f)) * kRadiansToDegrees;
+    if ((frame.xr_frame.view_state_flags & XR_VIEW_STATE_POSITION_VALID_BIT) != 0) {
+        const auto& left = frame.xr_frame.views[0].pose.position;
+        const auto& right = frame.xr_frame.views[1].pose.position;
+        const float dx = right.x - left.x;
+        const float dy = right.y - left.y;
+        const float dz = right.z - left.z;
+        geometry.ipd_millimeters = std::sqrt(dx * dx + dy * dy + dz * dz) * 1000.0f;
+    }
+    return geometry;
+}
+
 class OpenXRIntegration final {
 public:
     static OpenXRIntegration& Get() {
@@ -272,6 +332,11 @@ public:
                      kGraphicsBackendName + " submission");
             return OpenXRStartupResult::Unavailable;
         }
+        // The pacing thread is not running here (Shutdown above joined it), so
+        // the sink may be replaced.
+        diagnostics::SetLogSink(
+            [](std::string_view line) { RT_LOG(RT_TAG_RUNTIME) << line << std::endl; });
+        diagnostics::SetEnabled(RuntimeConfigFile::DiagnosticsOpenXRLogging(false));
         requested_ = RuntimeConfigFile::VrEnabled(kVrEnabledDefault);
         ConfigurePolicy(requested_);
         if (!requested_) {
@@ -381,6 +446,10 @@ public:
         WithdrawPublishedFrame();
         aurora_set_stereo_frame_provider(&OpenXRIntegration::ProvideStereoFrame, this);
         provider_registered_ = true;
+        if (convert_display_time_ != nullptr) {
+            diagnostics::SetDisplayTimeConverter(
+                [this](int64_t xr_time) { return static_cast<int64_t>(DisplayTimeNanos(xr_time)); });
+        }
         running_.store(true, std::memory_order_release);
         try {
             pacing_thread_ = std::thread([this] { PacingThread(); });
@@ -431,6 +500,8 @@ public:
         }
         running_.store(false, std::memory_order_release);
         MkwVRPolicySetSessionActive(false);
+        // The converter reads runtime_; the pacing thread has stopped using it.
+        diagnostics::SetDisplayTimeConverter({});
         backend_.reset();
         runtime_.reset();
         prepared_ = false;
@@ -513,6 +584,7 @@ private:
     }
 
     void ResetPreparedObjects() {
+        diagnostics::SetDisplayTimeConverter({});
         ShutdownOrRetainGraphicsObjects();
         input_.reset();
         backend_.reset();
@@ -556,6 +628,7 @@ private:
         if (frame == nullptr) {
             return false;
         }
+        diagnostics::NotePacketConsumed();
         *output = frame->frame;
         return true;
     }
@@ -579,6 +652,7 @@ private:
             if (session_run_serial != applied_session_run_serial_) {
                 applied_session_run_serial_ = session_run_serial;
                 ResetTrackingOrigin();
+                diagnostics::OnSessionStarted();
             }
             if (session_active != session_was_active_) {
                 session_was_active_ = session_active;
@@ -606,8 +680,10 @@ private:
             }
 
             const MkwVRPolicySnapshot policy = MkwVRPolicyGetSnapshot();
+            // Diagnostics lift the cap: a presentation flickering between the
+            // race and the virtual screen is exactly what a report needs to show.
             if ((!presentation_logged || policy.presentation != logged_presentation) &&
-                presentation_log_count < 16) {
+                (presentation_log_count < 16 || diagnostics::Enabled())) {
                 presentation_logged = true;
                 logged_presentation = policy.presentation;
                 ++presentation_log_count;
@@ -655,6 +731,9 @@ private:
             }
 
             UpdateFrameTiming(frame.xr_frame);
+            if (diagnostics::Enabled()) {
+                NoteFrameDiagnostics(frame, immersive);
+            }
             // Both of these read this frame's located head pose and must run
             // before FinishFrame submits a layer built from it.
             ServiceRecenterRequest();
@@ -675,6 +754,7 @@ 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)) {
                     SetError(backend_->LastError());
                     fatal = true;
@@ -690,6 +770,7 @@ private:
                 // the camera's own switch is not observable.
                 BuildPublishedFrame(frame, immersive, policy.EffectiveUnitsPerMeter(),
                                     policy.content_tag);
+                diagnostics::OnPacketPublished();
                 published_.store(&published_frame_, std::memory_order_release);
             }
             aurora_notify_stereo_frame();
@@ -711,9 +792,11 @@ private:
                         WithdrawPublishedFrame();
                         canceled_before_encode = backend_->TryCancelPendingFrame(frame);
                         if (canceled_before_encode) {
+                            diagnostics::OnPacketCanceled();
                             break;
                         }
                     }
+                    diagnostics::OnKeepaliveRepeat();
                     if (!backend_->RepeatFrame(frame)) {
                         SetError(backend_->LastError());
                         fatal = true;
@@ -739,6 +822,7 @@ private:
                 break;
             }
             const bool submit = submission == OpenXRSubmissionStatus::Success;
+            diagnostics::OnSubmission(submit);
             if (!backend_->FinishFrame(frame, submit)) {
                 SetError(backend_->LastError());
                 fatal = true;
@@ -965,6 +1049,72 @@ private:
         }
     }
 
+    // Pacing thread, only while diagnostics are on.
+    void NoteFrameDiagnostics(const OpenXRBackendFrame& frame, bool immersive) {
+        const XrViewStateFlags flags = frame.xr_frame.view_state_flags;
+        diagnostics::OnFrameBegun(immersive, frame.xr_frame.should_render, frame.xr_frame.views_valid,
+                                  (flags & XR_VIEW_STATE_ORIENTATION_VALID_BIT) != 0,
+                                  (flags & XR_VIEW_STATE_POSITION_VALID_BIT) != 0);
+        if (diagnostics::ConsumeSessionInfoRequest()) {
+            LogDiagnosticSession(frame);
+        }
+        if (frame.xr_frame.should_render && frame.xr_frame.views_valid) {
+            diagnostics::OnViewGeometry(DiagnosticViewGeometry(frame));
+        }
+    }
+
+    // Everything about the headset and runtime that a pacing report is read
+    // against. Written when logging starts and again for every new session.
+    void LogDiagnosticSession(const OpenXRBackendFrame& frame) const {
+        const auto& info = runtime_->RuntimeInfo();
+        std::ostringstream line;
+        line << "session: runtime '" << info.runtime_name << "' " << XR_VERSION_MAJOR(info.runtime_version) << '.'
+             << XR_VERSION_MINOR(info.runtime_version) << '.' << XR_VERSION_PATCH(info.runtime_version)
+             << ", system '" << info.system_name << "', vendor 0x" << std::hex << info.vendor_id << std::dec
+             << ", orientation tracking " << info.supports_orientation_tracking << ", position tracking "
+             << info.supports_position_tracking << ", max layers " << info.max_layer_count;
+        diagnostics::Info(line.str());
+
+        line.str({});
+        line << "session: " << kGraphicsBackendName << " backend, reference space "
+             << DiagnosticSpaceName(runtime_->AppSpaceType()) << ", blend mode "
+             << DiagnosticBlendModeName(runtime_->EnvironmentBlendMode()) << ", extensions";
+        for (const std::string& extension : runtime_->EnabledExtensions()) {
+            line << ' ' << extension;
+        }
+        diagnostics::Info(line.str());
+
+        line.str({});
+        const auto& views = runtime_->ViewConfiguration();
+        line << "session: recommended eye size " << views[0].properties.recommendedImageRectWidth << 'x'
+             << views[0].properties.recommendedImageRectHeight << " / "
+             << views[1].properties.recommendedImageRectWidth << 'x'
+             << views[1].properties.recommendedImageRectHeight << ", max "
+             << views[0].properties.maxImageRectWidth << 'x' << views[0].properties.maxImageRectHeight
+             << ", render_scale " << runtime_->Config().resolution_scale << ", swapchains "
+             << views[0].render_width << 'x' << views[0].render_height << " / " << views[1].render_width << 'x'
+             << views[1].render_height;
+        diagnostics::Info(line.str());
+
+        line.str({});
+        const uint32_t interpolation = frame_interpolation_fps_.load(std::memory_order_relaxed);
+        line << "session: display period ";
+        if (frame.xr_frame.predicted_display_period > 0) {
+            const double period_ms = static_cast<double>(frame.xr_frame.predicted_display_period) / 1.0e6;
+            line << period_ms << " ms (" << 1000.0 / period_ms << " Hz)";
+        } else {
+            line << "unknown";
+        }
+        line << ", refresh-rate extension " << (get_display_refresh_rate_ != nullptr ? "yes" : "no")
+             << ", display-time conversion " << (convert_display_time_ != nullptr ? "yes" : "no")
+             << ", VR frame interpolation "
+             << (interpolation == 0 ? std::string("off")
+                 : interpolation == 1 ? std::string("auto")
+                                      : std::to_string(interpolation))
+             << (FrameInterpolationAvailable() ? "" : " (unavailable)");
+        diagnostics::Info(line.str());
+    }
+
     // Converts the compositor's predicted display time onto the runtime's
     // steady clock, which is what Aurora's interpolation deadlines are paced by.
     uint64_t DisplayTimeNanos(XrTime display_time) noexcept {

runtime/src/vr/openxr_runtime.cpp

@@ -6,6 +6,7 @@
 #if defined(MKW_ENABLE_OPENXR)
 
 #include "vr/openxr_runtime.h"
+#include "vr/openxr_diagnostics.h"
 
 #include <algorithm>
 #include <chrono>
@@ -55,6 +56,19 @@ uint32_t ScaledDimension(uint32_t recommended, uint32_t maximum, float scale) {
     return static_cast<uint32_t>(clamped);
 }
 
+const char* ReferenceSpaceName(XrReferenceSpaceType type) {
+    switch (type) {
+    case XR_REFERENCE_SPACE_TYPE_VIEW:
+        return "VIEW";
+    case XR_REFERENCE_SPACE_TYPE_LOCAL:
+        return "LOCAL";
+    case XR_REFERENCE_SPACE_TYPE_STAGE:
+        return "STAGE";
+    default:
+        return "OTHER";
+    }
+}
+
 const char* SessionStateName(XrSessionState state) {
     switch (state) {
     case XR_SESSION_STATE_UNKNOWN:
@@ -520,6 +534,11 @@ OpenXREventStatus OpenXRRuntime::PollEvents() {
         case XR_TYPE_EVENT_DATA_REFERENCE_SPACE_CHANGE_PENDING: {
             const auto& space_event =
                 *reinterpret_cast<const XrEventDataReferenceSpaceChangePending*>(&event);
+            if (space_event.session == m_session) {
+                diagnostics::OnReferenceSpaceChange(ReferenceSpaceName(space_event.referenceSpaceType),
+                                                    space_event.poseValid == XR_TRUE,
+                                                    space_event.changeTime);
+            }
             // This slot is consumed to invalidate transforms located in the
             // application space. Events for VIEW or another supported type
             // must not overwrite a pending LOCAL/STAGE change.
@@ -647,9 +666,11 @@ OpenXRFrameStatus OpenXRRuntime::WaitFrame(OpenXRFrame& frame) {
 
     XrFrameWaitInfo wait_info{XR_TYPE_FRAME_WAIT_INFO};
     XrFrameState state{XR_TYPE_FRAME_STATE};
+    const diagnostics::Stopwatch wait_timer;
     if (!Check(xrWaitFrame(m_session, &wait_info, &state), "xrWaitFrame")) {
         return OpenXRFrameStatus::Error;
     }
+    diagnostics::OnWaitFrame(wait_timer, state.predictedDisplayTime, state.predictedDisplayPeriod);
 
     frame = {};
     frame.serial = m_next_frame_serial++;
@@ -678,6 +699,7 @@ bool OpenXRRuntime::BeginFrame(const OpenXRFrame& frame) {
         return Check(result, "xrBeginFrame");
     }
     m_frame_phase = FramePhase::Begun;
+    diagnostics::OnBeginFrame();
     return true;
 }
 
@@ -744,7 +766,9 @@ bool OpenXRRuntime::EndFrame(
     end_info.environmentBlendMode = m_blend_mode;
     end_info.layerCount = layer_count;
     end_info.layers = layers;
+    const diagnostics::Stopwatch end_timer;
     const XrResult result = xrEndFrame(m_session, &end_info);
+    diagnostics::OnEndFrame(end_timer);
     m_frame_phase = FramePhase::Idle;
     m_active_frame_serial = 0;
     m_active_frame_display_time = 0;

runtime/src/vr/openxr_vulkan.cpp

@@ -8,6 +8,7 @@
 #define XR_USE_PLATFORM_ANDROID
 
 #include "vr/openxr_vulkan.h"
+#include "vr/openxr_diagnostics.h"
 
 #include <aurora/vulkan_interop.h>
 
@@ -360,6 +361,7 @@ public:
             frame.render_height[1] = frame.render_height[0];
         }
 
+        const diagnostics::Stopwatch acquire_timer;
         for (uint32_t eye = 0; eye < target_count; ++eye) {
             if (!AcquireSwapchain(eye_swapchains_[eye])) {
                 ReleaseAcquiredSwapchains();
@@ -367,6 +369,7 @@ public:
                 return OpenXRBeginStatus::Error;
             }
         }
+        diagnostics::OnSwapchainAcquire(acquire_timer);
 
         std::array<AuroraVulkanStereoTarget, kOpenXREyeCount> targets{};
         const uint32_t slot = next_slot_;
@@ -475,7 +478,11 @@ public:
             AbandonAcquiredSwapchains();
             Fail("Aurora's stereo submission failed after GPU work may have been queued");
         }
+        const diagnostics::Stopwatch release_timer;
         bool release_ok = ReleaseAcquiredSwapchains();
+        if (frame.xr_frame.should_render && frame.xr_frame.views_valid) {
+            diagnostics::OnSwapchainRelease(release_timer);
+        }
         const bool position_valid =
             (frame.xr_frame.view_state_flags & XR_VIEW_STATE_POSITION_VALID_BIT) != 0;
         const bool composition_pose_valid =
@@ -483,6 +490,10 @@ public:
         const bool can_submit = submit_layer && release_ok && frame.xr_frame.should_render &&
                                 frame.xr_frame.views_valid && frame.expects_gpu_submission &&
                                 composition_pose_valid;
+        if (submit_layer && !can_submit) {
+            diagnostics::OnLayerRejected(diagnostics::ClassifyRejectedLayer(
+                release_ok, frame.xr_frame.should_render, frame.xr_frame.views_valid));
+        }
         if (can_submit) {
             // xrEndFrame references the most recently released image of a
             // swapchain, so keep the displayed pair separate from the pair
@@ -493,7 +504,7 @@ public:
             retained_space_serial_ = render_space_serial_;
             have_retained_frame_ = true;
         }
-        const bool end_ok = EndRetainedFrame();
+        const bool end_ok = EndRetainedFrame(can_submit);
 
         frame_active_ = false;
         active_frame_serial_ = 0;
@@ -514,7 +525,7 @@ public:
             frame.xr_frame.serial != active_frame_serial_) {
             return Fail("RepeatFrame received a stale or inactive render token");
         }
-        const bool end_ok = EndRetainedFrame();
+        const bool end_ok = EndRetainedFrame(false);
         frame_active_ = false;
         if (!end_ok) {
             return Fail("OpenXR could not resubmit the retained frame");
@@ -531,17 +542,26 @@ public:
         return true;
     }
 
-    bool EndRetainedFrame() {
+    // fresh: the retained layer was completed for this call rather than repeated.
+    bool EndRetainedFrame(bool fresh) {
         if (!runtime_->IsSessionRunning()) {
             return true;
         }
-        if (retained_session_serial_ != runtime_->SessionRunSerial() ||
-            retained_space_serial_ != runtime_->LastReferenceSpaceChange().serial) {
+        const bool session_changed = retained_session_serial_ != runtime_->SessionRunSerial();
+        if (session_changed || retained_space_serial_ != runtime_->LastReferenceSpaceChange().serial) {
+            if (have_retained_frame_) {
+                diagnostics::OnRetainedLayerDiscarded(session_changed
+                                                          ? diagnostics::DiscardReason::SessionRestarted
+                                                          : diagnostics::DiscardReason::ReferenceSpaceChanged);
+            }
             have_retained_frame_ = false;
         }
         if (!have_retained_frame_ || !active_frame_.should_render) {
+            diagnostics::OnEmptyFrame(!active_frame_.should_render ? diagnostics::EmptyFrameReason::ShouldRenderOff
+                                                                    : diagnostics::EmptyFrameReason::NoRetainedLayer);
             return runtime_->EndFrameWithoutLayers(active_frame_);
         }
+        diagnostics::OnLayer(fresh);
         const auto& frame = retained_frame_;
         if (frame.presentation.mode == OpenXRFrameMode::VirtualScreen) {
             XrCompositionLayerQuad quad{XR_TYPE_COMPOSITION_LAYER_QUAD};