diff --git a/crates/benilla-app/src/perf/mod.rs b/crates/benilla-app/src/perf/mod.rs index bbffe258..424b6441 100644 --- a/crates/benilla-app/src/perf/mod.rs +++ b/crates/benilla-app/src/perf/mod.rs @@ -10,7 +10,7 @@ //! - [`hud`]: the cost pill, //! - [`trace`] / [`journal`]: the CSV instruments (`WOW_STREAM_TRACE`, `WOW_FPS_JOURNAL`); the //! journal also answers the `fpsJournal` CVar, in every build, -//! - [`stall`]: the stuck-main-thread self-sampler (macOS), +//! - [`stall`]: the stuck-main-thread self-sampler (`sample` on macOS, `/proc` on Linux), //! - [`census`]: the env-gated premise counters. //! //! `clock` and `journal` compile in the player build; everything else is @@ -38,7 +38,9 @@ mod main_split; mod phases; #[cfg(feature = "dev")] mod render_stage; -#[cfg(all(feature = "dev", target_os = "macos"))] +// Every platform: the Linux arm reads `/proc` where macOS runs `sample`, and the teardown +// backstop is platform-independent. +#[cfg(feature = "dev")] mod stall; #[cfg(feature = "dev")] mod stats; @@ -142,9 +144,10 @@ impl Plugin for PerfPlugin { app.insert_resource(c); app.add_systems(Last, census::res_census::res_census); } - // `WOW_CRASH_INJECT=`: armed here, on every platform, not in the macOS-only sampler. + // `WOW_CRASH_INJECT=`: armed here, beside the stall injectors rather than inside the + // sampler, so a crash can be injected with the watchdog off. crash_inject::arm(app); - #[cfg(target_os = "macos")] + #[cfg(feature = "dev")] stall::plugin(app); phases::plugin(app); gpu::plugin(app); diff --git a/crates/benilla-app/src/perf/stall.rs b/crates/benilla-app/src/perf/stall.rs index 8761b5db..5f1953f7 100644 --- a/crates/benilla-app/src/perf/stall.rs +++ b/crates/benilla-app/src/perf/stall.rs @@ -1,8 +1,20 @@ -//! The stuck-main-thread self-sampler (macOS only; `WOW_STALL_SAMPLE=0` disables it): a watchdog -//! thread sees the main-thread heartbeat go stale and runs `/usr/bin/sample` on our own PID, so a -//! stall or teardown hang diagnoses itself on any run. Samples land in -//! `benilla-config/Diagnostics/` and the path prints on stderr, since the tracing subscriber may -//! be gone during teardown. +//! The stuck-main-thread self-sampler (`WOW_STALL_SAMPLE=0` disables it): a watchdog thread sees +//! the main-thread heartbeat go stale and asks the OS what the process is doing, so a stall or +//! teardown hang diagnoses itself on any run. Reports land in `benilla-config/Diagnostics/` and +//! the path prints on stderr, since the tracing subscriber may be gone during teardown. +//! +//! **macOS** runs `/usr/bin/sample`, a real backtrace of every thread. **Linux** reads `/proc` +//! instead: each thread's scheduler state, the kernel function it sleeps in (`wchan`) and its CPU +//! time. That is less than a backtrace but it settles the first question — **climbing CPU time is +//! a loop, flat time in `S` or `D` is a wait, and the wchan says what for** — and it costs +//! nothing, where a real Linux backtrace of our own process needs ptrace, which `yama`'s +//! `ptrace_scope=1` refuses between siblings and which this client is not going to ask for on a +//! player's machine. The player can still run `sudo eu-stack -p ` by hand on a wedged client +//! before killing it; the report names the pid for exactly that. +//! +//! The client froze on the player's machine on 2026-10-19 with nothing in the log and nothing in +//! the kernel ring, which is the hole this fills: the watchdog was registered on macOS only, so +//! on Linux no heartbeat was ever watched. //! //! In-frame sampling is skipped while an audio device is open: `sample` suspends every thread, //! the audio IO thread included, and each suspension is a crackle. `WOW_STALL_SAMPLE=force` @@ -34,8 +46,17 @@ static EXITING: AtomicBool = AtomicBool::new(false); /// The status `AppExit` asked for, so the backstop never turns a failed run into a passing one. static EXIT_CODE: AtomicU8 = AtomicU8::new(0); -/// In-frame staleness that means a real stall (ms), above the ~250 ms loading-screen hitches. -const STALL_MS: u64 = 600; +/// In-frame staleness that means a real stall (ms). +/// +/// macOS samples at 600 ms, above the ~250 ms loading-screen hitches, because a `sample` is cheap +/// to take and the suspension is brief. The Linux report is cheaper still but its budget is the +/// player's attention, and this client has honest frames of several seconds — a world entry's UI +/// load and a `/reload` both — so it waits until no frame has finished for ten. +const STALL_MS: u64 = if cfg!(target_os = "macos") { + 600 +} else { + 10_000 +}; /// In-frame sampling stays disarmed this long after launch, since startup legitimately stalls /// past [`STALL_MS`]; teardown is unaffected. const STARTUP_GRACE_MS: u64 = 15_000; @@ -44,8 +65,10 @@ const STARTUP_GRACE_MS: u64 = 15_000; const EXIT_STALL_MS: u64 = 2_500; /// Teardown backstop: still alive this long after `AppExit`, the process `_exit`s. const EXIT_KILL_MS: u64 = 8_000; -/// Rate limit: at most this many samples per run, at least [`SAMPLE_GAP_MS`] apart. -const SAMPLE_CAP: u32 = 5; +/// Rate limit: at most this many samples per run, at least [`SAMPLE_GAP_MS`] apart. A Linux +/// report suspends nothing, and a freeze is read from the *deltas* between consecutive reports, so +/// it takes more of them. +const SAMPLE_CAP: u32 = if cfg!(target_os = "macos") { 5 } else { 12 }; const SAMPLE_GAP_MS: u64 = 20_000; fn since_start_ms() -> u64 { @@ -148,8 +171,13 @@ fn watchdog(dir: Option) { && (taken == 0 || now.saturating_sub(last_sample_ms) > SAMPLE_GAP_MS) { // Not while an audio device is open: `sample` suspends the audio IO thread and the - // sound server times the client out, a crackle. Teardown samples regardless. - if !exiting && crate::sound::output::device_open() && !force { + // sound server times the client out, a crackle. Teardown samples regardless, and + // reading `/proc` suspends nothing, so only macOS declines. + if cfg!(target_os = "macos") + && !exiting + && crate::sound::output::device_open() + && !force + { if !declined { eprintln!( "stall-sample: main thread stale {age} ms — NOT sampled: an audio \ @@ -177,18 +205,118 @@ fn watchdog(dir: Option) { if exiting { " (teardown)" } else { "" }, file.display() ); - // 1 s in-frame so the stall dominates the capture; 2 s at teardown, where the wedge - // holds throughout. - let _ = std::process::Command::new("/usr/bin/sample") - .arg(&pid) - .arg(if exiting { "2" } else { "1" }) - .arg("-file") - .arg(&file) - .status(); + sample_into(&pid, exiting, &file, age); } } } +/// Ask the OS what the process is doing and write it to `file`. +#[cfg(target_os = "macos")] +fn sample_into(pid: &str, exiting: bool, file: &std::path::Path, _age: u64) { + // 1 s in-frame so the stall dominates the capture; 2 s at teardown, where the wedge holds + // throughout. + let _ = std::process::Command::new("/usr/bin/sample") + .arg(pid) + .arg(if exiting { "2" } else { "1" }) + .arg("-file") + .arg(file) + .status(); +} + +/// Every thread's state, wchan and CPU time, from `/proc`. Written to `file` in full, and the main +/// thread's line also goes to the log, because the log is what gets read after a freeze and a file +/// nobody knows about is not evidence. +#[cfg(target_os = "linux")] +fn sample_into(pid: &str, exiting: bool, file: &std::path::Path, age: u64) { + let threads = read_threads(); + let main = threads.first().cloned().unwrap_or_default(); + let body = format!( + "benilla stall report\npid: {pid}\nstale: {age} ms with no finished frame{}\n\n Each line is one thread: state, the kernel function it sleeps in, and its CPU time in\n clock ticks. R or climbing ticks is a loop; S or D with flat ticks is a wait, and the\n wchan names what for. A backtrace needs ptrace, which yama refuses here — run\n `sudo eu-stack -p {pid}` by hand if the client is still wedged.\n\n{}\n", + if exiting { " (during teardown)" } else { "" }, + threads + .iter() + .map(ThreadState::line) + .collect::>() + .join("\n"), + ); + let _ = std::fs::write(file, body); + warn!( + "stall: no frame finished in {age} ms — main thread {}; {} thread(s) in all, full report \ + in {}", + main.line(), + threads.len(), + file.display(), + ); +} + +/// One thread as `/proc` describes it. +#[cfg(target_os = "linux")] +#[derive(Clone, Default)] +struct ThreadState { + tid: u32, + name: String, + state: String, + wchan: String, + ticks: u64, +} + +#[cfg(target_os = "linux")] +impl ThreadState { + fn line(&self) -> String { + format!( + "tid {:<8} state {:<2} wchan {:<24} cpu {} ticks {}", + self.tid, self.state, self.wchan, self.ticks, self.name + ) + } + + fn read(tid: u32) -> Option { + let stat = std::fs::read_to_string(format!("/proc/self/task/{tid}/stat")).ok()?; + // The comm field is parenthesised and may hold spaces and parentheses of its own, so the + // fields start after its LAST `)`, exactly as `proc(5)` says to parse it. + let (head, rest) = stat.rsplit_once(')')?; + let fields: Vec<&str> = rest.split_whitespace().collect(); + let ticks = |i: usize| -> u64 { fields.get(i).and_then(|v| v.parse().ok()).unwrap_or(0) }; + Some(Self { + tid, + name: head + .split_once('(') + .map_or_else(String::new, |(_, c)| c.to_string()), + state: (*fields.first().unwrap_or(&"?")).to_string(), + // Often `0` for a thread that is not sleeping, and not always readable. + wchan: std::fs::read_to_string(format!("/proc/self/task/{tid}/wchan")) + .map(|s| s.trim().to_string()) + .ok() + .filter(|s| !s.is_empty() && s != "0") + .unwrap_or_else(|| String::from("-")), + // `utime` and `stime`, the 12th and 13th fields after the state. + ticks: ticks(11) + ticks(12), + }) + } +} + +/// Every thread of this process, the main thread first: its tid is the pid, since winit's event +/// loop is the process's first thread. +#[cfg(target_os = "linux")] +fn read_threads() -> Vec { + let main = std::process::id(); + let mut out: Vec = ThreadState::read(main).into_iter().collect(); + let Ok(dir) = std::fs::read_dir("/proc/self/task") else { + return out; + }; + let mut rest: Vec = dir + .filter_map(|e| e.ok()?.file_name().to_str()?.parse::().ok()) + .filter(|&tid| tid != main) + .filter_map(ThreadState::read) + .collect(); + rest.sort_by_key(|t| std::cmp::Reverse(t.ticks)); + out.append(&mut rest); + out +} + +/// Neither `sample` nor `/proc`: the watchdog still runs, and its teardown backstop with it. +#[cfg(not(any(target_os = "macos", target_os = "linux")))] +fn sample_into(_pid: &str, _exiting: bool, _file: &std::path::Path, _age: u64) {} + /// `WOW_STALL_INJECT=:`: one deliberate main-thread sleep, mid-run. #[derive(Resource)] struct StallInject {