diff options
| author | salmonik <salmonik@tuta.io> | 2026-11-01 17:09:59 +0100 |
|---|---|---|
| committer | salmonik <salmonik@tuta.io> | 2026-11-01 17:09:59 +0100 |
| commit | d99906b48698c1bd722a1fa5f2270b76317ec661 (patch) | |
| tree | 780a2b7bcf09733b7f6fedde9cf802c6b6e3abfb | |
| parent | ehci: diagnostics + hardening for the port-not-enabled case (diff) | |
| download | rs-dos-d99906b48698c1bd722a1fa5f2270b76317ec661.tar.gz rs-dos-d99906b48698c1bd722a1fa5f2270b76317ec661.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.md | 23 | ||||
| -rw-r--r-- | rsnix/src/ehci.rs | 87 | ||||
| -rw-r--r-- | rsnix/src/sched.rs | 2 | ||||
| -rw-r--r-- | 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: | |||
| 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 | |||
| 705 | Same QR (stage=1, PED=0), but now the machine never reaches the shell. Two | ||
| 706 | boot-time hazards, both introduced/exposed by the hardware diagnostics: | ||
| 707 | |||
| 708 | 1. **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). | ||
| 714 | 2. **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 | |||
| 718 | Fixes: all EHCI waits are wall-clock bounded (halt/reset/run 500 ms, PED | ||
| 719 | 200 ms, control transfer 500 ms), a per-controller 3 s port-scan budget, no | ||
| 720 | automatic re-scan (hotplug is explicit via `usb rescan`), a 300 ms power-up | ||
| 721 | settle, and the boot watchdog window raised to 20 s. The xHCI controller | ||
| 722 | also gets a persistent bottom-row summary. QEMU `make test-usb` is green | ||
| 723 | again (the 2 M-iteration PED poll had also eaten the 2 s scan budget and | ||
| 724 | 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); | |||
| 173 | /// Controller currently being initialized (registers/pointers resolve here). | 173 | /// Controller currently being initialized (registers/pointers resolve here). |
| 174 | static CUR: AtomicU32 = AtomicU32::new(0); | 174 | static CUR: AtomicU32 = AtomicU32::new(0); |
| 175 | static CTRL_UP: AtomicBool = AtomicBool::new(false); | 175 | static CTRL_UP: AtomicBool = AtomicBool::new(false); |
| 176 | static LAST_SCAN: AtomicU32 = AtomicU32::new(0); | ||
| 177 | static QR_SHOWN: AtomicBool = AtomicBool::new(false); | 176 | static QR_SHOWN: AtomicBool = AtomicBool::new(false); |
| 178 | 177 | ||
| 179 | unsafe fn ctrl_mut(i: usize) -> &'static mut Ctrl { | 178 | unsafe 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. | ||
| 246 | fn 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 | |||
| 246 | fn sleep_ms(ms: u64) { | 257 | fn 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. |
| 201 | const WATCHDOG_BOOT_SPIN_TICKS: u32 = 750; | 201 | const 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. | ||
| 1015 | fn 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 | |||
| 1011 | fn has_kind(kind: Kind) -> bool { | 1029 | fn 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 { |
