diff --git a/HANDOFF-crash-oracle-2026-07-16.md b/HANDOFF-crash-oracle-2026-07-16.md new file mode 100644 index 000000000..82d939403 --- /dev/null +++ b/HANDOFF-crash-oracle-2026-07-16.md @@ -0,0 +1,93 @@ +# HANDOFF — Ready-Room crash: NEW ORACLE says it's OUR code, not the game (2026-07-16) + +## TL;DR +The mid-game **crash** (guest `std::out_of_range` from the cache-manager flush, seen in the +**Ready Room** after a mission) is **introduced by our own changes**, not by the game and not by the +build toolchain. A clean bisection of our 19 commits + uncommitted working tree will find it. + +## The new oracle (this is the key result) +We built **stock upstream `6e5b8324f` `[APU] Pace audio subsystem`** with our own toolchain and +**zero custom code** (0 custom cvars in the binary — verified). The user ran it: + +> **Stock `6e5b8324f` → NO crash, NO sound-stop, played through the Ready Room fine.** + +This kills two earlier hypotheses and re-frames the whole problem: + +| Hypothesis | Verdict | +|---|---| +| "Genuine game data race, unfixable without masking" | **WRONG.** Stock game code is stable. | +| "Our build chain miscompiles (broken LTO) → crash" | **WRONG.** Same toolchain, stock source, no crash. | +| "The crash is in OUR 19 commits + 16 working-tree files" | **This is where it is.** Bisect it. | + +The out_of_range race is real, but it's **our timing changes** that push a concurrent cache-add into +the flush's unlocked iteration window. Stock timing never lands there. + +### Reproduce the oracle +```bash +cd "/home/fabi/RE - Project Sylpheed/xenia-canary-native" +git stash push -u +git checkout 6e5b8324f4101464de0f8c2334edb03cac8826c4 +git submodule update --init third_party/DirectXShaderCompiler third_party/snappy # sync to stock pins +cmake --build build --config Release --target xenia_canary -j16 # reuses object cache +# copy bin/Linux/Release/xenia_canary aside, then restore: +git checkout +git -C third_party/DirectXShaderCompiler checkout dc3e6c48d +git -C third_party/snappy checkout 77c78fad +git stash pop +``` +A prebuilt stock binary from this session is at `../stock-oracle/xenia_canary_STOCK_6e5b832` +(see "Artifacts" below). Run any binary through the launcher with `CANARY_BIN= ./run-canary-native.sh`. + +## Build-chain note (real, but NOT the crash cause) +Our LTO is silently disabled: `clang++` is **LLVM 18.1.3** but the linker's gold LTO plugin is +**LLVM 17.0.6**, so the plugin rejects clang-18 bitcode — +`failed to create LTO module: Unknown attribute kind (91)` **×420** (≈ every TU). ThinLTO is not +applied; our codegen differs from the fully-LTO'd official AppImage. Harmless for the crash (proven by +the oracle) but worth fixing for release parity: install/point at a matching `LLVMgold.so` (llvm-18), +or build `ld.lld`+`-fuse-ld=lld` which handles LTO in-tree, or disable LTO explicitly. + +## Bisection plan (suspects ranked by how much they perturb guest thread timing) +Each test = one build + one Ready-Room run. Do them in order; stop at the first that removes the crash. + +1. **`mem_watch` polling thread — FREE, no rebuild.** `kernel_state.cc` adds a detached host thread + (default **`--mem_watch=true`**) that wakes every 3 s and *reads the guest cache-manager memory* — + the exact struct the crash is about. Test: run our binary with `--mem_watch=false`. + → no crash = default it off / remove it; keep every real fix. **Best case.** +2. **Threading edits (uncommitted, load-bearing).** `threading_posix.cc` reap-once double-join fix + + `xma_decoder.cc work_event_->Set()` in `Pause()`. These *cure* the mission-teardown freeze + + permanent audio-death (see `project_audio_stall_freeze_diagnostics_2026_07_14`). Rebuild with them + reverted to stock; test. → **If these are the trigger, it's a real trade-off** (crash vs + freeze/audio-death) and needs a smarter fix, e.g. make the guest cache-flush loop + (PC `0x8245A154..0x8245A1CC`) atomic w.r.t. other guest threads instead of reverting the reap fix. +3. Other audio-fix files: `audio_system.cc` (+218), `xma_context_master.cc` (+44), + `xboxkrnl_audio.cc`, `apu_flags.*`, `alsa_audio_driver.cc`. +4. Committed audio fix `f10484834 [APU] Fix mission-audio silence`. +5. event_log Phase-A trampoline per-export overhead (`shim_utils.h`, committed). + +Faster alternative to 2–5: `git stash` the uncommitted tree and test the committed HEAD alone — splits +"uncommitted working changes" from "the 19 commits" in one run (caveat: without the threading fixes the +mission-teardown freeze may hit before you reach the Ready Room; if it freezes instead of crashing, +that itself localizes the reap fix as load-bearing). + +## Crash mechanism (already characterized — for context) +Guest cache manager (VA `0x828F4838`). Flush `sub_8245A098` snapshots the block deque under a critsec, +releases the lock, then iterates the ~654-entry deque **unlocked** doing `map::at` (`0x823070B0`, +throws at `0x8230711C`). A concurrent locked cache-add lands in the µs window → new deque key absent +from the frozen snapshot → `out_of_range`. Cascade count = 1 (a clean single-add TOCTOU). xenia never +dispatches the guest C++ throw, so it just crashes. Diagnostics for this live behind `--cache_throw_diag` +(default off) in `xboxkrnl_debug.cc`. + +## Current repo state +- Branch **`phase-a-args-fileread`** (fork remote `git.mc02.dev/fabi/Xenia-Canary.git`). +- This commit = WIP snapshot of all audio/threading fixes + investigation instrumentation (all diag + cvars default-OFF). 1139 insertions / 16 src files + 2 new headers + DXC submodule bump. +- `build/` currently holds **stock** objects (we built the oracle there). To get OUR binary back: + `cmake --build build --config Release --target xenia_canary -j16` (~148 TU). +- Cleanup owed before release: strip/gate the diagnostic instrumentation + (`LogGuestThrow`/`DumpCacheManagerOnThrow`/`DispatchGuestCatch` in `xboxkrnl_debug.cc`, the + `xex_module.cc` PE/PDATA/EH scans, `kernel_state.cc` mem_watch). The broken tree-walk node layout in + `DumpCacheManagerOnThrow` (finds 1–17 of 654 nodes) is only used by the moot orphan diag — low prio. + +## Artifacts (this session, scratchpad — EPHEMERAL, copy out if needed) +- `xenia_canary_OURS` — our full build (the crashing one) +- `xenia_canary_STOCK_6e5b832` — stock oracle (the stable one) diff --git a/src/xenia/apu/alsa/alsa_audio_driver.cc b/src/xenia/apu/alsa/alsa_audio_driver.cc index a38477b9c..0c5ab9ec9 100644 --- a/src/xenia/apu/alsa/alsa_audio_driver.cc +++ b/src/xenia/apu/alsa/alsa_audio_driver.cc @@ -20,6 +20,7 @@ #endif #include "xenia/apu/apu_flags.h" +#include "xenia/apu/audio_watchdog.h" #include "xenia/apu/conversion.h" #include "xenia/base/assert.h" #include "xenia/base/clock.h" @@ -315,6 +316,8 @@ void ALSAAudioDriver::WorkerThread() { snd_pcm_writei(pcm_handle_, silence.get(), silence_frames); while (running_) { + watchdog::alsa_state.store(static_cast(snd_pcm_state(pcm_handle_)), + std::memory_order_relaxed); if (paused_) { snd_pcm_drop(pcm_handle_); std::this_thread::sleep_for(std::chrono::milliseconds(10)); @@ -356,6 +359,8 @@ void ALSAAudioDriver::WorkerThread() { snd_pcm_writei(pcm_handle_, silence.get(), period_size_); if (w < 0) { RecoverFromUnderrun(w); + } else { + watchdog::alsa_silence.fetch_add(1, std::memory_order_relaxed); } } else { std::this_thread::sleep_for(std::chrono::milliseconds(2)); @@ -451,6 +456,7 @@ void ALSAAudioDriver::WorkerThread() { } else if (written != (snd_pcm_sframes_t)frames_to_write) { XELOGW("Partial write: {} of {} frames", written, frames_to_write); } + watchdog::alsa_writes.fetch_add(1, std::memory_order_relaxed); // Move to next frame in ring buffer // Use release semantics so writer thread sees this update @@ -470,6 +476,7 @@ void ALSAAudioDriver::WorkerThread() { } bool ALSAAudioDriver::RecoverFromUnderrun(int err) { + watchdog::alsa_xruns.fetch_add(1, std::memory_order_relaxed); if (err == -EPIPE) { // Underrun occurred XELOGW("ALSA underrun detected, recovering..."); diff --git a/src/xenia/apu/apu_flags.cc b/src/xenia/apu/apu_flags.cc index 1be7bf509..eb56b6f9a 100644 --- a/src/xenia/apu/apu_flags.cc +++ b/src/xenia/apu/apu_flags.cc @@ -10,3 +10,9 @@ #include "xenia/apu/apu_flags.h" DEFINE_bool(mute, false, "Mutes all audio output.", "APU") + +DEFINE_bool(audio_watchdog, false, + "Report which stage of the audio pipeline stopped when audio dies " + "(guest callback / XMA decode / frame submit / ALSA write). " + "Diagnostics only.", + "APU") diff --git a/src/xenia/apu/apu_flags.h b/src/xenia/apu/apu_flags.h index d48a32dcb..ae16b7904 100644 --- a/src/xenia/apu/apu_flags.h +++ b/src/xenia/apu/apu_flags.h @@ -12,5 +12,6 @@ #include "xenia/base/cvar.h" DECLARE_bool(mute) +DECLARE_bool(audio_watchdog) #endif // XENIA_APU_APU_FLAGS_H_ diff --git a/src/xenia/apu/audio_system.cc b/src/xenia/apu/audio_system.cc index 9d2f571b3..488c6e9d4 100644 --- a/src/xenia/apu/audio_system.cc +++ b/src/xenia/apu/audio_system.cc @@ -13,6 +13,7 @@ #include "xenia/apu/apu_flags.h" #include "xenia/apu/audio_driver.h" +#include "xenia/apu/audio_watchdog.h" #include "xenia/apu/xma_decoder.h" #include "xenia/base/assert.h" #include "xenia/base/byte_stream.h" @@ -66,12 +67,173 @@ AudioSystem::~AudioSystem() { } } +namespace { + +// --- audio watchdog (diagnostics, --audio_watchdog, default off) ------------- +// Samples the pipeline-stage counters in audio_watchdog.h once a second and +// reports which stage stopped when audio dies. Deliberately near-silent while +// healthy: log spam of its own would starve the very pipeline it watches. + +std::atomic watchdog_running_{false}; +std::thread watchdog_thread_; + +uint64_t WatchdogNowUs() { + return static_cast( + std::chrono::duration_cast( + std::chrono::steady_clock::now().time_since_epoch()) + .count()); +} + +const char* AlsaStateName(int state) { + // snd_pcm_state_t, kept as an int so we need no ALSA header here. + static const char* kNames[] = {"OPEN", "SETUP", "PREPARED", + "RUNNING", "XRUN", "DRAINING", + "PAUSED", "SUSPENDED", "DISCONNECTED"}; + if (state < 0 || state >= static_cast(xe::countof(kNames))) { + return "?"; + } + return kNames[state]; +} + +void AudioWatchdogMain() { + xe::threading::set_name("Audio Watchdog"); + + uint64_t last_pumps = 0, last_submits = 0, last_xma = 0; + uint64_t last_writes = 0, last_silence = 0, last_xruns = 0; + uint64_t last_loops = 0, last_skips = 0; + bool was_alive = true; + bool ever_alive = false; + uint64_t dead_ticks = 0; + + while (watchdog_running_) { + std::this_thread::sleep_for(std::chrono::seconds(1)); + if (!watchdog_running_) { + break; + } + + using namespace xe::apu::watchdog; + const uint64_t pumps = guest_pumps.load(std::memory_order_relaxed); + const uint64_t submits = frames_submitted.load(std::memory_order_relaxed); + const uint64_t xma = xma_works.load(std::memory_order_relaxed); + const uint64_t writes = alsa_writes.load(std::memory_order_relaxed); + const uint64_t silence = alsa_silence.load(std::memory_order_relaxed); + const uint64_t xruns = alsa_xruns.load(std::memory_order_relaxed); + + const uint64_t d_pumps = pumps - last_pumps; + const uint64_t d_submits = submits - last_submits; + const uint64_t d_xma = xma - last_xma; + const uint64_t d_writes = writes - last_writes; + const uint64_t d_silence = silence - last_silence; + const uint64_t d_xruns = xruns - last_xruns; + last_pumps = pumps; + last_submits = submits; + last_xma = xma; + last_writes = writes; + last_silence = silence; + last_xruns = xruns; + + // How long has the APU worker been stuck inside guest code? The guest + // callback runs on the pump thread, so a guest block here kills audio + // permanently -- this is the prime suspect for "sound never comes back". + const uint64_t in_guest_since = + in_guest_callback_since_us.load(std::memory_order_relaxed); + const double stuck_s = + in_guest_since ? (WatchdogNowUs() - in_guest_since) / 1000000.0 : 0.0; + + // "Alive" = the guest is still producing audio. Prefer real frames reaching + // the device, but fall back to pumps so this also works under --apu=nop + // (silent stress runs, where there is no host device to write to). + const bool alive = d_writes > 0 || d_pumps > 0; + + const uint64_t loops = worker_loops.load(std::memory_order_relaxed); + const uint64_t skips = pump_skips.load(std::memory_order_relaxed); + const int clients = clients_in_use.load(std::memory_order_relaxed); + const uint64_t regs = register_calls.load(std::memory_order_relaxed); + const uint64_t unregs = unregister_calls.load(std::memory_order_relaxed); + const uint64_t d_loops = loops - last_loops; + const uint64_t d_skips = skips - last_skips; + last_loops = loops; + last_skips = skips; + + const auto phase = worker_phase.load(std::memory_order_relaxed); + + // Name the culprit stage, walking the pipeline from the guest outward. The + // worker's own recorded phase beats any inference we could make from the + // outside, so trust it first. + const char* culprit = ""; + if (!alive) { + if (stuck_s >= 1.0) { + culprit = "guest audio callback BLOCKED (pump thread stuck in guest)"; + } else if (d_loops == 0 && + phase == WorkerPhase::kAcquiringGlobalLock) { + culprit = + "APU worker BLOCKED on the kernel global lock (someone else holds " + "it)"; + } else if (d_loops == 0 && phase == WorkerPhase::kParkedNoClient) { + culprit = + "NO AUDIO CLIENT: guest unregistered it and never re-registered"; + } else if (d_pumps == 0 && d_loops == 0) { + culprit = "worker stalled -- see phase="; + } else if (d_pumps == 0 && d_skips > 0) { + culprit = "worker looping but never gets a free output slot (semaphore)"; + } else if (d_pumps == 0) { + culprit = "APU worker not pumping the guest callback"; + } else if (d_submits == 0) { + culprit = "guest pumping but submitting no frames (starved upstream)"; + } else if (d_xma == 0 && xma > 0) { + culprit = "XMA decoder stopped doing work"; + } else { + culprit = "frames submitted but host driver is not writing them"; + } + } + + if (!alive) { + dead_ticks++; + } + if (alive) { + ever_alive = true; + } + + // Stay quiet until audio has actually played once: silence during boot / + // menus is not the bug. Then log every transition and once a second while + // dead -- "it was playing and then it stopped" is precisely the event. + if (!ever_alive) { + was_alive = alive; + continue; + } + + if (alive != was_alive || !alive) { + XELOGW( + "AUDIO-WD [{}] +pumps={} +submits={} +xma={} +writes={} " + "+silence={} +xruns={} +loops={} +skips={} clients={} reg={} " + "unreg={} phase={} pcm={} guest_cb_stuck={:.1f}s dead={}s {}", + alive ? "OK" : "DEAD", d_pumps, d_submits, d_xma, d_writes, d_silence, + d_xruns, d_loops, d_skips, clients, regs, unregs, + WorkerPhaseName(phase), + AlsaStateName(alsa_state.load(std::memory_order_relaxed)), stuck_s, + dead_ticks, culprit); + } + if (alive) { + dead_ticks = 0; + } + was_alive = alive; + } +} + +} // namespace + X_STATUS AudioSystem::Setup(kernel::KernelState* kernel_state) { X_STATUS result = xma_decoder_->Setup(kernel_state); if (result) { return result; } + if (cvars::audio_watchdog && !watchdog_running_) { + watchdog_running_ = true; + watchdog_thread_ = std::thread(AudioWatchdogMain); + XELOGW("AUDIO-WD watchdog armed (reports the stage that stops on silence)"); + } + worker_running_ = true; worker_thread_ = kernel::object_ref(new kernel::XHostThread( @@ -102,6 +264,8 @@ void AudioSystem::WorkerThreadMain() { // a host output slot is free, otherwise it is dropped (the host queue // is full, so it is already well buffered). while (worker_running_) { + watchdog::worker_loops.fetch_add(1, std::memory_order_relaxed); + const uint64_t now = static_cast( std::chrono::duration_cast( std::chrono::steady_clock::now().time_since_epoch()) @@ -112,9 +276,17 @@ void AudioSystem::WorkerThreadMain() { uint32_t client_callback = 0; uint32_t client_callback_arg = 0; { + watchdog::worker_phase.store(watchdog::WorkerPhase::kAcquiringGlobalLock, + std::memory_order_relaxed); auto global_lock = global_critical_region_.Acquire(); + watchdog::worker_phase.store(watchdog::WorkerPhase::kStart, + std::memory_order_relaxed); + int in_use_count = 0; for (size_t i = 0; i < kMaximumClientCount; ++i) { + if (clients_[i].in_use) { + ++in_use_count; + } if (!clients_[i].in_use || clients_[i].next_pump_us >= earliest_pump_us) { continue; @@ -122,6 +294,7 @@ void AudioSystem::WorkerThreadMain() { earliest_pump_us = clients_[i].next_pump_us; client_index = i; } + watchdog::clients_in_use.store(in_use_count, std::memory_order_relaxed); if (client_index != kMaximumClientCount) { client_callback = clients_[client_index].callback; @@ -138,6 +311,8 @@ void AudioSystem::WorkerThreadMain() { // No clients yet: park until one registers or we're told to stop. if (client_index == kMaximumClientCount) { + watchdog::worker_phase.store(watchdog::WorkerPhase::kParkedNoClient, + std::memory_order_relaxed); xe::threading::Wait(pending_work_event_.get(), true); if (paused_) { pause_fence_.Signal(); @@ -151,6 +326,8 @@ void AudioSystem::WorkerThreadMain() { ? earliest_pump_us - kAudioIntervalSlack : 0; if (wake_target_us > now) { + watchdog::worker_phase.store(watchdog::WorkerPhase::kPacingSleep, + std::memory_order_relaxed); const std::chrono::milliseconds timeout((wake_target_us - now) / 1000); auto result = xe::threading::Wait(pending_work_event_.get(), true, timeout); @@ -172,14 +349,30 @@ void AudioSystem::WorkerThreadMain() { } // Submit only if the host has a free output slot; - if (client_callback && + const bool have_slot = + client_callback && xe::threading::Wait(client_semaphores_[client_index].get(), false, std::chrono::milliseconds(0)) == - xe::threading::WaitResult::kSuccess) { + xe::threading::WaitResult::kSuccess; + if (!have_slot) { + watchdog::pump_skips.fetch_add(1, std::memory_order_relaxed); + } + if (have_slot) { SCOPE_profile_cpu_i("apu", "xe::apu::AudioSystem->client_callback"); uint64_t args[] = {client_callback_arg}; + // The guest callback runs in-line on this pump thread: if it blocks, the + // pump stops forever and audio never recovers. Bracket it so the + // watchdog can see (and name) that case. + watchdog::in_guest_callback_since_us.store(WatchdogNowUs(), + std::memory_order_relaxed); + watchdog::worker_phase.store(watchdog::WorkerPhase::kInGuestCallback, + std::memory_order_relaxed); processor_->Execute(worker_thread_->thread_state(), client_callback, args, xe::countof(args)); + watchdog::worker_phase.store(watchdog::WorkerPhase::kStart, + std::memory_order_relaxed); + watchdog::in_guest_callback_since_us.store(0, std::memory_order_relaxed); + watchdog::guest_pumps.fetch_add(1, std::memory_order_relaxed); } } worker_running_ = false; @@ -201,6 +394,13 @@ int AudioSystem::FindFreeClient() { void AudioSystem::Initialize() {} void AudioSystem::Shutdown() { + if (watchdog_running_) { + watchdog_running_ = false; + if (watchdog_thread_.joinable()) { + watchdog_thread_.join(); + } + } + worker_running_ = false; pending_work_event_->Set(); if (worker_thread_) { @@ -261,6 +461,12 @@ X_STATUS AudioSystem::RegisterClient(uint32_t callback, uint32_t callback_arg, clients_[index].wrapped_callback_arg = ptr; clients_[index].in_use = true; + watchdog::register_calls.fetch_add(1, std::memory_order_relaxed); + if (cvars::audio_watchdog) { + XELOGW("AUDIO-WD RegisterClient(index={}) callback={:08X} -- audio client back", + index, callback); + } + // Wake the worker so it re-scans and starts pacing this client immediately. pending_work_event_->Set(); @@ -277,6 +483,8 @@ X_STATUS AudioSystem::RegisterClient(uint32_t callback, uint32_t callback_arg, void AudioSystem::SubmitFrame(size_t index, float* samples) { SCOPE_profile_cpu_f("apu"); + watchdog::frames_submitted.fetch_add(1, std::memory_order_relaxed); + auto global_lock = global_critical_region_.Acquire(); assert_true(index < kMaximumClientCount); if (index >= kMaximumClientCount || !clients_[index].in_use || @@ -302,6 +510,12 @@ void AudioSystem::SubmitFrame(size_t index, float* samples) { void AudioSystem::UnregisterClient(size_t index) { SCOPE_profile_cpu_f("apu"); + watchdog::unregister_calls.fetch_add(1, std::memory_order_relaxed); + if (cvars::audio_watchdog) { + XELOGW("AUDIO-WD UnregisterClient(index={}) -- guest dropped its audio client", + index); + } + auto global_lock = global_critical_region_.Acquire(); assert_true(index < kMaximumClientCount); DestroyDriver(clients_[index].driver); diff --git a/src/xenia/apu/audio_watchdog.h b/src/xenia/apu/audio_watchdog.h new file mode 100644 index 000000000..c50bd6905 --- /dev/null +++ b/src/xenia/apu/audio_watchdog.h @@ -0,0 +1,104 @@ +/** + ****************************************************************************** + * Xenia : Xbox 360 Emulator Research Project * + ****************************************************************************** + * Copyright 2026 Ben Vanik. All rights reserved. * + * Released under the BSD license - see LICENSE in the root for more details. * + ****************************************************************************** + */ + +#ifndef XENIA_APU_AUDIO_WATCHDOG_H_ +#define XENIA_APU_AUDIO_WATCHDOG_H_ + +#include +#include + +// Read-only diagnostics for "audio stops mid-mission and never recovers". +// +// The audio pipeline has four stages, each of which can die independently: +// +// guest XAudio callback -> SubmitFrame -> ring buffer -> ALSA write +// (guest_pumps) (frames_submitted) (alsa_writes) +// XMA decoding feeds the guest (xma_works) +// +// Each stage bumps a counter here. The watchdog thread in audio_system.cc +// samples them once a second and, when audio dies, reports which stage stopped +// advancing -- turning "no sound" into a named culprit. +// +// Note the APU worker runs the guest's audio callback IN-LINE +// (AudioSystem::WorkerThreadMain -> processor_->Execute). If that guest call +// ever blocks, pumping stops forever and audio can never recover, so we also +// track how long we have been inside guest code. +// +// Everything here is counters only: cvar-gated (--audio_watchdog), no +// behaviour change. + +namespace xe { +namespace apu { +namespace watchdog { + +// Pumps of the guest XAudio callback (AudioSystem worker). +inline std::atomic guest_pumps{0}; +// steady_clock microseconds at which the worker entered guest code; 0 = not +// currently inside the guest callback. +inline std::atomic in_guest_callback_since_us{0}; +// Frames the guest handed to the driver (AudioSystem::SubmitFrame). +inline std::atomic frames_submitted{0}; +// XMA decoder Work() calls that actually decoded something. +inline std::atomic xma_works{0}; +// ALSA: periods of real guest audio written, silence keepalive periods +// written, and underruns recovered. +inline std::atomic alsa_writes{0}; +inline std::atomic alsa_silence{0}; +inline std::atomic alsa_xruns{0}; +// Last observed snd_pcm_state_t (-1 = unknown / driver not ALSA). +inline std::atomic alsa_state{-1}; + +// Why is the APU worker not pumping? Three very different causes look the same +// from outside the process, so distinguish them here: +// worker_loops == 0 && clients_in_use == 0 -> no client (guest unregistered) +// worker_loops == 0 && clients_in_use > 0 -> parked despite a client (pacing) +// worker_loops > 0 && pump_skips > 0 -> looping, but no free output slot +inline std::atomic worker_loops{0}; +inline std::atomic pump_skips{0}; +inline std::atomic clients_in_use{-1}; +inline std::atomic register_calls{0}; +inline std::atomic unregister_calls{0}; + +// Exactly where the APU worker thread is sitting. A parked worker and a worker +// blocked on the kernel global lock are indistinguishable from outside the +// process (both are futex waits with zero context switches), so record it. +enum class WorkerPhase : int { + kStart = 0, + kAcquiringGlobalLock, // blocked here => a kernel lock is held elsewhere + kParkedNoClient, // blocked here => guest has no audio client + kPacingSleep, // normal: waiting for the next 5.33ms deadline + kInGuestCallback, // normal: running the game's mixer + kSubmitting, +}; +inline std::atomic worker_phase{WorkerPhase::kStart}; + +inline const char* WorkerPhaseName(WorkerPhase p) { + switch (p) { + case WorkerPhase::kStart: + return "start"; + case WorkerPhase::kAcquiringGlobalLock: + return "ACQUIRING-GLOBAL-LOCK"; + case WorkerPhase::kParkedNoClient: + return "PARKED-NO-CLIENT"; + case WorkerPhase::kPacingSleep: + return "pacing"; + case WorkerPhase::kInGuestCallback: + return "in-guest-callback"; + case WorkerPhase::kSubmitting: + return "submitting"; + default: + return "?"; + } +} + +} // namespace watchdog +} // namespace apu +} // namespace xe + +#endif // XENIA_APU_AUDIO_WATCHDOG_H_ diff --git a/src/xenia/apu/xma_context_master.cc b/src/xenia/apu/xma_context_master.cc index 0cf57c339..0e7087a3a 100644 --- a/src/xenia/apu/xma_context_master.cc +++ b/src/xenia/apu/xma_context_master.cc @@ -9,7 +9,18 @@ #include "xenia/apu/xma_context_master.h" +#include #include +#include +#include + +#include "xenia/base/cvar.h" + +// [Phase-A / audio RE] Log each XMA stream's true params (channels/sample rate) +// + head bytes so raw sound.pak entries can be matched to real decode params. +DEFINE_bool(xma_param_probe, false, + "Log XMA per-stream params (channels/rate/head bytes) for audio RE.", + "APU"); #include "xenia/apu/xma_decoder.h" #include "xenia/apu/xma_helpers.h" @@ -317,6 +328,39 @@ void XmaContextMaster::Decode(XMA_CONTEXT_DATA* data) { : nullptr; uint8_t* current_input_buffer = data->current_buffer ? in1 : in0; + // [Phase-A / audio RE] Additive, cvar-gated probe: capture the true XMA + // per-stream parameters (channels + sample rate) the game supplies, keyed by + // the stream's head bytes so they can be matched back to a sound.pak entry + // offline. One line per unique stream (deduped on the first 8 bytes). No + // behaviour change — read-only, default-off. + if (cvars::xma_param_probe && in0 && data->input_buffer_0_valid && + data->input_buffer_0_packet_count) { + static std::mutex xma_probe_mu; + static std::set xma_probe_seen; + uint64_t key; + std::memcpy(&key, in0, sizeof(key)); + bool fresh; + { + std::lock_guard lock(xma_probe_mu); + fresh = xma_probe_seen.insert(key).second; + } + if (fresh) { + char head[65]; + for (int i = 0; i < 32; ++i) { + std::snprintf(head + i * 2, 3, "%02x", in0[i]); + } + // Warning level so it surfaces even at the audio-safe --log_level=1 the + // interactive runner uses (Info/Debug would starve the audio thread). + XELOGW( + "XMA-PARAM stereo={} channels={} rate_id={} rate={} packets={} " + "head={}", + static_cast(data->is_stereo), + data->is_stereo ? 2 : 1, static_cast(data->sample_rate), + GetSampleRate(data->sample_rate), + static_cast(data->input_buffer_0_packet_count), head); + } + } + // XELOGAPU("Processing context {} (offset {}, buffer {}, ptr {:p})", id(), // data->input_buffer_read_offset, data->current_buffer, // current_input_buffer); diff --git a/src/xenia/apu/xma_decoder.cc b/src/xenia/apu/xma_decoder.cc index ca06f8c6c..7fc9ae7e1 100644 --- a/src/xenia/apu/xma_decoder.cc +++ b/src/xenia/apu/xma_decoder.cc @@ -9,6 +9,7 @@ #include "xenia/apu/xma_decoder.h" +#include "xenia/apu/audio_watchdog.h" #include "xenia/apu/xma_context.h" #include "xenia/apu/xma_context_fake.h" #include "xenia/apu/xma_context_master.h" @@ -199,6 +200,7 @@ void XmaDecoder::WorkerThreadMain() { for (uint32_t n = 0; n < kContextCount; n++) { bool worked = contexts_[n]->Work(); if (worked) { + watchdog::xma_works.fetch_add(1, std::memory_order_relaxed); contexts_[n]->SignalWorkDone(); } did_work = did_work || worked; @@ -409,6 +411,13 @@ void XmaDecoder::Pause() { } paused_ = true; + // Wake the worker so it actually observes paused_. When no context is + // decoding, the worker sleeps in an infinite Wait(work_event_) and would + // never re-check the flag, never signal pause_fence_, and this would block + // forever -- deadlocking whoever paused us (e.g. the crash handler), which + // left audio permanently dead while the game kept running. + work_event_->Set(); + pause_fence_.Wait(); } diff --git a/src/xenia/base/guest_liveness.h b/src/xenia/base/guest_liveness.h new file mode 100644 index 000000000..6b3eba68d --- /dev/null +++ b/src/xenia/base/guest_liveness.h @@ -0,0 +1,35 @@ +/** + ****************************************************************************** + * Xenia : Xbox 360 Emulator Research Project * + ****************************************************************************** + * Copyright 2026 Ben Vanik. All rights reserved. * + * Released under the BSD license - see LICENSE in the root for more details. * + ****************************************************************************** + */ + +#ifndef XENIA_BASE_GUEST_LIVENESS_H_ +#define XENIA_BASE_GUEST_LIVENESS_H_ + +#include +#include + +// Guest-progress signal for the hang watchdog (--hang_watchdog_secs). +// +// A frozen guest is not the same as a frozen host: in the Project Sylpheed +// tutorial->menu freeze the host is fine (threads scheduled, GPU idle) while +// the guest main thread spins at 100% CPU on a memory flag that never changes. +// The cheapest honest "the game is still alive" signal is the guest presenting +// frames, i.e. calling VdSwap. If that stops, the game has stopped rendering. +// +// Counter only; no behaviour change. + +namespace xe { +namespace liveness { + +// Bumped by VdSwap (xboxkrnl_video.cc) -- the guest asking to present a frame. +inline std::atomic guest_swaps{0}; + +} // namespace liveness +} // namespace xe + +#endif // XENIA_BASE_GUEST_LIVENESS_H_ diff --git a/src/xenia/base/threading_posix.cc b/src/xenia/base/threading_posix.cc index b45e72ee0..60108c6d2 100644 --- a/src/xenia/base/threading_posix.cc +++ b/src/xenia/base/threading_posix.cc @@ -14,6 +14,7 @@ #include "xenia/base/platform.h" #include "xenia/base/threading_timer_queue.h" +#include #include #include #include @@ -981,11 +982,22 @@ class PosixCondition final : public PosixConditionBase { static void* ThreadStartRoutine(void* parameter); bool signaled() const override { return signaled_; } void post_execution() override { + // Reap exactly once. post_execution() runs on EVERY successful Wait(), and + // a thread object stays signaled forever once it has exited -- so every + // later wait on the same handle would pthread_join() a pthread_t that the + // first join already reaped and freed, faulting inside pthread_join. The + // guest does exactly this at mission teardown (several waiters on one + // thread handle), which crashed the waiting guest thread in a permanent + // fault loop: audio died and the game froze. + if (reaped_.exchange(true)) { + return; + } if (thread_) { pthread_join(thread_, nullptr); } sem_destroy(&suspend_sem_); } + std::atomic reaped_{false}; pthread_t thread_; pid_t tid_ = 0; // Kernel TID for setpriority() fallback mutable bool fifo_failed_ = false; // True after SCHED_FIFO was rejected diff --git a/src/xenia/cpu/xex_module.cc b/src/xenia/cpu/xex_module.cc index 7cbc60ac5..a45a95528 100644 --- a/src/xenia/cpu/xex_module.cc +++ b/src/xenia/cpu/xex_module.cc @@ -1568,18 +1568,101 @@ std::vector XexModule::PreanalyzeCode() { } } + for (auto&& sec : pe_sections_) { + XELOGE("PESEC name={} addr={:08X} size={}", sec.name, sec.address, + sec.size); + } + // EH-CONFIRM: scan .rdata for MSVC C++ FuncInfo (magic 0x19930520) and, for + // any whose IP2State map points into the cache-flush chain, dump its catch + // TypeDescriptor names -- this tells us if the flush's out_of_range is + // CAUGHT (vs only cleaned up). Layout (Xenon, 32-bit full VAs, big-endian): + // FuncInfo: +0 magic, +4 maxState, +8 pUnwindMap, +12 nTryBlocks, + // +16 pTryBlockMap, +20 nIPMap, +24 pIP2StateMap + // TryBlockMapEntry(20B): +0 tryLow,+4 tryHigh,+8 catchHigh,+12 nCatches, + // +16 pHandlerArray + // HandlerType(16B): +0 adjectives,+4 pType(TypeDescriptor),+8 dispCatch, + // +12 addressOfHandler + // TypeDescriptor: +0 vfptr,+4 spare,+8 name(mangled, e.g. ".?AV...@") + // IP2StateMapEntry(8B): +0 Ip(VA), +4 State + { + auto rd = [&](uint32_t va) -> uint32_t { + auto p = memory()->TranslateVirtual*>(va); + return p ? (uint32_t)*p : 0; + }; + auto valid = [](uint32_t va) { return va >= 0x82000000 && va < 0x82920000; }; + auto rdata = GetPESection(".rdata"); + if (rdata) { + uint32_t magic_hits = 0, raw_logged = 0; + for (uint32_t a = rdata->address; a < rdata->address + rdata->size; + a += 4) { + if (rd(a) != 0x19930522u) continue; // FuncInfo magic (newer MSVC) + uint32_t nTry = rd(a + 12), pTry = rd(a + 16); + uint32_t nIP = rd(a + 20), pIP = rd(a + 24); + ++magic_hits; + if (!valid(pIP) || nIP > 4096 || !nIP) continue; + // which function? use first + last IP in the IP2State map. + uint32_t firstIp = rd(pIP), lastIp = rd(pIP + (nIP - 1) * 8); + if (raw_logged < 6) { + XELOGE("EH-RAW FuncInfo@{:08X} nTry={} ip[{:08X}..{:08X}]", a, nTry, + firstIp, lastIp); + ++raw_logged; + } + // Log EVERY function that has a CATCH (nTry>=1) across the whole + // binary, so any stack frame can be mapped to a catch. (cleanup-only + // nTry=0 frames just re-propagate -- skip them to cut noise.) + if (!nTry || !valid(pTry) || nTry > 64) continue; + std::string cat; + for (uint32_t t = 0; t < nTry; ++t) { + uint32_t te = pTry + t * 20; + uint32_t nCatch = rd(te + 12), pH = rd(te + 16); + for (uint32_t c = 0; c < nCatch && c < 32 && valid(pH); ++c) { + uint32_t pType = rd(pH + c * 16 + 4); + uint32_t dispCatchObj = rd(pH + c * 16 + 8); + uint32_t funclet = rd(pH + c * 16 + 12); + std::string nm; + if (!pType) { + nm = "..."; + } else { + auto s = memory()->TranslateVirtual(pType + 8); + for (int i = 0; s && i < 96 && s[i]; ++i) nm.push_back(s[i]); + } + cat += fmt::format(" catch({} obj@fp+{:X} funclet={:08X})", nm, + dispCatchObj, funclet); + } + } + XELOGE("EH-CONFIRM FuncInfo@{:08X} ip[{:08X}..{:08X}] nTry={}{}", a, + firstIp, lastIp, nTry, cat); + } + XELOGE("EH-CONFIRM scan done; magic_hits={}", magic_hits); + } + } auto pdata = this->GetPESection(".pdata"); + XELOGE("PDATA-SCAN reached; pdata_section={}", + pdata ? "FOUND" : "NULL"); if (pdata) { uint32_t* pdata_base = (uint32_t*)this->memory()->TranslateVirtual(pdata->address); uint32_t n_pdata_entries = pdata->raw_size / 8; + XELOGE("PDATA-SCAN addr={:08X} raw_size={} entries={}", pdata->address, + pdata->raw_size, n_pdata_entries); for (uint32_t i = 0; i < n_pdata_entries; ++i) { uint32_t funcaddr = xe::load_and_swap(&pdata_base[i * 2]); if (funcaddr >= low_address_ && funcaddr <= highest_exec_addr) { add_new_func(funcaddr); + // DIAGNOSTIC: dump the unwind Flags word for the cache-flush region + // (Xbox360 PPC RUNTIME_FUNCTION: BeginAddress, then Flags with + // PrologLen:8, FuncLen:22, 32bit:1, ExceptionFlag:1[bit31]). The + // ExceptionFlag tells us whether a function has a language handler + // (C++ catch/cleanup) -- i.e. whether the game can CATCH the flush's + // out_of_range throw. Remove once the A-vs-B fix decision is settled. + if (funcaddr >= 0x82459000u && funcaddr <= 0x8245B200u) { + uint32_t flags = xe::load_and_swap(&pdata_base[i * 2 + 1]); + XELOGE("PDATA fn={:08X} flags={:08X} funclen={} excflag={}", + funcaddr, flags, (flags >> 2) & 0x3FFFFF, (flags & 1)); + } } else { // we hit 0 for func addr, that means we're done break; diff --git a/src/xenia/emulator.cc b/src/xenia/emulator.cc index 22cd25220..ee20bcf45 100644 --- a/src/xenia/emulator.cc +++ b/src/xenia/emulator.cc @@ -30,10 +30,13 @@ #include "xenia/base/platform.h" #include "xenia/base/string.h" #include "xenia/base/system.h" +#include "xenia/base/guest_liveness.h" #include "xenia/cpu/backend/code_cache.h" #include "xenia/cpu/backend/null_backend.h" #include "xenia/cpu/cpu_flags.h" +#include "xenia/cpu/ppc/ppc_context.h" #include "xenia/cpu/thread_state.h" +#include "xenia/kernel/xthread.h" #include "xenia/gpu/command_processor.h" #include "xenia/gpu/graphics_system.h" #include "xenia/hid/input_driver.h" @@ -92,6 +95,12 @@ DEFINE_int32(priority_class, 0, "values: 0 - Normal, 1 - Above normal, 2 - High", "General"); +DEFINE_int32(hang_watchdog_secs, 0, + "If the guest stops presenting frames for this many seconds, dump " + "every guest thread's registers and guest call stack to the log " + "(0 = off). Diagnostics only; requires no debugger.", + "General"); + namespace xe { using namespace xe::literals; @@ -166,6 +175,13 @@ Emulator::Emulator(const std::filesystem::path& command_line, Emulator::~Emulator() { // Note that we delete things in the reverse order they were initialized. + if (hang_watchdog_running_) { + hang_watchdog_running_ = false; + if (hang_watchdog_thread_.joinable()) { + hang_watchdog_thread_.join(); + } + } + // Give the systems time to shutdown before we delete them. if (graphics_system_) { graphics_system_->Shutdown(); @@ -308,6 +324,53 @@ X_STATUS Emulator::Setup( XELOGI("{}: Initializing Kernel...", __func__); // Shared kernel state. kernel_state_ = std::make_unique(this); + + // Hang watchdog (--hang_watchdog_secs, diagnostics, default off). + // + // The tutorial->menu freeze is a GUEST hang, not a host deadlock: the host + // keeps running while a guest thread spins on a memory flag nobody sets. A + // host debugger is awkward to attach to that (ptrace is locked down, and the + // window may die before we get to it), but the emulator can simply read its + // own guest state. When the guest stops presenting frames, dump every guest + // thread's registers plus a walk of its guest stack -- enough to name the + // spinning function and the address it is polling. + if (cvars::hang_watchdog_secs > 0) { + hang_watchdog_running_ = true; + hang_watchdog_thread_ = std::thread([this]() { + xe::threading::set_name("Hang Watchdog"); + const uint64_t limit = + static_cast(cvars::hang_watchdog_secs); + uint64_t last_swaps = 0; + uint64_t stalled_s = 0; + bool dumped = false; + while (hang_watchdog_running_) { + std::this_thread::sleep_for(std::chrono::seconds(1)); + if (!hang_watchdog_running_) { + break; + } + const uint64_t swaps = + xe::liveness::guest_swaps.load(std::memory_order_relaxed); + if (swaps != last_swaps) { + last_swaps = swaps; + if (stalled_s >= limit) { + XELOGE("HANG-WD guest recovered after {}s (swaps resumed)", + stalled_s); + } + stalled_s = 0; + dumped = false; + continue; + } + // Nothing presented for another second. + if (++stalled_s < limit || dumped) { + continue; + } + dumped = true; // one dump per hang, not one per second + DumpGuestHang(stalled_s); + } + }); + XELOGI("HANG-WD armed: dump guest state after {}s without a frame", + cvars::hang_watchdog_secs); + } #define LOAD_KERNEL_MODULE(t) \ static_cast(kernel_state_->LoadKernelModule()) // HLE kernel modules. @@ -532,6 +595,72 @@ Emulator::FileSignatureType Emulator::GetFileSignature( return FileSignatureType::Unknown; } +void Emulator::DumpGuestHang(uint64_t stalled_s) { + // Read-only autopsy of a hung guest. Racy by nature (the threads keep + // running); that is fine -- a spinning thread's stack pointer and link + // register are stable, which is exactly what we need. + constexpr uint32_t kCodeLo = 0x82000000u; + constexpr uint32_t kCodeHi = 0x84000000u; + + XELOGE("=========================== HANG-WD ==========================="); + XELOGE("HANG-WD no frame presented for {}s -- dumping guest threads.", + stalled_s); + + auto threads = + kernel_state()->object_table()->GetObjectsByType(); + for (const auto& thread : threads) { + if (!thread || !thread->is_guest_thread()) { + continue; + } + auto thread_state = thread->thread_state(); + if (!thread_state) { + continue; + } + auto ctx = thread_state->context(); + if (!ctx) { + continue; + } + + XELOGE( + "HANG-WD tid={:04X} '{}' running={} lr={:08X} ctr={:08X} r1={:08X}", + thread->thread_id(), thread->name(), thread->is_running(), + static_cast(ctx->lr), static_cast(ctx->ctr), + static_cast(ctx->r[1])); + XELOGE( + "HANG-WD r3={:08X} r4={:08X} r5={:08X} r6={:08X} r7={:08X} " + "r8={:08X} r9={:08X} r10={:08X} r11={:08X} r12={:08X}", + static_cast(ctx->r[3]), static_cast(ctx->r[4]), + static_cast(ctx->r[5]), static_cast(ctx->r[6]), + static_cast(ctx->r[7]), static_cast(ctx->r[8]), + static_cast(ctx->r[9]), static_cast(ctx->r[10]), + static_cast(ctx->r[11]), static_cast(ctx->r[12])); + + // Walk the guest stack: PowerPC back chain -- [sp] = caller sp, + // [sp+4] = saved LR. Stop on anything that stops looking like a frame. + std::string frames; + uint32_t sp = static_cast(ctx->r[1]); + for (int depth = 0; depth < 16; ++depth) { + if (sp < 0x1000 || !memory()->TranslateVirtual(sp)) { + break; + } + auto frame = memory()->TranslateVirtual(sp); + const uint32_t next_sp = xe::load_and_swap(frame); + const uint32_t saved_lr = xe::load_and_swap(frame + 4); + if (saved_lr >= kCodeLo && saved_lr < kCodeHi) { + frames += fmt::format(" {:08X}", saved_lr); + } + if (next_sp <= sp || next_sp - sp > 0x10000) { + break; // not a plausible back chain anymore + } + sp = next_sp; + } + if (!frames.empty()) { + XELOGE("HANG-WD guest stack:{}", frames); + } + } + XELOGE("HANG-WD ==== resolve these PCs with: zq.py fn ===="); +} + X_STATUS Emulator::LaunchPath(const std::filesystem::path& path) { X_STATUS mount_result = X_STATUS_SUCCESS; diff --git a/src/xenia/emulator.h b/src/xenia/emulator.h index f6c94536e..d1bc1eea9 100644 --- a/src/xenia/emulator.h +++ b/src/xenia/emulator.h @@ -10,11 +10,13 @@ #ifndef XENIA_EMULATOR_H_ #define XENIA_EMULATOR_H_ +#include #include #include #include #include #include +#include #include #include "xenia/apu/audio_media_player.h" @@ -309,6 +311,12 @@ class Emulator { xe::Delegate<> on_exit; private: + // Hang watchdog (--hang_watchdog_secs): when the guest stops presenting + // frames, dump every guest thread's registers + guest stack. Diagnostics. + void DumpGuestHang(uint64_t stalled_s); + std::atomic hang_watchdog_running_{false}; + std::thread hang_watchdog_thread_; + enum : uint64_t { EmulatorFlagDisclaimerAcknowledged = 1ULL << 0 }; static uint64_t GetPersistentEmulatorFlags(); static void SetPersistentEmulatorFlags(uint64_t new_flags); diff --git a/src/xenia/kernel/kernel_state.cc b/src/xenia/kernel/kernel_state.cc index 6dee13177..865480147 100644 --- a/src/xenia/kernel/kernel_state.cc +++ b/src/xenia/kernel/kernel_state.cc @@ -9,6 +9,14 @@ #include +#include +#include +#include +#include +#if defined(__linux__) +#include +#endif + #include "xenia/kernel/kernel_state.h" #include "xenia/base/byte_stream.h" @@ -41,9 +49,69 @@ DEFINE_uint32(kernel_build_version, 1888, "Define current kernel version", DECLARE_string(cl); +DEFINE_bool(mem_watch, true, + "Periodically log host RSS / malloc-vs-mmap / guest-physical / " + "cache-deque size to localize the mission memory leak.", "Kernel"); +DEFINE_uint32(mem_watch_secs, 3, "MEM-WATCH sample interval (seconds).", + "Kernel"); + namespace xe { namespace kernel { +// Diagnostic: a detached sampler that periodically logs where host memory is +// going, so a SHORT mission run localizes the leak (host malloc vs mmap vs +// guest-physical vs the cache work-queue). Gated by --mem_watch. +static std::atomic g_mem_watch_run{false}; + +static void MemWatchLoop(Memory* memory) { + uint64_t peak_rss_kb = 0; + while (g_mem_watch_run.load(std::memory_order_relaxed)) { + // Host RSS / VmSize from /proc/self/statm (fields in pages). + uint64_t rss_kb = 0, vsz_kb = 0; + if (FILE* f = std::fopen("/proc/self/statm", "r")) { + unsigned long vsz_pg = 0, rss_pg = 0; + if (std::fscanf(f, "%lu %lu", &vsz_pg, &rss_pg) == 2) { + rss_kb = static_cast(rss_pg) * 4; // 4KB pages + vsz_kb = static_cast(vsz_pg) * 4; + } + std::fclose(f); + } + if (rss_kb > peak_rss_kb) peak_rss_kb = rss_kb; + + // Host allocator breakdown: malloc-in-use vs mmap'd bytes. + uint64_t malloc_kb = 0, mmap_kb = 0; +#if defined(__linux__) + struct mallinfo2 mi = mallinfo2(); + malloc_kb = static_cast(mi.uordblks) / 1024; + mmap_kb = static_cast(mi.hblkhd) / 1024; +#endif + + // Cache work-queue (guest): deque count OBJ+0x58 / list count OBJ+0x38, + // only once the singleton is initialized (once-flag 0x828F48B4 bit0). + uint32_t deque = 0, listc = 0; + auto rd = [&](uint32_t va) -> uint32_t { + auto p = memory->TranslateVirtual*>(va); + return p ? static_cast(*p) : 0; + }; + if (rd(0x828F48B4u) & 1u) { + deque = rd(0x828F4890u); + listc = rd(0x828F4870u); + } + + XELOGE( + "MEM-WATCH rss={}MB (peak {}MB) vsz={}MB malloc_inuse={}MB mmap={}MB " + "cache_deque={} cache_list={}", + rss_kb / 1024, peak_rss_kb / 1024, vsz_kb / 1024, malloc_kb / 1024, + mmap_kb / 1024, deque, listc); + + for (uint32_t i = 0; i < cvars::mem_watch_secs * 10 && + g_mem_watch_run.load(std::memory_order_relaxed); + ++i) { + std::this_thread::sleep_for(std::chrono::milliseconds(100)); + } + } +} + constexpr std::chrono::milliseconds kDeferredOverlappedDelayMillis(25); // This is a global object initialized with the XboxkrnlModule. @@ -78,9 +146,16 @@ KernelState::KernelState(Emulator* emulator) kMemoryProtectRead | kMemoryProtectWrite); xenia_assert(fixed_alloc_worked); + + if (cvars::mem_watch) { + g_mem_watch_run.store(true, std::memory_order_relaxed); + Memory* mem = memory_; + std::thread([mem]() { MemWatchLoop(mem); }).detach(); + } } KernelState::~KernelState() { + g_mem_watch_run.store(false, std::memory_order_relaxed); SetExecutableModule(nullptr); if (dispatch_thread_running_) { diff --git a/src/xenia/kernel/xboxkrnl/xboxkrnl_audio.cc b/src/xenia/kernel/xboxkrnl/xboxkrnl_audio.cc index fb2e5bcba..1e9ed4581 100644 --- a/src/xenia/kernel/xboxkrnl/xboxkrnl_audio.cc +++ b/src/xenia/kernel/xboxkrnl/xboxkrnl_audio.cc @@ -7,7 +7,9 @@ ****************************************************************************** */ +#include "xenia/apu/apu_flags.h" #include "xenia/apu/audio_system.h" +#include "xenia/base/logging.h" #include "xenia/emulator.h" #include "xenia/kernel/kernel_state.h" #include "xenia/kernel/util/shim_utils.h" @@ -55,8 +57,13 @@ DECLARE_XBOXKRNL_EXPORT2(XAudioGetVoiceCategoryVolume, kAudio, kStub, dword_result_t XAudioEnableDucker_entry(dword_t unk) { return X_ERROR_SUCCESS; } DECLARE_XBOXKRNL_EXPORT1(XAudioEnableDucker, kAudio, kStub); -dword_result_t XAudioRegisterRenderDriverClient_entry(lpdword_t callback_ptr, - lpdword_t driver_ptr) { +dword_result_t XAudioRegisterRenderDriverClient_entry( + lpdword_t callback_ptr, lpdword_t driver_ptr, + const ppc_context_t& ppc_context) { + if (cvars::audio_watchdog) { + XELOGW("AUDIO-WD guest called XAudioRegisterRenderDriverClient lr={:08X}", + static_cast(ppc_context->lr)); + } if (!callback_ptr) { return X_E_INVALIDARG; } @@ -84,9 +91,17 @@ DECLARE_XBOXKRNL_EXPORT1(XAudioRegisterRenderDriverClient, kAudio, kImplemented); dword_result_t XAudioUnregisterRenderDriverClient_entry( - lpunknown_t driver_ptr) { + lpunknown_t driver_ptr, const ppc_context_t& ppc_context) { assert_true((driver_ptr.guest_address() & 0xFFFF0000) == 0x41550000); + // Who tore audio down? The guest's return address names the game code path + // (resolve with zq.py fn ) -- the game only does this on its own error / + // teardown logic, which is what we are hunting. Diagnostics only. + if (cvars::audio_watchdog) { + XELOGW("AUDIO-WD guest called XAudioUnregisterRenderDriverClient lr={:08X}", + static_cast(ppc_context->lr)); + } + auto audio_system = kernel_state()->emulator()->audio_system(); audio_system->UnregisterClient(driver_ptr.guest_address() & 0x0000FFFF); return X_ERROR_SUCCESS; diff --git a/src/xenia/kernel/xboxkrnl/xboxkrnl_debug.cc b/src/xenia/kernel/xboxkrnl/xboxkrnl_debug.cc index fdfa33cf4..0705c41cc 100644 --- a/src/xenia/kernel/xboxkrnl/xboxkrnl_debug.cc +++ b/src/xenia/kernel/xboxkrnl/xboxkrnl_debug.cc @@ -7,8 +7,17 @@ ****************************************************************************** */ +#include +#include +#include +#include + +#include "xenia/base/cvar.h" #include "xenia/base/debugging.h" #include "xenia/base/logging.h" +#include "xenia/cpu/backend/backend.h" +#include "xenia/cpu/function.h" +#include "xenia/cpu/processor.h" #include "xenia/emulator.h" #include "xenia/kernel/kernel_state.h" #include "xenia/kernel/util/shim_utils.h" @@ -19,6 +28,22 @@ #include "xenia/ui/window.h" #include "xenia/ui/windowed_app_context.h" +DEFINE_bool( + cache_throw_diag, false, + "Run the heavy guest-throw diagnostics (LogGuestThrow / cache-manager dump / " + "catch-frame walk) on every guest C++ throw. OFF by default: in missions the " + "cache throws constantly and these dumps allocate gigabytes -- they are for " + "targeted debugging only.", + "Kernel"); + +DEFINE_bool( + eh_dispatch, false, + "Dispatch guest C++ exceptions (0xE06D7363) to their catch handler instead " + "of letting the throw fall through. NOTE: disproven as a fix for the Project " + "Sylpheed cache crash (that throw is uncaught by design -- its stack ends at " + "the thread-entry Execute boundary); kept as inert infra + diagnostics.", + "Kernel"); + namespace xe { namespace kernel { namespace xboxkrnl { @@ -104,6 +129,468 @@ typedef struct { xe::be catchable_type_array_ptr; } x_s__ThrowInfo; +// Read a guest C-string, bounded. +static std::string GuestCString(uint32_t guest_ptr, size_t max_len = 128) { + if (!guest_ptr) { + return {}; + } + auto p = kernel_memory()->TranslateVirtual(guest_ptr); + if (!p) { + return {}; + } + std::string s; + for (size_t i = 0; i < max_len && p[i]; ++i) { + s.push_back(p[i]); + } + return s; +} + +// Name the thrown C++ type via the MSVC RTTI chain hanging off its vtable: +// object -> vtable ; vtable[-1] -> CompleteObjectLocator ; COL+0xC -> +// TypeDescriptor ; TypeDescriptor+8 -> mangled name (".?AVout_of_range@std@@") +static std::string ThrownTypeName(uint32_t thrown_ptr) { + if (!thrown_ptr) { + return ""; + } + auto rd32 = [](uint32_t va) -> uint32_t { + auto p = kernel_memory()->TranslateVirtual*>(va); + return p ? static_cast(*p) : 0; + }; + const uint32_t vtable = rd32(thrown_ptr); + if (!vtable) { + return ""; + } + const uint32_t col = rd32(vtable - 4); + if (!col) { + return ""; + } + const uint32_t type_desc = rd32(col + 0x0C); + if (!type_desc) { + return ""; + } + return GuestCString(type_desc + 8); +} + +// Diagnostics for the swallowed-throw crash: xenia does NOT dispatch guest C++ +// exceptions (see below), so a throw returns and the game crashes in the +// unreachable code after it. By then the crash dump's registers are already +// clobbered. Capture the guest state HERE, while the throwing call frame is +// still intact -- the thrown type, the registers (the failing lookup's key and +// loop state live in these), and the guest call stack. +// Dump the asset-cache-manager LRU state at the moment it throws out_of_range, +// so we can see WHICH access-order deque hash-pair is missing from the entry +// map (the desync that crashes in sub_8245A098). r25 survives the throw and +// holds the cache-manager global (guest VA 0x828F4838). Layout (from RE): +// OBJ+0x30 = std::list (map is rebuilt from this, keyed by hash-pair) +// OBJ+0x48 = std::deque: +0x4C block-map ptr, +0x50 map_size, +// +0x54 start off, +0x58 element count. Element i (8-byte, 2/block): +// bi=((start+i)/2); if bi>=map_size bi-=map_size; addr=blockmap[bi]+(i&1)*8 +static void DumpCacheManagerOnThrow(const ppc_context_t& ctx) { + const uint32_t OBJ = 0x828F4838u; + if (static_cast(ctx->r[25]) != OBJ) { + return; // not the cache-manager map::at that threw + } + auto rd = [](uint32_t va) -> uint32_t { + auto p = kernel_memory()->TranslateVirtual*>(va); + return p ? static_cast(*p) : 0; + }; + const uint32_t deque_count = rd(OBJ + 0x58); + const uint32_t list_count = rd(OBJ + 0x38); + const uint32_t blockmap = rd(OBJ + 0x4C); + const uint32_t map_size = rd(OBJ + 0x50); + const uint32_t start = rd(OBJ + 0x54); + XELOGE( + "CACHE-DUMP deque_count={} list_count={} blockmap={:08X} map_size={} " + "start={}", + deque_count, list_count, blockmap, map_size, start); + // Raw header words -- resolve the real container layout without guessing. + auto rawrow = [&](const char* tag, uint32_t base, int words) { + std::string s; + for (int i = 0; i < words; ++i) + s += fmt::format(" +{:X}={:08X}", i * 4, rd(base + i * 4)); + XELOGE("CACHE-RAW {} @{:08X}:{}", tag, base, s); + }; + rawrow("mgr+0x28", OBJ + 0x28, 16); // map(+0x30) + deque(+0x48) headers + // deque hash-pairs (access order) + std::string dq; + const uint32_t n = deque_count > 512 ? 512 : deque_count; // sanity cap + for (uint32_t i = 0; i < n; ++i) { + uint32_t bi = (start + i) / 2; + if (map_size && bi >= map_size) { + bi -= map_size; + } + const uint32_t block = rd(blockmap + bi * 4); + const uint32_t addr = block + (i & 1) * 8; + dq += fmt::format(" [{}]{:08X}:{:08X}", i, rd(addr), rd(addr + 4)); + } + XELOGE("CACHE-DUMP deque hashpairs:{}", dq); + + // Walk the entry map at OBJ+0x30 (MSVC _Tree, CONFIRMED by live raw dump: + // _Left@+0, _Parent@+4, _Right@+8, keyLo@+12, keyHi@+16, _Isnil@+25). Map + // object header is at OBJ+0x30; head=[OBJ+0x34]; root=head._Parent=[head+4]. + // This is the map sub_8245A098 queries per deque entry. + std::set map_keys; + const uint32_t head = rd(OBJ + 0x34); + const uint32_t root = head ? rd(head + 4) : 0; + std::vector stack; + if (root && (rd(root + 25) & 0xFF) == 0) { + stack.push_back(root); + } + // Hard guards: a corrupted map (cyclic/garbage node pointers -- common at the + // moment it throws) would otherwise balloon this walk to gigabytes. + uint32_t visits = 0; + while (!stack.empty() && map_keys.size() < 4096 && ++visits < 100000 && + stack.size() < 100000) { + const uint32_t nd = stack.back(); + stack.pop_back(); + const uint64_t key = (static_cast(rd(nd + 12)) << 32) | rd(nd + 16); + map_keys.insert(key); + const uint32_t l = rd(nd + 0), r = rd(nd + 8); + if (l && (rd(l + 25) & 0xFF) == 0) stack.push_back(l); + if (r && (rd(r + 25) & 0xFF) == 0) stack.push_back(r); + } + // For each deque key, flag whether it exists in the persistent map. The + // orphan(s) = deque keys absent from the map == the cause of the map::at miss. + std::string orphans; + uint32_t orphan_count = 0; + for (uint32_t i = 0; i < n; ++i) { + uint32_t bi = (start + i) / 2; + if (map_size && bi >= map_size) bi -= map_size; + const uint32_t block = rd(blockmap + bi * 4); + const uint32_t addr = block + (i & 1) * 8; + const uint64_t key = + (static_cast(rd(addr)) << 32) | rd(addr + 4); + if (!map_keys.count(key)) { + orphans += fmt::format(" [{}]{:08X}:{:08X}", i, rd(addr), rd(addr + 4)); + ++orphan_count; + } + } + XELOGE("CACHE-DUMP map_keys={} deque_orphans={} (deque keys NOT in map):{}", + static_cast(map_keys.size()), orphan_count, orphans); + + // --- SNAPSHOT vs LIVE: prove the TOCTOU race. The flush (sub_8245A098) locks, + // copies OBJ+0x30 into a temp map at [flush_r31+104], UNLOCKS (0x8245a150), + // then iterates the live deque doing map::at on the FROZEN snapshot. A + // concurrent LOCKED add (8245ABD8/8245AD00) pushes a deque + map entry during + // the unlocked window -> that key is in the LIVE map but NOT the snapshot -> + // map::at throws. Find the flush frame (its live PC is in the map::at loop); + // its snapshot map object is at frame_sp+104 (== r26 at the throw). + uint32_t flush_sp = 0; + { + uint32_t sp = static_cast(ctx->r[1]); + for (int depth = 0; depth < 128 && sp; ++depth) { + auto f = kernel_memory()->TranslateVirtual(sp); + if (!f) break; + uint32_t nsp = xe::load_and_swap(f); + if (nsp <= sp || nsp - sp > 0x1000000) break; + auto lp = kernel_memory()->TranslateVirtual(nsp - 8); + uint32_t pc = lp ? xe::load_and_swap(lp) : 0; + if (pc >= 0x8245A154u && pc <= 0x8245A1D0u) { // flush deque/map::at loop + flush_sp = nsp; + break; + } + sp = nsp; + } + } + if (!flush_sp) { + XELOGE("CACHE-DUMP flush frame not found on stack (snapshot compare skipped)"); + return; + } + rawrow("snapshot@r31+104", flush_sp + 96, 16); // raw temp-map header region + const uint32_t snap = flush_sp + 104; // temp map object [r31+104] + std::set snap_keys; + const uint32_t shead = rd(snap + 4); + const uint32_t sroot = shead ? rd(shead + 4) : 0; + std::vector st; + if (sroot && (rd(sroot + 25) & 0xFF) == 0) st.push_back(sroot); + uint32_t svisits = 0; + while (!st.empty() && snap_keys.size() < 4096 && ++svisits < 100000 && + st.size() < 100000) { + const uint32_t nd = st.back(); + st.pop_back(); + snap_keys.insert((static_cast(rd(nd + 12)) << 32) | rd(nd + 16)); + const uint32_t l = rd(nd + 0), r = rd(nd + 8); + if (l && (rd(l + 25) & 0xFF) == 0) st.push_back(l); + if (r && (rd(r + 25) & 0xFF) == 0) st.push_back(r); + } + std::string miss; + uint32_t miss_count = 0; + for (uint32_t i = 0; i < n; ++i) { + uint32_t bi = (start + i) / 2; + if (map_size && bi >= map_size) bi -= map_size; + const uint32_t addr = rd(blockmap + bi * 4) + (i & 1) * 8; + const uint64_t key = (static_cast(rd(addr)) << 32) | rd(addr + 4); + if (!snap_keys.count(key)) { + miss += fmt::format(" [{}]{:08X}:{:08X}(in_live_map={})", i, + static_cast(key >> 32), + static_cast(key), map_keys.count(key) ? 1 : 0); + ++miss_count; + } + } + XELOGE( + "CACHE-DUMP flush_sp={:08X} snapshot_keys={} deque_NOT_in_snapshot={} " + "(these are what map::at throws on; in_live_map=1 => added during the " + "flush's UNLOCKED window = the TOCTOU race):{}", + flush_sp, static_cast(snap_keys.size()), miss_count, miss); +} + +// --------------------------------------------------------------------------- +// Fix-A analysis half (read-only): determine which guest stack frame WOULD catch +// the current C++ throw and where it would resume, by parsing the guest's MSVC +// C++ EH tables. Zero behaviour change -- logs WOULD-CATCH so the frame-finding +// can be validated against a live crash before the control-transfer half is +// wired in. Layout (all BE u32 unless noted): +// FuncInfo (magic 0x19930522): +12 nTryBlocks, +16 pTryBlockMap, +// +20 nIPMap, +24 pIP2StateMap +// IP2StateMapEntry(8B): +0 Ip(VA), +4 State(int) +// TryBlockMapEntry(20B): +0 tryLow, +4 tryHigh, +8 catchHigh, +12 nCatches, +// +16 pHandlerArray +// HandlerType(16B): +4 pType(TypeDescriptor; 0=catch(...)), +8 dispCatchObj, +// +12 addressOfHandler(funclet) +// CatchableTypeArray: +0 count, +4 CatchableType*[]; CatchableType: +4 type_ptr +namespace { + +struct EhFuncInfo { + uint32_t funcinfo_va; + uint32_t func_start; // xenia function containing this FuncInfo's code + uint32_t first_ip, last_ip; // IP2State map coverage (fallback PC match) + uint32_t p_ip, n_ip; // IP2State map + uint32_t p_try, n_try; // try-block map +}; + +static std::vector* g_eh_catch_index = nullptr; + +static uint32_t EhRd(uint32_t va) { + auto p = kernel_memory()->TranslateVirtual*>(va); + return p ? static_cast(*p) : 0; +} + +// xenia function-start containing pc, or 0. Non-analyzing lookup: every frame on +// a live stack has already executed, so its function is known (no side effects). +static uint32_t EhFuncStart(uint32_t pc) { + auto* f = kernel_state()->processor()->LookupFunction(pc); + return f ? f->address() : 0; +} + +// Build the catch index once: scan .rdata for FuncInfo(magic) with nTry>=1. +static void EhBuildIndex() { + if (g_eh_catch_index) return; + g_eh_catch_index = new std::vector(); + // .rdata bounds from the PE section table (PESEC): addr 82000600 size 1142488. + const uint32_t lo = 0x82000600u, hi = 0x82000600u + 1142488u; + for (uint32_t a = lo; a + 28 < hi; a += 4) { + if (EhRd(a) != 0x19930522u) continue; + uint32_t n_try = EhRd(a + 12), p_try = EhRd(a + 16); + uint32_t n_ip = EhRd(a + 20), p_ip = EhRd(a + 24); + if (!n_try || !p_try || n_try > 64 || !n_ip || !p_ip) continue; + uint32_t first_ip = EhRd(p_ip); + uint32_t last_ip = EhRd(p_ip + (n_ip - 1) * 8); + uint32_t fn = EhFuncStart(first_ip); // first IP -> its function + if (!fn) fn = first_ip; // fall back to the IP itself + g_eh_catch_index->push_back( + {a, fn, first_ip, last_ip, p_ip, n_ip, p_try, n_try}); + } + XELOGE("EH-INDEX built: {} catch-bearing FuncInfos", + static_cast(g_eh_catch_index->size())); +} + +// State at pc: State of the IP2State entry with the greatest Ip<=pc; -1 if pc +// precedes the first entry (not inside any protected region). +static int EhStateAt(const EhFuncInfo& fi, uint32_t pc) { + int state = -1; + uint32_t best_ip = 0; + for (uint32_t i = 0; i < fi.n_ip; ++i) { + uint32_t ip = EhRd(fi.p_ip + i * 8); + if (ip <= pc && ip >= best_ip) { + best_ip = ip; + state = static_cast(EhRd(fi.p_ip + i * 8 + 4)); + } + } + return state; +} + +} // namespace + +// Sentinel return address ExecuteRaw() gives a guest function (matches +// Processor::ExecuteRaw). We force the catching frame's saved-LR slot to this so +// the catch funclet returns to us regardless of how it restores LR. +static constexpr uint32_t kFuncletReturnSentinel = 0xBCBCBCBCu; + +// Fix A. Dispatch the current guest C++ throw to the first stack frame that +// catches it, then resume the guest as if that frame had caught-and-returned. +// Returns true if dispatched -- in which case this does NOT return normally: it +// calls XThread::Reenter, which throws FiberReentryException to unwind every +// intervening host/JIT frame before resuming the guest at the catch frame's +// return site. Returns false (falls through to the old crash path) when no +// handler matches or --eh_dispatch=false. +bool DispatchGuestCatch(pointer_t record, + const ppc_context_t& ctx) { + EhBuildIndex(); + + const uint32_t thrown_obj = record->exception_information[1]; + + // Every TypeDescriptor the throw can be caught as -> its base-subobject + // displacement (x_PMD.mdisp), from the throw's CatchableTypeArray. + std::map catchable; + uint32_t cta = EhRd(record->exception_information[2] + 12); + if (cta) { + uint32_t n = EhRd(cta); + for (uint32_t i = 0; i < n && i < 32; ++i) { + uint32_t ct = EhRd(cta + 4 + i * 4); + if (ct) catchable[EhRd(ct + 4)] = static_cast(EhRd(ct + 8)); + } + } + + uint32_t sp = static_cast(ctx->r[1]); + for (int depth = 0; depth < 128; ++depth) { + auto frame = kernel_memory()->TranslateVirtual(sp); + if (!sp || !frame) { + XELOGE("EH-WALK stop depth={} sp={:08X} (untranslatable)", depth, sp); + break; + } + uint32_t next_sp = xe::load_and_swap(frame); + // The cache flush runs on a fiber/task stack; the back-chain can jump a long + // way (or to a different stack) when crossing into the dispatcher that has + // the try/catch. Only require it to go UP; allow large gaps. + if (next_sp <= sp) { + XELOGE("EH-WALK stop depth={} sp={:08X} next_sp={:08X} (not ascending)", + depth, sp, next_sp); + break; + } + if (next_sp - sp > 0x1000000) { + XELOGE("EH-WALK stop depth={} sp={:08X} next_sp={:08X} (gap>16M)", depth, + sp, next_sp); + break; + } + auto lrp = kernel_memory()->TranslateVirtual(next_sp - 8); + uint32_t pc = lrp ? xe::load_and_swap(lrp) : 0; + uint32_t frame_sp = next_sp; // SP_F: the catching frame's running SP + sp = next_sp; + uint32_t fn = (pc >= 0x82150000 && pc < 0x8284A000) ? EhFuncStart(pc) : 0; + XELOGE("EH-WALK depth={} SP_F={:08X} pc={:08X} fn={:08X}", depth, frame_sp, + pc, fn); + if (pc < 0x82150000 || pc >= 0x8284A000) continue; + + for (const auto& fi : *g_eh_catch_index) { + // Match the frame to a catch FuncInfo either by xenia's function-start or + // (robust to xenia splitting funcs/funclets) by the FuncInfo's IP range. + bool by_fn = fn && fi.func_start == fn; + bool by_ip = pc >= fi.first_ip && pc <= fi.last_ip; + if (!by_fn && !by_ip) continue; + int state = EhStateAt(fi, pc); + for (uint32_t t = 0; t < fi.n_try; ++t) { + uint32_t te = fi.p_try + t * 20; + int try_low = static_cast(EhRd(te)); + int try_high = static_cast(EhRd(te + 4)); + if (state < try_low || state > try_high) continue; + uint32_t n_catch = EhRd(te + 12), pH = EhRd(te + 16); + for (uint32_t c = 0; c < n_catch && c < 32; ++c) { + uint32_t pType = EhRd(pH + c * 16 + 4); + auto it = (pType == 0) ? catchable.end() : catchable.find(pType); + if (pType != 0 && it == catchable.end()) continue; + int32_t mdisp = (it == catchable.end()) ? 0 : it->second; + uint32_t dispCatchObj = EhRd(pH + c * 16 + 8); + uint32_t funclet = EhRd(pH + c * 16 + 12); + + // Establisher frame = SP at F's entry = the back-chain word saved at + // F's SP by its `stwu`. The funclet rebuilds its frame ptr as + // r31 = r12 - N, and __save/restgprlr save/restore F's nonvolatiles + + // return address at [establisher-8]. + uint32_t establisher = EhRd(frame_sp); + uint32_t f_return = EhRd(establisher - 8); // F's real return address + + XELOGE( + "GUEST-CATCH frame_pc={:08X} fn={:08X} SP_F={:08X} est={:08X} " + "f_return={:08X} state={} try{}[{}..{}] catch#{} pType={:08X} " + "obj@est+{:X} funclet={:08X} dispatch={}", + pc, fn, frame_sp, establisher, f_return, state, t, try_low, + try_high, c, pType, dispCatchObj, funclet, + cvars::eh_dispatch ? 1 : 0); + + if (!cvars::eh_dispatch) return false; + if (!establisher || !f_return) { + XELOGE("GUEST-CATCH abort: bad establisher/return frame"); + return false; + } + + auto store32 = [](uint32_t va, uint32_t val) { + auto p = kernel_memory()->TranslateVirtual*>(va); + if (p) *p = val; + }; + + // Hand the caught object (adjusted to the caught base) to the catch. + // catch(...) (dispCatchObj==0) takes no object. + if (dispCatchObj != 0) { + store32(establisher + dispCatchObj, + thrown_obj + static_cast(mdisp)); + } + // Force the funclet to return to us no matter how it restores LR. + store32(establisher - 8, kFuncletReturnSentinel); + + // Run the game's own catch funclet in F's frame: r12=r1=establisher. + // It runs the catch body, restores F's inherited nonvolatiles, and + // returns (r3 = F's return value). + ctx->r[12] = establisher; + ctx->r[1] = establisher; + ctx->processor->ExecuteRaw(ctx->thread_state, funclet); + + // F has effectively caught-and-returned: resume at F's caller with the + // funclet's return value. Reenter unwinds all the throw's host/JIT + // frames first. r1 is already the caller SP (establisher). + ctx->processor->backend()->PrepareForReentry(ctx.value()); + XELOGE("GUEST-CATCH dispatched -> resuming at f_return={:08X} r3={:08X}", + f_return, static_cast(ctx->r[3])); + XThread::GetCurrentThread()->Reenter(f_return); + return true; // not reached + } + } + } + } + XELOGE("GUEST-CATCH none (no matching handler frame found)"); + return false; +} + +void LogGuestThrow(pointer_t record, + const ppc_context_t& ctx) { + const uint32_t thrown_ptr = record->exception_information[1]; + XELOGE("GUEST-THROW type={} object={:08X} lr={:08X}", + ThrownTypeName(thrown_ptr), thrown_ptr, + static_cast(ctx->lr)); + DumpCacheManagerOnThrow(ctx); + + std::string regs; + for (int i = 3; i <= 31; ++i) { + regs += fmt::format(" r{}={:08X}", i, static_cast(ctx->r[i])); + } + XELOGE("GUEST-THROW regs:{}", regs); + + // Walk the guest stack. Xenon prologues do `mfspr r12,LR; stw r12,-8(r1)` + // BEFORE `stwu r1,-N(r1)`, so a frame's return address is stored at + // [caller_sp - 8] = [([sp]) - 8], NOT [sp+4]. Back chain = [sp]. Filter to + // .text (0x82150000..0x8284A000). + std::string frames; + uint32_t sp = static_cast(ctx->r[1]); + for (int depth = 0; depth < 64; ++depth) { + auto frame = kernel_memory()->TranslateVirtual(sp); + if (!sp || !frame) { + break; + } + const uint32_t next_sp = xe::load_and_swap(frame); + if (next_sp <= sp || next_sp - sp > 0x40000) { + break; + } + auto lrp = kernel_memory()->TranslateVirtual(next_sp - 8); + if (lrp) { + const uint32_t lr = xe::load_and_swap(lrp); + if (lr >= 0x82150000 && lr < 0x8284A000) { + frames += fmt::format(" {:08X}", lr); + } + } + sp = next_sp; + } + XELOGE("GUEST-THROW guest stack:{}", frames); +} + void HandleCppException(pointer_t record) { // C++ exception. // https://blogs.msdn.com/b/oldnewthing/archive/2010/07/30/10044061.aspx @@ -128,13 +615,29 @@ void HandleCppException(pointer_t record) { XELOGE("Guest attempted to throw a C++ exception!"); } -void RtlRaiseException_entry(pointer_t record) { +void RtlRaiseException_entry(pointer_t record, + const ppc_context_t& ppc_context) { switch (record->code) { case 0x406D1388: { HandleSetThreadName(record); return; } case 0xE06D7363: { + // Heavy diagnostics are OFF by default: in a mission the cache flush + // throws constantly, and these dumps (esp. the cache-manager tree walk on + // a corrupted map) allocate gigabytes per throw. Stock behaviour is just + // HandleCppException below. + if (cvars::cache_throw_diag) { + LogGuestThrow(record, ppc_context); + } + // Fix A: dispatch to the catch handler. On success this does not return + // (it reenters the guest at the catch frame). Disproven for the cache + // crash and default-off; also skip its (allocating) frame walk unless a + // diagnostic/dispatch knob is set. + if ((cvars::eh_dispatch || cvars::cache_throw_diag) && + DispatchGuestCatch(record, ppc_context)) { + return; + } HandleCppException(record); return; } diff --git a/src/xenia/kernel/xboxkrnl/xboxkrnl_io.cc b/src/xenia/kernel/xboxkrnl/xboxkrnl_io.cc index 5e6b354ea..c0adfecc2 100644 --- a/src/xenia/kernel/xboxkrnl/xboxkrnl_io.cc +++ b/src/xenia/kernel/xboxkrnl/xboxkrnl_io.cc @@ -783,6 +783,15 @@ void IoDeleteDevice_entry(dword_t device_ptr, const ppc_context_t& ctx) { DECLARE_XBOXKRNL_EXPORT1(IoDeleteDevice, kFileSystem, kStub); +// NOTE (2026-07-14): do NOT stub StfsCreateDevice / IoDismountVolumeByFileHandle +// without testing an actual playthrough. They are deliberately left +// unimplemented (the JIT's "undefined extern call" stub handles them, leaving +// guest r3 untouched so the title reads back its own first argument as the +// status). Implementing them -- even returning X_STATUS_NOT_SUPPORTED -- makes +// the title hang at boot (black screen) right after the devkit-memory +// allocation, before it ever calls StfsCreateDevice. Whatever the title keys +// off here, it is not a plain NTSTATUS check. + } // namespace xboxkrnl } // namespace kernel } // namespace xe diff --git a/src/xenia/kernel/xboxkrnl/xboxkrnl_video.cc b/src/xenia/kernel/xboxkrnl/xboxkrnl_video.cc index 12835232b..a4e58b5b9 100644 --- a/src/xenia/kernel/xboxkrnl/xboxkrnl_video.cc +++ b/src/xenia/kernel/xboxkrnl/xboxkrnl_video.cc @@ -9,6 +9,7 @@ #include "xenia/kernel/xboxkrnl/xboxkrnl_video.h" +#include "xenia/base/guest_liveness.h" #include "xenia/base/logging.h" #include "xenia/emulator.h" #include "xenia/gpu/graphics_system.h" @@ -472,6 +473,10 @@ void VdSwap_entry( lpdword_t frontbuffer_ptr, // ptr to frontbuffer address lpdword_t texture_format_ptr, lpdword_t color_space_ptr, lpdword_t width, lpdword_t height) { + // Guest-progress heartbeat for the hang watchdog: the game asking to present + // a frame is our "still alive" signal (diagnostics only). + xe::liveness::guest_swaps.fetch_add(1, std::memory_order_relaxed); + // All of these parameters are REQUIRED. assert(buffer_ptr); assert(fetch_ptr); diff --git a/src/xenia/memory.cc b/src/xenia/memory.cc index 1b64b754d..a9d963626 100644 --- a/src/xenia/memory.cc +++ b/src/xenia/memory.cc @@ -1388,7 +1388,18 @@ bool BaseHeap::Release(uint32_t base_address, uint32_t* out_region_size) { uint32_t base_page_number = (base_address - heap_base_) / page_size_; auto base_page_entry = page_table_[base_page_number]; if (base_page_entry.base_address != base_page_number) { - XELOGE("BaseHeap::Release failed because address is not a region start"); + // The guest asked us to free something we refuse to free -- it then + // believes that memory is gone while we still hold it. Say WHAT we + // refused: the address, the region we think it belongs to, and whether + // the page is even allocated. (Was a bare message with no data.) + const uint32_t owner_addr = + heap_base_ + base_page_entry.base_address * page_size_; + XELOGE( + "BaseHeap::Release failed because address is not a region start: " + "addr={:08X} heap_base={:08X} page={} owning_region_start={:08X} " + "region_page_count={} state={:02X}", + base_address, heap_base_, base_page_number, owner_addr, + base_page_entry.region_page_count, base_page_entry.state); return false; } diff --git a/third_party/DirectXShaderCompiler b/third_party/DirectXShaderCompiler index 69e54e290..dc3e6c48d 160000 --- a/third_party/DirectXShaderCompiler +++ b/third_party/DirectXShaderCompiler @@ -1 +1 @@ -Subproject commit 69e54e29086b7035acffb304cec57a350225f8b0 +Subproject commit dc3e6c48d451e15d8a730574ca693e4095c628b8