From d4dc5af3be1e5022b0bcb91184bf944e6be5ea08 Mon Sep 17 00:00:00 2001 From: Takoroka <137927095+Takoroka@users.noreply.github.com> Date: Wed, 28 Oct 2026 04:56:14 -0400 Subject: [PATCH] nx2: frame-locked input replay and quieter logs EDEN_NX2_KEY_RECORD records keyboard transitions as "f:code" against a global count of guest presents; EDEN_NX2_KEY_SCRIPT replays them on the same frames (or by seconds, as before), so a played session reproduces exactly. Debug aids: the PC/LR/SP of the first unmapped reads, NSO load addresses, EDEN_NX2_IPC_SUMMARY (request counts every 5 s), EDEN_NX2_FORCE_LOD0. Unmapped-access logging is rate limited and the per-draw/semaphore spam is demoted, so long sessions stay under the log size cap. --- src/core/arm/dynarmic/arm_dynarmic_64.cpp | 20 +++++-- src/core/core.cpp | 2 + src/core/core.h | 4 ++ src/core/hle/service/nx2_gsv.h | 1 + src/core/hle/service/service.cpp | 57 +++++++++++++++++++ src/core/loader/nso.cpp | 1 + src/core/memory.cpp | 14 ++++- src/core/memory.h | 3 + src/video_core/engines/puller.cpp | 4 +- .../renderer_vulkan/vk_rasterizer.cpp | 2 +- .../renderer_vulkan/vk_texture_cache.cpp | 5 ++ src/yuzu_cmd/emu_window/emu_window_sdl3.cpp | 23 ++++++++ src/yuzu_cmd/yuzu.cpp | 26 ++++++--- 13 files changed, 145 insertions(+), 17 deletions(-) diff --git a/src/core/arm/dynarmic/arm_dynarmic_64.cpp b/src/core/arm/dynarmic/arm_dynarmic_64.cpp index 894857a86d..c2bb05afba 100644 --- a/src/core/arm/dynarmic/arm_dynarmic_64.cpp +++ b/src/core/arm/dynarmic/arm_dynarmic_64.cpp @@ -4,6 +4,7 @@ // SPDX-FileCopyrightText: Copyright 2018 yuzu Emulator Project // SPDX-License-Identifier: GPL-2.0-or-later +#include #include "common/settings.h" #include "core/arm/dynarmic/arm_dynarmic.h" #include "core/arm/dynarmic/arm_dynarmic_64.h" @@ -24,13 +25,24 @@ DynarmicCallbacks64::DynarmicCallbacks64(ArmDynarmic64& parent, Kernel::KProcess u64 DynarmicCallbacks64::MemoryRead(u64 vaddr, size_t size) { CheckMemoryAccess(vaddr, size, Kernel::DebugWatchpointType::Read); + u64 value{}; switch (size) { - case sizeof(u64): return m_memory.Read64(vaddr); - case sizeof(u32): return m_memory.Read32(vaddr); - case sizeof(u16): return m_memory.Read16(vaddr); - case sizeof(u8): return m_memory.Read8(vaddr); + case sizeof(u64): value = m_memory.Read64(vaddr); break; + case sizeof(u32): value = m_memory.Read32(vaddr); break; + case sizeof(u16): value = m_memory.Read16(vaddr); break; + case sizeof(u8): value = m_memory.Read8(vaddr); break; default: UNREACHABLE(); } + // With memory aborts ignored the guest keeps running on zeros: say where it read from. + if (auto& unmapped = Core::Memory::UnmappedReadFlag(); unmapped != 0) { + unmapped = 0; + static std::atomic logged{}; + if (logged.fetch_add(1) < 32) { + LOG_ERROR(Core_ARM, "Unmapped read {:#x} ({} bytes) at pc {:#x} lr {:#x} sp {:#x}", vaddr, size, + m_parent.m_jit->GetPC(), m_parent.m_jit->GetRegister(30), m_parent.m_jit->GetSP()); + } + } + return value; } Dynarmic::A64::Vector DynarmicCallbacks64::MemoryRead128(u64 vaddr) { CheckMemoryAccess(vaddr, 16, Kernel::DebugWatchpointType::Read); diff --git a/src/core/core.cpp b/src/core/core.cpp index 06543b0833..eee91ef4fc 100644 --- a/src/core/core.cpp +++ b/src/core/core.cpp @@ -68,6 +68,8 @@ namespace Core { +std::atomic g_nx2_present_count{}; + FileSys::VirtualFile GetGameFileFromPath(const FileSys::VirtualFilesystem& vfs, const std::string& path) { // To account for split 00+01+etc files. diff --git a/src/core/core.h b/src/core/core.h index d88ed64151..0276679d76 100644 --- a/src/core/core.h +++ b/src/core/core.h @@ -6,6 +6,7 @@ #pragma once +#include #include #include #include @@ -115,6 +116,9 @@ class RenderdocAPI; namespace Core { +/// Frames the guest has presented (Switch 2 vi2 present calls); input replay is locked to it. +extern std::atomic g_nx2_present_count; + class CpuManager; class Debugger; class DeviceMemory; diff --git a/src/core/hle/service/nx2_gsv.h b/src/core/hle/service/nx2_gsv.h index 89f3a9fd50..302c5a41a8 100644 --- a/src/core/hle/service/nx2_gsv.h +++ b/src/core/hle/service/nx2_gsv.h @@ -564,6 +564,7 @@ private: void PresentClientBuffer(HLERequestContext& ctx) { const auto* w = ctx.CommandBuffer(); ++m_presents; + Core::g_nx2_present_count.fetch_add(1, std::memory_order_relaxed); if (m_presents <= 4 || (m_presents % 600) == 0) { LOG_INFO(Service, "nx2:vi2 229 present #{} token={:#x} slot={} image={}", m_presents, u64{w[2]} | (u64{w[3]} << 32), w[4], w[5]); diff --git a/src/core/hle/service/service.cpp b/src/core/hle/service/service.cpp index 931de1c3ef..df929e8193 100644 --- a/src/core/hle/service/service.cpp +++ b/src/core/hle/service/service.cpp @@ -4,6 +4,13 @@ // SPDX-FileCopyrightText: Copyright 2018 yuzu Emulator Project // SPDX-License-Identifier: GPL-2.0-or-later +#include "common/scope_exit.h" +#include +#include +#include +#include +#include +#include #include #include #include "common/assert.h" @@ -125,9 +132,59 @@ void ServiceFrameworkBase::InvokeRequestTipc(HLERequestContext& ctx) { handler_invoker(this, info->handler_callback, ctx); } +namespace { +// EDEN_NX2_IPC_SUMMARY: every 5 s, log how often each service command ran and with which result +// since the last summary (finds a game polling something that never becomes ready). +void CountRequest(const std::string& service, u32 command, u32 type, u32 result) { + static const bool enabled = std::getenv("EDEN_NX2_IPC_SUMMARY") != nullptr; + if (!enabled) { + return; + } + static std::mutex mutex; + static std::map, u32> counts; + static auto last = std::chrono::steady_clock::now(); + std::scoped_lock lock{mutex}; + ++counts[{service, command, type, result}]; + const auto now = std::chrono::steady_clock::now(); + if (now - last < std::chrono::seconds{5}) { + return; + } + last = now; + std::vector> lines; + for (const auto& [key, count] : counts) { + lines.emplace_back(count, fmt::format("{}::{}{} -> {:#x}", std::get<0>(key), std::get<1>(key), + std::get<2>(key) >= 16 ? " (tipc)" : "", + std::get<3>(key))); + } + std::sort(lines.begin(), lines.end(), [](const auto& a, const auto& b) { return a.first > b.first; }); + std::string text; + for (size_t i = 0; i < std::min(lines.size(), 24); ++i) { + text += fmt::format(" | {}x {}", lines[i].first, lines[i].second); + } + LOG_INFO(Service, "ipc summary ({} kinds){}", lines.size(), text); + counts.clear(); +} +} // Anonymous namespace + Result ServiceFrameworkBase::HandleSyncRequest(Kernel::KServerSession& session, HLERequestContext& ctx) { const auto guard = LockService(); + SCOPE_EXIT { + const auto* cmd_buf = ctx.CommandBuffer(); + u32 result_word = 0; + const u32 type = static_cast(ctx.GetCommandType()); + if (type >= 16) { + result_word = cmd_buf[2]; + } else { + for (int i = 0; i < 12; ++i) { + if (cmd_buf[i] == 0x4F434653) { // "SFCO" + result_word = cmd_buf[i + 2]; + break; + } + } + } + CountRequest(service_name, ctx.GetCommand(), type, result_word); + }; Result result = ResultSuccess; diff --git a/src/core/loader/nso.cpp b/src/core/loader/nso.cpp index ea1d1c9ecd..7e3b9a54c2 100644 --- a/src/core/loader/nso.cpp +++ b/src/core/loader/nso.cpp @@ -247,6 +247,7 @@ std::optional AppLoader_NSO::LoadModule(Kernel::KProcess& process, Core:: } // Load codeset for current process + LOG_INFO(Loader, "Module {} loaded at {:#x} (size {:#x})", nso_file.GetName(), load_base, image_size); process.LoadModule(system.Kernel(), std::move(codeset), load_base); return load_base + image_size; } diff --git a/src/core/memory.cpp b/src/core/memory.cpp index eabc6dfccb..6e0ab0ee6d 100644 --- a/src/core/memory.cpp +++ b/src/core/memory.cpp @@ -5,6 +5,7 @@ // SPDX-FileCopyrightText: 2018 yuzu Emulator Project // SPDX-License-Identifier: GPL-2.0-or-later +#include #include #include #include @@ -36,6 +37,11 @@ namespace Core::Memory { +u32& UnmappedReadFlag() { + thread_local u32 flag{}; + return flag; +} + static inline bool AddressSpaceContains(const Common::PageTable& table, const Common::ProcessAddress addr, const std::size_t size) { const Common::ProcessAddress max_addr = 1ULL << table.GetAddressSpaceBits(); return addr + size >= addr && addr + size <= max_addr; @@ -623,7 +629,13 @@ struct Memory::Impl { inline T Read(Common::ProcessAddress vaddr) noexcept requires(std::is_trivially_copyable_v) { const u64 addr = GetInteger(vaddr); if (auto const ptr = GetPointerImpl(addr, [addr]() { - LOG_ERROR(HW_Memory, "Unmapped Read{} @ {:#016x}", sizeof(T) * 8, addr); + // A guest spinning on a bad pointer reads unmapped memory tens of thousands of times + // a second: keep the first ones and then a sample. + static std::atomic unmapped_reads{}; + if (const u64 count = unmapped_reads.fetch_add(1); count < 1000 || count % 100000 == 0) { + LOG_ERROR(HW_Memory, "Unmapped Read{} @ {:#016x} (#{})", sizeof(T) * 8, addr, count); + } + ++UnmappedReadFlag(); }, [&]() { HandleRasterizerDownload(addr, sizeof(T)); }); ptr) [[likely]] { diff --git a/src/core/memory.h b/src/core/memory.h index 7167efbb84..204b7514f6 100644 --- a/src/core/memory.h +++ b/src/core/memory.h @@ -38,6 +38,9 @@ class MemoryManager; namespace Core::Memory { +/// Counts unmapped reads on this host thread since the CPU callbacks last checked (debug aid). +u32& UnmappedReadFlag(); + /** * Page size used by the ARM architecture. This is the smallest granularity with which memory can * be mapped. diff --git a/src/video_core/engines/puller.cpp b/src/video_core/engines/puller.cpp index f4aaed6036..54abf790d2 100644 --- a/src/video_core/engines/puller.cpp +++ b/src/video_core/engines/puller.cpp @@ -335,7 +335,7 @@ void Puller::CallPullerMethod(DmaPusher& dma_pusher, const MethodCall& method_ca break; } case BufferMethods::MemOpA: { - LOG_ERROR(HW_GPU, "Memory Operation A"); + LOG_TRACE(HW_GPU, "Memory Operation A"); break; } case BufferMethods::MemOpB: { @@ -345,7 +345,7 @@ void Puller::CallPullerMethod(DmaPusher& dma_pusher, const MethodCall& method_ca } case BufferMethods::MemOpC: case BufferMethods::MemOpD: { - LOG_ERROR(HW_GPU, "Memory Operation C,D"); + LOG_TRACE(HW_GPU, "Memory Operation C,D"); break; } case BufferMethods::SemaphoreAcquire: { diff --git a/src/video_core/renderer_vulkan/vk_rasterizer.cpp b/src/video_core/renderer_vulkan/vk_rasterizer.cpp index 1b05716653..1b0493c4b5 100644 --- a/src/video_core/renderer_vulkan/vk_rasterizer.cpp +++ b/src/video_core/renderer_vulkan/vk_rasterizer.cpp @@ -250,7 +250,7 @@ void RasterizerVulkan::PrepareDraw(bool is_indexed, Func&& draw_func) { auto& native = maxwell3d->GetNativeMacroEngine(); if (native.native_turing && !submitted) { native.native_execution_failed = true; - LOG_ERROR(HW_GPU, "Native graphics draw failed; refusing submission completion"); + LOG_DEBUG(HW_GPU, "Native graphics draw failed; refusing submission completion"); } }; FlushWork(); diff --git a/src/video_core/renderer_vulkan/vk_texture_cache.cpp b/src/video_core/renderer_vulkan/vk_texture_cache.cpp index 29afaac01b..312617475d 100644 --- a/src/video_core/renderer_vulkan/vk_texture_cache.cpp +++ b/src/video_core/renderer_vulkan/vk_texture_cache.cpp @@ -2826,6 +2826,11 @@ Sampler::Sampler(TextureCacheRuntime& runtime, const Tegra::Texture::TSCEntry& t if (tsc.mipmap_filter != TextureMipmapFilter::None) { min_lod = tsc.MinLod(); max_lod = tsc.MaxLod(); + // EDEN_NX2_FORCE_LOD0: sample only the top mip level (debug aid for mip layout problems). + if (static const bool force_lod0 = std::getenv("EDEN_NX2_FORCE_LOD0") != nullptr; force_lod0) { + min_lod = 0.0f; + max_lod = 0.25f; + } } base_ci = VkSamplerCreateInfo{ .sType = VK_STRUCTURE_TYPE_SAMPLER_CREATE_INFO, diff --git a/src/yuzu_cmd/emu_window/emu_window_sdl3.cpp b/src/yuzu_cmd/emu_window/emu_window_sdl3.cpp index f2026e9722..d62acb36cd 100644 --- a/src/yuzu_cmd/emu_window/emu_window_sdl3.cpp +++ b/src/yuzu_cmd/emu_window/emu_window_sdl3.cpp @@ -4,6 +4,10 @@ // SPDX-FileCopyrightText: 2016 Citra Emulator Project // SPDX-License-Identifier: GPL-2.0-or-later +#include +#include +#include +#include #include #include #ifdef __EMSCRIPTEN__ @@ -118,7 +122,26 @@ void EmuWindow_SDL3::OnFingerUp() { input_subsystem->GetTouchScreen()->ReleaseAllTouch(); } +// Seconds since the first frame; shared by the key script (yuzu.cpp) and key recording. +double Nx2KeyClockSeconds() { + static const auto begin = std::chrono::steady_clock::now(); + return std::chrono::duration(std::chrono::steady_clock::now() - begin).count(); +} + void EmuWindow_SDL3::OnKeyEvent(int key, u8 state) { + // EDEN_NX2_KEY_RECORD=: append each press/release ("seconds:code", "seconds:-code"). + static std::FILE* const record = [] { + const char* path = std::getenv("EDEN_NX2_KEY_RECORD"); + return path ? std::fopen(path, "w") : nullptr; + }(); + static std::array held{}; + if (record && key >= 0 && key < static_cast(held.size()) && held[key] != (state != 0)) { + held[key] = state != 0; + std::fprintf(record, "f%llu:%s%d,", + static_cast(Core::g_nx2_present_count.load()), + state != 0 ? "" : "-", key); + std::fflush(record); + } if (state != 0) { input_subsystem->GetKeyboard()->PressKey(static_cast(key)); } else { diff --git a/src/yuzu_cmd/yuzu.cpp b/src/yuzu_cmd/yuzu.cpp index b46534ec9d..96146abec3 100644 --- a/src/yuzu_cmd/yuzu.cpp +++ b/src/yuzu_cmd/yuzu.cpp @@ -333,9 +333,12 @@ extern "C" SDL_AppResult SDL_AppInit(void **appstate, int argc, char **argv) { } // EDEN_NX2_KEY_SCRIPT="seconds:code,seconds:-code,...": press (code) or release (-code) keyboard // keys, by SDL scancode, that many seconds after start. Lets hidden test runs drive menus. +double Nx2KeyClockSeconds(); // emu_window_sdl3.cpp + static void RunKeyScript(InputCommon::InputSubsystem& input_subsystem) { struct KeyEvent { - double seconds; + double seconds; // when frame is 0 + u64 frame; // "f:code": after that many presents int code; }; static const std::vector script = [] { @@ -347,22 +350,27 @@ static void RunKeyScript(InputCommon::InputSubsystem& input_subsystem) { const size_t end = std::min(list.find(',', start), list.size()); const std::string item = list.substr(start, end - start); if (const size_t colon = item.find(':'); colon != std::string::npos) { - events.push_back({std::stod(item.substr(0, colon)), - std::stoi(item.substr(colon + 1))}); + const std::string when = item.substr(0, colon); + const int code = std::stoi(item.substr(colon + 1)); + if (!when.empty() && when[0] == 'f') { + events.push_back({0.0, std::stoull(when.substr(1)), code}); + } else { + events.push_back({std::stod(when), 0, code}); + } } start = end + 1; } } return events; }(); - static const auto begin = std::chrono::steady_clock::now(); static size_t next = 0; - const double elapsed = - std::chrono::duration(std::chrono::steady_clock::now() - begin).count(); - while (next < script.size() && script[next].seconds <= elapsed) { + const double elapsed = Nx2KeyClockSeconds(); + const u64 frame = Core::g_nx2_present_count.load(); + while (next < script.size() && (script[next].frame != 0 ? script[next].frame <= frame + : script[next].seconds <= elapsed)) { const int code = script[next].code; - LOG_INFO(Frontend, "Key script: {} key {} at {:.1f} s", code < 0 ? "release" : "press", - code < 0 ? -code : code, elapsed); + LOG_INFO(Frontend, "Key script: {} key {} at {:.1f} s (frame {})", + code < 0 ? "release" : "press", code < 0 ? -code : code, elapsed, frame); if (code < 0) { input_subsystem.GetKeyboard()->ReleaseKey(static_cast(-code)); } else {