grom/benilla-octo
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

stall: the Linux client watches its own main thread

Browse Source 
It froze on him this morning while learning recipes at a trainer, and he had to
kill it. Both logs end on an ordinary line; the fps journal's last sample is a
second earlier with normal numbers; `journalctl -k` holds nothing but firewall
noise between 07:30 and 08:20, so no GPU reset and no OOM kill; and the two crash
reports in Diagnostics are from the 11th and the 15th by their own embedded
server-time lines. A frozen frame writes no line of its own, and a force-kill
writes no crash report, so the session left no evidence of where it stopped.

There was a watchdog for exactly this, with a heartbeat, a threshold set, an
`_exit` backstop and two injectors to test it — registered
`#[cfg(all(feature = "dev", target_os = "macos"))]`, because its diagnosis is
`/usr/bin/sample`. On Linux nothing was watching at all.

So the sampler grows a Linux arm instead of a second watchdog beside it. `/proc`
already knows: each thread's scheduler state, the kernel function it sleeps in,
and its CPU time in clock ticks. That is less than a backtrace, but it settles
the first question — climbing ticks is a loop, `S` or `D` with flat ticks is a
wait and the wchan says what for — and it is free, where a real backtrace of our
own process needs ptrace, which yama's `ptrace_scope=1` refuses between siblings
and which this client has no business asking for on a player's machine. The
report says so, and names the pid for `sudo eu-stack -p <pid>` by hand.

Verified with the injector that was already there, `WOW_STALL_INJECT=20:14000`:

  stall: no frame finished in 10072 ms — main thread tid 2793492 state S
  wchan hrtimer_nanosleep cpu 667 ticks benilla; 39 thread(s) in all

`S` on `hrtimer_nanosleep` is the injected sleep, read correctly as a wait. The
full report lists all 39 threads by CPU. The in-frame verdict goes to the log as
well as the file, because the log is what gets read after a freeze and a file
nobody knows about is not evidence.

Per-platform where the platforms differ: Linux waits ten seconds rather than
600 ms, since this client has honest frames of several (a world entry's UI load,
a `/reload`), and takes more reports, since reading `/proc` suspends nothing —
where a `sample` suspends the audio thread, which is itself a crackle, and still
declines for that reason.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01SgstFWtn1RxEJ5kVrpgYwn
This commit is contained in:
grom
2026-10-19 08:53:12 -06:00
co-authored by Claude Opus 5
parent b7ddc18782
commit af4bb2dd22
2 changed files with 154 additions and 23 deletions
Download Patch File Download Diff File Expand all files Collapse all files
crates/benilla-app/src/perf/mod.rs
+7 -4
View File
@@ -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=<at>`: armed here, on every platform, not in the macOS-only sampler.
// `WOW_CRASH_INJECT=<at>`: 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);
crates/benilla-app/src/perf/stall.rs
+147 -19
View File
@@ -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 <pid>` 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<std::path::PathBuf>) {
&& (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<std::path::PathBuf>) {
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::<Vec<_>>()
.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<Self> {
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<ThreadState> {
let main = std::process::id();
let mut out: Vec<ThreadState> = ThreadState::read(main).into_iter().collect();
let Ok(dir) = std::fs::read_dir("/proc/self/task") else {
return out;
};
let mut rest: Vec<ThreadState> = dir
.filter_map(|e| e.ok()?.file_name().to_str()?.parse::<u32>().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=<at_secs>:<ms>`: one deliberate main-thread sleep, mid-run.
#[derive(Resource)]
struct StallInject {