From d99906b48698c1bd722a1fa5f2270b76317ec661 Mon Sep 17 00:00:00 2001 From: salmonik Date: Sun, 1 Nov 2026 17:09:59 +0100 Subject: ehci: bound all init waits; stop auto-rescanning; wider boot watchdog Hardware run 3 showed the same PED=0 SETUP halt and then never reached the prompt. Two boot-time hazards explain the death: - reset_port polled PED with a 2,000,000-iteration MMIO loop (seconds on real silicon) and the reset retry ran it twice per port, so the port scan alone exceeded the boot watchdog window (task 0 in one frame for 7.5 s panics). - while no HID was found the cursor task re-ran the whole EHCI scan, port resets included, every second -- a rate-matching hub never settles. Changes: - every EHCI wait is wall-clock bounded: halt/reset/run 500 ms, PED 200 ms - control-transfer timeout 5 s -> 500 ms - per-controller 3 s port-scan budget; no automatic re-scan (explicit `usb rescan` only) - 300 ms power-up settle before the reset walk (RMH bring-up) - boot-phase watchdog 750 -> 2000 ticks (20 s), room for hub bring-up - xHCI gets the same persistent bottom-row port/device summary --- DEBUG_NOTES.md | 23 +++++++++++++++ rsnix/src/ehci.rs | 87 ++++++++++++++++++++++++++---------------------------- rsnix/src/sched.rs | 2 +- rsnix/src/usb.rs | 20 ++++++++++++- 4 files changed, 85 insertions(+), 47 deletions(-) diff --git a/DEBUG_NOTES.md b/DEBUG_NOTES.md index c9efdc1..b72a979 100644 --- a/DEBUG_NOTES.md +++ b/DEBUG_NOTES.md @@ -699,3 +699,26 @@ Follow-up hardening in the driver: - persistent bottom-row summary: per controller `64b=`/`leg=` handoff result, every connected port's PORTSC, and the HID device count — hardware runs without serial now show the whole picture, not just the first QR + +### OptiPlex — "dies at the prompt" (third run) + +Same QR (stage=1, PED=0), but now the machine never reaches the shell. Two +boot-time hazards, both introduced/exposed by the hardware diagnostics: + +1. **Count-based MMIO waits.** `reset_port` polled PED for 2,000,000 + iterations and the controller reset used 10,000,000-iteration loops. + On real silicon each iteration is an uncached MMIO read; with the new + reset retry that is seconds per port. The boot-phase watchdog panics + when task 0 keeps a fixed stack frame for 750 ticks (7.5 s), and its + panic band is the only visible trace (serial carries the rest). +2. **Automatic re-scan every second.** While no HID was found the cursor + task re-ran the entire EHCI scan (including port resets), so a rate + matching hub never got a chance to settle. + +Fixes: all EHCI waits are wall-clock bounded (halt/reset/run 500 ms, PED +200 ms, control transfer 500 ms), a per-controller 3 s port-scan budget, no +automatic re-scan (hotplug is explicit via `usb rescan`), a 300 ms power-up +settle, and the boot watchdog window raised to 20 s. The xHCI controller +also gets a persistent bottom-row summary. QEMU `make test-usb` is green +again (the 2 M-iteration PED poll had also eaten the 2 s scan budget and +skipped the keyboard). diff --git a/rsnix/src/ehci.rs b/rsnix/src/ehci.rs index 2d16d37..11625c7 100644 --- a/rsnix/src/ehci.rs +++ b/rsnix/src/ehci.rs @@ -173,7 +173,6 @@ static N_DEV: AtomicU32 = AtomicU32::new(0); /// Controller currently being initialized (registers/pointers resolve here). static CUR: AtomicU32 = AtomicU32::new(0); static CTRL_UP: AtomicBool = AtomicBool::new(false); -static LAST_SCAN: AtomicU32 = AtomicU32::new(0); static QR_SHOWN: AtomicBool = AtomicBool::new(false); unsafe fn ctrl_mut(i: usize) -> &'static mut Ctrl { @@ -243,6 +242,18 @@ unsafe fn wait_recl(timeout: usize) { } } +/// Poll `cond` until it is true or `ms` of wall time elapse. +fn wait_until(ms: u64, mut cond: impl FnMut() -> bool) -> bool { + let t0 = crate::interrupts::uptime_ms(); + while crate::interrupts::uptime_ms().saturating_sub(t0) < ms { + if cond() { + return true; + } + core::hint::spin_loop(); + } + cond() +} + fn sleep_ms(ms: u64) { let t0 = crate::interrupts::uptime_ms(); while crate::interrupts::uptime_ms().saturating_sub(t0) < ms { @@ -405,7 +416,7 @@ unsafe fn ctl_xfer( stage = 4; break; } - if t0 + 5000 < crate::interrupts::uptime_ms() { + if t0 + 500 < crate::interrupts::uptime_ms() { stage = 3; break; } @@ -1045,23 +1056,21 @@ unsafe fn init_one(bus: u8, dev: u8, func: u8) -> bool { c.legacy = legacy; } - // Halt, reset, wait for reset to clear. + // Halt, reset, wait for reset to clear (wall-clock bounded: MMIO + // reads are slow on real silicon and a count-based loop can eat + // seconds of the boot watchdog budget). wr(op(OPCMD), 0); - let mut t = 0; - while t < 1_000_000 && (rd(op(OPSTS)) & STS_HCH) == 0 { - t += 1; - core::hint::spin_loop(); - } + let halted = wait_until(500, || rd(op(OPSTS)) & STS_HCH != 0); wr(op(OPCMD), CMD_HCRESET); - t = 0; - while t < 10_000_000 && (rd(op(OPCMD)) & CMD_HCRESET) != 0 { - t += 1; - core::hint::spin_loop(); - } - t = 0; - while t < 10_000_000 && (rd(op(OPSTS)) & STS_HCH) == 0 { - t += 1; - core::hint::spin_loop(); + let hcreset = wait_until(500, || rd(op(OPCMD)) & CMD_HCRESET == 0); + let halted2 = wait_until(500, || rd(op(OPSTS)) & STS_HCH != 0); + if !(halted && hcreset && halted2) { + crate::serial_println!( + "ehci: reset sequence incomplete (halt={} hcreset={} halted={})", + halted, + hcreset, + halted2 + ); } wr(op(OPINTR), 0); @@ -1115,10 +1124,8 @@ unsafe fn init_one(bus: u8, dev: u8, func: u8) -> bool { } wr(op(0x14), (framelist as usize as u32) & !0x3FF); wr(op(OPCMD), CMD_RUN); - t = 0; - while t < 1_000_000 && (rd(op(OPSTS)) & STS_HCH) != 0 { - t += 1; - core::hint::spin_loop(); + if !wait_until(500, || rd(op(OPSTS)) & STS_HCH == 0) { + crate::serial_println!("ehci: controller did not leave halt"); } wr(op(OPCFGFLAG), 1); // route all ports to the host for p in 0..nports as usize { @@ -1131,7 +1138,7 @@ unsafe fn init_one(bus: u8, dev: u8, func: u8) -> bool { // Rate-matching hubs need noticeably longer than a direct device to // come up after port power; give them time and clear stale change // bits before the reset walk. - sleep_ms(100); + sleep_ms(300); for p in 0..nports as usize { let psc = prtsc(p); let v = rd(psc); @@ -1145,7 +1152,15 @@ unsafe fn init_one(bus: u8, dev: u8, func: u8) -> bool { CTRL_UP.store(true, Ordering::Relaxed); // ---- scan ports ---- + // Bounded: the boot-phase watchdog panics after 7.5 s with task 0 in + // one frame, and a device that NAKs forever costs one 500 ms transfer + // timeout each. Two seconds is plenty for the RMH + HID handshake. + let scan_t0 = crate::interrupts::uptime_ms(); for p in 0..nports as usize { + if crate::interrupts::uptime_ms().saturating_sub(scan_t0) > 3000 { + crate::serial_println!("ehci: port-scan budget exceeded — stopping"); + break; + } let v = rd(prtsc(p)); if v & PRT_CONNECT == 0 { continue; @@ -1191,16 +1206,7 @@ unsafe fn init_one(bus: u8, dev: u8, func: u8) -> bool { port: (p + 1) as u8, }) }; - let mut found = enumerate(0, speed, tt, p); - if found == 0 && !hs && speed == 0 { - // The PORTSC speed field is only trustworthy once the port is - // enabled; a low-speed device serviced as full-speed halts the - // SETUP split. Retry once as low-speed. - crate::serial_println!("ehci: port {} retrying as low-speed", p); - sleep_ms(20); - found = enumerate(0, 1, tt, p); - } - let _ = found; + enumerate(0, speed, tt, p); } arm_periodic(ci); @@ -1256,11 +1262,7 @@ unsafe fn reset_port(p: usize) -> bool { } } wr(psc, (rd(psc) & !PRT_RESET) & !PRT_RWC); - let mut t = 0; - while t < 2_000_000 && (rd(psc) & PRT_PED) == 0 { - t += 1; - core::hint::spin_loop(); - } + wait_until(200, || rd(psc) & PRT_PED != 0); rd(psc) & PRT_PED != 0 } } @@ -1443,14 +1445,9 @@ pub fn poll_mouse() -> Option { rearm(d); return Some(ev); } - // Nothing armed: retry discovery at most once per second. - if N_DEV.load(Ordering::Relaxed) == 0 && CTRL_UP.load(Ordering::Relaxed) { - let now = crate::interrupts::uptime_ms() as u32; - if now.wrapping_sub(LAST_SCAN.load(Ordering::Relaxed)) >= 1000 { - LAST_SCAN.store(now, Ordering::Relaxed); - rescan(); - } - } + // No automatic re-scan: repeatedly resetting ports keeps a rate + // matching hub from settling and burns boot/watchdog time. Hotplug + // discovery is explicit (`usb rescan` from the shell). None } } diff --git a/rsnix/src/sched.rs b/rsnix/src/sched.rs index 107dba6..d148164 100644 --- a/rsnix/src/sched.rs +++ b/rsnix/src/sched.rs @@ -198,7 +198,7 @@ const WATCHDOG_SPIN_TICKS: u32 = 1500; /// Boot-phase threshold for task 0 (the shell): before the REPL is live, /// task 0 runs init code where a fixed frame means a driver/controller /// hang — panic after ~15 s wall. The boot must finish well inside this. -const WATCHDOG_BOOT_SPIN_TICKS: u32 = 750; +const WATCHDOG_BOOT_SPIN_TICKS: u32 = 2000; // 20 s: room for hub/USB bring-up /// True once the shell REPL is live (set by main.rs before shell::run()). /// The shell legitimately blocks on its message queue once live; diff --git a/rsnix/src/usb.rs b/rsnix/src/usb.rs index 5a4136f..aa41b0e 100644 --- a/rsnix/src/usb.rs +++ b/rsnix/src/usb.rs @@ -699,6 +699,7 @@ fn enumerate(port: u32, speed: u32) -> bool { } NXDEV.fetch_add(1, Ordering::Relaxed); queue_report(idx); + show_summary(); crate::serial_println!( "usb: HID {} armed (slot {} mps {} interval {})", if kind == Kind::Mouse { "mouse" } else { "keyboard" }, @@ -968,10 +969,12 @@ pub fn init() -> bool { } } INITOK.store(true, Ordering::Relaxed); + let ports = unsafe { MAXPORTS }; crate::serial_println!( "usb: controller up ({} ports) — HID discovery deferred to polling", - unsafe { MAXPORTS } + ports ); + show_summary(); true } @@ -1008,6 +1011,21 @@ fn maybe_discover() { } } +/// Persistent bottom-row summary for hardware runs without serial. +fn show_summary() { + let (np, nd) = unsafe { (MAXPORTS, NXDEV.load(Ordering::Relaxed)) }; + let mut line = alloc::format!("xhci ports={} devs={}:", np, nd); + unsafe { + for p in 0..np.min(8) { + let v = rd(op(OP_PORTSC) + (p as usize) * PORT_STRIDE); + if v & PORT_CONNECT != 0 { + line.push_str(&alloc::format!(" p{}={:04x}", p, v & 0xffff)); + } + } + } + crate::gop::boot_marker_at(&line, crate::gop::bottom_row(3)); +} + fn has_kind(kind: Kind) -> bool { let n = NXDEV.load(Ordering::Relaxed) as usize; for i in 0..n { -- cgit v1.2.3