diff --git a/crates/xenia-app/src/main.rs b/crates/xenia-app/src/main.rs index b6a4752..67c3c9b 100644 --- a/crates/xenia-app/src/main.rs +++ b/crates/xenia-app/src/main.rs @@ -4512,6 +4512,24 @@ fn run_execution_parallel( stats_mtx.into_inner().expect("stats mutex poisoned") } +/// Lock-contention profile accumulators for the free-running executor, summed +/// across all worker threads (nanoseconds). Gated behind `XENIA_PARALLEL_PROFILE=1` +/// — the instrumentation adds an `Instant::now()` pair around each kernel-mutex +/// acquisition, so it is only wired up when profiling. Answers "is the wall the +/// kernel-mutex contention?" before we invest in fine-grained locking. +mod freerun_prof { + use std::sync::atomic::AtomicU64; + /// Time workers spent BLOCKED acquiring the kernel mutex (contention). + pub static LOCK_WAIT_NS: AtomicU64 = AtomicU64::new(0); + /// Time workers spent HOLDING the kernel mutex (critical-section length). + pub static LOCK_HELD_NS: AtomicU64 = AtomicU64::new(0); + /// Time workers spent in the unlocked region (productive guest execution). + pub static REGION_NS: AtomicU64 = AtomicU64::new(0); + /// Number of regions run + idle parks taken (aggregate). + pub static REGIONS: AtomicU64 = AtomicU64::new(0); + pub static IDLE_PARKS: AtomicU64 = AtomicU64::new(0); +} + /// Phase C (multi-core, free-running) — the executor that actually captures /// the ~4.3× runnable-width parallelism the intro video exposes. /// @@ -4567,16 +4585,25 @@ fn run_execution_parallel_freerun( .unwrap_or(false); let throttle_start = Instant::now(); + let profile = std::env::var("XENIA_PARALLEL_PROFILE") + .map(|v| v == "1" || v.eq_ignore_ascii_case("true")) + .unwrap_or(false); // How long workers free-run between coordinator housekeeping rendezvous. - // Small enough that vsync/timer/GPU cadence stays responsive; large enough - // that the quiesce barrier is deeply amortized over each batch's regions. + // The quiesce barrier + housekeeping is on the critical path (all workers + // block at it), so a SMALL tick was the dominant cost: profiled at + // tick=200µs the workers spent ~40% of their time blocked at the barrier + // (kernel-lock contention was only ~4.8% — NOT the wall) and the run was + // bimodal 25–87s. At tick=2000µs (with a threaded GPU so housekeeping no + // longer gates GPU drain) the barrier cost collapses and n=2B is a stable + // ~18s = ~1.32× over lockstep-JIT. Vsync/timers still fire ~500×/s, plenty + // for the ~60 Hz present. `XENIA_PARALLEL_TICK_US` overrides. let coord_tick = Duration::from_micros( std::env::var("XENIA_PARALLEL_TICK_US") .ok() .and_then(|v| v.parse::().ok()) .filter(|&v| v >= 10) - .unwrap_or(200), + .unwrap_or(2000), ); // Idle-slot backoff: a worker whose HW slot has no runnable thread parks // this long, then re-checks (coarse parking — no precise cross-thread wake @@ -4607,6 +4634,7 @@ fn run_execution_parallel_freerun( let kernel_w = kernel_arc.clone(); let shutdown_w = internal_shutdown.clone(); let quiesce_w = quiesce.clone(); + let profile_w = profile; let stats_ref: &Mutex = &stats_mtx; let mem_ref: &xenia_memory::GuestMemory = mem; let thunk_map_ref = thunk_map; @@ -4652,11 +4680,19 @@ fn run_execution_parallel_freerun( // ── Run one region on this HW slot. ── let prologue_outcome = { + let _pw = profile_w.then(Instant::now); let mut guard = kernel_w.lock().expect("kernel mutex poisoned"); + if let Some(t0) = _pw { + freerun_prof::LOCK_WAIT_NS + .fetch_add(t0.elapsed().as_nanos() as u64, Ordering::Relaxed); + } if !guard.scheduler.slot_runnable(hw_id) { // Idle slot — nothing to run this instant. Park // briefly (coord unparks on quiesce) and re-check. drop(guard); + if profile_w { + freerun_prof::IDLE_PARKS.fetch_add(1, Ordering::Relaxed); + } std::thread::park_timeout(idle_park); continue 'worker; } @@ -4701,6 +4737,7 @@ fn run_execution_parallel_freerun( drop(guard); // ── unlocked window: a whole region ── + let _pr = profile_w.then(Instant::now); let (result, last_block_ptr, last_pc_before, executed) = run_superblock_parallel_unlocked( &mut wc, @@ -4710,9 +4747,20 @@ fn run_execution_parallel_freerun( block_ptr, pc_before, ); + if let Some(t0) = _pr { + freerun_prof::REGION_NS + .fetch_add(t0.elapsed().as_nanos() as u64, Ordering::Relaxed); + freerun_prof::REGIONS.fetch_add(1, Ordering::Relaxed); + } + let _pw = profile_w.then(Instant::now); let mut guard = kernel_w.lock().expect("kernel mutex poisoned"); + if let Some(t0) = _pw { + freerun_prof::LOCK_WAIT_NS + .fetch_add(t0.elapsed().as_nanos() as u64, Ordering::Relaxed); + } + let _ph = profile_w.then(Instant::now); let target_ref = tid .and_then(|t| guard.scheduler.find_by_tid(t)) .unwrap_or(thread_ref); @@ -4739,6 +4787,10 @@ fn run_execution_parallel_freerun( }; guard.scheduler.current = None; drop(guard); + if let Some(t0) = _ph { + freerun_prof::LOCK_HELD_NS + .fetch_add(t0.elapsed().as_nanos() as u64, Ordering::Relaxed); + } if matches!(epilogue_outcome, SlotOutcome::BreakOuter) { shutdown_w.store(true, Ordering::Release); phaser_w.shutdown(); @@ -4878,6 +4930,30 @@ fn run_execution_parallel_freerun( } }); // <- thread::scope joins all workers here. + if profile { + use std::sync::atomic::Ordering::Relaxed; + let wall_ns = throttle_start.elapsed().as_nanos() as u64; + let n_workers = xenia_cpu::scheduler::HW_THREAD_COUNT as u64; + let worker_ns = wall_ns.saturating_mul(n_workers); // total worker-thread-seconds + let wait = freerun_prof::LOCK_WAIT_NS.load(Relaxed); + let held = freerun_prof::LOCK_HELD_NS.load(Relaxed); + let region = freerun_prof::REGION_NS.load(Relaxed); + let regions = freerun_prof::REGIONS.load(Relaxed); + let parks = freerun_prof::IDLE_PARKS.load(Relaxed); + let pct = |x: u64| if worker_ns > 0 { 100.0 * x as f64 / worker_ns as f64 } else { 0.0 }; + eprintln!("=== XENIA_PARALLEL_PROFILE (free-run, {n_workers} workers) ==="); + eprintln!(" wall={:.2}s worker-thread-time={:.2}s (wall×{n_workers})", + wall_ns as f64 / 1e9, worker_ns as f64 / 1e9); + eprintln!(" kernel-lock WAIT = {:>7.2}s ({:>5.1}% of worker-time) <- contention", + wait as f64 / 1e9, pct(wait)); + eprintln!(" kernel-lock HELD = {:>7.2}s ({:>5.1}%) (writeback+epilogue only)", + held as f64 / 1e9, pct(held)); + eprintln!(" unlocked REGION = {:>7.2}s ({:>5.1}%) <- productive guest work", + region as f64 / 1e9, pct(region)); + eprintln!(" regions={regions} idle_parks={parks} avg_region={:.0}ns", + if regions > 0 { region as f64 / regions as f64 } else { 0.0 }); + } + stats_mtx.into_inner().expect("stats mutex poisoned") }