From 2c883e9d5e3746219173597fe39d6854acd6beea Mon Sep 17 00:00:00 2001 From: MechaCat02 Date: Fri, 3 Jul 2026 07:43:53 +0200 Subject: [PATCH] [iterate-4A] diagnostics: XENIA_PROFILE wall-time profiler + probe/tooling snapshot MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Handoff snapshot of the env-gated diagnostic scaffolding used across the intro-video RE. Kept out of the milestone commits (645feb8..5573ac1) to keep those clean; committed here so nothing is lost on handoff. New — XENIA_PROFILE wall-time profiler (crates/xenia-gpu/src/prof.rs): Coarse buckets attributing playback wall time to interpreter (step_block), kernel HLE (call_export), block decode/cache (lookup_or_build), texture decode, host draw, and present; prints periodic snapshots (every 500M guest instr, or every 500 presents) + a clean-exit report. Hot path is gated on a cached is_on() (one relaxed load) so it is zero-cost when XENIA_PROFILE is unset. Call sites: main.rs run_superblock / parallel worker (step_block, lookup_or_build, call_export), texture_cache ensure_cached, render.rs present + dispatch_xenos_draws. First profile (movie playback, headless single-thread lockstep): effective ~35 MIPS; interpreter body ~40% @ ~95-102 MIPS; texture decode 0.3% (cache works); present ~0%; the rest is per-block dispatch + scheduler plumbing (~13 instr/block over 229M blocks). Overhead-bound, not interpreter-body bound; the levers are coarser execution units (superblock chaining) and ultimately a JIT. Pre-existing read-only probe knobs (were uncommitted; env-gated, observe-only): XENIA_RET_CAPTURE_PC/_REG/_MEM, LOG_RESUMES, LOG_WAITS, LOG_SIGNAL, FORCE_TID, STARVE_LIMIT, INCUMBENT_PICK, INSTR_PER_MS, DUMP_FRAME, DUMP_WGSL, BIND_LOG, CONST_LOG, DISPATCH_REC, AUDIT_PC_TRACE. Tooling: sylph-run.sh (movie oracle loop, 180s default timeout), zq.py (DuckDB disasm/xref helper). Co-Authored-By: Claude Opus 4.8 --- crates/xenia-app/src/main.rs | 48 ++++++- crates/xenia-cpu/src/interpreter.rs | 94 +++++++++++++ crates/xenia-cpu/src/scheduler.rs | 77 +++++++++- crates/xenia-gpu/src/gpu_system.rs | 36 +++++ crates/xenia-gpu/src/lib.rs | 1 + crates/xenia-gpu/src/prof.rs | 193 ++++++++++++++++++++++++++ crates/xenia-gpu/src/texture_cache.rs | 31 ++++- crates/xenia-gpu/src/translator.rs | 13 ++ crates/xenia-kernel/src/exports.rs | 55 +++++++- crates/xenia-kernel/src/state.rs | 24 ++++ crates/xenia-ui/src/render.rs | 133 ++++++++++++++++++ sylph-run.sh | 43 ++++++ zq.py | 66 +++++++++ 13 files changed, 800 insertions(+), 14 deletions(-) create mode 100644 crates/xenia-gpu/src/prof.rs create mode 100755 sylph-run.sh create mode 100755 zq.py diff --git a/crates/xenia-app/src/main.rs b/crates/xenia-app/src/main.rs index 31cc048..6f3009e 100644 --- a/crates/xenia-app/src/main.rs +++ b/crates/xenia-app/src/main.rs @@ -2713,7 +2713,15 @@ fn worker_prologue( let c = kernel.scheduler.ctx(hw_id); [c.gpr[3], c.gpr[4], c.gpr[5], c.gpr[6]] }; - kernel.call_export(module, ordinal_u32, mem); + { + let _pt = xenia_gpu::prof::is_on().then(|| { + xenia_gpu::prof::ScopeTimer::new( + &xenia_gpu::prof::KERNEL_NS, + &xenia_gpu::prof::KERNEL_CALLS, + ) + }); + kernel.call_export(module, ordinal_u32, mem); + } let post_ref = kernel.scheduler.current; let c = match post_ref { Some(r) => kernel.scheduler.ctx_mut_ref(r), @@ -2775,6 +2783,12 @@ fn worker_prologue( .current .expect("begin_slot_visit set scheduler.current to Some when slot has runnable thread"); let block_ptr: *const xenia_cpu::block_cache::DecodedBlock = { + let _pt = xenia_gpu::prof::is_on().then(|| { + xenia_gpu::prof::ScopeTimer::new( + &xenia_gpu::prof::BUILD_NS, + &xenia_gpu::prof::BUILD_CALLS, + ) + }); let pc_for_lookup = kernel.scheduler.ctx(hw_id).pc; let b: &xenia_cpu::block_cache::DecodedBlock = wc.block_cache.lookup_or_build(pc_for_lookup, mem); @@ -3112,6 +3126,7 @@ fn run_superblock( let cycle_before = kernel.scheduler.ctx_mut_ref(thread_ref).cycle_count; let mmio_before = mem.mmio_access_count(); let block = unsafe { &*block_ptr }; + let _prof_t0 = xenia_gpu::prof::is_on().then(std::time::Instant::now); let result = { let ctx = kernel.scheduler.ctx_mut_ref(thread_ref); step_block(ctx, mem, block) @@ -3121,6 +3136,13 @@ fn run_superblock( .ctx_mut_ref(thread_ref) .cycle_count .saturating_sub(cycle_before); + if let Some(t0) = _prof_t0 { + use xenia_gpu::prof; + prof::add(&prof::STEP_NS, t0.elapsed().as_nanos() as u64); + prof::add(&prof::STEP_INSTR, executed); + prof::add(&prof::STEP_CALLS, 1); + prof::maybe_report_by_instr(); + } total_executed = total_executed.saturating_add(executed); // STOP conditions (any → end the superblock, hand to epilogue): @@ -3161,7 +3183,15 @@ fn run_superblock( // invalidates the previous `block_ptr` — but we've already finished // using it (only `sync_sensitive`/diagnostics were read, above), so // the raw-pointer aliasing rule is respected. - block_ptr = wc.block_cache.lookup_or_build(next_pc, mem) as *const _; + { + let _pt = xenia_gpu::prof::is_on().then(|| { + xenia_gpu::prof::ScopeTimer::new( + &xenia_gpu::prof::BUILD_NS, + &xenia_gpu::prof::BUILD_CALLS, + ) + }); + block_ptr = wc.block_cache.lookup_or_build(next_pc, mem) as *const _; + } }; worker_epilogue( @@ -3610,10 +3640,19 @@ fn run_execution_parallel( // ── unlocked window ─────────────── let block = unsafe { &*block_ptr }; + let _prof_t0 = + xenia_gpu::prof::is_on().then(std::time::Instant::now); let result = step_block(&mut ctx_taken, mem_ref, block); let executed = ctx_taken .cycle_count .saturating_sub(cycle_before); + if let Some(t0) = _prof_t0 { + use xenia_gpu::prof; + prof::add(&prof::STEP_NS, t0.elapsed().as_nanos() as u64); + prof::add(&prof::STEP_INSTR, executed); + prof::add(&prof::STEP_CALLS, 1); + prof::maybe_report_by_instr(); + } // ────────────────────────────────── let mut guard = kernel_w.lock().expect("kernel mutex poisoned"); @@ -4305,6 +4344,11 @@ fn dump_thread_diagnostic( } use xenia_kernel::objects::KernelObject; + // Probe-patch (UNCOMMITTED): env-gated wall-time profile of the run. + if xenia_gpu::prof::enabled() { + xenia_gpu::prof::report(0); + } + // STEP-10 diagnostic (observe-only, env-gated `XENIA_DUMP_SLOTS=1`). // Prints each scheduler slot's full runqueue with the fields needed to // distinguish "Blocked(Suspended) forever" from "Ready but never picked": diff --git a/crates/xenia-cpu/src/interpreter.rs b/crates/xenia-cpu/src/interpreter.rs index d1748b9..c9a234c 100644 --- a/crates/xenia-cpu/src/interpreter.rs +++ b/crates/xenia-cpu/src/interpreter.rs @@ -15,6 +15,58 @@ use xenia_memory::MemoryAccess; /// `reserved_line = ea & !RESERVATION_MASK` in [context::PpcContext]. pub const RESERVATION_MASK: u32 = 0x7F; +/// RE diagnostic (milestone-2 intro-video). `XENIA_RET_CAPTURE_PC=0x..` +/// names a guest block-head PC at which to log r3/r4/r5 every time the +/// block is entered. Unlike the block-/slot-level audit probes in +/// `KernelState`, this fires in `step_block` at *every* block entry, so +/// it reaches mid-function return points (e.g. the instruction right +/// after a `bcctrl`) that the slot-visit probes miss. Read-only: only +/// emits a `println!`, mutates no guest state, so a captured run is +/// byte-identical to an unprobed one. 0 (unset env) → inert (one cached +/// `OnceLock` load + a `!= 0` branch per block). +fn ret_capture_pc() -> u32 { + use std::sync::OnceLock; + static RET_CAPTURE_PC: OnceLock = OnceLock::new(); + *RET_CAPTURE_PC.get_or_init(|| { + std::env::var("XENIA_RET_CAPTURE_PC") + .ok() + .and_then(|s| { + let t = s.trim(); + u32::from_str_radix(t.trim_start_matches("0x"), 16).ok() + }) + .unwrap_or(0) + }) +} + +/// RE diagnostic companion to [`ret_capture_pc`]. When `XENIA_RET_CAPTURE_MEM=1` +/// the RET-CAPTURE site also dumps the guest words at `r3+0x30 .. r3+0x48` +/// (the decoder *track* ring header: `+0x34` write cursor, `+0x44` read +/// cursor — fill = write − read). Read-only (`mem.read_u32` + `println!`). +fn ret_capture_mem() -> bool { + use std::sync::OnceLock; + static RET_CAPTURE_MEM: OnceLock = OnceLock::new(); + *RET_CAPTURE_MEM.get_or_init(|| { + std::env::var("XENIA_RET_CAPTURE_MEM") + .map(|s| s.trim() == "1") + .unwrap_or(false) + }) +} + +/// Which GPR holds the base pointer for the `XENIA_RET_CAPTURE_MEM` dump. +/// Defaults to r3; set `XENIA_RET_CAPTURE_REG=21` to dump the pointee of r21 +/// (e.g. the ring element the pump pops). Read-only. +fn ret_capture_reg() -> usize { + use std::sync::OnceLock; + static RET_CAPTURE_REG: OnceLock = OnceLock::new(); + *RET_CAPTURE_REG.get_or_init(|| { + std::env::var("XENIA_RET_CAPTURE_REG") + .ok() + .and_then(|s| s.trim().parse::().ok()) + .filter(|&n| n < 32) + .unwrap_or(3) + }) +} + /// Result of executing a single instruction. #[derive(Debug, Clone, Copy, PartialEq, Eq)] pub enum StepResult { @@ -97,6 +149,48 @@ pub fn step_block( mem: &dyn MemoryAccess, block: &crate::block_cache::DecodedBlock, ) -> StepResult { + // RE diagnostic: log r3/r4/r5 at a configured block-head PC (e.g. the + // return point after a `bcctrl`). Read-only; inert unless the env is set. + let cap = ret_capture_pc(); + if cap != 0 && block.start_pc == cap { + // KeTimeStampBundle tick_count (ms): [([0x820007D0]) + 0x10]. Read-only; + // lets a capture correlate guest progress with the guest-visible clock. + let bundle = mem.read_u32(0x820007D0); + let tick_ms = if bundle != 0 { mem.read_u32(bundle.wrapping_add(0x10)) } else { 0 }; + println!("RET-CAPTURE-TICK pc={:#010x} tid={} tick_ms={} cycle={}", block.start_pc, ctx.thread_id, tick_ms, ctx.cycle_count); + println!( + "RET-CAPTURE pc={:#010x} tid={} r3={:#010x} r4={:#010x} r5={:#010x} r21={:#010x} lr={:#010x} cycle={}", + block.start_pc, + ctx.thread_id, + ctx.gpr[3] as u32, + ctx.gpr[4] as u32, + ctx.gpr[5] as u32, + ctx.gpr[21] as u32, + ctx.lr as u32, + ctx.cycle_count, + ); + if ret_capture_mem() { + let reg = ret_capture_reg(); + let base = ctx.gpr[reg] as u32; + let w = |off: u32| mem.read_u32(base.wrapping_add(off)); + // Dump +0x00 (vtable ptr) .. +0x48 so callers can inspect either a + // ring element (60-byte struct, vtable at +0) or the track header + // (+0x34 write / +0x44 read cursors). + println!( + "RET-CAPTURE-MEM r{} base={:#010x} +00={:#010x} +04={:#010x} +08={:#010x} +0c={:#010x} +10={:#010x} +14={:#010x} +18={:#010x} +1c={:#010x} +20={:#010x} +24={:#010x} +28={:#010x} +2c={:#010x} +30={:#010x} +34={:#010x} +38={:#010x} +3c={:#010x} +40={:#010x} +44={:#010x} +48={:#010x}", + reg, base, + w(0x00), w(0x04), w(0x08), w(0x0c), w(0x10), w(0x14), w(0x18), w(0x1c), + w(0x20), w(0x24), w(0x28), w(0x2c), w(0x30), w(0x34), w(0x38), w(0x3c), + w(0x40), w(0x44), w(0x48), + ); + // Extra slots: stack locals [r1+0x50]/[r1+0x54] when reg=1; engine + // worker-resume gate +0xF0 (pending flag) / +0x110 (worker handle). + println!( + "RET-CAPTURE-MEM2 r{} base={:#010x} +50={:#010x} +54={:#010x} +f0={:#010x} +110={:#010x}", + reg, base, w(0x50), w(0x54), w(0xF0), w(0x110), + ); + } + } let mut result = StepResult::Continue; for instr in &block.instrs { let expected_next = instr.addr.wrapping_add(4); diff --git a/crates/xenia-cpu/src/scheduler.rs b/crates/xenia-cpu/src/scheduler.rs index 44aaab8..b8d3611 100644 --- a/crates/xenia-cpu/src/scheduler.rs +++ b/crates/xenia-cpu/src/scheduler.rs @@ -49,10 +49,27 @@ pub const QUANTUM_DEFAULT: u32 = 50_000; /// guarantees *bounded* forward progress, it does not invert priority. pub const STARVE_LIMIT: u32 = 4096; -/// Toggle for the `pick_runnable` incumbent-preference tiebreak (the fix). -/// Default on. `XENIA_INCUMBENT_PICK=0` reverts to the old lowest-index -/// tiebreak — a rollback knob to A/B the fix's effect on boot rendering vs -/// the movie feeder-starvation cure. Inert unless explicitly set to 0. +/// RE diagnostic: `XENIA_STARVE_LIMIT=` overrides [`STARVE_LIMIT`] at +/// runtime (cached). Lets a fairness test boost starved co-located threads +/// (e.g. the feeder tid24 on hw=1) much sooner without a full monopoly — +/// distinguishing "fair scheduling fixes the deadlock" from "needs more". +/// Unset → the compiled 4096 default (inert). +fn starve_limit() -> u32 { + use std::sync::OnceLock; + static SL: OnceLock = OnceLock::new(); + *SL.get_or_init(|| { + std::env::var("XENIA_STARVE_LIMIT") + .ok() + .and_then(|s| s.trim().parse::().ok()) + .filter(|&n| n > 0) + .unwrap_or(STARVE_LIMIT) + }) +} + +/// Diagnostic A/B toggle for the `pick_runnable` incumbent-preference +/// tiebreak. Default on (the fix). `XENIA_INCUMBENT_PICK=0` reverts to the +/// old lowest-index tiebreak, to measure the fix's effect on boot rendering +/// vs the movie feeder-starvation cure. Inert unless explicitly set to 0. fn incumbent_pick() -> bool { use std::sync::OnceLock; static IP: OnceLock = OnceLock::new(); @@ -200,6 +217,28 @@ pub enum HwState { ServicingIrq(BlockReason), } +/// RE diagnostic: gate for the `XENIA_LOG_WAITS=1` `PARK` logger in +/// [`Scheduler::park_current`]. Cached; inert unless the env is set. +fn log_waits_enabled() -> bool { + use std::sync::OnceLock; + static EN: OnceLock = OnceLock::new(); + *EN.get_or_init(|| std::env::var("XENIA_LOG_WAITS").is_ok()) +} + +/// RE diagnostic: `XENIA_FORCE_TID=` — guest tid that `pick_runnable` +/// always prefers when Ready (un-starve test for the feeder deadlock). +/// 0 / unset = inert. Cached. +fn force_tid() -> u32 { + use std::sync::OnceLock; + static FT: OnceLock = OnceLock::new(); + *FT.get_or_init(|| { + std::env::var("XENIA_FORCE_TID") + .ok() + .and_then(|s| s.trim().parse::().ok()) + .unwrap_or(0) + }) +} + #[derive(Debug, Clone, PartialEq, Eq)] pub enum BlockReason { Suspended, @@ -274,6 +313,20 @@ impl HwSlot { /// `STARVE_LIMIT` visits). The boost is a pure function of the per-thread /// counters/priority/index, so picks stay deterministic. pub fn pick_runnable(&self) -> Option { + // RE diagnostic (milestone-2 intro-video). `XENIA_FORCE_TID=` makes + // this slot always prefer the named guest tid whenever it is Ready on + // this slot — fully un-starving it. Used to separate "tid is starved" + // from "tid is genuinely stuck" for the feeder tid24 deadlock. Slots + // not carrying that tid fall through to normal selection. Behaviour- + // changing, so strictly env-gated (inert when unset). + let force = force_tid(); + if force != 0 { + if let Some((i, _)) = self.runqueue.iter().enumerate().find(|(_, t)| { + t.tid == force && matches!(t.state, HwState::Ready | HwState::ServicingIrq(_)) + }) { + return Some(i); + } + } // Tiebreak among equal-effective-priority Ready threads PREFERS THE // INCUMBENT (`running_idx`) over the lowest index. `decrement_quantum` // rotates `running_idx` to the next same-priority peer when the 50k @@ -307,7 +360,7 @@ impl HwSlot { /// visits is lifted to `i32::MAX` so it wins the next pick regardless of /// peer priority; otherwise its nominal priority is used unchanged. fn effective_priority(t: &GuestThread) -> i32 { - if t.steps_starved >= STARVE_LIMIT { + if t.steps_starved >= starve_limit() { i32::MAX } else { t.priority @@ -991,7 +1044,7 @@ impl Scheduler { if i == me { t.steps_starved = 0; } else if matches!(t.state, HwState::Ready | HwState::ServicingIrq(_)) { - t.steps_starved = STARVE_LIMIT; + t.steps_starved = starve_limit(); promoted = true; } } @@ -1015,6 +1068,18 @@ impl Scheduler { self.timed_waits.push((d, r)); self.timed_waits.sort_by_key(|&(d, _)| d); } + // RE diagnostic (milestone-2 intro-video). `XENIA_LOG_WAITS=1` logs a + // `PARK` line (tid, pc, cycle, block reason incl. waited handles) every + // time a thread blocks — the symmetric counterpart of the resume log, + // for pinning the producer↔consumer deadlock (what does the feeder + // tid24 wait on after its one pass). Read-only diagnostic. + if log_waits_enabled() { + let t = self.thread_mut(r); + println!( + "PARK tid={} pc={:#010x} cycle={} reason={:?}", + t.tid, t.ctx.pc, t.ctx.cycle_count, reason, + ); + } self.thread_mut(r).state = HwState::Blocked(reason); self.recompute_slot_runnable(r.hw_id); } diff --git a/crates/xenia-gpu/src/gpu_system.rs b/crates/xenia-gpu/src/gpu_system.rs index 1cf17fe..3dd909e 100644 --- a/crates/xenia-gpu/src/gpu_system.rs +++ b/crates/xenia-gpu/src/gpu_system.rs @@ -1246,6 +1246,17 @@ impl GpuSystem { let mut ds = draw_state::extract(&self.register_file, vgt, dma_base, dma_size); ds.vs_blob_key = self.active_vs_key; ds.ps_blob_key = self.active_ps_key; + if std::env::var("XENIA_CONST_LOG").is_ok() { + let c254x = f32::from_bits(self.register_file.read(CONST_BASE_ALU + 254 * 4)); + let c255x = f32::from_bits(self.register_file.read(CONST_BASE_ALU + 255 * 4)); + if c254x != 0.0 || c255x != 0.0 { + eprintln!( + "DRAW-CONST draw={} ps={:#x} c254.x={c254x} c255.x={c255x}", + self.stats.draws_seen, + self.active_ps_key.unwrap_or(0) + ); + } + } let processed = primitive::process(ds.primitive, ds.vertex_count, None); metrics::counter!( "gpu.draw", @@ -1468,6 +1479,15 @@ impl GpuSystem { let v = self.read_payload(mem, 2 + i); self.register_file.write(base + index + i, v); } + if std::env::var("XENIA_CONST_LOG").is_ok() { + // Compact histogram-able line: type + index-range for every + // SET_CONSTANT. `covers254` flags an ALU write hitting c254. + eprintln!( + "SC t={const_type} i={index} n={} covers254={}", + count - 1, + const_type == 0 && index <= 1016 && 1016 < index + (count - 1) + ); + } } pm4::PM4_SET_CONSTANT2 => { // payload[0] = 16-bit index; subsequent payloads write consecutive regs. @@ -1476,6 +1496,15 @@ impl GpuSystem { let v = self.read_payload(mem, 2 + i); self.register_file.write(index + i, v); } + if std::env::var("XENIA_CONST_LOG").is_ok() { + let alu_lo = CONST_BASE_ALU; + let alu_hi = CONST_BASE_ALU + 2048; + eprintln!( + "SC2 i={index:#x} n={} in_alu={}", + count - 1, + index >= alu_lo && index < alu_hi + ); + } } pm4::PM4_LOAD_ALU_CONSTANT => { // payload[0] = source mem addr, [1] = offset_type, [2] = size_dwords @@ -1496,6 +1525,13 @@ impl GpuSystem { let v = mem.read_u32(src + i * 4); self.register_file.write(base + index + i, v); } + if std::env::var("XENIA_CONST_LOG").is_ok() && const_type == 0 { + eprintln!( + "LOAD-ALU-CONST src={src:#x} idx={index} size={size_dwords} first={:?} covers254={}", + f32::from_bits(mem.read_u32(src)), + index <= 1016 && 1016 < index + size_dwords + ); + } } pm4::PM4_IM_LOAD | pm4::PM4_IM_LOAD_IMMEDIATE => { // Canary (pm4_command_processor_implement.h:1271-1330): diff --git a/crates/xenia-gpu/src/lib.rs b/crates/xenia-gpu/src/lib.rs index b1dbace..156dc55 100644 --- a/crates/xenia-gpu/src/lib.rs +++ b/crates/xenia-gpu/src/lib.rs @@ -20,6 +20,7 @@ pub mod handle; pub mod mmio_region; pub mod pm4; pub mod primitive; +pub mod prof; pub mod register_file; pub mod ring_drain; pub mod ring_view; diff --git a/crates/xenia-gpu/src/prof.rs b/crates/xenia-gpu/src/prof.rs new file mode 100644 index 0000000..6e1e4fc --- /dev/null +++ b/crates/xenia-gpu/src/prof.rs @@ -0,0 +1,193 @@ +//! Lightweight env-gated wall-time profiler (probe-patch, UNCOMMITTED). +//! +//! Attributes emulator wall time to coarse buckets so we can tell whether the +//! movie-playback slowdown is CPU-interpreter bound, texture-decode bound, or +//! GPU-present bound. Enabled only when `XENIA_PROFILE` is set; the hot-path +//! cost when disabled is a single relaxed atomic add of already-measured nanos +//! (callers still pay `Instant::now()` — acceptable at the coarse boundaries we +//! instrument: per basic-block, per texture upload, per present). +//! +//! Read the buckets with `xenia_gpu::prof::report(wall_ns)` at clean shutdown. + +use std::sync::atomic::{AtomicU64, Ordering}; +use std::sync::OnceLock; + +static START: OnceLock = OnceLock::new(); + +/// Lazily anchor the wall-time window (first call wins). Called from `add`. +#[inline] +fn mark_start() { + START.get_or_init(std::time::Instant::now); +} + +/// Nanos since the profiler's first accounted event. +pub fn wall_ns() -> u64 { + START.get().map(|t| t.elapsed().as_nanos() as u64).unwrap_or(0) +} + +pub static STEP_NS: AtomicU64 = AtomicU64::new(0); // guest interpreter (step_block) +pub static STEP_INSTR: AtomicU64 = AtomicU64::new(0); // guest instructions retired +pub static STEP_CALLS: AtomicU64 = AtomicU64::new(0); + +pub static TEXDEC_NS: AtomicU64 = AtomicU64::new(0); // texture decode + host upload +pub static TEXDEC_CALLS: AtomicU64 = AtomicU64::new(0); +pub static TEXDEC_BYTES: AtomicU64 = AtomicU64::new(0); + +pub static PRESENT_NS: AtomicU64 = AtomicU64::new(0); // frontbuffer present +pub static PRESENT_CALLS: AtomicU64 = AtomicU64::new(0); + +pub static DRAW_NS: AtomicU64 = AtomicU64::new(0); // host draw submission +pub static DRAW_CALLS: AtomicU64 = AtomicU64::new(0); + +pub static KERNEL_NS: AtomicU64 = AtomicU64::new(0); // kernel HLE export dispatch +pub static KERNEL_CALLS: AtomicU64 = AtomicU64::new(0); + +pub static BUILD_NS: AtomicU64 = AtomicU64::new(0); // block decode / cache lookup +pub static BUILD_CALLS: AtomicU64 = AtomicU64::new(0); + +/// Cached on/off state so the per-block hot path never touches the +/// environment. 0 = uninitialised, 1 = on, 2 = off. +static ENABLED: std::sync::atomic::AtomicU8 = std::sync::atomic::AtomicU8::new(0); + +/// Cheap (one relaxed load + branch) enabled check for hot paths. Resolves +/// `XENIA_PROFILE` from the environment exactly once, then caches it. +#[inline] +pub fn is_on() -> bool { + match ENABLED.load(Ordering::Relaxed) { + 1 => true, + 2 => false, + _ => { + let on = std::env::var_os("XENIA_PROFILE").is_some(); + ENABLED.store(if on { 1 } else { 2 }, Ordering::Relaxed); + on + } + } +} + +#[inline] +pub fn enabled() -> bool { + is_on() +} + +#[inline] +pub fn add(counter: &AtomicU64, v: u64) { + mark_start(); + counter.fetch_add(v, Ordering::Relaxed); +} + +/// RAII timer: adds elapsed nanos to `ns` and bumps `calls` on drop. +pub struct ScopeTimer { + t0: std::time::Instant, + ns: &'static AtomicU64, + calls: &'static AtomicU64, +} + +impl ScopeTimer { + #[inline] + pub fn new(ns: &'static AtomicU64, calls: &'static AtomicU64) -> Self { + mark_start(); + Self { t0: std::time::Instant::now(), ns, calls } + } +} + +impl Drop for ScopeTimer { + #[inline] + fn drop(&mut self) { + self.ns.fetch_add(self.t0.elapsed().as_nanos() as u64, Ordering::Relaxed); + self.calls.fetch_add(1, Ordering::Relaxed); + } +} + +static NEXT_REPORT_INSTR: AtomicU64 = AtomicU64::new(500_000_000); + +/// Fire a snapshot every ~500M retired guest instructions (headless runs have +/// no present() to piggyback on and may never reach the clean-exit report). +#[inline] +pub fn maybe_report_by_instr() { + if !enabled() { + return; + } + let instr = STEP_INSTR.load(Ordering::Relaxed); + let thresh = NEXT_REPORT_INSTR.load(Ordering::Relaxed); + if instr >= thresh + && NEXT_REPORT_INSTR + .compare_exchange(thresh, thresh + 500_000_000, Ordering::Relaxed, Ordering::Relaxed) + .is_ok() + { + report(0); + } +} + +/// Print the accumulated buckets against the profiler's own wall window. +/// The argument is accepted for call-site convenience but ignored in favour +/// of the internally-anchored window (`wall_ns()`). +pub fn report(_ignored: u64) { + let wall_ns = wall_ns(); + let g = |c: &AtomicU64| c.load(Ordering::Relaxed); + let ms = |ns: u64| ns as f64 / 1e6; + let pct = |ns: u64| { + if wall_ns == 0 { + 0.0 + } else { + 100.0 * ns as f64 / wall_ns as f64 + } + }; + let step_ns = g(&STEP_NS); + let step_instr = g(&STEP_INSTR); + let tex_ns = g(&TEXDEC_NS); + let pres_ns = g(&PRESENT_NS); + let draw_ns = g(&DRAW_NS); + let mips = if step_ns == 0 { + 0.0 + } else { + step_instr as f64 / (step_ns as f64 / 1e3) // instr / us = MIPS + }; + eprintln!("=== XENIA_PROFILE (wall {:.1} ms) ===", ms(wall_ns)); + eprintln!( + " interp step_block : {:>10.1} ms {:>5.1}% ({} calls, {} instr, {:.1} MIPS)", + ms(step_ns), + pct(step_ns), + g(&STEP_CALLS), + step_instr, + mips + ); + eprintln!( + " texture decode+up : {:>10.1} ms {:>5.1}% ({} calls, {} MiB)", + ms(tex_ns), + pct(tex_ns), + g(&TEXDEC_CALLS), + g(&TEXDEC_BYTES) / (1024 * 1024) + ); + eprintln!( + " host draw submit : {:>10.1} ms {:>5.1}% ({} calls)", + ms(draw_ns), + pct(draw_ns), + g(&DRAW_CALLS) + ); + let kern_ns = g(&KERNEL_NS); + let build_ns = g(&BUILD_NS); + eprintln!( + " kernel HLE export : {:>10.1} ms {:>5.1}% ({} calls)", + ms(kern_ns), + pct(kern_ns), + g(&KERNEL_CALLS) + ); + eprintln!( + " block decode/cache: {:>10.1} ms {:>5.1}% ({} calls)", + ms(build_ns), + pct(build_ns), + g(&BUILD_CALLS) + ); + eprintln!( + " frontbuffer present: {:>9.1} ms {:>5.1}% ({} calls)", + ms(pres_ns), + pct(pres_ns), + g(&PRESENT_CALLS) + ); + let accounted = step_ns + tex_ns + draw_ns + pres_ns + kern_ns + build_ns; + eprintln!( + " ---- accounted {:.1}% ; remainder (locks/kernel/scheduler/idle) {:.1}%", + pct(accounted), + pct(wall_ns.saturating_sub(accounted)) + ); +} diff --git a/crates/xenia-gpu/src/texture_cache.rs b/crates/xenia-gpu/src/texture_cache.rs index 04cf0bc..55a4434 100644 --- a/crates/xenia-gpu/src/texture_cache.rs +++ b/crates/xenia-gpu/src/texture_cache.rs @@ -652,6 +652,7 @@ impl TextureCache { } self.restale_total += 1; } + let _prof_t0 = std::time::Instant::now(); let bytes = match key.format { TextureFormat::K8 => decode_k8(&key, mem)?, TextureFormat::K8888 => decode_k8888_tiled(&key, mem)?, @@ -659,9 +660,37 @@ impl TextureCache { TextureFormat::Dxt1 => decode_dxt1_tiled(&key, mem)?, TextureFormat::Dxt2_3 => decode_dxt23_tiled(&key, mem)?, TextureFormat::Dxt4_5 => decode_dxt45_tiled(&key, mem)?, - _ => return Err(DecodeError::UnsupportedFormat), + _ => { + // XENIA_TEX_REJECT_LOG diagnostic (STEP 87, read-only): the + // intro video uploads its YUV420 planes as `k_8` linear + // textures; if we have no decoder for the requested format we + // reject it here and it never reaches the GPU (→ black video). + // Rate-limited so a per-frame flood stays grep-able. + use std::sync::atomic::{AtomicUsize, Ordering}; + static N: AtomicUsize = AtomicUsize::new(0); + let n = N.fetch_add(1, Ordering::Relaxed); + if n < 120 { + tracing::warn!( + fmt = ?key.format, + w = key.width, + h = key.height, + base = format_args!("0x{:08x}", key.base_address), + dim = ?key.dimension, + pitch = key.pitch_texels, + n, + "TEX-REJECT: unsupported texture format (no host decoder)" + ); + } + return Err(DecodeError::UnsupportedFormat); + } }; self.decodes_total += 1; + { + use crate::prof; + prof::add(&prof::TEXDEC_NS, _prof_t0.elapsed().as_nanos() as u64); + prof::add(&prof::TEXDEC_CALLS, 1); + prof::add(&prof::TEXDEC_BYTES, bytes.len() as u64); + } let entry = CachedTexture { key, version_when_uploaded: current_version, diff --git a/crates/xenia-gpu/src/translator.rs b/crates/xenia-gpu/src/translator.rs index 16e7ecb..bbe3ed2 100644 --- a/crates/xenia-gpu/src/translator.rs +++ b/crates/xenia-gpu/src/translator.rs @@ -460,6 +460,16 @@ impl EmitCtx { let b = src_operand(alu.src_b, alu.src_b_is_temp, alu.src_b_swiz, alu.src_b_negate, const_base); let c = src_operand(alu.src_c, alu.src_c_is_temp, alu.src_c_swiz, alu.src_c_negate, const_base); + if (42..=47).contains(&alu.scalar_opcode) && std::env::var("XENIA_SC_LOG").is_ok() { + eprintln!( + "SC-OP opc={} sa={} atmp={} asw={:#04x} sb={} btmp={} bsw={:#04x} sc={} ctmp={} csw={:#04x}", + alu.scalar_opcode, + alu.src_a, alu.src_a_is_temp as u8, alu.src_a_swiz, + alu.src_b, alu.src_b_is_temp as u8, alu.src_b_swiz, + alu.src_c, alu.src_c_is_temp as u8, alu.src_c_swiz, + ); + } + // Vector pipe. if alu.vector_write_mask != 0 { let expr = vector_expr(alu.vector_opcode, &a, &b, &c) @@ -501,6 +511,9 @@ impl EmitCtx { let expr = match scalar_expr(alu.scalar_opcode, &scl_src_a, &scl_src_b, "ps") { Some(e) => e, None => { + if std::env::var("XENIA_BIND_LOG").is_ok() { + eprintln!("SCL-UNSUPPORTED opcode={:#04x} ({})", alu.scalar_opcode, alu.scalar_opcode); + } return Err(reject::SCL_OP_UNSUPPORTED); } }; diff --git a/crates/xenia-kernel/src/exports.rs b/crates/xenia-kernel/src/exports.rs index 536dcbf..5ac51de 100644 --- a/crates/xenia-kernel/src/exports.rs +++ b/crates/xenia-kernel/src/exports.rs @@ -1351,10 +1351,16 @@ fn nt_read_file(ctx: &mut PpcContext, mem: &GuestMemory, state: &mut KernelState mem.write_bulk(buffer, slice); *position = start_pos + avail as u64; - tracing::info!( - "NtReadFile: {} bytes from {:?} @ {} (handle={:#x})", - avail, path, start_pos, handle, - ); + { + // STEP 51 — tag NtReadFile with the calling tid + cycle so the + // window-prefetch thread can be correlated against tid24's demux read. + let hw_id = state.scheduler.current_hw_id().unwrap_or(0); + let rtid = state.scheduler.tid(hw_id).unwrap_or(0); + tracing::info!( + "NtReadFile: {} bytes from {:?} @ {} (handle={:#x}) tid={} cycle={}", + avail, path, start_pos, handle, rtid, ctx.cycle_count, + ); + } write_io_status_block(mem, io_status_block, STATUS_SUCCESS as u32, avail as u32); ctx.gpr[3] = STATUS_SUCCESS; signal_io_completion_event(state, event_handle); @@ -3187,6 +3193,20 @@ fn vd_swap(ctx: &mut PpcContext, mem: &GuestMemory, state: &mut KernelState) { let constants = xenia_gpu::xenos_constants::XenosConstantsBlock::snapshot( &gpu_inline.register_file, ); + if std::env::var("XENIA_CONST_LOG").is_ok() { + let nz: Vec = constants + .alu + .iter() + .enumerate() + .filter(|(_, v)| v.iter().any(|c| *c != 0.0)) + .map(|(i, _)| i) + .collect(); + eprintln!( + "CONST-LOG alu_nonzero={} idxs={:?} c254={:?} c255={:?} c510={:?} c511={:?}", + nz.len(), nz, constants.alu[254], constants.alu[255], + constants.alu[510], constants.alu[511] + ); + } ui.publish_assets(blobs, constants); // P5b: publish the texture the last draw's *active pixel shader* @@ -4470,12 +4490,30 @@ fn nt_yield_execution(ctx: &mut PpcContext, _mem: &GuestMemory, _state: &mut Ker ctx.gpr[3] = STATUS_SUCCESS; } +/// RE diagnostic (milestone-2 intro-video): `XENIA_LOG_RESUMES=1` makes +/// `Ke/NtResumeThread` emit a `RESUME` line naming the resumed thread's +/// tid, start_entry (so decode workers — entries 0x82506588/0x825065b8 — +/// are identifiable), current pc and the prior suspend_count. Cold-path +/// (resume is rare); inert unless the env is set. Read-only diagnostic. +fn log_resumes_enabled() -> bool { + use std::sync::OnceLock; + static EN: OnceLock = OnceLock::new(); + *EN.get_or_init(|| std::env::var("XENIA_LOG_RESUMES").is_ok()) +} + fn ke_resume_thread(ctx: &mut PpcContext, _mem: &GuestMemory, state: &mut KernelState) { let raw = ctx.gpr[3] as u32; let handle = resolve_pseudo_handle(state, raw); match state.scheduler.find_by_handle(handle) { Some(r) => { - state.scheduler.resume_ref(r); + let prev = state.scheduler.resume_ref(r); + if log_resumes_enabled() { + let t = state.scheduler.thread(r); + tracing::info!( + "RESUME(Ke) tid={} start_entry={:#010x} pc={:#010x} prev_suspend={}", + t.tid, t.start_entry, t.ctx.pc, prev, + ); + } ctx.gpr[3] = STATUS_SUCCESS; } None => { @@ -4491,6 +4529,13 @@ fn nt_resume_thread(ctx: &mut PpcContext, mem: &GuestMemory, state: &mut KernelS match state.scheduler.find_by_handle(handle) { Some(r) => { let prev = state.scheduler.resume_ref(r); + if log_resumes_enabled() { + let t = state.scheduler.thread(r); + tracing::info!( + "RESUME(Nt) tid={} start_entry={:#010x} pc={:#010x} prev_suspend={}", + t.tid, t.start_entry, t.ctx.pc, prev, + ); + } if prev_ptr != 0 { mem.write_u32(prev_ptr, prev); } diff --git a/crates/xenia-kernel/src/state.rs b/crates/xenia-kernel/src/state.rs index 8698874..30ce116 100644 --- a/crates/xenia-kernel/src/state.rs +++ b/crates/xenia-kernel/src/state.rs @@ -909,6 +909,30 @@ impl KernelState { /// Record a Set/Pulse/Release/etc. call against a handle. `aux` is the /// previous signal state (or per-export-specific data). pub fn audit_signal(&mut self, handle: u32, lr: u32, source: &'static str, aux: u64) { + // RE diagnostic (milestone-2 intro-video). `XENIA_LOG_SIGNAL=0x` + // (or `0xffffffff` for all) logs every event signal/pulse targeting + // that object — to pin who, if anyone, signals the engine event + // 0x40D10214 that tid23 waits on (the worker-resume gate). Read-only. + { + use std::sync::OnceLock; + static SIG_T: OnceLock = OnceLock::new(); + let t = *SIG_T.get_or_init(|| { + std::env::var("XENIA_LOG_SIGNAL") + .ok() + .and_then(|s| u32::from_str_radix(s.trim().trim_start_matches("0x"), 16).ok()) + .unwrap_or(0) + }); + if t != 0 && (t == u32::MAX || t == handle) { + let tid = self + .scheduler + .current_hw_id() + .and_then(|h| self.scheduler.tid(h)) + .unwrap_or(0); + tracing::info!( + "SIGNAL src={source} handle={handle:#010x} tid={tid} lr={lr:#010x} prev_signaled={aux}" + ); + } + } if !self.audit.enabled { return; } diff --git a/crates/xenia-ui/src/render.rs b/crates/xenia-ui/src/render.rs index 5ec4818..67cbd0f 100644 --- a/crates/xenia-ui/src/render.rs +++ b/crates/xenia-ui/src/render.rs @@ -600,6 +600,8 @@ impl RenderState { if count == 0 { return; } + let _prof_g = + xenia_gpu::prof::ScopeTimer::new(&xenia_gpu::prof::DRAW_NS, &xenia_gpu::prof::DRAW_CALLS); let _span = tracing::debug_span!( "ui.xenos.dispatch", count, @@ -881,6 +883,36 @@ impl RenderState { cap.ps_key, rstate, ); + // Log only the "interesting" draws — multi-texture or any non-K8888 + // (e.g. the movie's k_8 YUV planes) — so the boot's single-K8888 + // quads don't flood the cap before the movie composites. + let interesting = cap.textures.len() > 1 + || cap.textures.iter().any(|(_, k, ..)| { + !matches!(k.format, xenia_gpu::texture_cache::TextureFormat::K8888) + }); + if std::env::var("XENIA_BIND_LOG").is_ok() && interesting { + use std::sync::atomic::{AtomicUsize, Ordering}; + static N: AtomicUsize = AtomicUsize::new(0); + let n = N.fetch_add(1, Ordering::Relaxed); + if n < 200 { + let slots: Vec = cap.textures.iter().map(|(s, ..)| *s).collect(); + let fmts: Vec = cap + .textures + .iter() + .map(|(_, k, ..)| format!("{:?}", k.format)) + .collect(); + eprintln!( + "BIND-LOG ps={:#x} vs={:#x} ntex={} slots={:?} fmts={:?} translated={} verts={}", + cap.ps_key, + cap.vs_key, + cap.textures.len(), + slots, + fmts, + served_translated, + cap.host_vertex_count, + ); + } + } if served_translated { self.xenos_dispatches_translator = self.xenos_dispatches_translator.saturating_add(1); @@ -901,6 +933,26 @@ impl RenderState { self.xenos_draws_rendered = self .xenos_draws_rendered .saturating_add(captures.len() as u64); + // Frontbuffer readback for offline color verification (XENIA_DUMP_FRAME). + // Counts frames that contained a movie (k_8 YUV) draw and dumps the + // composited frontbuffer at a few fade-in stages so the YUV→RGB output + // can be inspected as a raw RGBA image without needing a live viewer. + if std::env::var("XENIA_DUMP_FRAME").is_ok() { + use std::sync::atomic::{AtomicUsize, Ordering}; + static MOVIE_FRAMES: AtomicUsize = AtomicUsize::new(0); + let has_movie = captures.iter().any(|c| { + c.textures.iter().any(|(_, k, _, _)| { + matches!(k.format, xenia_gpu::texture_cache::TextureFormat::K8) + }) + }); + if has_movie { + let n = MOVIE_FRAMES.fetch_add(1, Ordering::Relaxed); + if n % 20 == 0 && n <= 2000 { + let dir = "/tmp/claude-1000/-home-fabi-RE---Project-Sylpheed/c5711e5b-8a9c-410c-860d-662365e450a4/scratchpad"; + self.dump_frontbuffer(&format!("{dir}/fb_movie_{n:04}.raw")); + } + } + } self.real_geometry_draws = self .real_geometry_draws .saturating_add(real_count as u64); @@ -915,6 +967,64 @@ impl RenderState { real_count } + /// Diagnostic: copy the current frontbuffer back to the CPU and write it + /// as tight RGBA8 bytes (`width*height*4`) to `path`. Blocks on the GPU. + /// Used to verify rendered colors offline (e.g. the intro-video YUV→RGB). + fn dump_frontbuffer(&self, path: &str) { + let (w, h) = self.frontbuffer_size; + if w == 0 || h == 0 { + return; + } + let bpp = 4u32; + let unpadded = w * bpp; + let align = wgpu::COPY_BYTES_PER_ROW_ALIGNMENT; + let padded = unpadded.div_ceil(align) * align; + let buffer = self.device.create_buffer(&wgpu::BufferDescriptor { + label: Some("frontbuffer readback"), + size: (padded * h) as u64, + usage: wgpu::BufferUsages::COPY_DST | wgpu::BufferUsages::MAP_READ, + mapped_at_creation: false, + }); + let mut encoder = self + .device + .create_command_encoder(&wgpu::CommandEncoderDescriptor { label: Some("fb-dump") }); + encoder.copy_texture_to_buffer( + wgpu::ImageCopyTexture { + texture: &self.frontbuffer_tex, + mip_level: 0, + origin: wgpu::Origin3d::ZERO, + aspect: wgpu::TextureAspect::All, + }, + wgpu::ImageCopyBuffer { + buffer: &buffer, + layout: wgpu::ImageDataLayout { + offset: 0, + bytes_per_row: Some(padded), + rows_per_image: Some(h), + }, + }, + wgpu::Extent3d { + width: w, + height: h, + depth_or_array_layers: 1, + }, + ); + self.queue.submit(std::iter::once(encoder.finish())); + let slice = buffer.slice(..); + slice.map_async(wgpu::MapMode::Read, |_| {}); + self.device.poll(wgpu::Maintain::Wait); + let data = slice.get_mapped_range(); + let mut out = Vec::with_capacity((unpadded * h) as usize); + for row in 0..h as usize { + let s = row * padded as usize; + out.extend_from_slice(&data[s..s + unpadded as usize]); + } + drop(data); + buffer.unmap(); + let _ = std::fs::write(path, &out); + eprintln!("FRONTBUFFER-DUMP {w}x{h} -> {path} ({} bytes)", out.len()); + } + /// Count of distinct translator pipelines compiled so far. Surfaced /// on the HUD as `xlated=N` to make "is P7 working?" observable. pub fn translated_pipeline_count(&self) -> usize { @@ -1072,8 +1182,19 @@ impl RenderState { pass.draw(0..self.hud_vertex_count, 0..1); } } + let _prof_t0 = std::time::Instant::now(); self.queue.submit(std::iter::once(encoder.finish())); frame.present(); + { + use xenia_gpu::prof; + prof::add(&prof::PRESENT_NS, _prof_t0.elapsed().as_nanos() as u64); + let n = prof::PRESENT_CALLS.fetch_add(1, std::sync::atomic::Ordering::Relaxed) + 1; + // Periodic snapshot so a SIGTERM'd (timed-out) movie run still + // yields a profile — the clean-exit report may never be reached. + if prof::enabled() && n % 500 == 0 { + prof::report(0); + } + } Ok(()) } } @@ -1107,6 +1228,9 @@ fn ensure_translated_pipeline( "reason" => reason, ) .increment(1); + if std::env::var("XENIA_BIND_LOG").is_ok() { + eprintln!("TRANSLATE-REJECT vs={vs_key:#x} ps={ps_key:#x} stage=vs reason={reason}"); + } return false; } }; @@ -1119,10 +1243,18 @@ fn ensure_translated_pipeline( "reason" => reason, ) .increment(1); + if std::env::var("XENIA_BIND_LOG").is_ok() { + eprintln!("TRANSLATE-REJECT vs={vs_key:#x} ps={ps_key:#x} stage=ps reason={reason}"); + } return false; } }; let wgsl = combine_stages(&vs_body, &ps_body); + if let Ok(dir) = std::env::var("XENIA_DUMP_WGSL") { + let path = format!("{dir}/wgsl_vs{vs_key:#x}_ps{ps_key:#x}.wgsl"); + let _ = std::fs::write(&path, &wgsl); + eprintln!("DUMP-WGSL wrote {path}"); + } xenos_pipeline.insert_translated(device, vs_key, ps_key, &wgsl) } @@ -1143,6 +1275,7 @@ fn make_frontbuffer(device: &wgpu::Device, w: u32, h: u32) -> (wgpu::Texture, wg // this texture instead of only consuming CPU-side raw scrapes. usage: wgpu::TextureUsages::TEXTURE_BINDING | wgpu::TextureUsages::COPY_DST + | wgpu::TextureUsages::COPY_SRC | wgpu::TextureUsages::RENDER_ATTACHMENT, view_formats: &[], }); diff --git a/sylph-run.sh b/sylph-run.sh new file mode 100755 index 0000000..e060567 --- /dev/null +++ b/sylph-run.sh @@ -0,0 +1,43 @@ +#!/usr/bin/env bash +# sylph-run.sh — run the ours xenia-rs emulator N times and report the standard +# intro-video oracles. Inherits any XENIA_* probe knobs from the caller's env +# (e.g. XENIA_FORCE_TID=24, XENIA_STARVE_LIMIT=16, XENIA_LOG_SIGNAL=0x40d10214). +# +# Usage: [XENIA_*=... ] sylph-run.sh [runs] [n_instr] [timeout_s] [extra_grep_regex] +# runs default 6 +# n_instr default 3000000000 +# timeout_s default 180 (boot is DETERMINISTIC and reaches the intro +# movie's first on-screen frame at ~81s wall; the movie then +# plays reliably. The old 90s default sat ~9s above that point, +# so host-load wall-clock jitter cut some runs off just before +# the movie — the apparent "~1/3 of runs" flakiness. 180s clears +# it with margin. Guest-instruction execution is identical run +# to run; only wall time varies with host speed.) +# extra_grep optional ERE; matching stdout lines are saved per-run for ad-hoc inspection +# +# Always-on oracles: source-read 0x824ff708 count (>1 = feeder looped), decode-worker +# resumes (tid25 start_entry 0x82506588 / tid26 0x825065b8). Full per-run log kept under +# /tmp/sylph-run/. +set -u +cd "/home/fabi/RE - Project Sylpheed/xenia-rs" || exit 2 +RUNS="${1:-6}"; N="${2:-3000000000}"; TO="${3:-180}"; XGREP="${4:-}" +OUT=/tmp/sylph-run; mkdir -p "$OUT" +BIN=./target/release/xenia-rs +[ -x "$BIN" ] || { echo "build first: (cd xenia-rs && export CARGO_BUILD_JOBS=4 && cargo build --release)"; exit 3; } + +echo "sylph-run: runs=$RUNS n=$N timeout=${TO}s knobs=[$(env | grep -oE 'XENIA_[A-Z_]+=[^ ]*' | tr '\n' ' ')]" +for i in $(seq 1 "$RUNS"); do + F="$OUT/run_$i.log"; REC="$OUT/rec_$i.txt" + RUST_LOG="${RUST_LOG:-warn,xenia_kernel::exports=info,xenia_kernel::state=info}" \ + XENIA_DISPATCH_REC=1 XENIA_DISPATCH_REC_SITES="${XENIA_DISPATCH_REC_SITES:-0x824ff708}" \ + XENIA_DISPATCH_REC_OUT="$REC" \ + timeout "$TO" "$BIN" exec sylpheed.iso -n "$N" >"$F" 2>&1 + pkill -x xenia-rs 2>/dev/null + sc=$(grep 0x824ff708 "$REC" 2>/dev/null | awk '{print $3}' | head -1) + w25=$(grep -c "RESUME.*0x82506588" "$F" 2>/dev/null) + w26=$(grep -c "RESUME.*0x825065b8" "$F" 2>/dev/null) + xg=""; [ -n "$XGREP" ] && xg=" match($XGREP)=$(grep -cE "$XGREP" "$F" 2>/dev/null)" + reached="movie"; [ "${sc:-0}" = "0" ] && reached="no-movie" + echo " run $i: [$reached] source-read=${sc:-0} tid25-resume=$w25 tid26-resume=$w26$xg (log: $F)" +done +echo "done. per-run logs in $OUT/. Reliable: source-read>1 = feeder looped; tid25/26 resume = pipeline progressed." diff --git a/zq.py b/zq.py new file mode 100755 index 0000000..e334368 --- /dev/null +++ b/zq.py @@ -0,0 +1,66 @@ +#!/usr/bin/env python3 +"""Sylpheed static-analysis helper over DuckDB `sylpheed.db`. + +Hides the gotchas: DECIMAL bounds (DuckDB rejects 0x literals), read-only connect, +and the fact that the engine vtable / rdata is NOT in the DB (read it from guest +memory with `xenia-rs exec ... --dump-addr=0x` instead). + +Usage: + zq.py dis # disassemble [lo,hi) + zq.py fn # function containing pc (address,name,end) + zq.py xref # xrefs whose target == addr (callers) + zq.py callers # call-sites of vtable slot at byte offset N + # (finds `lwz r11, N(r11)` + reports the fn) + zq.py grep # instructions whose operands LIKE %substr% + zq.py find # instructions whose raw word == value (e.g. a ptr) +""" +import duckdb, sys + +DB = '/home/fabi/RE - Project Sylpheed/xenia-rs/sylpheed.db' +c = duckdb.connect(DB, read_only=True) +H = lambda x: '0x%08x' % x + + +def _fn(pc): + r = c.execute('SELECT address,name,end_address FROM functions WHERE address<=? AND end_address>? ' + 'ORDER BY address DESC LIMIT 1', [pc, pc]).fetchall() + return f'{r[0][1]}({H(r[0][0])})' if r else '?' + + +def main(): + if len(sys.argv) < 2: + print(__doc__); return + cmd = sys.argv[1] + if cmd == 'dis': + lo, hi = int(sys.argv[2], 16), int(sys.argv[3], 16) + for a, m, o in c.execute('SELECT address,mnemonic,operands FROM instructions ' + 'WHERE address>=? AND address