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.