fabi/Xenia-Canary
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

[Phase A] Port args / file.read extraction tracing onto instrument-current

Browse Source 
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 <noreply@anthropic.com>
This commit is contained in:
MechaCat02
2026-07-13 19:13:36 +02:00
parent f970a5173f
commit a40bc50159
5 changed files with 967 additions and 0 deletions
Download Patch File Download Diff File Expand all files Collapse all files

25
src/xenia/cpu/cpu_flags.cc
View File

@@ -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");

7
src/xenia/cpu/cpu_flags.h
View File

@@ -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_

709
src/xenia/kernel/event_log.cc Normal file
View File

@@ -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 <atomic>
#include <chrono>
#include <cstdio>
#include <cstring>
#include <mutex>
#include <string>
#include <unordered_map>
#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<int> 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<uint32_t, uint64_t> g_tid_counters;
std::mutex g_tid_counters_mu;
uint64_t NextTidEventIdx(uint32_t tid) {
std::lock_guard<std::mutex> 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<std::mutex> 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<std::chrono::nanoseconds>(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<X_KTHREAD>()->thread_id;
}
void WriteLine(const std::string& line) {
std::lock_guard<std::mutex> 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<unsigned char>(*p);
if (c == '\\' || c == '"') {
out.push_back('\\');
out.push_back(static_cast<char>(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<char>(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<uint8_t>(v & 0xFF);
bytes[off + 1] = static_cast<uint8_t>((v >> 8) & 0xFF);
bytes[off + 2] = static_cast<uint8_t>((v >> 16) & 0xFF);
bytes[off + 3] = static_cast<uint8_t>((v >> 24) & 0xFF);
};
auto put_u64 = [&](size_t off, uint64_t v) {
for (int i = 0; i < 8; ++i)
bytes[off + i] = static_cast<uint8_t>((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<uint32_t>(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<uint32_t, uint64_t> 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<std::mutex> lock(g_handle_sids_mu);
g_handle_sids[raw_handle_id] = sid;
}
uint64_t LookupHandleSemanticId(uint32_t raw_handle_id) {
std::lock_guard<std::mutex> 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<std::mutex> 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<uint64_t>(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<const char*>(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<u32> replace_existing
// offset 4 be<u32> 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<const char*>(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<uint32_t>(ctx->r[3]));
}
// NtOpenSymbolicLinkObject: r4 = obj_attrs
if (std::strcmp(name, "NtOpenSymbolicLinkObject") == 0) {
return ReadObjectAttributesRawName(static_cast<uint32_t>(ctx->r[4]));
}
// NtCreateFile, NtOpenFile: r5 = obj_attrs
if (std::strcmp(name, "NtCreateFile") == 0 ||
std::strcmp(name, "NtOpenFile") == 0) {
return ReadObjectAttributesRawName(static_cast<uint32_t>(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<uint32_t>(ctx->r[7]) == 10) {
return ReadFileRenameInformationRawTarget(
static_cast<uint32_t>(ctx->r[5]),
static_cast<uint32_t>(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<uint32_t>(ctx->r[3]);
uint32_t buffer = static_cast<uint32_t>(ctx->r[8]);
uint32_t length = static_cast<uint32_t>(ctx->r[9]);
uint32_t byteoff_ptr = static_cast<uint32_t>(ctx->r[10]);
uint64_t offset = 0;
if (byteoff_ptr && memory) {
auto* p = memory->TranslateVirtual<::xe::be<uint64_t>*>(byteoff_ptr);
if (p) offset = static_cast<uint64_t>(*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

191
src/xenia/kernel/event_log.h Normal file
View File

@@ -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 <cstdint>
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_

35
src/xenia/kernel/util/shim_utils.h
View File

@@ -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 <size_t I = 0, typename... Ps>
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<R>::value) {
KernelTrampoline(fn, std::forward<std::tuple<Ps...>>(params),
std::make_index_sequence<sizeof...(Ps)>());
if (phase_a_on) {
phase_a_bridge::EmitReturn(export_entry->name, 0);
}
} else {
auto result =
KernelTrampoline(fn, std::forward<std::tuple<Ps...>>(params),
std::make_index_sequence<sizeof...(Ps)>());
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.