From f222eedf6be4b23912d0314087b768368a08227e Mon Sep 17 00:00:00 2001 From: iChris4 Date: Thu, 17 Sep 2026 02:05:12 +0200 Subject: [PATCH] Implement log export functionality and OpenXR diagnostics --- OPENXR.md | 65 +++ runtime/CMakeLists.txt | 18 +- runtime/include/log_export.h | 43 ++ runtime/include/runtime_config.h | 13 + runtime/include/vr/openxr_diagnostics.h | 303 +++++++++++ runtime/src/log_export.cpp | 153 ++++++ runtime/src/settings_overlay.cpp | 157 ++++++ runtime/src/vr/openxr_d3d12.cpp | 30 +- runtime/src/vr/openxr_diagnostics.cpp | 559 +++++++++++++++++++++ runtime/src/vr/openxr_integration.cpp | 152 +++++- runtime/src/vr/openxr_runtime.cpp | 24 + runtime/src/vr/openxr_vulkan.cpp | 30 +- runtime/tests/log_export_tests.cpp | 113 +++++ runtime/tests/openxr_diagnostics_tests.cpp | 291 +++++++++++ 14 files changed, 1939 insertions(+), 12 deletions(-) create mode 100644 runtime/include/log_export.h create mode 100644 runtime/include/vr/openxr_diagnostics.h create mode 100644 runtime/src/log_export.cpp create mode 100644 runtime/src/vr/openxr_diagnostics.cpp create mode 100644 runtime/tests/log_export_tests.cpp create mode 100644 runtime/tests/openxr_diagnostics_tests.cpp diff --git a/OPENXR.md b/OPENXR.md index 3415780..2b2a395 100644 --- a/OPENXR.md +++ b/OPENXR.md @@ -317,6 +317,71 @@ Kart Wii's minimap are treated as game art and remain eligible for the screen. A uses the full eye viewport and scissor because its recorded rectangle no longer describes where it ended up; its original viewport is folded into the projection instead. +## Diagnostics + +**F10 > Diagnostics** holds two bug-report aids. + +**OpenXR diagnostic logging** is off by default. When it is off, each hook on the pacing thread is +one atomic test. It applies immediately and is remembered as: + +```toml +[diagnostics] +openxr_logging = false +``` + +When it is on, `console.log` receives lines tagged `[runtime] [xr-diag]` +(`runtime/src/vr/openxr_diagnostics.cpp`). They cover both the D3D12 and the Vulkan backend. + +- **Session description.** Written when logging starts and again for every new OpenXR session. It + gives the runtime and system names and versions, vendor id, tracking support, backend, reference + space, blend mode, enabled extensions, recommended and maximum eye sizes, `render_scale`, swapchain + sizes, display period, and the VR frame interpolation setting. +- **View geometry.** Written on the first located views and again whenever they change by more + than 0.5° or 0.5 mm. It gives per-eye FOV half-angles, the eye cant (the angle between the two + eyes' forward axes: 0 for parallel displays, non-zero for canted ones such as Pimax without + parallel projections), and the IPD. +- **A one-second summary.** Timings are `median/worst` in milliseconds; for `end-margin`, worst is + the minimum. + +| Field | Meaning | +| --- | --- | +| `Hz`, `cycles` | Display rate from the predicted display period; compositor cycles (xrWaitFrame/xrEndFrame pairs, repeats included). | +| `skipped-slots` | Display slots the predicted display time jumped over: the runtime throttled or dropped frames. | +| `late` | Frames whose xrEndFrame came after their predicted display time (needs `XR_KHR_win32_convert_performance_counter_time` or `XR_KHR_convert_timespec_time`). | +| `layers new/repeat/empty` | Cycles ending with a newly rendered layer, the retained layer again, or no layer at all (black). | +| `discarded`, `layer-rejected` | Retained layers dropped by a session or reference-space change; rendered layers not submitted (invalid pose or views, failed release). | +| `wait-frame`, `open`, `end-call` | Time blocked in xrWaitFrame, from xrBeginFrame to xrEndFrame, and inside xrEndFrame. | +| `end-margin`, `end-gap` | Predicted display time minus the xrEndFrame time; interval between xrEndFrame calls. | +| `pickup`, `render` | Stereo packet published until Aurora's frame worker takes it (without interpolation this includes waiting for the next 60 Hz game frame); taken until the eye copy is submitted. | +| `acquire`, `release` | Swapchain image acquire+wait and release. | +| `keepalive` | Retained-layer repeats while Aurora was still encoding past the 50 ms keep-alive. | +| `packet-unused`, `packet-rejected`, `submit-failed` | Packets no game frame took within 50 ms; packets Aurora took but rendered mono (content tag or transform check); failed stereo copies. | +| `interp-skip` | Cycles the VR interpolation rate cap chose not to render. | +| `frames immersive/screen` | Cycles per presentation mode; `not-rendered` counts cycles without views to render. | +| `no-orientation`, `no-position` | Cycles whose head orientation or position was not valid. | +| `suppressed` | Event lines dropped by the rate limit. | + +- **Event lines.** At most 8 per second; the rest are counted in `suppressed`. They report late + frames, skipped display slots, stalls (more than 2.5 display periods, and at least 25 ms, between + xrEndFrame calls), empty frames and their reason, discarded retained layers, rejected layers, + withdrawn or rejected packets, failed submissions, and head-tracking loss and recovery. + Reference-space change events are never rate-limited. +- **Presentation changes.** While logging is on, every `[mkw-vr] presentation=` transition is + logged, not just the first 16. + +**Export Logs** opens the system folder picker. It then creates a +`WiiCompiled-logs-YYYYMMDD-HHMMSS` folder at the chosen location, containing: + +- `Logs/`: every retained run folder, the current session included. The runtime prunes run + folders after four days. +- `Config.toml`. +- `export-info.txt`: the export time, the exporting process id (whose run folder ends in `_pid`), + and the OpenXR state. + +The current `console.log` is copied through a shared-read stream while it is still being written. +The copy runs on SDL's dialog thread (`runtime/src/log_export.cpp`), and the outcome is shown under +the button. `mkw_openxr_diagnostics_tests` and `mkw_log_export_tests` cover both without a headset. + ## Backend status | Backend | Status | diff --git a/runtime/CMakeLists.txt b/runtime/CMakeLists.txt index 21922cb..6d5f9e5 100644 --- a/runtime/CMakeLists.txt +++ b/runtime/CMakeLists.txt @@ -418,9 +418,25 @@ if(CMAKE_CXX_COMPILER_ID MATCHES "Clang|GNU") endif() add_test(NAME mkw_vr_policy_tests COMMAND mkw_vr_policy_tests) +# F10 > Diagnostics: the OpenXR frame-diagnostics collector is free of OpenXR +# and guest state, so its window accounting runs on a synthetic clock here. +add_executable(mkw_openxr_diagnostics_tests tests/openxr_diagnostics_tests.cpp src/vr/openxr_diagnostics.cpp) +target_include_directories(mkw_openxr_diagnostics_tests PRIVATE "${CMAKE_CURRENT_LIST_DIR}/include") +target_link_libraries(mkw_openxr_diagnostics_tests PRIVATE mkw::toml11) +target_compile_features(mkw_openxr_diagnostics_tests PRIVATE cxx_std_20) +set_target_properties(mkw_openxr_diagnostics_tests PROPERTIES UNITY_BUILD OFF) +add_test(NAME mkw_openxr_diagnostics_tests COMMAND mkw_openxr_diagnostics_tests) + +# F10 > Diagnostics > Export Logs, against temporary folders. +add_executable(mkw_log_export_tests tests/log_export_tests.cpp src/log_export.cpp) +target_include_directories(mkw_log_export_tests PRIVATE "${CMAKE_CURRENT_LIST_DIR}/include") +target_compile_features(mkw_log_export_tests PRIVATE cxx_std_20) +set_target_properties(mkw_log_export_tests PROPERTIES UNITY_BUILD OFF) +add_test(NAME mkw_log_export_tests COMMAND mkw_log_export_tests) + if(MKW_ENABLE_OPENXR AND MKW_PLATFORM_WINDOWS) add_executable(mkw_openxr_replay_tests - tests/openxr_d3d12_replay_tests.cpp src/vr/openxr_d3d12.cpp) + tests/openxr_d3d12_replay_tests.cpp src/vr/openxr_d3d12.cpp src/vr/openxr_diagnostics.cpp) target_include_directories(mkw_openxr_replay_tests PRIVATE "${CMAKE_CURRENT_LIST_DIR}/include" "${CMAKE_CURRENT_LIST_DIR}/../aurora-main/include" diff --git a/runtime/include/log_export.h b/runtime/include/log_export.h new file mode 100644 index 0000000..4cea562 --- /dev/null +++ b/runtime/include/log_export.h @@ -0,0 +1,43 @@ +// SPDX-License-Identifier: GPL-3.0-or-later + +#pragma once + +#include +#include +#include +#include +#include + +// F10 > Diagnostics > Export Logs: gathers what a bug report needs into one +// folder the player chose, ready to zip and attach. +namespace log_export { + +inline constexpr std::string_view kExportFolderPrefix = "WiiCompiled-logs-"; + +struct Result { + // The folder created for this export; empty when it could not be created. + std::filesystem::path destination; + size_t files_copied = 0; + size_t files_failed = 0; + // The first problem met, suitable for display. + std::string error; + + bool Succeeded() const { return !destination.empty() && files_failed == 0 && error.empty(); } +}; + +// Creates "WiiCompiled-logs-YYYYMMDD-HHMMSS" (local time, with a numeric suffix +// if that name exists) inside `parent` and copies into it: +// Logs/ the whole run-log tree, one folder per run, current run included +// Config.toml the player's configuration +// export-info.txt the export time followed by `note` +// A missing logs directory or config file is skipped, not an error, as long as +// something was exported. +// +// Files are copied through ordinary shared-read streams rather than a platform +// copy call, so the running session's console.log, which is still open for +// writing, is exported up to its current end. +Result ExportLogs(const std::filesystem::path& logs_directory, const std::filesystem::path& config_file, + const std::filesystem::path& parent, std::string_view note, + std::chrono::system_clock::time_point now); + +} // namespace log_export diff --git a/runtime/include/runtime_config.h b/runtime/include/runtime_config.h index ee3c6c7..85b360a 100644 --- a/runtime/include/runtime_config.h +++ b/runtime/include/runtime_config.h @@ -70,6 +70,9 @@ struct RuntimeUserConfig { std::optional vrFirstPersonRotation; std::optional vrRecenterKey; std::optional vrLeanBackDegrees; + // F10 > Diagnostics: OpenXR pacing and presentation logging in console.log. + // Off unless set; it is a bug-report aid, not something to leave running. + std::optional diagnosticsOpenXRLogging; std::optional audioVolume; std::optional audioMusicVolume; std::optional audioSoundEffectsVolume; @@ -684,6 +687,7 @@ inline RuntimeUserConfig ParseConfigDocument(const toml::value& document) { value && *value >= -1 && *value <= 31) { config.vrFirstPersonHiddenModel = static_cast(*value); } + config.diagnosticsOpenXRLogging = FindConfigValue(document, "diagnostics", "openxr_logging"); auto readVolume = [&](std::string_view key) -> std::optional { auto value = FindConfigFloat(document, "audio", key); @@ -1338,6 +1342,15 @@ inline uint32_t VrFrameInterpolationFps() { return mkw::vr::NormalizeFrameInterpolationFps(Get().vrFrameInterpolationFps.value_or(0)); } +inline bool DiagnosticsOpenXRLogging(bool fallback = false) { + return Get().diagnosticsOpenXRLogging.value_or(fallback); +} + +inline bool SetDiagnosticsOpenXRLogging(bool value) { + Mutable().diagnosticsOpenXRLogging = value; + return WriteSetting("diagnostics", "openxr_logging", value ? "true" : "false"); +} + inline std::string VrFirstPersonRotation(std::string fallback = kVrFirstPersonRotationDefault) { const auto& value = Get().vrFirstPersonRotation; return value && IsSupportedVrFirstPersonRotation(*value) ? *value : std::move(fallback); diff --git a/runtime/include/vr/openxr_diagnostics.h b/runtime/include/vr/openxr_diagnostics.h new file mode 100644 index 0000000..eca40d4 --- /dev/null +++ b/runtime/include/vr/openxr_diagnostics.h @@ -0,0 +1,303 @@ +// SPDX-License-Identifier: GPL-3.0-or-later + +#pragma once + +#include +#include +#include +#include +#include +#include +#include + +// Opt-in OpenXR pacing and presentation diagnostics (F10 > Diagnostics). +// +// Off by default. Every hook below is an inline test of one atomic that returns +// at once while logging is off, so carrying them costs the XR pacing thread +// nothing measurable. When on, one-second windows are accumulated and written to +// console.log as a "[xr-diag]" summary line, plus rate-limited event lines for +// late, empty or discarded frames. OPENXR.md documents every field. +// +// All hooks except SetEnabled/Enabled and NotePacketConsumed run on the XR +// pacing thread, the collector's only writer. Nothing here includes OpenXR, so +// the settings overlay and the headless tests can use it in any build. +namespace mkw::vr::diagnostics { + +enum class EmptyFrameReason : uint8_t { + NoRetainedLayer, + ShouldRenderOff, +}; + +enum class DiscardReason : uint8_t { + SessionRestarted, + ReferenceSpaceChanged, +}; + +// Why a layer Aurora finished rendering was not submitted. +enum class RejectReason : uint8_t { + ReleaseFailed, + ShouldRenderOff, + ViewsInvalid, + PositionInvalid, +}; + +// The backends' submit condition, checked in the same order: release, then +// should_render, then views; a layer passing all three failed on head position. +inline RejectReason ClassifyRejectedLayer(bool release_ok, bool should_render, bool views_valid) noexcept { + if (!release_ok) { + return RejectReason::ReleaseFailed; + } + if (!should_render) { + return RejectReason::ShouldRenderOff; + } + return views_valid ? RejectReason::PositionInvalid : RejectReason::ViewsInvalid; +} + +struct ViewGeometry { + // Per eye: left, right, up, down half-angles, in degrees. + std::array, 2> fov_degrees{}; + // Angle between the two eyes' forward axes; non-zero on canted displays. + float cant_degrees = 0.0f; + // Negative when the runtime reported no valid eye positions. + float ipd_millimeters = -1.0f; + std::array width{}; + std::array height{}; +}; + +// Accumulates one window of frame measurements and formats it. Times are +// steady-clock nanoseconds passed in by the caller, so tests can drive it with +// a synthetic clock. Not synchronized: one thread owns an instance. +class FrameDiagnostics { +public: + using Sink = std::function; + + static constexpr int64_t kWindowNs = 1'000'000'000; + static constexpr uint32_t kMaxEventsPerWindow = 8; + + explicit FrameDiagnostics(Sink sink = {}); + + void SetSink(Sink sink); + // Starts a fresh window and forgets per-session state (display-time grid, + // tracking, logged geometry), and asks for the session description again. + void Reset(int64_t now_ns); + // True once after each Reset: the owner should describe the session. + bool ConsumeSessionInfoRequest(); + + // Compositor cycle: xrWaitFrame returned. deadline_ns is the predicted + // display time on the steady clock, or 0 when it cannot be converted. + void OnWaitFrame(int64_t now_ns, int64_t wait_ns, int64_t display_time, + int64_t display_period, int64_t deadline_ns); + void OnBeginFrame(int64_t now_ns); + // xrEndFrame was entered at submit_ns and took call_ns. + void OnEndFrame(int64_t submit_ns, int64_t call_ns); + + void OnFrameBegun(bool immersive, bool should_render, bool views_valid, + bool orientation_valid, bool position_valid); + void OnViewGeometry(const ViewGeometry& geometry); + void OnSwapchainAcquire(int64_t ns); + void OnSwapchainRelease(int64_t ns); + + void OnLayer(bool fresh); + void OnEmptyFrame(EmptyFrameReason reason); + void OnRetainedLayerDiscarded(DiscardReason reason); + void OnLayerRejected(RejectReason reason); + + void OnInterpolationSkip(); + void OnPacketPublished(int64_t now_ns); + // consumed_ns is when Aurora took the packet, or 0 if it never did. + void OnPacketCanceled(int64_t consumed_ns); + void OnKeepaliveRepeat(); + void OnSubmission(int64_t now_ns, int64_t consumed_ns, bool success); + + void OnReferenceSpaceChange(std::string_view space, bool pose_valid, bool effective_known, + double effective_in_ms); + + // Unconditional line (session description); not rate-limited. + void Info(std::string_view text); + + // Emits the summary when the window has lasted kWindowNs. Called from + // OnEndFrame, so any compositor cycle, repeated or not, flushes it. + void Tick(int64_t now_ns); + +private: + struct Samples { + std::vector values; + void Add(double ms); + void Clear() { values.clear(); } + }; + + void Event(std::string_view text); + void ClearWindow(int64_t now_ns); + void EmitSummary(int64_t now_ns); + + Sink sink_; + int64_t window_start_ns_ = 0; + bool session_info_requested_ = true; + + int64_t last_display_time_ = 0; + int64_t display_period_ = 0; + int64_t deadline_ns_ = 0; + int64_t begin_ns_ = 0; + int64_t last_submit_ns_ = 0; + int64_t published_ns_ = 0; + + bool tracking_known_ = false; + bool orientation_valid_ = false; + bool position_valid_ = false; + bool geometry_logged_ = false; + ViewGeometry geometry_{}; + + uint32_t cycles_ = 0; + uint32_t skipped_slots_ = 0; + uint32_t late_ = 0; + uint32_t layers_new_ = 0; + uint32_t layers_repeat_ = 0; + uint32_t empty_ = 0; + uint32_t discarded_ = 0; + uint32_t layer_rejected_ = 0; + uint32_t keepalive_ = 0; + uint32_t packet_unused_ = 0; + uint32_t packet_rejected_ = 0; + uint32_t submit_failed_ = 0; + uint32_t interp_skip_ = 0; + uint32_t immersive_ = 0; + uint32_t screen_ = 0; + uint32_t not_rendered_ = 0; + uint32_t no_orientation_ = 0; + uint32_t no_position_ = 0; + uint32_t events_ = 0; + uint32_t suppressed_ = 0; + + Samples wait_frame_ms_; + Samples open_ms_; + Samples margin_ms_; + Samples end_gap_ms_; + Samples end_call_ms_; + Samples acquire_ms_; + Samples release_ms_; + Samples game_wait_ms_; + Samples encode_ms_; +}; + +namespace detail { +inline std::atomic_bool g_enabled{false}; +inline std::atomic_int64_t g_packet_consumed_ns{0}; + +int64_t NowNs() noexcept; +void OnWaitFrame(int64_t wait_ns, int64_t display_time, int64_t display_period); +void OnBeginFrame(); +void OnEndFrame(int64_t submit_ns, int64_t call_ns); +void OnFrameBegun(bool immersive, bool should_render, bool views_valid, bool orientation_valid, + bool position_valid); +void OnViewGeometry(const ViewGeometry& geometry); +void OnSwapchainAcquire(int64_t ns); +void OnSwapchainRelease(int64_t ns); +void OnLayer(bool fresh); +void OnEmptyFrame(EmptyFrameReason reason); +void OnRetainedLayerDiscarded(DiscardReason reason); +void OnLayerRejected(RejectReason reason); +void OnInterpolationSkip(); +void OnPacketPublished(); +void OnPacketCanceled(); +void OnKeepaliveRepeat(); +void OnSubmission(bool success); +void OnReferenceSpaceChange(std::string_view space, bool pose_valid, int64_t change_time); +void OnSessionStarted(); +bool ConsumeSessionInfoRequest(); +void Info(std::string_view text); +} // namespace detail + +inline bool Enabled() noexcept { return detail::g_enabled.load(std::memory_order_relaxed); } + +// Live switch. Turning logging on starts a new window and re-describes the +// session on the next frame. +void SetEnabled(bool enabled) noexcept; + +// Where lines go; installed by the OpenXR integration. Set it only while the +// pacing thread is not running. +void SetLogSink(FrameDiagnostics::Sink sink); + +// Converts an XrTime to steady-clock nanoseconds, or returns 0. Set it only +// while the pacing thread is not running, and clear it before its runtime dies. +void SetDisplayTimeConverter(std::function converter); + +// Measures a span only when logging was on at its start. +class Stopwatch { +public: + Stopwatch() noexcept : start_ns_(Enabled() ? detail::NowNs() : 0) {} + int64_t StartNs() const noexcept { return start_ns_; } + // -1 when the stopwatch did not start. + int64_t ElapsedNs() const noexcept { return start_ns_ == 0 ? -1 : detail::NowNs() - start_ns_; } + +private: + int64_t start_ns_; +}; + +inline void OnWaitFrame(const Stopwatch& wait, int64_t display_time, int64_t display_period) { + if (const int64_t ns = wait.ElapsedNs(); ns >= 0 && Enabled()) detail::OnWaitFrame(ns, display_time, display_period); +} +inline void OnBeginFrame() { + if (Enabled()) detail::OnBeginFrame(); +} +inline void OnEndFrame(const Stopwatch& call) { + if (const int64_t ns = call.ElapsedNs(); ns >= 0 && Enabled()) detail::OnEndFrame(call.StartNs(), ns); +} +inline void OnFrameBegun(bool immersive, bool should_render, bool views_valid, bool orientation_valid, + bool position_valid) { + if (Enabled()) detail::OnFrameBegun(immersive, should_render, views_valid, orientation_valid, position_valid); +} +inline void OnSwapchainAcquire(const Stopwatch& acquire) { + if (const int64_t ns = acquire.ElapsedNs(); ns >= 0 && Enabled()) detail::OnSwapchainAcquire(ns); +} +inline void OnSwapchainRelease(const Stopwatch& release) { + if (const int64_t ns = release.ElapsedNs(); ns >= 0 && Enabled()) detail::OnSwapchainRelease(ns); +} +inline void OnLayer(bool fresh) { + if (Enabled()) detail::OnLayer(fresh); +} +inline void OnEmptyFrame(EmptyFrameReason reason) { + if (Enabled()) detail::OnEmptyFrame(reason); +} +inline void OnRetainedLayerDiscarded(DiscardReason reason) { + if (Enabled()) detail::OnRetainedLayerDiscarded(reason); +} +inline void OnLayerRejected(RejectReason reason) { + if (Enabled()) detail::OnLayerRejected(reason); +} +inline void OnInterpolationSkip() { + if (Enabled()) detail::OnInterpolationSkip(); +} +inline void OnPacketPublished() { + if (Enabled()) detail::OnPacketPublished(); +} +// Aurora's frame worker took the published packet. Any thread. +inline void NotePacketConsumed() { + if (Enabled()) detail::g_packet_consumed_ns.store(detail::NowNs(), std::memory_order_relaxed); +} +inline void OnPacketCanceled() { + if (Enabled()) detail::OnPacketCanceled(); +} +inline void OnKeepaliveRepeat() { + if (Enabled()) detail::OnKeepaliveRepeat(); +} +inline void OnSubmission(bool success) { + if (Enabled()) detail::OnSubmission(success); +} +inline void OnReferenceSpaceChange(std::string_view space, bool pose_valid, int64_t change_time) { + if (Enabled()) detail::OnReferenceSpaceChange(space, pose_valid, change_time); +} +inline void OnSessionStarted() { + if (Enabled()) detail::OnSessionStarted(); +} +inline void OnViewGeometry(const ViewGeometry& geometry) { + if (Enabled()) detail::OnViewGeometry(geometry); +} +// True once after logging starts or a session begins: describe the session. +inline bool ConsumeSessionInfoRequest() { + return Enabled() && detail::ConsumeSessionInfoRequest(); +} +inline void Info(std::string_view text) { + if (Enabled()) detail::Info(text); +} + +} // namespace mkw::vr::diagnostics diff --git a/runtime/src/log_export.cpp b/runtime/src/log_export.cpp new file mode 100644 index 0000000..cb79dd1 --- /dev/null +++ b/runtime/src/log_export.cpp @@ -0,0 +1,153 @@ +// SPDX-License-Identifier: GPL-3.0-or-later + +#include "log_export.h" + +#include +#include +#include +#include + +namespace log_export { +namespace { + +// UTF-8, like every narrow path string in the runtime. +std::string ExportPathText(const std::filesystem::path& path) { + const std::u8string text = path.u8string(); + return std::string(text.begin(), text.end()); +} + +std::tm ExportLocalTime(std::chrono::system_clock::time_point now) { + const std::time_t seconds = std::chrono::system_clock::to_time_t(now); + std::tm local{}; +#if defined(_WIN32) + localtime_s(&local, &seconds); +#else + localtime_r(&seconds, &local); +#endif + return local; +} + +std::string FormatExportTime(std::chrono::system_clock::time_point now, const char* format) { + const std::tm local = ExportLocalTime(now); + char buffer[64]; + const size_t length = std::strftime(buffer, sizeof(buffer), format, &local); + return std::string(buffer, length); +} + +bool CopyExportFile(const std::filesystem::path& source, const std::filesystem::path& destination, + std::string& error) { + std::ifstream input(source, std::ios::binary); + if (!input) { + error = "could not read " + ExportPathText(source); + return false; + } + std::ofstream output(destination, std::ios::binary | std::ios::trunc); + if (!output) { + error = "could not write " + ExportPathText(destination); + return false; + } + // A loop rather than `output << input.rdbuf()`, which flags an empty file + // as a failed insertion. + std::vector buffer(64 * 1024); + while (input) { + input.read(buffer.data(), static_cast(buffer.size())); + const std::streamsize count = input.gcount(); + if (count > 0) { + output.write(buffer.data(), count); + } + } + if (input.bad() || !output) { + error = "could not copy " + ExportPathText(source); + return false; + } + return true; +} + +} // namespace + +Result ExportLogs(const std::filesystem::path& logs_directory, const std::filesystem::path& config_file, + const std::filesystem::path& parent, std::string_view note, + std::chrono::system_clock::time_point now) { + Result result; + std::error_code ec; + if (!std::filesystem::is_directory(parent, ec)) { + result.error = "the chosen folder does not exist: " + ExportPathText(parent); + return result; + } + + const std::string base = std::string(kExportFolderPrefix) + FormatExportTime(now, "%Y%m%d-%H%M%S"); + std::filesystem::path destination = parent / base; + for (int suffix = 2; std::filesystem::exists(destination, ec); ++suffix) { + if (suffix > 99) { + result.error = "too many exports named " + base + " in " + ExportPathText(parent); + return result; + } + destination = parent / (base + "-" + std::to_string(suffix)); + } + if (!std::filesystem::create_directories(destination, ec)) { + result.error = "could not create " + ExportPathText(destination) + (ec ? ": " + ec.message() : ""); + return result; + } + result.destination = destination; + + const auto copy = [&](const std::filesystem::path& from, const std::filesystem::path& to) { + std::string error; + if (CopyExportFile(from, to, error)) { + ++result.files_copied; + } else { + ++result.files_failed; + if (result.error.empty()) { + result.error = std::move(error); + } + } + }; + + if (std::filesystem::is_directory(logs_directory, ec)) { + const std::filesystem::path logs_target = destination / "Logs"; + std::filesystem::create_directories(logs_target, ec); + // Choosing the Logs folder itself as the destination must not copy the + // export into itself. + const std::filesystem::path own_folder = std::filesystem::weakly_canonical(destination, ec); + std::filesystem::recursive_directory_iterator entry( + logs_directory, std::filesystem::directory_options::skip_permission_denied, ec); + for (; !ec && entry != std::filesystem::recursive_directory_iterator(); entry.increment(ec)) { + const std::filesystem::path target = logs_target / entry->path().lexically_relative(logs_directory); + std::error_code entry_ec; + if (entry->is_directory(entry_ec)) { + if (std::filesystem::weakly_canonical(entry->path(), entry_ec) == own_folder) { + entry.disable_recursion_pending(); + continue; + } + std::filesystem::create_directories(target, entry_ec); + continue; + } + if (!entry->is_regular_file(entry_ec)) { + continue; + } + std::filesystem::create_directories(target.parent_path(), entry_ec); + copy(entry->path(), target); + } + if (ec) { + ++result.files_failed; + if (result.error.empty()) { + result.error = "could not list " + ExportPathText(logs_directory) + ": " + ec.message(); + } + } + } + if (std::filesystem::is_regular_file(config_file, ec)) { + copy(config_file, destination / config_file.filename()); + } + + std::ofstream info(destination / "export-info.txt", std::ios::binary | std::ios::trunc); + info << "Exported " << FormatExportTime(now, "%Y-%m-%d %H:%M:%S") << " (local time)\n" << note; + if (!note.empty() && note.back() != '\n') { + info << '\n'; + } + + if (result.files_copied == 0 && result.files_failed == 0) { + result.error = "no logs or configuration were found to export"; + } + return result; +} + +} // namespace log_export diff --git a/runtime/src/settings_overlay.cpp b/runtime/src/settings_overlay.cpp index eb49d55..e9ee2d1 100644 --- a/runtime/src/settings_overlay.cpp +++ b/runtime/src/settings_overlay.cpp @@ -4,16 +4,20 @@ #include "controller_mapping_wizard.h" #include "input_bindings.h" #include "game_graphics_options.h" +#include "log_export.h" #include "music_attenuation.h" #include "runtime_config.h" #include "runtime_log.h" #include "vr/mkw_vr_first_person.h" #include "vr/mkw_vr_policy.h" +#include "vr/openxr_diagnostics.h" #include "vr/openxr_integration.h" #include "vr/openxr_wii_remote.h" #include "wii_remote_input.h" #include +#include +#include #include #include #include @@ -27,8 +31,11 @@ #include #include #include +#include #include #include +#include +#include #include #include #include @@ -37,6 +44,8 @@ #define WIN32_LEAN_AND_MEAN #include #include +#else +#include #endif #include @@ -126,6 +135,7 @@ int g_vrFrameInterpolationMode = [] { kVrInterpolationFps.begin()); }(); int g_vrFirstPersonHiddenModel = RuntimeConfigFile::VrFirstPersonHiddenModel(); +bool g_openxrDiagnosticsLogging = RuntimeConfigFile::DiagnosticsOpenXRLogging(false); // Config spellings and menu labels for the desktop mirror, index-matched to // AuroraStereoMirrorView so the combo selection converts to either directly. constexpr std::array kVrMirrorViewNames{"normal", "both", "left", "right", "none"}; @@ -1196,6 +1206,147 @@ void DrawVrSettings() { } } +// Export Logs. SDL shows the folder picker without blocking the game and calls +// back on a thread of its choosing (its own dialog thread on Windows), where the +// copy then runs; the menu only reads the outcome through this state. +struct LogExportState { + std::mutex mutex; + std::string note; + std::string message; + bool failed = false; +}; +LogExportState g_logExport; +std::atomic_bool g_logExportInProgress{false}; + +void SetLogExportMessage(std::string message, bool failed) { + std::lock_guard lock(g_logExport.mutex); + g_logExport.message = std::move(message); + g_logExport.failed = failed; +} + +// Captured on the click, so the export describes the moment the player asked. +std::string BuildLogExportNote() { +#if defined(_WIN32) + const unsigned long pid = ::GetCurrentProcessId(); +#else + const auto pid = static_cast(::getpid()); +#endif + std::ostringstream note; + note << "Exported by process " << pid << "; its run folder under Logs ends in _pid" << pid << ".\n" + << "OpenXR diagnostic logging: " << (g_openxrDiagnosticsLogging ? "on" : "off") << '\n' + << "OpenXR running: " << (mkw::vr::OpenXRIsRunning() ? "yes" : "no") << '\n'; + if (const auto xrError = mkw::vr::OpenXRLastError(); !xrError.empty()) { + note << "OpenXR last error: " << xrError << '\n'; + } + return note.str(); +} + +void SDLCALL OnLogExportFolderChosen(void*, const char* const* filelist, int) { + // SDL's C caller must never see an exception. + try { + if (filelist == nullptr) { + SetLogExportMessage(std::string("Could not open the folder picker: ") + SDL_GetError(), true); + } else if (filelist[0] == nullptr) { + SetLogExportMessage("Export canceled.", false); + } else { + std::string note; + { + std::lock_guard lock(g_logExport.mutex); + note = g_logExport.note; + } + SetLogExportMessage("Exporting...", false); + const auto result = log_export::ExportLogs( + RuntimeConfigFile::ApplicationDataDirectory() / "Logs", RuntimeConfigFile::ResolveConfigPath(), + RuntimeConfigFile::PathFromUtf8(filelist[0]), note, std::chrono::system_clock::now()); + const std::string destination = RuntimeConfigFile::PathToUtf8(result.destination); + if (result.Succeeded()) { + SetLogExportMessage("Exported " + std::to_string(result.files_copied) + " files to " + destination, + false); + } else if (!result.destination.empty()) { + SetLogExportMessage("Exported " + std::to_string(result.files_copied) + " files to " + destination + + ", but " + std::to_string(result.files_failed) + + " could not be copied: " + result.error, + true); + } else { + SetLogExportMessage("Export failed: " + result.error, true); + } + RT_LOG(RT_TAG_RUNTIME) << "Log export to " << destination << ": " << result.files_copied + << " file(s) copied, " << result.files_failed << " failed" + << (result.error.empty() ? "" : " (" + result.error + ")") << std::endl; + } + } catch (const std::exception& exception) { + SetLogExportMessage(std::string("Export failed: ") + exception.what(), true); + } catch (...) { + SetLogExportMessage("Export failed.", true); + } + g_logExportInProgress.store(false, std::memory_order_release); +} + +void StartLogExport() { + bool expected = false; + if (!g_logExportInProgress.compare_exchange_strong(expected, true, std::memory_order_acq_rel)) { + return; + } + { + std::lock_guard lock(g_logExport.mutex); + g_logExport.note = BuildLogExportNote(); + } + SetLogExportMessage("Choose the folder to export the logs into.", false); + // Parented to the game window so the picker opens in front of it. SDL may + // call back before returning if the dialog cannot be shown at all. + SDL_ShowOpenFolderDialog(&OnLogExportFolderChosen, nullptr, SDL_GetKeyboardFocus(), nullptr, false); +} + +void DrawDiagnosticsSettings() { + if (ImGui::Checkbox("OpenXR diagnostic logging", &g_openxrDiagnosticsLogging)) { + mkw::vr::diagnostics::SetEnabled(g_openxrDiagnosticsLogging); + RuntimeConfigFile::SetDiagnosticsOpenXRLogging(g_openxrDiagnosticsLogging); + } + if (ImGui::IsItemHovered()) { + ImGui::SetTooltip( + "Writes VR frame timing to console.log once per second: late, skipped, repeated and\n" + "empty (black) frames, how long each frame waited for the game and for rendering,\n" + "head-tracking loss, reference-space changes, and the headset's view layout.\n" + "Turn it on to report stutter or black frames in VR, and off again afterwards.\n" + "Off by default. Applies immediately and is remembered."); + } + ImGui::PushTextWrapPos(ImGui::GetCursorPosX() + 380.0f); + if (g_openxrDiagnosticsLogging && !mkw::vr::OpenXRIsRunning()) { + ImGui::TextDisabled("OpenXR is not running, so nothing is logged until a VR session starts."); + } + ImGui::PopTextWrapPos(); + + ImGui::Separator(); + const bool exporting = g_logExportInProgress.load(std::memory_order_acquire); + ImGui::BeginDisabled(exporting); + if (ImGui::Button("Export Logs")) { + StartLogExport(); + } + ImGui::EndDisabled(); + if (ImGui::IsItemHovered(ImGuiHoveredFlags_AllowWhenDisabled)) { + ImGui::SetTooltip( + "Choose a folder, and the logs of recent sessions (the last four days, this one\n" + "included) are copied into a new WiiCompiled-logs folder there, together with\n" + "Config.toml. Zip that folder to attach it to a bug report."); + } + std::string message; + bool failed = false; + { + std::lock_guard lock(g_logExport.mutex); + message = g_logExport.message; + failed = g_logExport.failed; + } + if (!message.empty()) { + ImGui::PushTextWrapPos(ImGui::GetCursorPosX() + 380.0f); + if (failed) { + ImGui::TextColored(ImVec4(1.0f, 0.45f, 0.35f, 1.0f), "%s", message.c_str()); + } else { + ImGui::TextDisabled("%s", message.c_str()); + } + ImGui::PopTextWrapPos(); + } +} + void DrawFpsOverlay() { AuroraPresentTiming presentTiming{}; aurora_get_present_timing(&presentTiming); @@ -1346,6 +1497,11 @@ void DrawTopBar() { ImGui::EndMenu(); } + if (ImGui::BeginMenu("Diagnostics")) { + DrawDiagnosticsSettings(); + ImGui::EndMenu(); + } + const float hideWidth = ImGui::CalcTextSize("Hide (F10)").x + ImGui::GetStyle().FramePadding.x * 2.0f; ImGui::SetCursorPosX(std::max(ImGui::GetCursorPosX(), ImGui::GetWindowWidth() - hideWidth - 8.0f)); if (ImGui::MenuItem("Hide (F10)")) { @@ -1446,6 +1602,7 @@ void InitializeRuntimeSettings() noexcept { ApplyVrHudVirtualScreen(); aurora_set_skip_unready_pipelines(g_skipUnreadyPipelines); mkw::vr::MkwVRFirstPersonApplyConfiguredSettings(); + mkw::vr::diagnostics::SetEnabled(g_openxrDiagnosticsLogging); g_strapInputAccepted.store(false, std::memory_order_relaxed); g_startupDismissFrame.store(UINT64_MAX, std::memory_order_relaxed); PADBlockInput(false); diff --git a/runtime/src/vr/openxr_d3d12.cpp b/runtime/src/vr/openxr_d3d12.cpp index 4063a78..73d5f93 100644 --- a/runtime/src/vr/openxr_d3d12.cpp +++ b/runtime/src/vr/openxr_d3d12.cpp @@ -9,6 +9,7 @@ #endif #include "vr/openxr_d3d12.h" +#include "vr/openxr_diagnostics.h" #include @@ -290,6 +291,7 @@ public: } std::array 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(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}; diff --git a/runtime/src/vr/openxr_diagnostics.cpp b/runtime/src/vr/openxr_diagnostics.cpp new file mode 100644 index 0000000..8c26788 --- /dev/null +++ b/runtime/src/vr/openxr_diagnostics.cpp @@ -0,0 +1,559 @@ +// SPDX-License-Identifier: GPL-3.0-or-later + +#include "vr/openxr_diagnostics.h" + +#include +#include +#include +#include +#include +#include +#include +#include + +namespace mkw::vr::diagnostics { +namespace { + +constexpr double kNanosecondsPerMillisecond = 1'000'000.0; + +double Milliseconds(int64_t nanoseconds) noexcept { + return static_cast(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(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& 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(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(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(slots - 1), Milliseconds(advance), + 1.0e9 / static_cast(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(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 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 converter) { + GlobalDiagnostics::Global().converter = std::move(converter); +} + +namespace detail { + +int64_t NowNs() noexcept { + return std::chrono::duration_cast( + 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 diff --git a/runtime/src/vr/openxr_integration.cpp b/runtime/src/vr/openxr_integration.cpp index 3d2b664..d0d4473 100644 --- a/runtime/src/vr/openxr_integration.cpp +++ b/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 #include @@ -23,6 +24,7 @@ #include #include #include +#include #include #include @@ -254,6 +256,64 @@ void ViewFromBase(const XrPosef& eye_pose, const std::array& 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, 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(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(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 { diff --git a/runtime/src/vr/openxr_runtime.cpp b/runtime/src/vr/openxr_runtime.cpp index 05626ca..db7caab 100644 --- a/runtime/src/vr/openxr_runtime.cpp +++ b/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 #include @@ -55,6 +56,19 @@ uint32_t ScaledDimension(uint32_t recommended, uint32_t maximum, float scale) { return static_cast(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(&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; diff --git a/runtime/src/vr/openxr_vulkan.cpp b/runtime/src/vr/openxr_vulkan.cpp index bba67ef..b9af2d0 100644 --- a/runtime/src/vr/openxr_vulkan.cpp +++ b/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 @@ -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 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}; diff --git a/runtime/tests/log_export_tests.cpp b/runtime/tests/log_export_tests.cpp new file mode 100644 index 0000000..1f9dcc0 --- /dev/null +++ b/runtime/tests/log_export_tests.cpp @@ -0,0 +1,113 @@ +// SPDX-License-Identifier: GPL-3.0-or-later +// F10 > Diagnostics > Export Logs against a synthetic application data folder. + +#include "log_export.h" + +#include +#include +#include +#include +#include +#include +#include + +namespace { + +namespace fs = std::filesystem; + +void RequireAt(bool condition, int line, const char* expression) { + if (!condition) { + std::cerr << "log_export_tests.cpp:" << line << ": requirement failed: " << expression << '\n'; + std::abort(); + } +} +#define Require(condition) RequireAt((condition), __LINE__, #condition) + +void Write(const fs::path& path, const std::string& text) { + fs::create_directories(path.parent_path()); + std::ofstream(path, std::ios::binary) << text; +} + +std::string Read(const fs::path& path) { + std::ifstream input(path, std::ios::binary); + return std::string(std::istreambuf_iterator(input), std::istreambuf_iterator()); +} + +size_t CountExports(const fs::path& parent) { + size_t count = 0; + for (const auto& entry : fs::directory_iterator(parent)) { + count += entry.path().filename().string().rfind(log_export::kExportFolderPrefix, 0) == 0 ? 1 : 0; + } + return count; +} + +} // namespace + +int main() { + const fs::path root = fs::temp_directory_path() / "wiicompiled_log_export_tests"; + fs::remove_all(root); + const fs::path data = root / "WiiCompiledOpenXRVR"; + const fs::path logs = data / "Logs"; + const fs::path config = data / "Config.toml"; + const fs::path target = root / "Chosen folder"; + fs::create_directories(target); + + Write(logs / "base_100_pid1" / "console.log", "[runtime] first run\n"); + Write(logs / "base_200_pid2" / "console.log", "[runtime] [xr-diag] 1.00s 72.0Hz cycles=72\n"); + Write(logs / "base_200_pid2" / "crash.txt", ""); + Write(config, "[vr]\nenabled = true\n"); + + // The running session's transcript is still open for writing while it is exported. + fs::create_directories(logs / "base_300_pid3"); + std::ofstream live(logs / "base_300_pid3" / "console.log", std::ios::binary); + Require(static_cast(live)); + live << "[runtime] live session\n"; + live.flush(); + + const auto now = std::chrono::system_clock::now(); + const auto result = log_export::ExportLogs(logs, config, target, "Exported by process 3.\n", now); + Require(result.Succeeded()); + Require(result.files_copied == 5); + Require(result.files_failed == 0); + Require(result.destination.parent_path() == target); + Require(result.destination.filename().string().rfind(log_export::kExportFolderPrefix, 0) == 0); + Require(Read(result.destination / "Logs" / "base_200_pid2" / "console.log") == + "[runtime] [xr-diag] 1.00s 72.0Hz cycles=72\n"); + Require(fs::exists(result.destination / "Logs" / "base_200_pid2" / "crash.txt")); + Require(fs::file_size(result.destination / "Logs" / "base_200_pid2" / "crash.txt") == 0); + Require(Read(result.destination / "Logs" / "base_300_pid3" / "console.log") == "[runtime] live session\n"); + Require(Read(result.destination / "Config.toml") == "[vr]\nenabled = true\n"); + const std::string info = Read(result.destination / "export-info.txt"); + Require(info.rfind("Exported ", 0) == 0); + Require(info.find("Exported by process 3.\n") != std::string::npos); + live.close(); + + // Exporting twice in the same second makes a second folder, not a merge. + const auto again = log_export::ExportLogs(logs, config, target, {}, now); + Require(again.Succeeded()); + Require(again.destination != result.destination); + Require(CountExports(target) == 2); + + // Choosing the Logs folder itself must not copy the export into itself. + const auto inside = log_export::ExportLogs(logs, config, logs, {}, now); + Require(inside.Succeeded()); + Require(inside.files_copied == 5); + Require(!fs::exists(inside.destination / "Logs" / inside.destination.filename())); + + // Missing sources: only the configuration exists. + const auto config_only = log_export::ExportLogs(root / "missing Logs", config, target, {}, now); + Require(config_only.Succeeded()); + Require(config_only.files_copied == 1); + + const auto nothing = log_export::ExportLogs(root / "missing Logs", root / "missing.toml", target, {}, now); + Require(!nothing.Succeeded()); + Require(!nothing.destination.empty()); + Require(!nothing.error.empty()); + + const auto bad_parent = log_export::ExportLogs(logs, config, root / "does not exist", {}, now); + Require(!bad_parent.Succeeded()); + Require(bad_parent.destination.empty()); + + fs::remove_all(root); + std::cout << "Log export tests passed\n"; +} diff --git a/runtime/tests/openxr_diagnostics_tests.cpp b/runtime/tests/openxr_diagnostics_tests.cpp new file mode 100644 index 0000000..94e0129 --- /dev/null +++ b/runtime/tests/openxr_diagnostics_tests.cpp @@ -0,0 +1,291 @@ +// SPDX-License-Identifier: GPL-3.0-or-later +// Headless checks for the F10 > Diagnostics OpenXR logging: the collector's +// window accounting, event classification and rate limit, driven with a +// synthetic clock, plus the global switch and its Config.toml key. + +#include "vr/openxr_diagnostics.h" +#include "runtime_config.h" + +#include +#include +#include +#include +#include + +namespace { + +using namespace mkw::vr::diagnostics; + +void RequireAt(bool condition, int line, const char* expression) { + if (!condition) { + std::cerr << "openxr_diagnostics_tests.cpp:" << line << ": requirement failed: " << expression << '\n'; + std::abort(); + } +} +#define Require(condition) RequireAt((condition), __LINE__, #condition) + +constexpr int64_t kMs = 1'000'000; +constexpr int64_t kPeriod72Hz = 13'888'889; + +struct Capture { + std::vector lines; + FrameDiagnostics::Sink Sink() { + return [this](std::string_view line) { lines.emplace_back(line); }; + } + size_t Count(std::string_view needle) const { + size_t count = 0; + for (const auto& line : lines) { + count += line.find(needle) != std::string::npos ? 1 : 0; + } + return count; + } + const std::string& Summary() const { + for (auto it = lines.rbegin(); it != lines.rend(); ++it) { + if (it->find("cycles=") != std::string::npos) { + return *it; + } + } + static const std::string none; + return none; + } +}; + +// One compositor cycle on a 72 Hz grid: waits 1 ms, is begun, and ends +// `open_ns` later, `margin_ns` before its display deadline. +void Cycle(FrameDiagnostics& diagnostics, int64_t& now, int64_t& display_time, int64_t open_ns, int64_t margin_ns, + int64_t slots = 1) { + display_time += kPeriod72Hz * slots; + now += kMs; + const int64_t submit = now + open_ns; + diagnostics.OnWaitFrame(now, kMs, display_time, kPeriod72Hz, submit + margin_ns); + diagnostics.OnBeginFrame(now); + diagnostics.OnEndFrame(submit, kMs / 2); + now = submit + kMs / 2; +} + +void TestSteadyWindow() { + Capture capture; + FrameDiagnostics diagnostics(capture.Sink()); + int64_t now = 5'000 * kMs; + int64_t display_time = 1'000'000 * kMs; + diagnostics.Reset(now); + Require(diagnostics.ConsumeSessionInfoRequest()); + Require(!diagnostics.ConsumeSessionInfoRequest()); + const int64_t window_start = now; + for (int frame = 0; frame < 72; ++frame) { + diagnostics.OnFrameBegun(true, true, true, true, true); + diagnostics.OnLayer(true); + Cycle(diagnostics, now, display_time, 12 * kMs, 4 * kMs); + } + // 72 cycles of 13.5 ms fall just short of the window; nothing is emitted early. + Require(capture.lines.empty()); + diagnostics.Tick(window_start + FrameDiagnostics::kWindowNs); + const std::string& summary = capture.Summary(); + Require(!summary.empty()); + Require(summary.rfind("[xr-diag] ", 0) == 0); + Require(summary.find("72.0Hz") != std::string::npos); + Require(summary.find("skipped-slots=0 late=0") != std::string::npos); + Require(summary.find("cycles=72 ") != std::string::npos); + Require(summary.find("layers new=72 repeat=0 empty=0") != std::string::npos); + Require(summary.find("end-margin=4.0/4.0") != std::string::npos); + Require(summary.find("open=12.0/12.0") != std::string::npos); + Require(summary.find("suppressed=0") != std::string::npos); + // A steady run produces no event lines, only the summary. + Require(capture.lines.size() == 1); +} + +void TestLateSkippedAndStalledFrames() { + Capture capture; + FrameDiagnostics diagnostics(capture.Sink()); + int64_t now = 1'000 * kMs; + int64_t display_time = 500'000 * kMs; + diagnostics.Reset(now); + Cycle(diagnostics, now, display_time, 5 * kMs, 3 * kMs); + // Ends 2 ms after its display time, two slots after the previous frame. + Cycle(diagnostics, now, display_time, 20 * kMs, -2 * kMs, 3); + Require(capture.Count("late frame: xrEndFrame came 2.0 ms after") == 1); + Require(capture.Count("compositor skipped 2 display slot(s)") == 1); + // A 60 ms gap between xrEndFrame calls is a stall at 72 Hz. + Cycle(diagnostics, now, display_time, 60 * kMs, 1 * kMs); + Require(capture.Count("stall:") == 1); + now += 2'000 * kMs; + diagnostics.Tick(now); + const std::string& summary = capture.Summary(); + Require(summary.find("cycles=3 skipped-slots=2 late=1") != std::string::npos); +} + +void TestEventsAreRateLimited() { + Capture capture; + FrameDiagnostics diagnostics(capture.Sink()); + int64_t now = 1'000 * kMs; + diagnostics.Reset(now); + for (int frame = 0; frame < 20; ++frame) { + diagnostics.OnEmptyFrame(EmptyFrameReason::NoRetainedLayer); + } + Require(capture.Count("empty frame submitted (no layers): no completed layer is retained") == + FrameDiagnostics::kMaxEventsPerWindow); + now += 1'001 * kMs; + diagnostics.Tick(now); + Require(capture.Summary().find("empty=20") != std::string::npos); + Require(capture.Summary().find("suppressed=12") != std::string::npos); + // The next window has a fresh budget. + diagnostics.OnRetainedLayerDiscarded(DiscardReason::ReferenceSpaceChanged); + Require(capture.Count("retained layer discarded: the reference space changed") == 1); +} + +void TestTrackingEdgesAndRejections() { + Capture capture; + FrameDiagnostics diagnostics(capture.Sink()); + diagnostics.Reset(1); + diagnostics.OnFrameBegun(true, true, true, true, true); + diagnostics.OnFrameBegun(true, true, true, true, false); + diagnostics.OnFrameBegun(true, true, true, true, false); + diagnostics.OnFrameBegun(true, true, true, true, true); + // Views are not located when the runtime does not want rendering. + diagnostics.OnFrameBegun(false, false, false, false, false); + Require(capture.Count("tracking: head position lost") == 1); + Require(capture.Count("tracking: head position regained") == 1); + Require(capture.Count("orientation") == 0); + + Require(ClassifyRejectedLayer(false, false, false) == RejectReason::ReleaseFailed); + Require(ClassifyRejectedLayer(true, false, true) == RejectReason::ShouldRenderOff); + Require(ClassifyRejectedLayer(true, true, false) == RejectReason::ViewsInvalid); + Require(ClassifyRejectedLayer(true, true, true) == RejectReason::PositionInvalid); + diagnostics.OnLayerRejected(RejectReason::PositionInvalid); + Require(capture.Count("rendered layer not submitted: the head position was not valid") == 1); + + diagnostics.Tick(2'000 * kMs); + const std::string& summary = capture.Summary(); + Require(summary.find("immersive=4 screen=1 not-rendered=1") != std::string::npos); + Require(summary.find("no-orientation=0 no-position=2") != std::string::npos); + Require(summary.find("layer-rejected=1") != std::string::npos); +} + +void TestPacketAccounting() { + Capture capture; + FrameDiagnostics diagnostics(capture.Sink()); + int64_t now = 10'000 * kMs; + diagnostics.Reset(now); + + diagnostics.OnPacketPublished(now); + diagnostics.OnSubmission(now + 18 * kMs, now + 15 * kMs, true); + + diagnostics.OnPacketPublished(now + 20 * kMs); + diagnostics.OnPacketCanceled(0); + Require(capture.Count("no game frame picked it up within 50 ms") == 1); + + diagnostics.OnPacketPublished(now + 80 * kMs); + diagnostics.OnPacketCanceled(now + 90 * kMs); + Require(capture.Count("Aurora picked it up but rendered that frame without it") == 1); + + diagnostics.OnPacketPublished(now + 200 * kMs); + diagnostics.OnSubmission(now + 210 * kMs, now + 205 * kMs, false); + Require(capture.Count("stereo submission failed") == 1); + + diagnostics.Tick(now + 1'500 * kMs); + const std::string& summary = capture.Summary(); + Require(summary.find("packet-unused=1 packet-rejected=1 submit-failed=1") != std::string::npos); + // Two submissions: pickup 15 and 5 ms, render 3 and 5 ms. + Require(summary.find("pickup=15.0/15.0") != std::string::npos); + Require(summary.find("render=5.0/5.0") != std::string::npos); +} + +void TestViewGeometry() { + Capture capture; + FrameDiagnostics diagnostics(capture.Sink()); + diagnostics.Reset(1); + ViewGeometry pimax{}; + pimax.fov_degrees = {{{-60.0f, 45.0f, 50.0f, -50.0f}, {-45.0f, 60.0f, 50.0f, -50.0f}}}; + pimax.cant_degrees = 20.0f; + pimax.ipd_millimeters = 64.0f; + pimax.width = {4834, 4834}; + pimax.height = {4056, 4056}; + diagnostics.OnViewGeometry(pimax); + Require(capture.Count("view geometry: swapchains 4834x4056 / 4834x4056") == 1); + Require(capture.Count("eye cant 20.0 deg (canted displays)") == 1); + Require(capture.Count("ipd 64.0 mm") == 1); + // Tracking noise below the tolerance is not re-logged. + pimax.ipd_millimeters = 64.2f; + pimax.cant_degrees = 20.1f; + diagnostics.OnViewGeometry(pimax); + Require(capture.Count("view geometry") == 1); + // Switching the headset to parallel projections is. + pimax.cant_degrees = 0.0f; + diagnostics.OnViewGeometry(pimax); + Require(capture.Count("view geometry") == 2); + Require(capture.Count("(parallel)") == 1); + // Geometry and session descriptions are never rate-limited away. + for (int event = 0; event < 20; ++event) { + diagnostics.OnEmptyFrame(EmptyFrameReason::ShouldRenderOff); + } + diagnostics.OnReferenceSpaceChange("LOCAL", true, true, 12.5); + Require(capture.Count("reference space change pending: LOCAL, previous pose valid, takes effect in 12.5 ms") == 1); + diagnostics.OnReferenceSpaceChange("STAGE", false, false, 0.0); + Require(capture.Count("reference space change pending: STAGE, previous pose not valid") == 1); +} + +void TestResetStartsANewSession() { + Capture capture; + FrameDiagnostics diagnostics(capture.Sink()); + int64_t now = 1'000 * kMs; + int64_t display_time = 10'000 * kMs; + diagnostics.Reset(now); + Require(diagnostics.ConsumeSessionInfoRequest()); + Cycle(diagnostics, now, display_time, 5 * kMs, 1 * kMs); + diagnostics.Reset(now); + Require(diagnostics.ConsumeSessionInfoRequest()); + // A new session's display clock must not read as thousands of skipped slots. + display_time = 5 * kMs; + Cycle(diagnostics, now, display_time, 5 * kMs, 1 * kMs); + Require(capture.Count("skipped") == 0); + Require(capture.Count("stall") == 0); +} + +void TestGlobalSwitchAndConfig() { + std::vector lines; + SetLogSink([&](std::string_view line) { lines.emplace_back(line); }); + Require(!Enabled()); + { + const Stopwatch stopwatch; + Require(stopwatch.ElapsedNs() == -1); + } + OnEmptyFrame(EmptyFrameReason::NoRetainedLayer); + Require(lines.empty()); + + SetEnabled(true); + Require(Enabled()); + Require(lines.size() == 1 && lines[0] == "[xr-diag] logging enabled"); + { + const Stopwatch stopwatch; + Require(stopwatch.ElapsedNs() >= 0); + } + Require(ConsumeSessionInfoRequest()); + Require(!ConsumeSessionInfoRequest()); + SetEnabled(true); + Require(lines.size() == 1); + SetEnabled(false); + Require(lines.back() == "[xr-diag] logging disabled"); + Require(!ConsumeSessionInfoRequest()); + SetLogSink({}); + + std::istringstream missing("[vr]\nenabled = true\n"); + Require(!RuntimeConfigFile::ParseConfig(missing).diagnosticsOpenXRLogging.has_value()); + std::istringstream on("[diagnostics]\nopenxr_logging = true\n"); + Require(RuntimeConfigFile::ParseConfig(on).diagnosticsOpenXRLogging == true); + std::istringstream off("[diagnostics]\nopenxr_logging = false\n"); + Require(RuntimeConfigFile::ParseConfig(off).diagnosticsOpenXRLogging == false); +} + +} // namespace + +int main() { + TestSteadyWindow(); + TestLateSkippedAndStalledFrames(); + TestEventsAreRateLimited(); + TestTrackingEdgesAndRejections(); + TestPacketAccounting(); + TestViewGeometry(); + TestResetStartsANewSession(); + TestGlobalSwitchAndConfig(); + std::cout << "OpenXR diagnostics tests passed\n"; +}