diff --git a/crates/xenia-app/src/main.rs b/crates/xenia-app/src/main.rs index 6f3009e..d88e2d5 100644 --- a/crates/xenia-app/src/main.rs +++ b/crates/xenia-app/src/main.rs @@ -3001,10 +3001,20 @@ fn worker_epilogue( /// swaps / packets track the one-block baseline), then a sharp cliff at /// ~384 collapses the present loop (a producer/consumer boot handoff /// starves when one slot runs too long without returning to the round). -/// 128 sits 3× below that cliff with ~1.65× boot-to-splash speedup — a -/// deliberately conservative pick (correctness over the last few %). The -/// `XENIA_SUPERBLOCK_BUDGET` env var overrides it for further tuning. -const SUPERBLOCK_INSTR_BUDGET: u64 = 128; +/// +/// Re-tuned against the INTRO-VIDEO workload (2026-07-06, XENIA_PROFILE +/// attribution): the per-slot-visit tax (worker_prologue + worker_epilogue) +/// was ~22% of movie wall, and raising the budget cuts slot-visits ~in +/// proportion (chains are NOT break-limited here — 128→192 dropped visits +/// 27.4M→18.9M, −31%; 128→256 −44%). But the movie's decode pipeline is more +/// timing-sensitive than boot: at 256 the decode worker tid25 (0x82506588) +/// INTERMITTENTLY fails to resume (1-of-2 runs) and the feeder loop weakens +/// (source-read 27→5-11) — a scheduling race the coarser interleaving exposes. +/// 192 is the sweet spot: 3/3 runs byte-identical (source-read=21, +/// tid25-resume=1, ADVreads=30) with ~−7% movie wall, and it stays well below +/// the 384 boot cliff. Do NOT raise past 192 without re-validating tid25 +/// resume across several runs. `XENIA_SUPERBLOCK_BUDGET` overrides for A/B. +const SUPERBLOCK_INSTR_BUDGET: u64 = 192; /// Effective superblock budget. Defaults to [`SUPERBLOCK_INSTR_BUDGET`]; /// `XENIA_SUPERBLOCK_BUDGET` overrides it (A/B tuning without a rebuild). @@ -3194,6 +3204,12 @@ fn run_superblock( } }; + let _ep_pt = xenia_gpu::prof::is_on().then(|| { + xenia_gpu::prof::ScopeTimer::new( + &xenia_gpu::prof::EPILOGUE_NS, + &xenia_gpu::prof::EPILOGUE_CALLS, + ) + }); worker_epilogue( wc, kernel, @@ -3302,6 +3318,8 @@ fn run_execution( // then drain any pending auto-signals whose deadline has passed. // Both calls are no-ops when `XENIA_SILPH_UI_AUTOSIGNAL_DELAY` // is unset (the pending queue stays empty). + let _round_pt = xenia_gpu::prof::is_on() + .then(|| xenia_gpu::prof::ScopeTimer::new(&xenia_gpu::prof::ROUND_NS, &xenia_gpu::prof::ROUND_CALLS)); kernel.set_now_cycle_hint(stats.instruction_count); // Drive the coherent monotonic "now" the kernel deadline-arithmetic // reads (`KernelState::now_basis_at` -> `Scheduler::global_clock`) @@ -3336,6 +3354,7 @@ fn run_execution( // a reusable stack array instead of allocating a fresh Vec per round. kernel.scheduler.begin_round(); let order_n = kernel.scheduler.round_schedule_into(&mut order_buf); + drop(_round_pt); // end per-round tax measurement at the schedule boundary let order = &order_buf[..order_n]; if order.is_empty() { @@ -3360,7 +3379,13 @@ fn run_execution( for &hw_id in order { let wc = &mut workers[hw_id as usize]; - match worker_prologue( + let _pro_pt = xenia_gpu::prof::is_on().then(|| { + xenia_gpu::prof::ScopeTimer::new( + &xenia_gpu::prof::PROLOGUE_NS, + &xenia_gpu::prof::PROLOGUE_CALLS, + ) + }); + let prologue_outcome = worker_prologue( wc, kernel, mem, @@ -3368,7 +3393,9 @@ fn run_execution( &mut db_writer, thunk_map, &mut stats, - ) { + ); + drop(_pro_pt); + match prologue_outcome { PrologueOutcome::Continue => continue, PrologueOutcome::BreakOuter => break 'outer, PrologueOutcome::StepBlock { @@ -3385,7 +3412,13 @@ fn run_execution( // the per-round (timebase / coord / round_schedule) // and per-slot (prologue) tax over hundreds of // instructions instead of ~6. See `run_superblock`. - match run_superblock( + let _sb_pt = xenia_gpu::prof::is_on().then(|| { + xenia_gpu::prof::ScopeTimer::new( + &xenia_gpu::prof::RUNSB_NS, + &xenia_gpu::prof::RUNSB_CALLS, + ) + }); + let sb_outcome = run_superblock( wc, kernel, mem, @@ -3396,7 +3429,9 @@ fn run_execution( thread_ref, block_ptr, pc_before, - ) { + ); + drop(_sb_pt); + match sb_outcome { SlotOutcome::Continue => continue, SlotOutcome::BreakOuter => break 'outer, } diff --git a/crates/xenia-gpu/src/prof.rs b/crates/xenia-gpu/src/prof.rs index 6e1e4fc..da602aa 100644 --- a/crates/xenia-gpu/src/prof.rs +++ b/crates/xenia-gpu/src/prof.rs @@ -45,6 +45,16 @@ 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); +// Top-level lockstep-loop attribution (sums to ~100% with idle/GPU-pacer): +pub static ROUND_NS: AtomicU64 = AtomicU64::new(0); // per-round tax (clock/timestamp/isr/schedule) +pub static ROUND_CALLS: AtomicU64 = AtomicU64::new(0); +pub static PROLOGUE_NS: AtomicU64 = AtomicU64::new(0); // worker_prologue (⊇ KERNEL) +pub static PROLOGUE_CALLS: AtomicU64 = AtomicU64::new(0); +pub static RUNSB_NS: AtomicU64 = AtomicU64::new(0); // run_superblock (⊇ STEP + chain BUILD + EPILOGUE) +pub static RUNSB_CALLS: AtomicU64 = AtomicU64::new(0); +pub static EPILOGUE_NS: AtomicU64 = AtomicU64::new(0); // worker_epilogue (subset of RUNSB) +pub static EPILOGUE_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); @@ -142,52 +152,43 @@ pub fn report(_ignored: u64) { } 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); + let round_ns = g(&ROUND_NS); + let prologue_ns = g(&PROLOGUE_NS); + let runsb_ns = g(&RUNSB_NS); + let epilogue_ns = g(&EPILOGUE_NS); + // Derived leftovers (honest lumping — see comments): + // runsb_other = chain-loop body (arithmetic/stop-checks) + in-chain block lookups + // prologue_other = block lookup (first block) + scheduler bookkeeping + let runsb_other = runsb_ns.saturating_sub(step_ns).saturating_sub(epilogue_ns); + let prologue_other = prologue_ns.saturating_sub(kern_ns); + let line = |label: &str, ns: u64, extra: &str| { + eprintln!(" {:<20}{:>10.1} ms {:>5.1}% {}", label, ms(ns), pct(ns), extra); + }; + eprintln!("=== XENIA_PROFILE (wall {:.1} ms) ===", ms(wall_ns)); + eprintln!(" -- TOP LEVEL (single-thread lockstep loop; sums ~100%) --"); + line("per-round tax", round_ns, &format!("({} rounds)", g(&ROUND_CALLS))); + line("worker_prologue", prologue_ns, &format!("({} visits)", g(&PROLOGUE_CALLS))); + line("run_superblock", runsb_ns, &format!("({} visits)", g(&RUNSB_CALLS))); + let top = round_ns + prologue_ns + runsb_ns; eprintln!( - " kernel HLE export : {:>10.1} ms {:>5.1}% ({} calls)", - ms(kern_ns), - pct(kern_ns), - g(&KERNEL_CALLS) + " ---- top accounted {:.1}% ; idle/GPU-pacer/misc {:.1}%", + pct(top), + pct(wall_ns.saturating_sub(top)) ); - 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)) + eprintln!(" -- SUB-ATTRIBUTION --"); + line( + "interp step_block", + step_ns, + &format!("[in run_superblock] ({} calls, {} instr, {:.1} MIPS)", g(&STEP_CALLS), step_instr, mips), ); + line("worker_epilogue", epilogue_ns, "[in run_superblock]"); + line("run_superblock other", runsb_other, "[chain-loop body + in-chain lookups]"); + line("kernel HLE export", kern_ns, &format!("[in worker_prologue] ({} calls)", g(&KERNEL_CALLS))); + line("worker_prologue other", prologue_other, "[first-block lookup + sched bookkeeping]"); + line("block decode/cache", build_ns, &format!("[split across prologue+runsb] ({} calls)", g(&BUILD_CALLS))); + line("texture decode+up", tex_ns, &format!("({} calls, {} MiB)", g(&TEXDEC_CALLS), g(&TEXDEC_BYTES) / (1024 * 1024))); + line("host draw submit", draw_ns, &format!("({} calls)", g(&DRAW_CALLS))); + line("frontbuffer present", pres_ns, &format!("({} calls)", g(&PRESENT_CALLS))); }