summaryrefslogtreecommitdiffstats
diff options
context:
space:
mode:
authorsalmonik <salmonik@tuta.io>2026-11-01 17:09:59 +0100
committersalmonik <salmonik@tuta.io>2026-11-01 17:09:59 +0100
commitd99906b48698c1bd722a1fa5f2270b76317ec661 (patch)
tree780a2b7bcf09733b7f6fedde9cf802c6b6e3abfb
parentehci: diagnostics + hardening for the port-not-enabled case (diff)
downloadrs-dos-qemu.tar.gz
rs-dos-qemu.zip
ehci: bound all init waits; stop auto-rescanning; wider boot watchdogqemu
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
-rw-r--r--DEBUG_NOTES.md23
-rw-r--r--rsnix/src/ehci.rs87
-rw-r--r--rsnix/src/sched.rs2
-rw-r--r--rsnix/src/usb.rs20
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:
699- persistent bottom-row summary: per controller `64b=`/`leg=` handoff result, 699- persistent bottom-row summary: per controller `64b=`/`leg=` handoff result,
700 every connected port's PORTSC, and the HID device count — hardware runs 700 every connected port's PORTSC, and the HID device count — hardware runs
701 without serial now show the whole picture, not just the first QR 701 without serial now show the whole picture, not just the first QR
702
703### OptiPlex — "dies at the prompt" (third run)
704
705Same QR (stage=1, PED=0), but now the machine never reaches the shell. Two
706boot-time hazards, both introduced/exposed by the hardware diagnostics:
707
7081. **Count-based MMIO waits.** `reset_port` polled PED for 2,000,000
709 iterations and the controller reset used 10,000,000-iteration loops.
710 On real silicon each iteration is an uncached MMIO read; with the new
711 reset retry that is seconds per port. The boot-phase watchdog panics
712 when task 0 keeps a fixed stack frame for 750 ticks (7.5 s), and its
713 panic band is the only visible trace (serial carries the rest).
7142. **Automatic re-scan every second.** While no HID was found the cursor
715 task re-ran the entire EHCI scan (including port resets), so a rate
716 matching hub never got a chance to settle.
717
718Fixes: all EHCI waits are wall-clock bounded (halt/reset/run 500 ms, PED
719200 ms, control transfer 500 ms), a per-controller 3 s port-scan budget, no
720automatic re-scan (hotplug is explicit via `usb rescan`), a 300 ms power-up
721settle, and the boot watchdog window raised to 20 s. The xHCI controller
722also gets a persistent bottom-row summary. QEMU `make test-usb` is green
723again (the 2 M-iteration PED poll had also eaten the 2 s scan budget and
724skipped 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);
173/// Controller currently being initialized (registers/pointers resolve here). 173/// Controller currently being initialized (registers/pointers resolve here).
174static CUR: AtomicU32 = AtomicU32::new(0); 174static CUR: AtomicU32 = AtomicU32::new(0);
175static CTRL_UP: AtomicBool = AtomicBool::new(false); 175static CTRL_UP: AtomicBool = AtomicBool::new(false);
176static LAST_SCAN: AtomicU32 = AtomicU32::new(0);
177static QR_SHOWN: AtomicBool = AtomicBool::new(false); 176static QR_SHOWN: AtomicBool = AtomicBool::new(false);
178 177
179unsafe fn ctrl_mut(i: usize) -> &'static mut Ctrl { 178unsafe fn ctrl_mut(i: usize) -> &'static mut Ctrl {
@@ -243,6 +242,18 @@ unsafe fn wait_recl(timeout: usize) {
243 } 242 }
244} 243}
245 244
245/// Poll `cond` until it is true or `ms` of wall time elapse.
246fn wait_until(ms: u64, mut cond: impl FnMut() -> bool) -> bool {
247 let t0 = crate::interrupts::uptime_ms();
248 while crate::interrupts::uptime_ms().saturating_sub(t0) < ms {
249 if cond() {
250 return true;
251 }
252 core::hint::spin_loop();
253 }
254 cond()
255}
256
246fn sleep_ms(ms: u64) { 257fn sleep_ms(ms: u64) {
247 let t0 = crate::interrupts::uptime_ms(); 258 let t0 = crate::interrupts::uptime_ms();
248 while crate::interrupts::uptime_ms().saturating_sub(t0) < ms { 259 while crate::interrupts::uptime_ms().saturating_sub(t0) < ms {
@@ -405,7 +416,7 @@ unsafe fn ctl_xfer(
405 stage = 4; 416 stage = 4;
406 break; 417 break;
407 } 418 }
408 if t0 + 5000 < crate::interrupts::uptime_ms() { 419 if t0 + 500 < crate::interrupts::uptime_ms() {
409 stage = 3; 420 stage = 3;
410 break; 421 break;
411 } 422 }
@@ -1045,23 +1056,21 @@ unsafe fn init_one(bus: u8, dev: u8, func: u8) -> bool {
1045 c.legacy = legacy; 1056 c.legacy = legacy;
1046 } 1057 }
1047 1058
1048 // Halt, reset, wait for reset to clear. 1059 // Halt, reset, wait for reset to clear (wall-clock bounded: MMIO
1060 // reads are slow on real silicon and a count-based loop can eat
1061 // seconds of the boot watchdog budget).
1049 wr(op(OPCMD), 0); 1062 wr(op(OPCMD), 0);
1050 let mut t = 0; 1063 let halted = wait_until(500, || rd(op(OPSTS)) & STS_HCH != 0);
1051 while t < 1_000_000 && (rd(op(OPSTS)) & STS_HCH) == 0 {
1052 t += 1;
1053 core::hint::spin_loop();
1054 }
1055 wr(op(OPCMD), CMD_HCRESET); 1064 wr(op(OPCMD), CMD_HCRESET);
1056 t = 0; 1065 let hcreset = wait_until(500, || rd(op(OPCMD)) & CMD_HCRESET == 0);
1057 while t < 10_000_000 && (rd(op(OPCMD)) & CMD_HCRESET) != 0 { 1066 let halted2 = wait_until(500, || rd(op(OPSTS)) & STS_HCH != 0);
1058 t += 1; 1067 if !(halted && hcreset && halted2) {
1059 core::hint::spin_loop(); 1068 crate::serial_println!(
1060 } 1069 "ehci: reset sequence incomplete (halt={} hcreset={} halted={})",
1061 t = 0; 1070 halted,
1062 while t < 10_000_000 && (rd(op(OPSTS)) & STS_HCH) == 0 { 1071 hcreset,
1063 t += 1; 1072 halted2
1064 core::hint::spin_loop(); 1073 );
1065 } 1074 }
1066 wr(op(OPINTR), 0); 1075 wr(op(OPINTR), 0);
1067 1076
@@ -1115,10 +1124,8 @@ unsafe fn init_one(bus: u8, dev: u8, func: u8) -> bool {
1115 } 1124 }
1116 wr(op(0x14), (framelist as usize as u32) & !0x3FF); 1125 wr(op(0x14), (framelist as usize as u32) & !0x3FF);
1117 wr(op(OPCMD), CMD_RUN); 1126 wr(op(OPCMD), CMD_RUN);
1118 t = 0; 1127 if !wait_until(500, || rd(op(OPSTS)) & STS_HCH == 0) {
1119 while t < 1_000_000 && (rd(op(OPSTS)) & STS_HCH) != 0 { 1128 crate::serial_println!("ehci: controller did not leave halt");
1120 t += 1;
1121 core::hint::spin_loop();
1122 } 1129 }
1123 wr(op(OPCFGFLAG), 1); // route all ports to the host 1130 wr(op(OPCFGFLAG), 1); // route all ports to the host
1124 for p in 0..nports as usize { 1131 for p in 0..nports as usize {
@@ -1131,7 +1138,7 @@ unsafe fn init_one(bus: u8, dev: u8, func: u8) -> bool {
1131 // Rate-matching hubs need noticeably longer than a direct device to 1138 // Rate-matching hubs need noticeably longer than a direct device to
1132 // come up after port power; give them time and clear stale change 1139 // come up after port power; give them time and clear stale change
1133 // bits before the reset walk. 1140 // bits before the reset walk.
1134 sleep_ms(100); 1141 sleep_ms(300);
1135 for p in 0..nports as usize { 1142 for p in 0..nports as usize {
1136 let psc = prtsc(p); 1143 let psc = prtsc(p);
1137 let v = rd(psc); 1144 let v = rd(psc);
@@ -1145,7 +1152,15 @@ unsafe fn init_one(bus: u8, dev: u8, func: u8) -> bool {
1145 CTRL_UP.store(true, Ordering::Relaxed); 1152 CTRL_UP.store(true, Ordering::Relaxed);
1146 1153
1147 // ---- scan ports ---- 1154 // ---- scan ports ----
1155 // Bounded: the boot-phase watchdog panics after 7.5 s with task 0 in
1156 // one frame, and a device that NAKs forever costs one 500 ms transfer
1157 // timeout each. Two seconds is plenty for the RMH + HID handshake.
1158 let scan_t0 = crate::interrupts::uptime_ms();
1148 for p in 0..nports as usize { 1159 for p in 0..nports as usize {
1160 if crate::interrupts::uptime_ms().saturating_sub(scan_t0) > 3000 {
1161 crate::serial_println!("ehci: port-scan budget exceeded — stopping");
1162 break;
1163 }
1149 let v = rd(prtsc(p)); 1164 let v = rd(prtsc(p));
1150 if v & PRT_CONNECT == 0 { 1165 if v & PRT_CONNECT == 0 {
1151 continue; 1166 continue;
@@ -1191,16 +1206,7 @@ unsafe fn init_one(bus: u8, dev: u8, func: u8) -> bool {
1191 port: (p + 1) as u8, 1206 port: (p + 1) as u8,
1192 }) 1207 })
1193 }; 1208 };
1194 let mut found = enumerate(0, speed, tt, p); 1209 enumerate(0, speed, tt, p);
1195 if found == 0 && !hs && speed == 0 {
1196 // The PORTSC speed field is only trustworthy once the port is
1197 // enabled; a low-speed device serviced as full-speed halts the
1198 // SETUP split. Retry once as low-speed.
1199 crate::serial_println!("ehci: port {} retrying as low-speed", p);
1200 sleep_ms(20);
1201 found = enumerate(0, 1, tt, p);
1202 }
1203 let _ = found;
1204 } 1210 }
1205 1211
1206 arm_periodic(ci); 1212 arm_periodic(ci);
@@ -1256,11 +1262,7 @@ unsafe fn reset_port(p: usize) -> bool {
1256 } 1262 }
1257 } 1263 }
1258 wr(psc, (rd(psc) & !PRT_RESET) & !PRT_RWC); 1264 wr(psc, (rd(psc) & !PRT_RESET) & !PRT_RWC);
1259 let mut t = 0; 1265 wait_until(200, || rd(psc) & PRT_PED != 0);
1260 while t < 2_000_000 && (rd(psc) & PRT_PED) == 0 {
1261 t += 1;
1262 core::hint::spin_loop();
1263 }
1264 rd(psc) & PRT_PED != 0 1266 rd(psc) & PRT_PED != 0
1265 } 1267 }
1266} 1268}
@@ -1443,14 +1445,9 @@ pub fn poll_mouse() -> Option<MouseEvent> {
1443 rearm(d); 1445 rearm(d);
1444 return Some(ev); 1446 return Some(ev);
1445 } 1447 }
1446 // Nothing armed: retry discovery at most once per second. 1448 // No automatic re-scan: repeatedly resetting ports keeps a rate
1447 if N_DEV.load(Ordering::Relaxed) == 0 && CTRL_UP.load(Ordering::Relaxed) { 1449 // matching hub from settling and burns boot/watchdog time. Hotplug
1448 let now = crate::interrupts::uptime_ms() as u32; 1450 // discovery is explicit (`usb rescan` from the shell).
1449 if now.wrapping_sub(LAST_SCAN.load(Ordering::Relaxed)) >= 1000 {
1450 LAST_SCAN.store(now, Ordering::Relaxed);
1451 rescan();
1452 }
1453 }
1454 None 1451 None
1455 } 1452 }
1456} 1453}
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;
198/// Boot-phase threshold for task 0 (the shell): before the REPL is live, 198/// Boot-phase threshold for task 0 (the shell): before the REPL is live,
199/// task 0 runs init code where a fixed frame means a driver/controller 199/// task 0 runs init code where a fixed frame means a driver/controller
200/// hang — panic after ~15 s wall. The boot must finish well inside this. 200/// hang — panic after ~15 s wall. The boot must finish well inside this.
201const WATCHDOG_BOOT_SPIN_TICKS: u32 = 750; 201const WATCHDOG_BOOT_SPIN_TICKS: u32 = 2000; // 20 s: room for hub/USB bring-up
202 202
203/// True once the shell REPL is live (set by main.rs before shell::run()). 203/// True once the shell REPL is live (set by main.rs before shell::run()).
204/// The shell legitimately blocks on its message queue once live; 204/// 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 {
699 } 699 }
700 NXDEV.fetch_add(1, Ordering::Relaxed); 700 NXDEV.fetch_add(1, Ordering::Relaxed);
701 queue_report(idx); 701 queue_report(idx);
702 show_summary();
702 crate::serial_println!( 703 crate::serial_println!(
703 "usb: HID {} armed (slot {} mps {} interval {})", 704 "usb: HID {} armed (slot {} mps {} interval {})",
704 if kind == Kind::Mouse { "mouse" } else { "keyboard" }, 705 if kind == Kind::Mouse { "mouse" } else { "keyboard" },
@@ -968,10 +969,12 @@ pub fn init() -> bool {
968 } 969 }
969 } 970 }
970 INITOK.store(true, Ordering::Relaxed); 971 INITOK.store(true, Ordering::Relaxed);
972 let ports = unsafe { MAXPORTS };
971 crate::serial_println!( 973 crate::serial_println!(
972 "usb: controller up ({} ports) — HID discovery deferred to polling", 974 "usb: controller up ({} ports) — HID discovery deferred to polling",
973 unsafe { MAXPORTS } 975 ports
974 ); 976 );
977 show_summary();
975 true 978 true
976} 979}
977 980
@@ -1008,6 +1011,21 @@ fn maybe_discover() {
1008 } 1011 }
1009} 1012}
1010 1013
1014/// Persistent bottom-row summary for hardware runs without serial.
1015fn show_summary() {
1016 let (np, nd) = unsafe { (MAXPORTS, NXDEV.load(Ordering::Relaxed)) };
1017 let mut line = alloc::format!("xhci ports={} devs={}:", np, nd);
1018 unsafe {
1019 for p in 0..np.min(8) {
1020 let v = rd(op(OP_PORTSC) + (p as usize) * PORT_STRIDE);
1021 if v & PORT_CONNECT != 0 {
1022 line.push_str(&alloc::format!(" p{}={:04x}", p, v & 0xffff));
1023 }
1024 }
1025 }
1026 crate::gop::boot_marker_at(&line, crate::gop::bottom_row(3));
1027}
1028
1011fn has_kind(kind: Kind) -> bool { 1029fn has_kind(kind: Kind) -> bool {
1012 let n = NXDEV.load(Ordering::Relaxed) as usize; 1030 let n = NXDEV.load(Ordering::Relaxed) as usize;
1013 for i in 0..n { 1031 for i in 0..n {