From 5a2d4947eaa31b2d2017a52990944272e825ce79 Mon Sep 17 00:00:00 2001 From: MechaCat02 Date: Sun, 5 Jul 2026 19:33:55 +0200 Subject: [PATCH] [iterate-4D] multi-core: free-run lock-contention profiler + tick=2000 default; REFUTES lock-splitting MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Adds XENIA_PARALLEL_PROFILE=1 to the free-run executor: reports, summed across workers, kernel-lock WAIT (contention), HELD, unlocked REGION, and idle-park counts. This measured the actual bottleneck before committing to fine-grained locking — and refuted it: n=2B free-run profile (worker-thread-time basis): kernel-lock WAIT = 4.8% <- contention is NOT the wall kernel-lock HELD = 0.5% unlocked REGION = 27.1% <- productive idle_parks = 2.45M ; ~40% = workers blocked at the quiesce barrier So fine-grained kernel locking would NOT help — the wall is COORDINATION (the per-tick quiesce barrier + idle-park wake latency) and guest spin-waits. Also raises the coordinator tick default 200µs -> 2000µs: the barrier is on the critical path, so the small tick was the dominant cost. This roughly halves the good-case time (n=2B ~17-18s vs lockstep-JIT ~24s = ~1.35×). BUT free-run is still BIMODAL — a coordination pathology intermittently latches (~60s). (A/B tests that looked like "XENIA_GPU_THREAD makes it fast" were run-ordering noise: use_threaded=true either way — the flag is a no-op here; the split was the pathology.) Next lever = attack the coordination bimodality (precise cross-slot wake to kill the ≤50µs idle-park latency; or skip in-flight slots in the ISR housekeeping to drop the barrier), NOT lock-splitting. Opt-in (XENIA_PARALLEL_FREERUN=1); lockstep golden byte-identical (interp+JIT). Co-Authored-By: Claude Opus 4.8 --- crates/xenia-app/src/main.rs | 82 ++++++++++++++++++++++++++++++++++-- 1 file changed, 79 insertions(+), 3 deletions(-) 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") }