diff --git a/TESTING.md b/TESTING.md index e37d75498..7cfcd85e5 100644 --- a/TESTING.md +++ b/TESTING.md @@ -515,7 +515,10 @@ console on the graphics board and a screenshot to match. It reads the seeded NVRAM back from the PROM and from the booted guest, and checks that iris quits cleanly. What it seeds and checks is `tests/irix/boot.toml`. Each check is a JUnit case, so a failed run is annotated with the check that failed, and the run -keeps the logs. [clanker/testing/ci-unattended-irix-boot.md](clanker/testing/ci-unattended-irix-boot.md) +keeps the logs. When the headless run never reaches the PROM's menu or a prompt, +`phase-a.log` holds everything the PROM printed and `phase-a-cpu.log` the CPU's +registers where it stopped (on the O2, also the words at physical 0x1000 and +0x4000). [clanker/testing/ci-unattended-irix-boot.md](clanker/testing/ci-unattended-irix-boot.md) has the details. ## Disk persistence on exit diff --git a/clanker/INDEX.md b/clanker/INDEX.md index b3e55f016..8cc4c996e 100644 --- a/clanker/INDEX.md +++ b/clanker/INDEX.md @@ -124,6 +124,7 @@ Non-graphics devices: MC/MEMCFG and RAM banks, HPC3, VDMA, EEPROMs and NVRAM, PS | [o2-readback-transfer-registers.md](devices/o2-readback-transfer-registers.md) | rule | O2 glReadPixels: the frame-buffer-to-linear transfer, GL vertices, edge type, src steps and linStride as IRIX uses them | | [ip32-o2-bringup-log.md](devices/ip32-o2-bringup-log.md) | history | The O2 (IP32) bring-up log: PROM, POST, CRIME/MACE/GBE, SCSI, PCI, the OSes | | [ip32-headless-irix-panics.md](devices/ip32-headless-irix-panics.md) | rule | O2 TLBMISS at 0xff800000 in early boot was `crmFifoWait` timing out on our host-thread RE; status polls now wait for the engine (fixed) | +| [o2-prom-does-not-wait-for-its-mte-clear.md](devices/o2-prom-does-not-wait-for-its-mte-clear.md) | rule | O2 PROM 4.18 clears low memory with the MTE and reads RE status once without waiting; a late engine thread wiped its cookie (`SL-9600-8E>`) or its POST code. A status read now answers busy until every queued transfer is done | | [ip30-octane-bringup.md](devices/ip30-octane-bringup.md) | rule | What the Octane's PROM insists on (memory sizing, the Bridge status bit, empty slots, IOC3 bits, the one-wire parts' formats, its device tree) and what booting it through to IRIX added (cached flash lines, low-memory JIT counters, the ISP stall, HQ4 before a context switch) | | [ip30-memory-past-4gb-takes-a-16gb-window.md](devices/ip30-memory-past-4gb-takes-a-16gb-window.md) | design | Octane past 4 GB: 16 GB window, 256 MB per bitmap bit, per-machine shift | | [ip30-module-name-must-match-active-cpus.md](devices/ip30-module-name-must-match-active-cpus.md) | rule | Octane: the module record must say PM10 for one CPU and PM20 for two, or the PROM fails its NIC diagnostic | diff --git a/clanker/devices/o2-prom-does-not-wait-for-its-mte-clear.md b/clanker/devices/o2-prom-does-not-wait-for-its-mte-clear.md new file mode 100644 index 000000000..9e2511bc6 --- /dev/null +++ b/clanker/devices/o2-prom-does-not-wait-for-its-mte-clear.md @@ -0,0 +1,25 @@ +# The O2 PROM does not wait for its MTE clear: a status read must + +Status: fixed (2026-11-12). + +**Symptom.** On a busy host the O2 now and then sat at `SL-9600-8E>` on +serial with nothing before it, instead of reaching the PROM menu. A later +form of the same race prints nothing and parks the CPU at `0xbfc003a0` on a +reserved instruction. + +**Cause.** PROM 4.18 clears 32 KB at RAM base with the MTE (`0xbfc061f0`), +reads RE status once without acting on it (`0xbfc06400`), stores a cookie at +`0xa000_1008` and copies its POST code to `0xa000_4000`. It checks the cookie +after POST (`0xbfc044f4`) and drops to the serial loader if it changed. The MTE +runs on the CRIME-RE host thread, and a status read waited at most 100 us. +When the host kept that thread off a processor longer, the clear ran late and +zeroed the cookie, or later still the POST code. + +**Rule.** A status read answers `BUS_BUSY` until every MTE transfer queued +before it is done (`transfers_queued` against `transfers_done` in `CrimeRe`). +Primitives keep the bounded wait. MTE copies longer than 100 us lose their +overlap with the CPU. Software that reuses memory a transfer wrote without +reading the status word still races the engine. The same race exists for +primitives, whose frame buffers are main memory: a read-back with no idle wait +could see pixels not yet drawn. It is left uncovered on purpose, as no known +guest does that and holding primitives would cost drawing overlap. diff --git a/clanker/testing/ci-unattended-irix-boot.md b/clanker/testing/ci-unattended-irix-boot.md index 5cff9a8a2..7cbb0e8e9 100644 --- a/clanker/testing/ci-unattended-irix-boot.md +++ b/clanker/testing/ci-unattended-irix-boot.md @@ -45,6 +45,16 @@ The serial boot stays alongside the graphics one: it is cheap, and when a boot fails its transcript shows how far it got, which a screenshot does not. The PROM lists a seeded `AutoLoad` as `Yes` and the guest's `nvram` as `Y`, so only the PROM's listing is checked. The test then seeds NVRAM again with `console g` and boots a second time. + +When the headless pass gets stuck (no `Option?`, no Command Monitor prompt) the +test keeps what the PROM printed that no wait took in `phase-a.log`, stops the +CPU through the monitor (`stop`, `regs`) and writes the registers to +`phase-a-cpu.log`. On the O2 it adds `mem 0xa0001000 4 w` and +`mem 0xa0004000 4 w`: zeros at the PROM's stack cookie (0x1008) or POST code +(0x4000) mean a late MTE clear, as in +[o2-prom-does-not-wait-for-its-mte-clear.md](../devices/o2-prom-does-not-wait-for-its-mte-clear.md). Both are in the job's artifact. The O2 PROM's own +failures say little on serial (`SL-9600-8E>` and nothing else is common), so +the PC is what tells a parked serial loader from a POST hang. The login is drawn on the framebuffer, so `iris-ci screen-wait` polls screenshots until one matches `scripts/boot-goldens/indy-irix53.png`. Serial is not silent on every disk: the stock disk has a getty on `ttyd1`, so `IRIS diff --git a/docs/graphics/o2.md b/docs/graphics/o2.md index 62e958a34..c52d054a5 100644 --- a/docs/graphics/o2.md +++ b/docs/graphics/o2.md @@ -68,7 +68,12 @@ only setting the register. Page `0x2000` starts a primitive (`pixel_pipe`). Page A read of the engine's registers while it is busy answers `BUS_BUSY` (`read_reg`). The status word reports the buffer level as CRIME's own FIFO would show it (`read_reg_now`). A status read first waits up to 100 us for the engine to go idle, -or 20 ms when the previous poll found it busy. +or 20 ms when the previous poll found it busy. A memory transfer (MTE) is not +left behind that way: until every transfer queued before it is done, a status +read answers `BUS_BUSY` and the CPU retries it. The O2's PROM clears memory with +the MTE, reads the status word once without acting on it, and uses that memory +straight after. An MTE copy longer than 100 us therefore no longer overlaps +the CPU's next status read. GBE's registers are written in place (`Gbe::write_reg`). A write to a shadowed register goes to a pending list with the frame number. The pending writes are diff --git a/src/dev/o2gfx.rs b/src/dev/o2gfx.rs index 276341ee2..7024b551f 100644 --- a/src/dev/o2gfx.rs +++ b/src/dev/o2gfx.rs @@ -1179,6 +1179,12 @@ pub struct CrimeRe { /// nothing since: a further status read is a guest waiting in a loop. /// Host pacing only, not CRIME state, so a snapshot does not keep it. polled_busy: std::sync::atomic::AtomicBool, + /// MTE transfers the CPU has queued, and those the engine has carried + /// out: a status read answers only once the second has caught up (see + /// `read_reg_now`). Host pacing too. `done` can lead for a moment, as the + /// count is raised after the push, and the `>=` test absorbs that. + transfers_queued: std::sync::atomic::AtomicU64, + transfers_done: std::sync::atomic::AtomicU64, asleep: std::sync::atomic::AtomicBool, started: std::sync::atomic::AtomicBool, /// Set by [`Self::stop`]: the engine's thread ends once the buffer is @@ -1283,6 +1289,8 @@ impl CrimeRe { ib: unsafe { Box::::new_zeroed().assume_init() }, busy: std::sync::atomic::AtomicBool::new(false), polled_busy: std::sync::atomic::AtomicBool::new(false), + transfers_queued: std::sync::atomic::AtomicU64::new(0), + transfers_done: std::sync::atomic::AtomicU64::new(0), asleep: std::sync::atomic::AtomicBool::new(false), started: std::sync::atomic::AtomicBool::new(false), quit: std::sync::atomic::AtomicBool::new(false), @@ -1439,6 +1447,25 @@ impl CrimeRe { true } + /// Wait up to `limit` for the engine to carry out every MTE transfer + /// queued so far. + fn transfers_caught_up(&self, limit: std::time::Duration) -> bool { + use std::sync::atomic::Ordering::Acquire; + let caught_up = || self.transfers_done.load(Acquire) >= self.transfers_queued.load(Acquire); + if caught_up() { + return true; + } + let until = std::time::Instant::now() + limit; + let backoff = crossbeam_utils::Backoff::new(); + while !caught_up() { + if std::time::Instant::now() >= until { + return false; + } + backoff.snooze(); + } + true + } + /// Wait until the engine is idle (tests and replays; the CPU retries). #[cfg(test)] fn wait_idle(&self) { @@ -1528,6 +1555,9 @@ impl CrimeRe { return BUS_BUSY; } crate::pf_value!(self.pf_level, crate::perfetto::events::RE_IB_LEVEL, self.ib.len()); + if off & 0xf800 == 0x3800 { + self.transfers_queued.fetch_add(1, std::sync::atomic::Ordering::Release); + } self.polled_busy.store(false, std::sync::atomic::Ordering::Relaxed); self.record(off, val, width); self.wake(); @@ -1591,6 +1621,16 @@ impl CrimeRe { // queued while that fits, one entry past it, so software that // waits for room (the kernel's MTE copies wait for 64 - level) // always finds some and the CPU runs ahead of the engine. + // + // That holds for primitives only: while an MTE transfer is + // outstanding the read answers busy (the CPU retries) until it is + // done. The O2's PROM clears memory with the MTE, reads this word + // once and reuses that memory, which a late engine thread wiped. MTE + // copies longer than 100 us lose their overlap with the CPU. + // Primitives draw into main memory too, so software that reads + // pixels back without an idle wait could race the same way. No + // known guest does, and holding there would cost drawing overlap. + STATUS | 0x4004 if !self.transfers_caught_up(RE_STATUS_POLL_WAIT) => None, STATUS | 0x4004 => Some(if self.idle() || self.drain(self.status_wait()) { self.polled_busy.store(false, std::sync::atomic::Ordering::Relaxed); RE_STATUS_IDLE @@ -1623,7 +1663,7 @@ impl CrimeRe { if page == 0x2000 { self.pixel_pipe(); } else { - self.mte(); + self.transfer(); } } } @@ -2785,6 +2825,13 @@ impl CrimeRe { } } + /// Carry out an MTE transfer, and count it done for a status read + /// waiting on it. + fn transfer(&self) { + self.mte(); + self.transfers_done.fetch_add(1, std::sync::atomic::Ordering::Release); + } + fn mte(&self) { crate::pf_scope!(crate::perfetto::events::RE_MTE, self.drawn.load(std::sync::atomic::Ordering::Relaxed)); self.drawn.fetch_add(1, std::sync::atomic::Ordering::Relaxed); @@ -2958,7 +3005,7 @@ impl CrimeRe { if page == 0x2000 { self.pixel_pipe(); } else { - self.mte(); + self.transfer(); } } } @@ -3999,6 +4046,46 @@ mod tests { assert_eq!(re.read32((0x1500_0000 + FG) as u64).data, 1000); } + /// The O2's PROM clears the bottom 32 KB of memory with the MTE, reads + /// the status word once and goes on storing into that memory without + /// looking at what it read. Its clear has to be done by the time the + /// read answers, however late the engine's thread gets to run. A clear + /// that lands later wipes what the PROM stored since: on a busy host + /// the PROM stopped at its serial loader prompt, `SL-9600-8E>`. + #[test] + fn a_status_read_answers_only_once_a_queued_transfer_is_done() { + let ram = Arc::new(O2Memory::single(32 << 20)); + let addr = 0x0011_4000u32; + ram.write(addr as usize, &[0x55; 0x2000]); + let re = Arc::new(CrimeRe::new(ram.clone())); + let reg = |off: u32| (0x1500_0000 + off) as u64; + let page = addr >> 12; + let pair = ((1u64 << 31 | page as u64) << 32) | (1u64 << 31 | (page + 1) as u64); + assert_eq!(re.write64(reg(TLB_LINEAR_A + 8 * ((page & 31) >> 1)), pair), BUS_OK); + for (off, val) in [(MTE_DST0, addr), (MTE_DST1, addr + 0x1fff), (MTE_FG, 0), (MTE_BYTEMASK, 0xffff_ffff), (MTE_MODE | 0x800, 0x11)] { + assert_eq!(re.write32(reg(off), val), BUS_OK); + } + // The engine's thread starts 200 ms from now, far past the status + // read's own wait. + let late = re.clone(); + let starter = std::thread::spawn(move || { + std::thread::sleep(std::time::Duration::from_millis(200)); + late.start(late.clone(), |r| r); + }); + // The PROM's one read, retried while it answers busy as the CPU + // retries it. + let status = loop { + let r = re.read32(reg(STATUS)); + if r.status != BUS_BUSY { + break r.data; + } + }; + let cleared = ram.bytes(addr as usize, 0x2000).iter().all(|&b| b == 0); + starter.join().unwrap(); + assert!(cleared, "the read answered before the clear was done"); + assert_eq!(status, RE_STATUS_IDLE); + } + /// A full interface buffer holds the CPU's write back (BUS_BUSY) with /// nothing lost, and the status word shows the level as CRIME's 64 /// entries would: what is queued below that, one entry past it. diff --git a/src/iris_ci_boot.rs b/src/iris_ci_boot.rs index c3c8400d5..84f5cb2cf 100644 --- a/src/iris_ci_boot.rs +++ b/src/iris_ci_boot.rs @@ -117,7 +117,7 @@ pub fn run(args: Args) -> Result<()> { } let out = abs(&args.out)?; std::fs::create_dir_all(&out).map_err(|e| local(&out, e))?; - for f in ["nvram.bin", "serial.log", "phase-a.log", "boot-test.xml"] { + for f in ["nvram.bin", "serial.log", "phase-a.log", "phase-a-cpu.log", "boot-test.xml"] { let _ = std::fs::remove_file(out.join(f)); } @@ -130,6 +130,7 @@ pub fn run(args: Args) -> Result<()> { opts: Opts { socket: PathBuf::from(socket), json: false, quiet: true }, child: None, prompt: monitor_prompt(machine), + stuck: stuck_commands(machine), check: String::new(), cases: Vec::new(), failed: false, @@ -168,6 +169,18 @@ fn monitor_prompt(machine: iris::config::MachineProfile) -> &'static str { if machine == iris::config::MachineProfile::O2Ip32 { "> " } else { ">> " } } +/// What the monitor is asked when phase A is stuck: the registers, and on +/// the O2 the words at physical 0x1000 and 0x4000. The O2 PROM keeps a stack +/// cookie at 0x1008 and its POST code at 0x4000. Zeros there mean a memory +/// clear landed after the PROM had stored them. +fn stuck_commands(machine: iris::config::MachineProfile) -> &'static [&'static str] { + if machine == iris::config::MachineProfile::O2Ip32 { + &["stop", "regs", "mem 0xa0001000 4 w", "mem 0xa0004000 4 w"] + } else { + &["stop", "regs"] + } +} + /// The CI socket: TCP on Windows, and elsewhere a Unix socket in the host's /// temporary directory, as iris's own default is. A path under the output /// directory could pass macOS's 104-byte limit on a Unix socket path. @@ -204,6 +217,27 @@ fn config(disk: &Path, socket: &str, machine: &str) -> String { format!("# Written by iris-ci boot-test.\n{}", toml::to_string(&t).expect("a table of plain values")) } +/// Run `cmds` on iris's monitor at `addr` and return what it printed. The +/// monitor hangs up after `quit`, so the reply is everything up to then. +fn monitor_run(addr: &str, cmds: &[&str]) -> std::io::Result { + use std::io::Read; + let to = std::time::Duration::from_secs(10); + let addr: std::net::SocketAddr = addr.parse().map_err(|e| std::io::Error::new(std::io::ErrorKind::InvalidInput, e))?; + let mut s = std::net::TcpStream::connect_timeout(&addr, to)?; + s.set_read_timeout(Some(to))?; + s.write_all(format!("{}\nquit\n", cmds.join("\n")).as_bytes())?; + // Keep what came before a read that timed out. + let mut out = Vec::new(); + if let Err(e) = s.read_to_end(&mut out) { + if out.is_empty() { + return Err(e); + } + } + // From the first prompt on: before it is the monitor's banner. + let text = String::from_utf8_lossy(&out).replace("\r\n", "\n"); + Ok(text.find("> ").map_or(text.as_str(), |i| &text[i..]).to_string()) +} + fn log(msg: &str) { let day = std::time::SystemTime::now() .duration_since(std::time::UNIX_EPOCH).map_or(0, |d| d.as_secs()) % 86400; @@ -245,6 +279,8 @@ struct Test { child: Option, /// What the PROM's Command Monitor prints when it wants a line. prompt: &'static str, + /// Monitor commands that say where a stuck phase A stopped. + stuck: &'static [&'static str], /// The case a failure that ends the test is filed under. check: String, cases: Vec, @@ -363,6 +399,30 @@ impl Test { ok.then_some(text) } + /// Phase A is stuck: keep what the PROM printed that no wait took, and + /// where the CPU is (with `stuck`'s memory words), in phase-a.log and + /// phase-a-cpu.log, and print both. + /// The serial output is often a single prompt, and the registers say + /// which loop the PROM is parked in. + fn prom_stopped(&self) { + let serial = self.out.join("phase-a.log"); + if let Ok(Value::String(rest)) = send(&self.opts, "serial-read", json!({})) { + if let Ok(mut f) = std::fs::OpenOptions::new().append(true).create(true).open(&serial) { + let _ = f.write_all(rest.as_bytes()); + } + } + self.dump(&serial); + let cpu = self.out.join("phase-a-cpu.log"); + let regs = send(&self.opts, "status", json!({})).ok() + .and_then(|s| s.get("monitor_addr").and_then(Value::as_str).map(str::to_string)) + .ok_or_else(|| "no monitor address".to_string()) + .and_then(|addr| monitor_run(&addr, self.stuck).map_err(|e| format!("monitor {addr}: {e}"))); + let text = regs.unwrap_or_else(|e| format!("CPU state not read: {e}\n")); + let _ = std::fs::write(&cpu, &text); + log(&format!("CPU state, also in {}:", cpu.display())); + print!("{text}"); + } + /// Type a Command Monitor line and wait for the prompt. What the monitor /// printed comes back. fn monitor(&mut self, line: &str) -> Step { @@ -370,7 +430,7 @@ impl Test { match sent.is_ok().then(|| self.prom_wait(self.prompt, PROMPT_WAIT)).flatten() { Some(text) => Ok(text), None => { - self.dump(&self.out.join("phase-a.log")); + self.prom_stopped(); Err(self.abort(format!("phase A: '{line}' got no prompt back"))) } } @@ -389,13 +449,13 @@ impl Test { self.start_iris(&format!("iris-seed-{console}.log"), &["--headless"])?; let _ = send(&self.opts, "start", json!({})); if self.prom_wait("Option?", MENU_WAIT).is_none() { - self.dump(&self.out.join("phase-a.log")); + self.prom_stopped(); return Err(self.abort("phase A: PROM menu never appeared on serial".into())); } // Enter Command Monitor. let _ = send(&self.opts, "serial-send", json!({"data": "5\r"})); if self.prom_wait(self.prompt, PROMPT_WAIT).is_none() { - self.dump(&self.out.join("phase-a.log")); + self.prom_stopped(); return Err(self.abort("phase A: no Command Monitor prompt".into())); } for (k, v) in seeded(vars, console, false) { @@ -578,6 +638,7 @@ mod tests { opts: Opts { socket: PathBuf::new(), json: false, quiet: true }, child: None, prompt: ">> ", + stuck: &["stop", "regs"], check: String::new(), cases: Vec::new(), failed: false, @@ -633,6 +694,31 @@ mod tests { assert!(sock.len() - std::env::temp_dir().as_os_str().len() < 40); } + /// The CPU dump of a stuck phase A: each command's answer, without the + /// monitor's banner, read until the monitor hangs up after `quit`. + #[test] + fn the_monitor_answers_come_back_without_its_banner() { + use std::io::{BufRead, BufReader}; + let l = std::net::TcpListener::bind("127.0.0.1:0").unwrap(); + let addr = l.local_addr().unwrap().to_string(); + let server = std::thread::spawn(move || { + let (s, _) = l.accept().unwrap(); + let mut w = s.try_clone().unwrap(); + w.write_all(b" ## \r\nMonitor\r\n> ").unwrap(); + for line in BufReader::new(s).lines() { + match line.unwrap().as_str() { + "quit" => break, + "stop" => w.write_all(b"CPU stopped\r\n> ").unwrap(), + "regs" => w.write_all(b"PC: 0xffffffffbfc013ac\r\n> ").unwrap(), + _ => w.write_all(b"Unknown command.\r\n> ").unwrap(), + } + } + }); + let got = monitor_run(&addr, &["stop", "regs"]).unwrap(); + server.join().unwrap(); + assert_eq!(got, "> CPU stopped\n> PC: 0xffffffffbfc013ac\n> "); + } + #[test] fn the_config_names_the_disk_whatever_its_path_holds() { let disk = Path::new("C:\\a \"b\"\\irix.chd");