From a40bc50159eddd8067cf28b9c7be99fc6351b787 Mon Sep 17 00:00:00 2001 From: MechaCat02 Date: Mon, 13 Jul 2026 19:13:36 +0200 Subject: [PATCH 1/7] [Phase A] Port args / file.read extraction tracing onto instrument-current Bring the cvar-gated JSONL extraction tracer (event_log) forward from the phase-a-tracing line so args/args_resolved + file.read events are available alongside the GPU draw logging. Purely additive: - src/xenia/kernel/event_log.{cc,h}: the tracer (auto-globbed into the kernel target). Tier 1 fills kernel.call args (raw r3..r10) + args_resolved.path under --phase_a_trace_args; Tier 2 resolves NtReadFile handle->path via the object table and emits file.read. - cpu_flags: phase_a_event_log_path / _mem_writes / _trace_args / _hash_probe / kernel_emit_contention (all default-off). - shim_utils.h: phase_a_bridge decl + EmitImportAndCallWithCtx/EmitReturn hooks in the active X::Trampoline, skipped when Enabled() is false. Deliberately EXCLUDES the Tier-3 hash-probe HIR/emitter trap (the IPFB name-hash was recovered statically, so the probe is moot). The phase_a_hash_probe cvar is defined but inert. Default-off => instrument-current behaviour byte-identical when unused. Not yet compile-verified against instrument-current's toolchain. Co-Authored-By: Claude Opus 4.8 --- src/xenia/cpu/cpu_flags.cc | 25 + src/xenia/cpu/cpu_flags.h | 7 + src/xenia/kernel/event_log.cc | 709 +++++++++++++++++++++++++++++ src/xenia/kernel/event_log.h | 191 ++++++++ src/xenia/kernel/util/shim_utils.h | 35 ++ 5 files changed, 967 insertions(+) create mode 100644 src/xenia/kernel/event_log.cc create mode 100644 src/xenia/kernel/event_log.h diff --git a/src/xenia/cpu/cpu_flags.cc b/src/xenia/cpu/cpu_flags.cc index 3ff067e15..cfadac56c 100644 --- a/src/xenia/cpu/cpu_flags.cc +++ b/src/xenia/cpu/cpu_flags.cc @@ -57,3 +57,28 @@ DEFINE_bool(break_condition_truncate, true, "truncate value to 32-bits", "CPU"); DEFINE_bool(break_on_debugbreak, true, "int3 on JITed __debugbreak requests.", "CPU"); + +// Phase A — expansive extraction tracing (game-data RE); see kernel/event_log.h. +// All default-off so instrument-current behaviour is unchanged when unused. +DEFINE_string(phase_a_event_log_path, "", + "Phase A: write schema-v1 JSONL event log to this path. " + "Empty (default) = disabled.", + "Audit"); +DEFINE_bool(phase_a_event_log_mem_writes, false, + "Phase A: include mem.write events in the JSONL log. RESERVED — " + "not wired in this phase. Default false.", + "Audit"); +DEFINE_bool(phase_a_trace_args, false, + "Phase A extraction: populate the kernel.call args (raw r3..r10) and " + "args_resolved (file I/O path/offset/length/buffer, alloc size, " + "handle names) fields, and emit file.read events. Default false.", + "Audit"); +DEFINE_string(phase_a_hash_probe, "", + "Phase A extraction: CSV of guest PCs — RESERVED (the HIR/emitter " + "trap that drives it is not ported to instrument-current). Inert. " + "Default empty (off).", + "Audit"); +DEFINE_bool(kernel_emit_contention, false, + "Phase D Stage 1: emit `contention.observed` events. Default false " + "(zero cost when disabled). Requires --phase_a_event_log_path.", + "Audit"); diff --git a/src/xenia/cpu/cpu_flags.h b/src/xenia/cpu/cpu_flags.h index 38c4f98ba..467311cc1 100644 --- a/src/xenia/cpu/cpu_flags.h +++ b/src/xenia/cpu/cpu_flags.h @@ -35,4 +35,11 @@ DECLARE_bool(break_condition_truncate); DECLARE_bool(break_on_debugbreak); +// Phase A — expansive extraction tracing; see kernel/event_log.h. +DECLARE_string(phase_a_event_log_path); +DECLARE_bool(phase_a_event_log_mem_writes); +DECLARE_bool(phase_a_trace_args); +DECLARE_string(phase_a_hash_probe); +DECLARE_bool(kernel_emit_contention); + #endif // XENIA_CPU_CPU_FLAGS_H_ diff --git a/src/xenia/kernel/event_log.cc b/src/xenia/kernel/event_log.cc new file mode 100644 index 000000000..219c2b538 --- /dev/null +++ b/src/xenia/kernel/event_log.cc @@ -0,0 +1,709 @@ +/** + ****************************************************************************** + * Xenia : Xbox 360 Emulator Research Project * + ****************************************************************************** + * Phase A event-log emitter — see event_log.h and schema-v1.md. + ****************************************************************************** + */ + +#include "xenia/kernel/event_log.h" + +#include +#include +#include +#include +#include +#include +#include + +#include "third_party/fmt/include/fmt/format.h" + +#include "xenia/base/cvar.h" +#include "xenia/cpu/ppc/ppc_context.h" +#include "xenia/kernel/kernel.h" +#include "xenia/kernel/kernel_state.h" +#include "xenia/kernel/util/object_table.h" +#include "xenia/kernel/xfile.h" +#include "xenia/kernel/xthread.h" +#include "xenia/memory.h" + +DECLARE_string(phase_a_event_log_path); +DECLARE_bool(kernel_emit_contention); +DECLARE_bool(phase_a_trace_args); +DECLARE_string(phase_a_hash_probe); + +namespace xe { +namespace kernel { +namespace phase_a { + +namespace { + +// Cached enabled state, computed lazily from cvar (cheap fast-path). +std::atomic g_state{0}; // 0=untouched, 1=enabled, 2=disabled +std::FILE* g_file = nullptr; +std::mutex g_file_mu; +std::once_flag g_init_once; + +// Per-thread monotonic event index (key for the diff tool). +// Phase C+15-α: per-tid (not per-host-thread). Multiple host threads +// can emit with tid=0 (boot + XThread bootstrap before guest tid is +// assigned), and a thread_local counter aliased across host threads +// produces duplicate `tid_event_idx` values, breaking the diff tool's +// monotonicity invariant. Use a tid-keyed map guarded by a mutex. +std::unordered_map g_tid_counters; +std::mutex g_tid_counters_mu; + +uint64_t NextTidEventIdx(uint32_t tid) { + std::lock_guard lock(g_tid_counters_mu); + auto& c = g_tid_counters[tid]; + uint64_t v = c; + c = v + 1; + return v; +} + +uint64_t PeekTidEventIdxLocked(uint32_t tid) { + std::lock_guard lock(g_tid_counters_mu); + auto it = g_tid_counters.find(tid); + return it == g_tid_counters.end() ? 0 : it->second; +} + +// Process-start ns for the host_ns field. Captured on first use; debug only. +std::chrono::steady_clock::time_point g_t0; +std::once_flag g_t0_once; + +void EnsureT0() { + std::call_once(g_t0_once, + []() { g_t0 = std::chrono::steady_clock::now(); }); +} + +int64_t HostNsSinceStart() { + EnsureT0(); + auto now = std::chrono::steady_clock::now(); + return std::chrono::duration_cast(now - g_t0) + .count(); +} + +void OpenIfNeeded() { + std::call_once(g_init_once, []() { + const std::string& path = cvars::phase_a_event_log_path; + if (path.empty()) { + g_state.store(2, std::memory_order_release); + return; + } + g_file = std::fopen(path.c_str(), "wb"); + if (!g_file) { + g_state.store(2, std::memory_order_release); + return; + } + g_state.store(1, std::memory_order_release); + // Write the schema header as the first line — synthetic tid=0. + auto header = fmt::format( + "{{\"schema_version\":1,\"engine\":\"canary\",\"kind\":\"schema_version" + "\",\"tid\":0,\"tid_event_idx\":0,\"guest_cycle\":0,\"host_ns\":{},\"" + "deterministic\":true,\"payload\":{{\"version\":1,\"emitter_build\":\"" + "canary-phaseA\"}}}}\n", + HostNsSinceStart()); + std::fwrite(header.data(), 1, header.size(), g_file); + std::fflush(g_file); + }); +} + +uint32_t CurrentTid() { + // Phase C+15-α: AddHandle / RemoveHandle hooks can fire from boot + // code (XEX loader, kernel-state init) BEFORE any XThread exists. + // `XThread::GetCurrentThreadId` asserts in that case. Use the + // safe `TryGetCurrentThread` accessor (returns null instead of + // asserting). Return 0 (synthetic "no-thread" tid) when not in a + // guest thread, matching ours's `scheduler.current == None` + // semantics during boot init. + XThread* t = XThread::TryGetCurrentThread(); + if (!t) { + return 0; + } + return t->guest_object()->thread_id; +} + +void WriteLine(const std::string& line) { + std::lock_guard lock(g_file_mu); + if (!g_file) return; + std::fwrite(line.data(), 1, line.size(), g_file); + std::fputc('\n', g_file); + // Flush every line so a crash mid-boot still produces a useful prefix. + std::fflush(g_file); +} + +// Common-fields prefix. Caller appends `,\"payload\":{...}}`. +// kind, tid, tid_event_idx, guest_cycle=0 (canary has no kernel-layer cycle), +// host_ns, deterministic, engine. +std::string CommonPrefix(const char* kind, uint32_t tid, uint64_t idx, + bool deterministic) { + return fmt::format( + "{{\"schema_version\":1,\"engine\":\"canary\",\"kind\":\"{}\",\"tid\":{}," + "\"tid_event_idx\":{},\"guest_cycle\":0,\"host_ns\":{},\"deterministic\":" + "{}", + kind, tid, idx, HostNsSinceStart(), deterministic ? "true" : "false"); +} + +// Escape a JSON string. Keep it minimal — kernel names are ASCII. +std::string EscapeJson(const char* s) { + if (!s) return "null"; + std::string out; + out.reserve(std::strlen(s) + 2); + for (const char* p = s; *p; ++p) { + unsigned char c = static_cast(*p); + if (c == '\\' || c == '"') { + out.push_back('\\'); + out.push_back(static_cast(c)); + } else if (c == '\n') { + out += "\\n"; + } else if (c == '\r') { + out += "\\r"; + } else if (c == '\t') { + out += "\\t"; + } else if (c < 0x20) { + out += fmt::format("\\u{:04x}", c); + } else { + out.push_back(static_cast(c)); + } + } + return out; +} + +} // namespace + +bool IsEnabled() { + int s = g_state.load(std::memory_order_acquire); + if (s == 0) { + OpenIfNeeded(); + s = g_state.load(std::memory_order_acquire); + } + return s == 1; +} + +uint64_t PeekTidEventIdx() { return PeekTidEventIdxLocked(CurrentTid()); } + +uint64_t ComputeSemanticId(uint32_t create_site_pc, uint32_t creating_tid, + uint64_t tid_event_idx_at_creation, + uint32_t object_type) { + uint8_t bytes[4 + 4 + 8 + 4]; + auto put_u32 = [&](size_t off, uint32_t v) { + bytes[off + 0] = static_cast(v & 0xFF); + bytes[off + 1] = static_cast((v >> 8) & 0xFF); + bytes[off + 2] = static_cast((v >> 16) & 0xFF); + bytes[off + 3] = static_cast((v >> 24) & 0xFF); + }; + auto put_u64 = [&](size_t off, uint64_t v) { + for (int i = 0; i < 8; ++i) + bytes[off + i] = static_cast((v >> (i * 8)) & 0xFF); + }; + put_u32(0, create_site_pc); + put_u32(4, creating_tid); + put_u64(8, tid_event_idx_at_creation); + put_u32(16, object_type); + uint64_t h = 0xCBF29CE484222325ULL; + for (size_t i = 0; i < sizeof(bytes); ++i) { + h ^= bytes[i]; + h *= 0x100000001B3ULL; + } + return h; +} + +void EmitSchemaHeader() { + if (!IsEnabled()) return; + // tid=0, tid_event_idx=0, deterministic=true. NOT consuming the per-tid + // counter (the header is on a synthetic tid 0). + std::string line = fmt::format( + "{{\"schema_version\":1,\"engine\":\"canary\",\"kind\":\"schema_version" + "\",\"tid\":0,\"tid_event_idx\":0,\"guest_cycle\":0,\"host_ns\":{},\"" + "deterministic\":true,\"payload\":{{\"version\":1,\"emitter_build\":\"" + "canary-phaseA\"}}}}", + HostNsSinceStart()); + WriteLine(line); +} + +void EmitImportCall(const char* module_name, uint16_t ordinal, + const char* fn_name) { + if (!IsEnabled()) return; + uint32_t tid = CurrentTid(); + uint64_t idx = NextTidEventIdx(tid); + std::string line = CommonPrefix("import.call", tid, idx, true); + line += fmt::format( + ",\"payload\":{{\"module\":\"{}\",\"ord\":{},\"name\":\"{}\"}}}}", + EscapeJson(module_name), ordinal, EscapeJson(fn_name)); + WriteLine(line); +} + +void EmitKernelCall(const char* name) { + if (!IsEnabled()) return; + uint32_t tid = CurrentTid(); + uint64_t idx = NextTidEventIdx(tid); + std::string line = CommonPrefix("kernel.call", tid, idx, true); + line += fmt::format(",\"payload\":{{\"name\":\"{}\",\"args\":{{}},\"args_" + "resolved\":{{}}}}}}", + EscapeJson(name)); + WriteLine(line); +} + +// Phase C+10 schema-v1 extension: emit a `kernel.call` event whose +// `args_resolved` field includes a `"path"` entry. The path string is +// the canonical post-prefix-strip form (forward slashes, leading +// device prefix removed). When `path` is null/empty, degrades to the +// existing empty-args_resolved form so output is byte-identical to +// the pre-extension behavior for unknown export names. +void EmitKernelCallWithPath(const char* name, const char* path) { + if (!IsEnabled()) return; + uint32_t tid = CurrentTid(); + uint64_t idx = NextTidEventIdx(tid); + std::string line = CommonPrefix("kernel.call", tid, idx, true); + if (path && *path) { + line += fmt::format( + ",\"payload\":{{\"name\":\"{}\",\"args\":{{}},\"args_resolved\":" + "{{\"path\":\"{}\"}}}}}}", + EscapeJson(name), EscapeJson(path)); + } else { + line += fmt::format(",\"payload\":{{\"name\":\"{}\",\"args\":{{}},\"args_" + "resolved\":{{}}}}}}", + EscapeJson(name)); + } + WriteLine(line); +} + +void EmitKernelReturn(const char* name, uint64_t return_value) { + if (!IsEnabled()) return; + uint32_t tid = CurrentTid(); + uint64_t idx = NextTidEventIdx(tid); + std::string line = CommonPrefix("kernel.return", tid, idx, true); + line += fmt::format( + ",\"payload\":{{\"name\":\"{}\",\"return_value\":{},\"status\":\"0x{:08x}" + "\",\"side_effects\":[]}}}}", + EscapeJson(name), return_value, static_cast(return_value)); + WriteLine(line); +} + +void EmitHandleCreate(uint64_t semantic_id, uint32_t object_type, + uint32_t raw_handle_id, const char* object_name) { + if (!IsEnabled()) return; + uint32_t tid = CurrentTid(); + uint64_t idx = NextTidEventIdx(tid); + std::string line = CommonPrefix("handle.create", tid, idx, true); + if (object_name && *object_name) { + line += fmt::format( + ",\"payload\":{{\"handle_semantic_id\":\"{:016x}\",\"object_type\":{}," + "\"object_name\":\"{}\",\"raw_handle_id\":\"0x{:08x}\"}}}}", + semantic_id, object_type, EscapeJson(object_name), raw_handle_id); + } else { + line += fmt::format( + ",\"payload\":{{\"handle_semantic_id\":\"{:016x}\",\"object_type\":{}," + "\"object_name\":null,\"raw_handle_id\":\"0x{:08x}\"}}}}", + semantic_id, object_type, raw_handle_id); + } + WriteLine(line); +} + +void EmitHandleDestroy(uint64_t semantic_id, uint32_t raw_handle_id, + uint32_t prior_refcount) { + if (!IsEnabled()) return; + uint32_t tid = CurrentTid(); + uint64_t idx = NextTidEventIdx(tid); + std::string line = CommonPrefix("handle.destroy", tid, idx, true); + line += fmt::format( + ",\"payload\":{{\"handle_semantic_id\":\"{:016x}\",\"raw_handle_id\":\"" + "0x{:08x}\",\"prior_refcount\":{}}}}}", + semantic_id, raw_handle_id, prior_refcount); + WriteLine(line); +} + +void EmitThreadCreate(uint64_t semantic_id, uint32_t parent_tid, + uint32_t entry_pc, uint32_t ctx_ptr, uint32_t priority, + uint32_t affinity, uint32_t stack_size, bool suspended) { + if (!IsEnabled()) return; + uint32_t tid = CurrentTid(); + uint64_t idx = NextTidEventIdx(tid); + std::string line = CommonPrefix("thread.create", tid, idx, true); + line += fmt::format( + ",\"payload\":{{\"handle_semantic_id\":\"{:016x}\",\"parent_tid\":{}," + "\"entry_pc\":\"0x{:08x}\",\"ctx_ptr\":\"0x{:08x}\",\"priority\":{}," + "\"affinity\":{},\"stack_size\":{},\"suspended\":{}}}}}", + semantic_id, parent_tid, entry_pc, ctx_ptr, priority, affinity, + stack_size, suspended ? "true" : "false"); + WriteLine(line); +} + +void EmitThreadExit(uint32_t exit_code) { + if (!IsEnabled()) return; + uint32_t tid = CurrentTid(); + uint64_t idx = NextTidEventIdx(tid); + std::string line = CommonPrefix("thread.exit", tid, idx, true); + line += fmt::format(",\"payload\":{{\"exit_code\":{}}}}}", exit_code); + WriteLine(line); +} + +void EmitWaitBegin(const uint64_t* handles_semantic_ids, uint32_t count, + int64_t timeout_ns, bool alertable, bool wait_all) { + if (!IsEnabled()) return; + uint32_t tid = CurrentTid(); + uint64_t idx = NextTidEventIdx(tid); + std::string line = CommonPrefix("wait.begin", tid, idx, true); + std::string ids = "["; + for (uint32_t i = 0; i < count; ++i) { + if (i) ids += ","; + ids += fmt::format("\"{:016x}\"", handles_semantic_ids[i]); + } + ids += "]"; + line += fmt::format( + ",\"payload\":{{\"handles_semantic_ids\":{},\"timeout_ns\":{}," + "\"alertable\":{},\"wait_type\":\"{}\"}}}}", + ids, timeout_ns, alertable ? "true" : "false", + wait_all ? "all" : "any"); + WriteLine(line); +} + +void EmitWaitEnd(uint32_t status, uint64_t woken_by_semantic_id_or_zero) { + if (!IsEnabled()) return; + uint32_t tid = CurrentTid(); + uint64_t idx = NextTidEventIdx(tid); + std::string line = CommonPrefix("wait.end", tid, idx, false); + if (woken_by_semantic_id_or_zero) { + line += fmt::format( + ",\"payload\":{{\"status\":\"0x{:08x}\",\"woken_by_semantic_id\":\"" + "{:016x}\",\"wait_duration_cycles\":0}}}}", + status, woken_by_semantic_id_or_zero); + } else { + line += fmt::format( + ",\"payload\":{{\"status\":\"0x{:08x}\",\"woken_by_semantic_id\":null," + "\"wait_duration_cycles\":0}}}}", + status); + } + WriteLine(line); +} + +// ===== Phase C+15-α — Handle semantic ID registry ===== +namespace { +std::unordered_map g_handle_sids; +std::mutex g_handle_sids_mu; +} // namespace + +void RegisterHandleSemanticId(uint32_t raw_handle_id, uint64_t sid) { + if (!IsEnabled()) return; + std::lock_guard lock(g_handle_sids_mu); + g_handle_sids[raw_handle_id] = sid; +} + +uint64_t LookupHandleSemanticId(uint32_t raw_handle_id) { + std::lock_guard lock(g_handle_sids_mu); + auto it = g_handle_sids.find(raw_handle_id); + return it == g_handle_sids.end() ? 0 : it->second; +} + +uint64_t ForgetHandleSemanticId(uint32_t raw_handle_id) { + std::lock_guard lock(g_handle_sids_mu); + auto it = g_handle_sids.find(raw_handle_id); + if (it == g_handle_sids.end()) return 0; + uint64_t sid = it->second; + g_handle_sids.erase(it); + return sid; +} + +uint64_t EmitHandleCreateAuto(uint32_t create_site_pc, uint32_t object_type, + uint32_t raw_handle_id, + const char* object_name) { + if (!IsEnabled()) return 0; + uint32_t tid = CurrentTid(); + uint64_t idx_at_creation = PeekTidEventIdxLocked(tid); + uint64_t sid = + ComputeSemanticId(create_site_pc, tid, idx_at_creation, object_type); + RegisterHandleSemanticId(raw_handle_id, sid); + EmitHandleCreate(sid, object_type, raw_handle_id, object_name); + return sid; +} + +void EmitHandleDestroyAuto(uint32_t raw_handle_id, uint32_t prior_refcount) { + if (!IsEnabled()) return; + uint64_t sid = ForgetHandleSemanticId(raw_handle_id); + EmitHandleDestroy(sid, raw_handle_id, prior_refcount); +} + +// ===== Phase C+18 — Shared-global SIDs ===== + +uint64_t ComputeSharedGlobalSemanticId(uint32_t pointer, uint32_t object_type) { + // Reuse the same FNV-1a recipe as `ComputeSemanticId` but with inputs + // chosen to be scheduling-invariant: + // create_site_pc = kSharedGlobalSidMarker (distinguishes from regular SIDs) + // creating_tid = 0 + // tid_event_idx_at_creation = pointer (as u64) + // object_type = object_type + // Matches `event_log.rs::semantic_id_shared_global` byte-for-byte. + return ComputeSemanticId(kSharedGlobalSidMarker, 0, + static_cast(pointer), object_type); +} + +void EmitHandleCreateSharedGlobal(uint32_t pointer, uint32_t object_type, + uint32_t raw_handle_id, + const char* object_name) { + if (!IsEnabled()) return; + uint64_t sid = ComputeSharedGlobalSemanticId(pointer, object_type); + RegisterHandleSemanticId(raw_handle_id, sid); + EmitHandleCreate(sid, object_type, raw_handle_id, object_name); +} + +// Phase C+18: per-host-thread flag that the AddHandle hook checks to +// skip its `EmitHandleCreateAuto` call for XObjects synthesized by +// `XObject::GetNativeObject` (a single boolean — the global critical +// region is held across the GetNativeObject body so re-entrancy isn't +// expected). +namespace { +thread_local bool t_in_get_native_object = false; +} // namespace + +void SetInGetNativeObject(bool active) { t_in_get_native_object = active; } +bool IsInGetNativeObject() { return t_in_get_native_object; } + +// ===== Phase D Stage 1 — contention.observed ===== + +void EmitContentionObserved(uint32_t cs_guest_ptr, bool contended) { + // Two-gate fast path: cvar OFF is the default and must be byte-identical + // to pre-Stage-1 canary. The cvar is checked first to short-circuit even + // when the phase A event log itself is enabled (Stage 0/baseline cold + // runs may have event log on but contention emit off). + if (!cvars::kernel_emit_contention) return; + if (!IsEnabled()) return; + uint32_t tid = CurrentTid(); + uint64_t idx = NextTidEventIdx(tid); + uint64_t site_sid = + ComputeSharedGlobalSemanticId(cs_guest_ptr, kObjCriticalSection); + std::string line = CommonPrefix("contention.observed", tid, idx, true); + line += fmt::format( + ",\"payload\":{{\"cs_ptr\":\"0x{:08x}\",\"site_sid\":\"{:016x}\"," + "\"contended\":{}}}}}", + cs_guest_ptr, site_sid, contended ? "true" : "false"); + WriteLine(line); +} + +// ── Expansive extraction tracing (game-data RE) ──────────────────────────── +// All gated by `phase_a_trace_args` / `phase_a_hash_probe` (default off), so +// with those unset the JSONL output is byte-identical to the diff-schema form. + +// kernel.call with populated `args` (raw r3..r10) and `args_resolved` +// (currently the resolved file path, when known). `ppc_context` is a +// PPCContext* passed as void* to keep the header free of the PPC include. +void EmitKernelCallArgs(const char* name, void* ppc_context, + const char* resolved_path) { + if (!IsEnabled()) return; + auto* ctx = reinterpret_cast<::xe::cpu::ppc::PPCContext*>(ppc_context); + uint32_t tid = CurrentTid(); + uint64_t idx = NextTidEventIdx(tid); + std::string line = CommonPrefix("kernel.call", tid, idx, true); + std::string args; + if (ctx) { + args = fmt::format( + "\"r3\":{},\"r4\":{},\"r5\":{},\"r6\":{},\"r7\":{},\"r8\":{},\"r9\":{}," + "\"r10\":{}", + ctx->r[3], ctx->r[4], ctx->r[5], ctx->r[6], ctx->r[7], ctx->r[8], + ctx->r[9], ctx->r[10]); + } + std::string resolved; + if (resolved_path && *resolved_path) { + resolved = fmt::format("\"path\":\"{}\"", EscapeJson(resolved_path)); + } + line += fmt::format( + ",\"payload\":{{\"name\":\"{}\",\"args\":{{{}}},\"args_resolved\":{{{}}}}}}}", + EscapeJson(name), args, resolved); + WriteLine(line); +} + +// file.read — a guest read from an open file handle. `path` is resolved from +// the handle via the object table; `offset` is the requested byte offset. +void EmitFileRead(uint32_t handle, const char* path, uint64_t offset, + uint32_t length, uint32_t buffer_va) { + if (!IsEnabled()) return; + uint32_t tid = CurrentTid(); + uint64_t idx = NextTidEventIdx(tid); + std::string line = CommonPrefix("file.read", tid, idx, true); + line += fmt::format( + ",\"payload\":{{\"handle\":\"0x{:08x}\",\"path\":\"{}\",\"offset\":{}," + "\"length\":{},\"buffer_va\":\"0x{:08x}\"}}}}", + handle, EscapeJson(path), offset, length, buffer_va); + WriteLine(line); +} + +// guest.call — fired by the guest-PC hash probe (Tier 3). `arg_str` is r3 +// dereferenced as a guest C-string (the archive path being hashed). +void EmitGuestCall(uint32_t pc, const char* arg_str, uint32_t r3, uint32_t r4, + uint32_t r5, uint32_t r6) { + if (!IsEnabled()) return; + uint32_t tid = CurrentTid(); + uint64_t idx = NextTidEventIdx(tid); + std::string line = CommonPrefix("guest.call", tid, idx, true); + line += fmt::format( + ",\"payload\":{{\"pc\":\"0x{:08x}\",\"arg_str\":\"{}\",\"r3\":\"0x{:08x}\"," + "\"r4\":\"0x{:08x}\",\"r5\":\"0x{:08x}\",\"r6\":\"0x{:08x}\"}}}}", + pc, EscapeJson(arg_str), r3, r4, r5, r6); + WriteLine(line); +} + +} // namespace phase_a + +// Bridge entry points referenced from shim_utils.h. Defined here so the +// template-heavy header does not need to include event_log.h directly. +namespace shim { +namespace phase_a_bridge { + +namespace { + +// Phase C+10: read an OBJECT_ATTRIBUTES* guest address and return the +// raw ANSI_STRING path (trimmed). Empty/null returns std::string(). +// Mirrors ours's `path::object_attributes_raw_name`. +std::string ReadObjectAttributesRawName(uint32_t obj_attrs_ptr) { + if (!obj_attrs_ptr) return std::string(); + auto* ks = ::xe::kernel::KernelState::shared(); + if (!ks) return std::string(); + auto* memory = ks->memory(); + if (!memory) return std::string(); + auto* obj_attrs = + memory->TranslateVirtual<::xe::kernel::X_OBJECT_ATTRIBUTES*>( + obj_attrs_ptr); + if (!obj_attrs) return std::string(); + uint32_t name_ptr = obj_attrs->name_ptr; + if (!name_ptr) return std::string(); + auto* ansi = + memory->TranslateVirtual<::xe::kernel::X_ANSI_STRING*>(name_ptr); + if (!ansi) return std::string(); + uint16_t length = ansi->length; + uint32_t buffer = ansi->pointer; + if (!length || !buffer) return std::string(); + auto* bytes = memory->TranslateVirtual(buffer); + if (!bytes) return std::string(); + std::string raw(bytes, length); + // Strip trailing NULs that some callers include in the byte count. + while (!raw.empty() && raw.back() == '\0') raw.pop_back(); + // Trim whitespace (mirror canary's `string_util::trim`). + auto first = raw.find_first_not_of(" \t\r\n"); + auto last = raw.find_last_not_of(" \t\r\n"); + if (first == std::string::npos) return std::string(); + return raw.substr(first, last - first + 1); +} + +// Phase C+11 — read an `X_FILE_RENAME_INFORMATION` buffer's rename +// target ANSI_STRING. Layout per `info/file.h:79-83` (16 bytes): +// offset 0 be replace_existing +// offset 4 be root_dir_handle +// offset 8 X_ANSI_STRING { u16 Length, u16 MaxLength, u32 Buffer } +// Caller is expected to check `info_length >= 16` before invoking. +// Mirrors ours's `path::file_rename_information_raw_target`. +std::string ReadFileRenameInformationRawTarget(uint32_t info_ptr, + uint32_t info_length) { + if (!info_ptr || info_length < 16) return std::string(); + auto* ks = ::xe::kernel::KernelState::shared(); + if (!ks) return std::string(); + auto* memory = ks->memory(); + if (!memory) return std::string(); + auto* ansi = memory->TranslateVirtual<::xe::kernel::X_ANSI_STRING*>( + info_ptr + 8); + if (!ansi) return std::string(); + uint16_t length = ansi->length; + uint32_t buffer = ansi->pointer; + if (!length || !buffer) return std::string(); + auto* bytes = memory->TranslateVirtual(buffer); + if (!bytes) return std::string(); + std::string raw(bytes, length); + while (!raw.empty() && raw.back() == '\0') raw.pop_back(); + auto first = raw.find_first_not_of(" \t\r\n"); + auto last = raw.find_last_not_of(" \t\r\n"); + if (first == std::string::npos) return std::string(); + return raw.substr(first, last - first + 1); +} + +// Phase C+10/C+11: known path-bearing exports. Returns the empty string +// for any export whose name is not in the set OR whose OBJECT_ATTRIBUTES* +// arg is null. Argument positions verified against canary's +// `xboxkrnl_io.cc` / `xboxkrnl_io_info.cc` signatures. +std::string ResolvePathArg(const char* name, + ::xe::cpu::ppc::PPCContext* ctx) { + if (!name || !ctx) return std::string(); + // r3..r7 only — narrow the dispatch by first char to keep the + // hot-path branch table tight. + if (name[0] != 'N') return std::string(); + // NtQueryFullAttributesFile: r3 = obj_attrs + if (std::strcmp(name, "NtQueryFullAttributesFile") == 0) { + return ReadObjectAttributesRawName(static_cast(ctx->r[3])); + } + // NtOpenSymbolicLinkObject: r4 = obj_attrs + if (std::strcmp(name, "NtOpenSymbolicLinkObject") == 0) { + return ReadObjectAttributesRawName(static_cast(ctx->r[4])); + } + // NtCreateFile, NtOpenFile: r5 = obj_attrs + if (std::strcmp(name, "NtCreateFile") == 0 || + std::strcmp(name, "NtOpenFile") == 0) { + return ReadObjectAttributesRawName(static_cast(ctx->r[5])); + } + // NtSetInformationFile: r5 = info_ptr, r6 = info_length, r7 = info_class. + // Surface the rename target path when info_class==10 + // (XFileRenameInformation). Mirrors ours's C+11 dispatch in + // `crates/xenia-kernel/src/state.rs` call_export. + if (std::strcmp(name, "NtSetInformationFile") == 0 && + static_cast(ctx->r[7]) == 10) { + return ReadFileRenameInformationRawTarget( + static_cast(ctx->r[5]), + static_cast(ctx->r[6])); + } + return std::string(); +} + +} // namespace + +bool Enabled() { return ::xe::kernel::phase_a::IsEnabled(); } +void EmitImportAndCall(const char* module_name, uint16_t ord, + const char* name) { + ::xe::kernel::phase_a::EmitImportCall(module_name, ord, name); + ::xe::kernel::phase_a::EmitKernelCall(name); +} +// Tier 2: for NtReadFile, resolve the handle to its file path (object table) +// and emit a file.read event with the requested byte offset / length / buffer. +// NtReadFile(r3=FileHandle, .., r8=Buffer, r9=Length, r10=ByteOffset*). +void MaybeEmitFileRead(const char* name, ::xe::cpu::ppc::PPCContext* ctx) { + if (!ctx || std::strcmp(name, "NtReadFile") != 0) return; + auto* ks = ::xe::kernel::KernelState::shared(); + if (!ks) return; + auto* memory = ks->memory(); + uint32_t handle = static_cast(ctx->r[3]); + uint32_t buffer = static_cast(ctx->r[8]); + uint32_t length = static_cast(ctx->r[9]); + uint32_t byteoff_ptr = static_cast(ctx->r[10]); + uint64_t offset = 0; + if (byteoff_ptr && memory) { + auto* p = memory->TranslateVirtual<::xe::be*>(byteoff_ptr); + if (p) offset = static_cast(*p); + } + std::string path; + auto file = ks->object_table()->LookupObject<::xe::kernel::XFile>(handle); + if (file) path = file->path(); + ::xe::kernel::phase_a::EmitFileRead(handle, path.c_str(), offset, length, + buffer); +} + +void EmitImportAndCallWithCtx(const char* module_name, uint16_t ord, + const char* name, void* ppc_context) { + ::xe::kernel::phase_a::EmitImportCall(module_name, ord, name); + auto* ctx = reinterpret_cast<::xe::cpu::ppc::PPCContext*>(ppc_context); + std::string path = ResolvePathArg(name, ctx); + if (cvars::phase_a_trace_args) { + // Extraction mode: raw GPR args + resolved path, plus file.read detail. + ::xe::kernel::phase_a::EmitKernelCallArgs( + name, ppc_context, path.empty() ? nullptr : path.c_str()); + MaybeEmitFileRead(name, ctx); + return; + } + if (!path.empty()) { + ::xe::kernel::phase_a::EmitKernelCallWithPath(name, path.c_str()); + } else { + ::xe::kernel::phase_a::EmitKernelCall(name); + } +} +void EmitReturn(const char* name, uint64_t return_value) { + ::xe::kernel::phase_a::EmitKernelReturn(name, return_value); +} +} // namespace phase_a_bridge +} // namespace shim + +} // namespace kernel +} // namespace xe diff --git a/src/xenia/kernel/event_log.h b/src/xenia/kernel/event_log.h new file mode 100644 index 000000000..5845bcd67 --- /dev/null +++ b/src/xenia/kernel/event_log.h @@ -0,0 +1,191 @@ +/** + ****************************************************************************** + * Xenia : Xbox 360 Emulator Research Project * + ****************************************************************************** + * Phase A event-log emitter. Cvar-gated (default off). Schema v1. + * Companion: xenia-rs/audit-runs/phase-a-diff-harness/schema-v1.md + ****************************************************************************** + */ + +#ifndef XENIA_KERNEL_EVENT_LOG_H_ +#define XENIA_KERNEL_EVENT_LOG_H_ + +#include + +namespace xe { +namespace kernel { +namespace phase_a { + +// Object-type codes (must match ours's enum exactly — see schema-v1.md). +enum ObjectType : uint32_t { + kObjUnknown = 0x00, + kObjEvent = 0x01, + kObjMutant = 0x02, + kObjSemaphore = 0x03, + kObjTimer = 0x04, + kObjThread = 0x05, + kObjFile = 0x06, + kObjIoCompletion = 0x07, + kObjModule = 0x08, + kObjEnumState = 0x09, + kObjSection = 0x0A, + kObjNotification = 0x0B, + // Phase D Stage 1: pseudo-type used as the `object_type` input to + // `ComputeSharedGlobalSemanticId` for RTL_CRITICAL_SECTION pointers. CS + // is not a regular `XObject` (it lives as a guest-memory struct, not a + // handle-tabled kernel object), but the `site_sid` field of + // `contention.observed` reuses the shared-global SID recipe so the + // Stage-3 manifest loader can compute the same SID in both engines. + kObjCriticalSection = 0x0C, +}; + +// Fast bool check (default off). Inlinable so we can guard hot paths cheaply. +bool IsEnabled(); + +// Emitted once at startup if enabled (first line of the JSONL). +void EmitSchemaHeader(); + +// FNV-1a 64-bit identity (see schema-v1.md). Both engines compute identically. +uint64_t ComputeSemanticId(uint32_t create_site_pc, uint32_t creating_tid, + uint64_t tid_event_idx_at_creation, + uint32_t object_type); + +// One emit per imported kernel function invocation. Emitted by the export +// trampoline before the kernel.call event. +void EmitImportCall(const char* module_name, uint16_t ordinal, + const char* fn_name); + +// Kernel call entry / return. args/args_resolved are deferred to a later +// phase; v1 emits the name + return value only (sufficient for the diff +// tool to align by sequence). +void EmitKernelCall(const char* name); +// Phase C+10: schema-v1 extension — emit kernel.call whose +// `args_resolved` field carries a resolved `"path"` value (see +// schema-v1.md kernel.call payload). `path == nullptr || *path == '\0'` +// degrades to the existing empty-args_resolved form. +void EmitKernelCallWithPath(const char* name, const char* path); +void EmitKernelReturn(const char* name, uint64_t return_value); + +// Handle lifecycle. raw_handle_id is engine-local; the diff key is the +// FNV-1a semantic id. +void EmitHandleCreate(uint64_t semantic_id, uint32_t object_type, + uint32_t raw_handle_id, const char* object_name); +void EmitHandleDestroy(uint64_t semantic_id, uint32_t raw_handle_id, + uint32_t prior_refcount); + +// Thread create/exit. parent_tid is the caller; entry_pc is the spawned +// thread's first instruction. +void EmitThreadCreate(uint64_t semantic_id, uint32_t parent_tid, + uint32_t entry_pc, uint32_t ctx_ptr, uint32_t priority, + uint32_t affinity, uint32_t stack_size, bool suspended); +void EmitThreadExit(uint32_t exit_code); + +// Wait begin/end. handles_count + handles_semantic_ids array. +void EmitWaitBegin(const uint64_t* handles_semantic_ids, uint32_t count, + int64_t timeout_ns, bool alertable, bool wait_all); +void EmitWaitEnd(uint32_t status, uint64_t woken_by_semantic_id_or_zero); + +// Returns the next per-tid event index (post-increment). Useful for +// `tid_event_idx_at_creation` capture before calling ComputeSemanticId. +uint64_t PeekTidEventIdx(); + +// Phase C+15-α: handle-semantic-ID registry. Maps raw handle id -> +// FNV-1a 64-bit SID assigned at handle creation, so subsequent +// `handle.destroy` / `wait.begin` / etc. events can emit a stable +// cross-engine identity. No-op when event_log is disabled. +void RegisterHandleSemanticId(uint32_t raw_handle_id, uint64_t sid); +uint64_t LookupHandleSemanticId(uint32_t raw_handle_id); +uint64_t ForgetHandleSemanticId(uint32_t raw_handle_id); + +// Convenience: at handle creation time, peek tid_event_idx, compute +// the FNV-1a SID, register it for `raw_handle_id`, and emit a +// `handle.create` event. Returns the SID. `create_site_pc` is set to +// 0 by callers that cannot resolve a guest LR — both engines agree +// on `0` for canonicalization at v1.1. +uint64_t EmitHandleCreateAuto(uint32_t create_site_pc, uint32_t object_type, + uint32_t raw_handle_id, + const char* object_name); + +// Convenience: forget mapping + emit `handle.destroy` with the +// previously registered SID. +void EmitHandleDestroyAuto(uint32_t raw_handle_id, uint32_t prior_refcount); + +// Phase C+18: marker constant used as `create_site_pc` in shared-global +// SID computation. Both engines must use exactly this value. See +// schema-v1.md §"Shared-global SIDs". +constexpr uint32_t kSharedGlobalSidMarker = 0xC01AB005; + +// Phase C+18: compute the scheduling-invariant SID for a +// **process-global** kernel dispatcher (canary's +// `XObject::GetNativeObject` lazy-wrap on first guest-thread touch). +// Keyed on `(SHARED_GLOBAL_SID_MARKER, 0, pointer, object_type)` so the +// SID depends only on the object's identity, not on the scheduling order. +uint64_t ComputeSharedGlobalSemanticId(uint32_t pointer, uint32_t object_type); + +// Phase C+18: emit `handle.create` with a scheduling-invariant SID for +// a process-global kernel dispatcher synthesized by +// `XObject::GetNativeObject`. The SID is computed via +// `ComputeSharedGlobalSemanticId(pointer, object_type)` so the same +// dispatcher yields the same SID in both engines regardless of which +// guest thread happens to be the first toucher. `raw_handle_id` is the +// XObject's allocated handle; `pointer` is the guest dispatcher +// (`X_DISPATCH_HEADER*`) pointer (used only to derive the SID). +// +// Caller MUST avoid the regular AddHandle emit for this XObject (set +// the in-flight thread-local marker around the `new XEvent` / +// `new XSemaphore` ctor and have the AddHandle hook short-circuit). +void EmitHandleCreateSharedGlobal(uint32_t pointer, uint32_t object_type, + uint32_t raw_handle_id, + const char* object_name); + +// Phase C+18: thread-local flag indicating the current host thread is +// inside `XObject::GetNativeObject` lazy-wrap, which constructs a new +// XEvent/XSemaphore wrapper for a process-global guest dispatcher. +// `AddHandle` consults this to skip its regular per-thread +// `handle.create` emit; the explicit shared-global emit happens in +// `GetNativeObject` after `StashHandle`. The flag is a single +// host-thread-local bool — re-entrancy is not expected (the global +// critical region is held throughout). +void SetInGetNativeObject(bool active); +bool IsInGetNativeObject(); + +// Phase D Stage 1: emit a `contention.observed` event from +// `RtlEnterCriticalSection_entry` when the spin-loop is exhausted and +// control falls through to `xeKeWaitForSingleObject`. The Stage-2 manifest +// builder filters on `contended=true` and keys on `(tid, tid_event_idx)` +// so the Stage-3 replay loop in ours can park its own `rtl_enter_critical_section` +// at exactly the same per-tid ordinal. +// +// `cs_guest_ptr` is the guest VA of the `X_RTL_CRITICAL_SECTION` (the +// argument to RtlEnterCS). `site_sid` is computed via +// `ComputeSharedGlobalSemanticId(cs_guest_ptr, kObjCriticalSection)` so +// both engines agree on the SID for the same CS pointer. +// +// Gated on `cvars::kernel_emit_contention && IsEnabled()`. Default +// behavior (cvar off) is byte-identical to pre-Stage-1 canary. +void EmitContentionObserved(uint32_t cs_guest_ptr, bool contended); + +// ── Expansive extraction tracing (game-data RE; gated by phase_a_trace_args / +// phase_a_hash_probe, default off) ───────────────────────────────────────── + +// kernel.call with populated `args` (raw r3..r10 from the PPCContext, passed +// as void*) and `args_resolved` (the resolved file path when known). +void EmitKernelCallArgs(const char* name, void* ppc_context, + const char* resolved_path); + +// file.read — a guest read from an open file handle (path resolved from the +// handle via the object table). Enables correlating .pak reads to TOC entries. +void EmitFileRead(uint32_t handle, const char* path, uint64_t offset, + uint32_t length, uint32_t buffer_va); + +// guest.call — emitted by the guest-PC hash probe: `arg_str` is r3 dereferenced +// as a guest C-string (the archive path being hashed). Used to recover the +// custom IPFB/IDXD name-hash by observing (string -> hash) pairs. +void EmitGuestCall(uint32_t pc, const char* arg_str, uint32_t r3, uint32_t r4, + uint32_t r5, uint32_t r6); + +} // namespace phase_a +} // namespace kernel +} // namespace xe + +#endif // XENIA_KERNEL_EVENT_LOG_H_ diff --git a/src/xenia/kernel/util/shim_utils.h b/src/xenia/kernel/util/shim_utils.h index 0bb1786ea..6cb637949 100644 --- a/src/xenia/kernel/util/shim_utils.h +++ b/src/xenia/kernel/util/shim_utils.h @@ -479,6 +479,29 @@ enum class KernelModuleId { xbdm, }; +// Phase A bridge — see kernel/event_log.h. Declared inline here to avoid +// pulling the event_log / PPCContext headers into shim_utils.h's transitive +// include set. Zero-cost when --phase_a_event_log_path is unset (Enabled() +// returns false and the hooks are skipped). +namespace phase_a_bridge { +constexpr const char* KernelModuleIdName(KernelModuleId m) { + switch (m) { + case KernelModuleId::xboxkrnl: return "xboxkrnl.exe"; + case KernelModuleId::xam: return "xam.xex"; + case KernelModuleId::xbdm: return "xbdm.xex"; + } + return "unknown"; +} +bool Enabled(); +void EmitReturn(const char* name, uint64_t return_value); +// Resolves path-bearing export args (OBJECT_ATTRIBUTES*, handles) from the PPC +// context and, under --phase_a_trace_args, fills args/args_resolved and emits +// file.read events. `ppc_context` is a void* to keep PPCContext out of this +// header's transitive includes. +void EmitImportAndCallWithCtx(const char* module_name, uint16_t ord, + const char* name, void* ppc_context); +} // namespace phase_a_bridge + template requires(I == sizeof...(Ps)) void AppendKernelCallParams(StringBuffer& string_buffer, @@ -558,14 +581,26 @@ struct ExportRegistrerHelper { cvars::log_high_frequency_kernel_calls)) { PrintKernelCall(export_entry, params); } + const bool phase_a_on = phase_a_bridge::Enabled(); + if (phase_a_on) { + phase_a_bridge::EmitImportAndCallWithCtx( + phase_a_bridge::KernelModuleIdName(MODULE), ORDINAL, + export_entry->name, ppc_context); + } if constexpr (std::is_void::value) { KernelTrampoline(fn, std::forward>(params), std::make_index_sequence()); + if (phase_a_on) { + phase_a_bridge::EmitReturn(export_entry->name, 0); + } } else { auto result = KernelTrampoline(fn, std::forward>(params), std::make_index_sequence()); result.Store(ppc_context); + if (phase_a_on) { + phase_a_bridge::EmitReturn(export_entry->name, 0); + } if (TAGS & (xe::cpu::ExportTag::kLog | xe::cpu::ExportTag::kLogResult)) { // TODO(benvanik): log result. From 0aa3eadca7ab7af90e95521b1dc0075a5689e388 Mon Sep 17 00:00:00 2001 From: MechaCat02 Date: Mon, 13 Jul 2026 20:42:54 +0200 Subject: [PATCH 2/7] [Kernel] Add null-safe XThread::TryGetCurrentThread() accessor The additive event_log extraction tracer needs a current-thread lookup that returns nullptr instead of asserting when called from boot code before any XThread exists (GetCurrentThread asserts on non-guest threads). New read-only static accessor over the thread-local; no behaviour change. Fixes the native Linux build of the phase-a args/file.read tracer. Co-Authored-By: Claude Opus 4.8 --- src/xenia/kernel/xthread.cc | 2 ++ src/xenia/kernel/xthread.h | 5 +++++ 2 files changed, 7 insertions(+) diff --git a/src/xenia/kernel/xthread.cc b/src/xenia/kernel/xthread.cc index e2c4ecedc..657c0fb37 100644 --- a/src/xenia/kernel/xthread.cc +++ b/src/xenia/kernel/xthread.cc @@ -117,6 +117,8 @@ XThread* XThread::GetCurrentThread() { return thread; } +XThread* XThread::TryGetCurrentThread() { return current_xthread_tls_; } + uint32_t XThread::GetCurrentThreadHandle() { XThread* thread = XThread::GetCurrentThread(); return thread->handle(); diff --git a/src/xenia/kernel/xthread.h b/src/xenia/kernel/xthread.h index 2c1e75856..31ec31398 100644 --- a/src/xenia/kernel/xthread.h +++ b/src/xenia/kernel/xthread.h @@ -408,6 +408,11 @@ class XThread : public XObject, public cpu::Thread { static bool IsInThread(XThread* other); static bool IsInThread(); static XThread* GetCurrentThread(); + // Null-safe variant of GetCurrentThread: returns nullptr (instead of + // asserting) when the calling OS thread is not a guest XThread. Used by + // additive instrumentation that can fire from boot code before any XThread + // exists. Read-only accessor; no behaviour change. + static XThread* TryGetCurrentThread(); static uint32_t GetCurrentThreadHandle(); static uint32_t GetCurrentThreadId(); From 7b6902e08f9d3d51fbf98c69c59944a6bbe2b2a4 Mon Sep 17 00:00:00 2001 From: MechaCat02 Date: Thu, 16 Jul 2026 22:43:50 +0200 Subject: [PATCH 3/7] [WIP] Audio/threading fixes + crash investigation; NEW ORACLE: crash is ours not the game Snapshot for handoff. Contains the mission-audio + threading fixes and the crash-investigation instrumentation (all diagnostic cvars default-OFF). Fixes (behavioral): - threading_posix.cc: reap-once guard on PosixCondition::post_execution (double pthread_join at mission teardown -> fault loop -> audio death + freeze). - xma_decoder.cc: work_event_->Set() in Pause() so the idle XMA worker observes paused_ and signals pause_fence_ (Pause() deadlock -> permanent audio death). - audio_system / xma_context_master / xboxkrnl_audio / apu_flags / alsa: mission audio keepalive + guest_audio_flags + watchdogs. Instrumentation (additive, default-off): xboxkrnl_debug cache-throw diag + guest-catch dispatcher, xex_module PE/PDATA/EH scans, kernel_state mem_watch (NOTE: mem_watch DEFAULTS TRUE -- an always-on host poll thread; prime crash suspect). NEW ORACLE (see HANDOFF-crash-oracle-2026-07-16.md): stock 6e5b8324f built with our toolchain + zero custom code = NO crash, NO sound-stop, plays the Ready Room. => the Ready-Room out_of_range crash is introduced by THESE changes, not the game and not the (LTO-broken) build chain. Bisection plan + suspect ranking in the note. Co-Authored-By: Claude Opus 4.8 --- HANDOFF-crash-oracle-2026-07-16.md | 93 ++++ src/xenia/apu/alsa/alsa_audio_driver.cc | 7 + src/xenia/apu/apu_flags.cc | 6 + src/xenia/apu/apu_flags.h | 1 + src/xenia/apu/audio_system.cc | 218 ++++++++- src/xenia/apu/audio_watchdog.h | 104 ++++ src/xenia/apu/xma_context_master.cc | 44 ++ src/xenia/apu/xma_decoder.cc | 9 + src/xenia/base/guest_liveness.h | 35 ++ src/xenia/base/threading_posix.cc | 12 + src/xenia/cpu/xex_module.cc | 83 ++++ src/xenia/emulator.cc | 129 +++++ src/xenia/emulator.h | 8 + src/xenia/kernel/kernel_state.cc | 75 +++ src/xenia/kernel/xboxkrnl/xboxkrnl_audio.cc | 21 +- src/xenia/kernel/xboxkrnl/xboxkrnl_debug.cc | 505 +++++++++++++++++++- src/xenia/kernel/xboxkrnl/xboxkrnl_io.cc | 9 + src/xenia/kernel/xboxkrnl/xboxkrnl_video.cc | 5 + src/xenia/memory.cc | 13 +- third_party/DirectXShaderCompiler | 2 +- 20 files changed, 1371 insertions(+), 8 deletions(-) create mode 100644 HANDOFF-crash-oracle-2026-07-16.md create mode 100644 src/xenia/apu/audio_watchdog.h create mode 100644 src/xenia/base/guest_liveness.h 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 From 201553aea3b28b2f2e1831a04432f641253bd0fb Mon Sep 17 00:00:00 2001 From: MechaCat02 Date: Thu, 23 Jul 2026 06:56:45 +0200 Subject: [PATCH 4/7] Instrument: file.read offset tracer + XMA-PARAM probe (voice RE) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Additive, cvar-gated instrumentation used to reverse-engineer Project Sylpheed's cutscene-voice storage (movie -> continuous sound-stream cue region). Default-off; no behaviour change. - event_log.cc: MaybeEmitFileRead emits `file.read` events with the real NtReadFile ByteOffset (from r10), length, handle->path, and buffer VA, so a sound.pNN read offset can be mapped to a sound.pak TOC entry. Gate: --phase_a_fileio_only=true --phase_a_event_log_path=. - cpu_flags.cc: phase_a_fileio_only cvar (+ xma_param_probe). - xma_context_new.cc: XMA-PARAM probe in XmaContextNew::Decode (the decoder the title actually uses) logging ctx/buffer/read-offset/channels/packets/byte_size /signature — to confirm which bytes get decoded for a given cutscene. Used to produce /tmp/rt_fileio.jsonl (RT01A playthrough), which cracked the movie->voice mapping now implemented in sylpheed-reborn. Next: run the same file.read trace on an unbound hokyu (e.g. hokyu_LS_s03A) to resolve which VOICE_D the game streams for the 13 manifest-unbound resupply cutscenes. Co-Authored-By: Claude Opus 4.8 --- src/xenia/apu/xma_context_new.cc | 69 ++++++++++++++++++++++++++++++++ src/xenia/cpu/cpu_flags.cc | 6 +++ src/xenia/kernel/event_log.cc | 19 ++++++++- 3 files changed, 93 insertions(+), 1 deletion(-) diff --git a/src/xenia/apu/xma_context_new.cc b/src/xenia/apu/xma_context_new.cc index a154c8a87..3a12c9580 100644 --- a/src/xenia/apu/xma_context_new.cc +++ b/src/xenia/apu/xma_context_new.cc @@ -10,10 +10,19 @@ #include "xenia/apu/xma_context_new.h" #include "xenia/apu/xma_helpers.h" +#include +#include +#include + +#include "xenia/base/cvar.h" #include "xenia/base/logging.h" #include "xenia/base/platform.h" #include "xenia/base/profiling.h" +// [Phase-A / audio RE] Defined in xma_context_master.cc; declared here so the +// probe fires in the DEFAULT ("new") decoder — the one the game actually uses. +DECLARE_bool(xma_param_probe); + extern "C" { #if XE_COMPILER_MSVC #pragma warning(push) @@ -392,6 +401,66 @@ void XmaContextNew::Decode(XMA_CONTEXT_DATA* data) { uint8_t* current_input_buffer = GetCurrentInputBuffer(data); + // [Phase-A / audio RE] Additive, cvar-gated probe (default-off, read-only). + // Capture the true XMA per-stream parameters the game supplies, keyed by + // (input buffer ptr, packet count) — the pair is unique per sub-wave, so it + // tells us WHICH sub-wave of a movie's `.slb` the game actually decodes. No + // behaviour change. Lives in the DEFAULT decoder so it observes the real + // playback path; probes WHICHEVER buffer is current (0 or 1). + if (cvars::xma_param_probe) { + static std::once_flag xma_probe_alive; + std::call_once(xma_probe_alive, [this]() { + XELOGW("XMA-PROBE active (ctx {} first decode) — cvar parsed OK", id()); + }); + const uint32_t buf = data->current_buffer; + const uint32_t buf_ptr = buf ? data->input_buffer_1_ptr + : data->input_buffer_0_ptr; + const uint32_t buf_pkts = buf ? data->input_buffer_1_packet_count + : data->input_buffer_0_packet_count; + if (data->IsCurrentInputBufferValid() && buf_pkts) { + uint8_t* in = memory()->TranslatePhysical(buf_ptr); + if (in) { + static std::mutex xma_probe_mu; + static std::set xma_probe_seen; + uint64_t key = (static_cast(buf_ptr) << 20) ^ + static_cast(buf_pkts); + 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", in[i]); + } + // Deep content signature: 48 bytes taken well into the stream (the + // first packet header is identical across all voices, so it can't + // discriminate). This uniquely fingerprints the actual recording, so + // the played voice can be matched back to a specific `.slb` blob + // regardless of the (scrambled) file name. `byte_size` = the XMA input + // size (packets * 2048), itself a strong discriminator. + const uint32_t byte_size = buf_pkts * 2048u; + const uint32_t sig_off = byte_size > 1088u ? 1024u : 0u; + char sig[97]; + for (int i = 0; i < 48; ++i) { + std::snprintf(sig + i * 2, 3, "%02x", in[sig_off + i]); + } + XELOGW( + "XMA-PARAM ctx={} buf={} ptr=0x{:08x} read_off={} stereo={} " + "channels={} rate_id={} rate={} packets={} byte_size={} " + "sig_off={} head={} sig={}", + id(), buf, buf_ptr, + static_cast(data->input_buffer_read_offset), + static_cast(data->is_stereo), data->is_stereo ? 2 : 1, + static_cast(data->sample_rate), + GetSampleRate(data->sample_rate), buf_pkts, byte_size, sig_off, + head, sig); + } + } + } + } + input_buffer_.fill(0); // Detect if we're about to decode the loop end frame (before diff --git a/src/xenia/cpu/cpu_flags.cc b/src/xenia/cpu/cpu_flags.cc index cfadac56c..19e87186b 100644 --- a/src/xenia/cpu/cpu_flags.cc +++ b/src/xenia/cpu/cpu_flags.cc @@ -73,6 +73,12 @@ DEFINE_bool(phase_a_trace_args, false, "args_resolved (file I/O path/offset/length/buffer, alloc size, " "handle names) fields, and emit file.read events. Default false.", "Audit"); +DEFINE_bool(phase_a_fileio_only, false, + "Phase A extraction (LIGHTWEIGHT): emit ONLY file opens (path) and " + "file.read events (path/offset/length) — no per-export import/kernel " + "call spam. Use to trace which sound.pak/movie bytes a title reads " + "(e.g. movie->voice mapping) without perturbing timing. Default false.", + "Audit"); DEFINE_string(phase_a_hash_probe, "", "Phase A extraction: CSV of guest PCs — RESERVED (the HIR/emitter " "trap that drives it is not ported to instrument-current). Inert. " diff --git a/src/xenia/kernel/event_log.cc b/src/xenia/kernel/event_log.cc index 219c2b538..230b7669a 100644 --- a/src/xenia/kernel/event_log.cc +++ b/src/xenia/kernel/event_log.cc @@ -30,6 +30,7 @@ DECLARE_string(phase_a_event_log_path); DECLARE_bool(kernel_emit_contention); DECLARE_bool(phase_a_trace_args); +DECLARE_bool(phase_a_fileio_only); DECLARE_string(phase_a_hash_probe); namespace xe { @@ -683,8 +684,20 @@ void MaybeEmitFileRead(const char* name, ::xe::cpu::ppc::PPCContext* ctx) { void EmitImportAndCallWithCtx(const char* module_name, uint16_t ord, const char* name, void* ppc_context) { - ::xe::kernel::phase_a::EmitImportCall(module_name, ord, name); auto* ctx = reinterpret_cast<::xe::cpu::ppc::PPCContext*>(ppc_context); + if (cvars::phase_a_fileio_only) { + // Lightweight file-I/O-only mode: emit ONLY file opens (name + resolved + // path) and file.read events (path/offset/length). No import.call/kernel.call + // per-export spam, so a timing-sensitive title stays performant. For + // non-file exports both helpers early-out on a cheap name check. + std::string path = ResolvePathArg(name, ctx); + if (!path.empty()) { + ::xe::kernel::phase_a::EmitKernelCallWithPath(name, path.c_str()); + } + MaybeEmitFileRead(name, ctx); + return; + } + ::xe::kernel::phase_a::EmitImportCall(module_name, ord, name); std::string path = ResolvePathArg(name, ctx); if (cvars::phase_a_trace_args) { // Extraction mode: raw GPR args + resolved path, plus file.read detail. @@ -700,6 +713,10 @@ void EmitImportAndCallWithCtx(const char* module_name, uint16_t ord, } } void EmitReturn(const char* name, uint64_t return_value) { + // File-I/O-only tracing captures everything on the call side (opens + reads), + // so suppress the per-export return spam — it dominated the log (millions of + // lines / GBs) and perturbs timing. + if (cvars::phase_a_fileio_only) return; ::xe::kernel::phase_a::EmitKernelReturn(name, return_value); } } // namespace phase_a_bridge From 87d02d59f179894a95d360b02d1117dff6f8da93 Mon Sep 17 00:00:00 2001 From: MechaCat02 Date: Fri, 24 Jul 2026 09:49:45 +0200 Subject: [PATCH 5/7] [GPU] F10 ship-placement capture: dump world-space draw vertices for RE One-shot snapshot for reversing capital-ship part placement. F10 arms RequestShipCaptureFrame(); the next batch of draws is dumped to xenia_ship_capture.log with each draw's guest vertex-buffer address, vertex/ index counts, and up to 64 WORLD-space vertex positions. Capital-ship parts are transformed into world space before the draw (unlike stage geometry, which matches the .xpr byte-for-byte), so these are ground truth for the assembled placement; a reborn-side correlator affine-fits each decoded .xpr part to a captured draw to recover its exact transform. De-duped by buffer address, gated independently of the log_draws cvar, budget-capped at 8000 draws / 4096 buffers. Co-Authored-By: Claude Opus 4.8 --- src/xenia/app/emulator_window.cc | 5 ++ src/xenia/gpu/command_processor.cc | 107 +++++++++++++++++++++++++++++ src/xenia/gpu/command_processor.h | 12 ++++ 3 files changed, 124 insertions(+) diff --git a/src/xenia/app/emulator_window.cc b/src/xenia/app/emulator_window.cc index 8e3a31540..6f2e01201 100644 --- a/src/xenia/app/emulator_window.cc +++ b/src/xenia/app/emulator_window.cc @@ -1067,6 +1067,11 @@ void EmulatorWindow::OnKeyDown(ui::KeyEvent& e) { case ui::VirtualKey::kF12: { TakeScreenshot(); } break; + case ui::VirtualKey::kF10: { + // RE: snapshot the next frame's draws (world-space vertex positions) to + // xenia_ship_capture.log for capital-ship placement correlation. + xe::gpu::RequestShipCaptureFrame(); + } break; case ui::VirtualKey::kEscape: { // Allow users to escape fullscreen (but not enter it). diff --git a/src/xenia/gpu/command_processor.cc b/src/xenia/gpu/command_processor.cc index c7b01575c..68670281d 100644 --- a/src/xenia/gpu/command_processor.cc +++ b/src/xenia/gpu/command_processor.cc @@ -125,8 +125,115 @@ const char* ReVertexFormatName(xenos::VertexFormat f) { } } // namespace +// ── Ship-placement capture (RE) ───────────────────────────────────────────── +// A hotkey (F10 in the emulator window) requests a one-shot snapshot: the next +// batch of draws is dumped to xenia_ship_capture.log with each draw's guest +// vertex-buffer address, vertex/index counts, and up to 64 WORLD-space vertex +// positions. Capital-ship parts are transformed into world space before the +// draw, so these positions are ground truth for the assembled placement — a +// tool correlates each draw to a decoded .xpr part (vertex count → affine fit). +// De-duped by buffer address, so a static ship's parts collapse to one record +// each even across the few frames the budget spans. +namespace { +constexpr int kShipCaptureBudget = 8000; // draws to scan per request +std::atomic g_ship_capture_gen{0}; +std::atomic g_ship_capture_remaining{0}; +} // namespace + +void RequestShipCaptureFrame() { + g_ship_capture_gen.fetch_add(1, std::memory_order_relaxed); + g_ship_capture_remaining.store(kShipCaptureBudget, std::memory_order_relaxed); + XELOGI("[SHIP-CAP] capture armed → xenia_ship_capture.log"); +} + +void CommandProcessor::CaptureShipDrawForRE( + uint32_t vgt_draw_initiator_value, + const IndexBufferInfo* index_buffer_info) { + if (g_ship_capture_remaining.load(std::memory_order_relaxed) <= 0) { + return; + } + static std::mutex cap_mutex; + static std::ofstream cap_out; + static std::unordered_set cap_seen; // by vertex-buffer address + static uint32_t cap_gen = 0; + std::lock_guard lock(cap_mutex); + if (g_ship_capture_remaining.load(std::memory_order_relaxed) <= 0) { + return; + } + // A new request (fresh generation) reopens the file and clears the de-dup set. + uint32_t gen = g_ship_capture_gen.load(std::memory_order_relaxed); + if (gen != cap_gen || !cap_out.is_open()) { + cap_out.open("xenia_ship_capture.log", std::ios::out | std::ios::trunc); + cap_seen.clear(); + cap_gen = gen; + XELOGI("[SHIP-CAP] writing xenia_ship_capture.log"); + } + g_ship_capture_remaining.fetch_sub(1, std::memory_order_relaxed); + if (!cap_out.is_open()) { + return; + } + + reg::VGT_DRAW_INITIATOR init; + init.value = vgt_draw_initiator_value; + Shader* vs = active_vertex_shader_; + if (!vs || !vs->is_ucode_analyzed() || vs->vertex_bindings().empty()) { + return; + } + const auto& binding = vs->vertex_bindings()[0]; + xenos::xe_gpu_vertex_fetch_t fetch = + register_file_->GetVertexFetch(binding.fetch_constant); + int32_t pos_off_bytes = -1; + for (const auto& attr : binding.attributes) { + if (attr.fetch_instr.attributes.data_format == + xenos::VertexFormat::k_32_32_32_FLOAT) { + pos_off_bytes = attr.fetch_instr.attributes.offset * 4; + break; + } + } + uint32_t stride = binding.stride_words * 4; + uint32_t vbase = uint32_t(fetch.address) << 2; + uint32_t buf_bytes = uint32_t(fetch.size) * 4; + if (pos_off_bytes < 0 || stride == 0 || vbase == 0) { + return; // no float-position stream (UI/effects) — skip + } + // One record per distinct vertex buffer. + if (!cap_seen.insert(vbase).second) { + return; + } + if (cap_seen.size() > 4096) { + return; + } + uint32_t vcount = buf_bytes / stride; + cap_out << fmt::format( + "DRAW vbase=0x{:08X} stride={} vcount={} indices={} prim={} vs=0x{:016X}\n", + vbase, stride, vcount, uint32_t(init.num_indices), + uint32_t(init.prim_type), vs->ucode_data_hash()); + uint32_t n = vcount < 64 ? vcount : 64; + cap_out << " pos:"; + auto be_f32 = [](const uint8_t* q) { + uint32_t w = (uint32_t(q[0]) << 24) | (uint32_t(q[1]) << 16) | + (uint32_t(q[2]) << 8) | uint32_t(q[3]); + float f; + std::memcpy(&f, &w, 4); + return f; + }; + for (uint32_t v = 0; v < n; ++v) { + uint32_t a = vbase + v * stride + uint32_t(pos_off_bytes); + const uint8_t* p = memory_->TranslatePhysical(a); + if (!p) { + break; + } + cap_out << fmt::format(" ({:.4f},{:.4f},{:.4f})", be_f32(p), be_f32(p + 4), + be_f32(p + 8)); + } + cap_out << "\n"; + cap_out.flush(); +} + void CommandProcessor::LogDrawForRE(uint32_t vgt_draw_initiator_value, const IndexBufferInfo* index_buffer_info) { + // One-shot ship-placement capture runs independently of the log_draws cvar. + CaptureShipDrawForRE(vgt_draw_initiator_value, index_buffer_info); if (!cvars::log_draws) { return; } diff --git a/src/xenia/gpu/command_processor.h b/src/xenia/gpu/command_processor.h index 4c1962963..3214d6c8c 100644 --- a/src/xenia/gpu/command_processor.h +++ b/src/xenia/gpu/command_processor.h @@ -35,6 +35,10 @@ class ByteStream; namespace gpu { +// Arm a one-shot ship-placement capture (see CommandProcessor::CaptureShipDrawForRE). +// Called from the UI thread (F10 hotkey); thread-safe. Defined in command_processor.cc. +void RequestShipCaptureFrame(); + enum class GPUSetting { ClearMemoryPageState, ReadbackMemexport }; enum class ReadbackResolveMode { @@ -453,6 +457,14 @@ class CommandProcessor { void LogDrawForRE(uint32_t vgt_draw_initiator_value, const IndexBufferInfo* index_buffer_info); + // Ship-placement capture (RE): a one-shot snapshot armed by RequestShipCaptureFrame() + // (F10 hotkey). Dumps each draw's guest vertex-buffer address, vertex/index + // counts, and up to 64 WORLD-space positions to xenia_ship_capture.log, so a + // correlator can recover each capital-ship part's exact placement. Defined in + // command_processor.cc. + void CaptureShipDrawForRE(uint32_t vgt_draw_initiator_value, + const IndexBufferInfo* index_buffer_info); + // "Actual" is for the command processor thread, to be read by the // implementations. SwapPostEffect GetActualSwapPostEffect() const { From 3ba56a5005a11132a0aa4a0a432539c7c28b0fc0 Mon Sep 17 00:00:00 2001 From: MechaCat02 Date: Fri, 24 Jul 2026 10:18:40 +0200 Subject: [PATCH 6/7] [GPU] ship-capture: also dump VS float constants (the placement matrix) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The captured vertex BUFFER holds LOCAL positions (byte-identical to the .xpr) — capital-ship parts are placed entirely in the vertex shader, not in the buffer. So the per-part world/WVP matrix lives in the VS float constants. Extend the F10 capture to dump the first 48 vec4 from the SQ_VS_CONST base per draw; diffing two parts isolates the world matrix (the camera VP block is shared across draws). Co-Authored-By: Claude Opus 4.8 --- src/xenia/gpu/command_processor.cc | 23 +++++++++++++++++++++++ 1 file changed, 23 insertions(+) diff --git a/src/xenia/gpu/command_processor.cc b/src/xenia/gpu/command_processor.cc index 68670281d..89863b6ee 100644 --- a/src/xenia/gpu/command_processor.cc +++ b/src/xenia/gpu/command_processor.cc @@ -227,6 +227,29 @@ void CommandProcessor::CaptureShipDrawForRE( be_f32(p + 8)); } cap_out << "\n"; + + // Vertex-shader float constants: the buffer holds LOCAL positions, so the + // per-part world (or world-view-projection) matrix that places the part lives + // here as a run of float4 constants. Diffing two parts' constants isolates the + // matrix (the camera VP block is shared). Dump the first 48 vec4 from the VS + // constant base as host-float (the register file stores them host-endian). + auto vsc = register_file_->Get(); + uint32_t cbase = vsc.base; // starting float4 index + cap_out << fmt::format(" vsconst base={}:", cbase); + for (uint32_t i = 0; i < 48; ++i) { + uint32_t idx = cbase + i; + if (idx >= 256) { + break; + } + uint32_t r = XE_GPU_REG_SHADER_CONSTANT_000_X + 4 * idx; + float cx = register_file_->Get(r); + float cy = register_file_->Get(r + 1); + float cz = register_file_->Get(r + 2); + float cw = register_file_->Get(r + 3); + cap_out << fmt::format(" c{}=({:.4f},{:.4f},{:.4f},{:.4f})", i, cx, cy, cz, + cw); + } + cap_out << "\n"; cap_out.flush(); } From 877163792b1565438a5f6e24d40744584ace3af6 Mon Sep 17 00:00:00 2001 From: MechaCat02 Date: Sun, 26 Jul 2026 19:15:43 +0200 Subject: [PATCH 7/7] [GPU] ship-capture: numbered per-press snapshots + capture every instance F10 now writes xenia_ship_capture_NN.log (NN = press number) so several angles can be captured in one run without overwriting, and de-dups by (vertex-buffer address, c0..c2 WVP hash) instead of address alone -- the same part buffer drawn at different transforms (two engine nacelles, each ship of a fleet) now yields one record per distinct placement. Seen-set cap raised to 8192. Co-Authored-By: Claude Fable 5 --- src/xenia/gpu/command_processor.cc | 51 ++++++++++++++++++++---------- 1 file changed, 35 insertions(+), 16 deletions(-) diff --git a/src/xenia/gpu/command_processor.cc b/src/xenia/gpu/command_processor.cc index 89863b6ee..48d15e5d9 100644 --- a/src/xenia/gpu/command_processor.cc +++ b/src/xenia/gpu/command_processor.cc @@ -127,13 +127,13 @@ const char* ReVertexFormatName(xenos::VertexFormat f) { // ── Ship-placement capture (RE) ───────────────────────────────────────────── // A hotkey (F10 in the emulator window) requests a one-shot snapshot: the next -// batch of draws is dumped to xenia_ship_capture.log with each draw's guest -// vertex-buffer address, vertex/index counts, and up to 64 WORLD-space vertex -// positions. Capital-ship parts are transformed into world space before the -// draw, so these positions are ground truth for the assembled placement — a -// tool correlates each draw to a decoded .xpr part (vertex count → affine fit). -// De-duped by buffer address, so a static ship's parts collapse to one record -// each even across the few frames the budget spans. +// batch of draws is dumped to xenia_ship_capture_NN.log (NN = press number — +// several angles can be captured in one run without overwriting) with each +// draw's guest vertex-buffer address, vertex/index counts, up to 64 LOCAL +// vertex positions, and the first 48 VS float constants (c0..c2 = the WVP rows +// that place the part). De-duped by (buffer address, c0..c2 transform) — NOT by +// address alone — so the SAME part buffer drawn several times (two engine +// nacelles, every ship of a fleet) yields one record per distinct placement. namespace { constexpr int kShipCaptureBudget = 8000; // draws to scan per request std::atomic g_ship_capture_gen{0}; @@ -141,9 +141,9 @@ std::atomic g_ship_capture_remaining{0}; } // namespace void RequestShipCaptureFrame() { - g_ship_capture_gen.fetch_add(1, std::memory_order_relaxed); + uint32_t gen = g_ship_capture_gen.fetch_add(1, std::memory_order_relaxed) + 1; g_ship_capture_remaining.store(kShipCaptureBudget, std::memory_order_relaxed); - XELOGI("[SHIP-CAP] capture armed → xenia_ship_capture.log"); + XELOGI("[SHIP-CAP] capture armed → xenia_ship_capture_{:02d}.log", gen); } void CommandProcessor::CaptureShipDrawForRE( @@ -154,19 +154,24 @@ void CommandProcessor::CaptureShipDrawForRE( } static std::mutex cap_mutex; static std::ofstream cap_out; - static std::unordered_set cap_seen; // by vertex-buffer address + static std::unordered_set cap_seen; // by (vbase, WVP transform) static uint32_t cap_gen = 0; std::lock_guard lock(cap_mutex); if (g_ship_capture_remaining.load(std::memory_order_relaxed) <= 0) { return; } - // A new request (fresh generation) reopens the file and clears the de-dup set. + // A new request (fresh generation) opens its own numbered snapshot file and + // clears the de-dup set, so each F10 press yields an independent capture. uint32_t gen = g_ship_capture_gen.load(std::memory_order_relaxed); if (gen != cap_gen || !cap_out.is_open()) { - cap_out.open("xenia_ship_capture.log", std::ios::out | std::ios::trunc); + if (cap_out.is_open()) { + cap_out.close(); + } + auto name = fmt::format("xenia_ship_capture_{:02d}.log", gen); + cap_out.open(name, std::ios::out | std::ios::trunc); cap_seen.clear(); cap_gen = gen; - XELOGI("[SHIP-CAP] writing xenia_ship_capture.log"); + XELOGI("[SHIP-CAP] writing {}", name); } g_ship_capture_remaining.fetch_sub(1, std::memory_order_relaxed); if (!cap_out.is_open()) { @@ -196,11 +201,25 @@ void CommandProcessor::CaptureShipDrawForRE( if (pos_off_bytes < 0 || stride == 0 || vbase == 0) { return; // no float-position stream (UI/effects) — skip } - // One record per distinct vertex buffer. - if (!cap_seen.insert(vbase).second) { + // One record per distinct (buffer, placement): hash the c0..c2 WVP rows so + // repeated draws of the SAME buffer at DIFFERENT transforms (multi-instance + // parts, fleet ships) each get their own record. + auto vsc0 = register_file_->Get(); + uint64_t th = 1469598103934665603ull; // FNV-1a over the 12 c0..c2 floats + for (uint32_t i = 0; i < 12; ++i) { + uint32_t idx = vsc0.base + (i / 4); + if (idx >= 256) { + break; + } + uint32_t r = XE_GPU_REG_SHADER_CONSTANT_000_X + 4 * idx + (i % 4); + uint32_t bits = register_file_->values[r]; + th = (th ^ bits) * 1099511628211ull; + } + uint64_t key = (uint64_t(vbase) << 32) ^ (th & 0xFFFFFFFFull) ^ (th >> 32); + if (!cap_seen.insert(key).second) { return; } - if (cap_seen.size() > 4096) { + if (cap_seen.size() > 8192) { return; } uint32_t vcount = buf_bytes / stride;