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

sys-timing: a stall report names the thread and how long it was stuck

Browse Source 
Two durations were being conflated. How long the thread has not moved is the defect; how long the
span it is inside has been open is only where it is stuck, and for an enclosing span that is the
whole session — which is why the live log said "has been running 360380 ms" and then "was in there
at least 360406 ms" about a 150 ms hiccup.

So both, labelled, and the thread's name beside them: the span it is stuck in may be unnamed, since
an enclosing `info_span!` carries no `name` field for `on_new_span` to record, and then the thread
is the only thing the report can name. Before this, such a stall printed `span #2473901162497` and
nothing else.

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-20 19:17:44 -06:00
co-authored by Claude Opus 5
parent e4851df7df
commit 4393bde4ec
1 changed files with 37 additions and 14 deletions
Download Patch File Download Diff File Expand all files Collapse all files
crates/benilla-world/src/sys_timing.rs
+37 -14
View File
@@ -46,6 +46,11 @@ struct Slot {
/// slot shows a span that has been open since the app started whenever an inner one returns.
/// A thread that is actually wedged stops moving this.
beat: AtomicU64,
/// Which thread took this slot, written once when it claims one. The span it is stuck inside
/// may be unnamed — an enclosing `info_span!` carries no `name` field for `on_new_span` to
/// record — and then the thread is the only thing a report can name. Behind a lock because it
/// is read when printing and never while detecting.
thread: Mutex<Option<String>>,
}
/// The process clock every [`Slot::since_ns`] is measured against.
@@ -136,6 +141,10 @@ impl SystemTiming {
}
let taken = self.next_slot.fetch_add(1, Ordering::Relaxed);
local.slot = if taken < SLOTS { taken } else { usize::MAX };
if let Some(slot) = self.slots.get(local.slot) {
*slot.thread.lock().unwrap_or_else(|e| e.into_inner()) =
std::thread::current().name().map(str::to_string);
}
}
/// Fold this thread's tally into the shared one, dropping spans that are not systems, and
@@ -426,10 +435,10 @@ fn spawn_watchdog(names: &Arc<Mutex<HashMap<u64, String>>>, slots: &Arc<Vec<Slot
let spawned = std::thread::Builder::new()
.name("benilla stall watch".to_string())
.spawn(move || {
// Slot → `(name, since_ns)` of what was reported, so a stall is announced once and
// its end once. Keyed by slot, not span: what is stalled is the thread, and the span
// it is stuck in is only how we name it.
let mut reported: HashMap<usize, (String, u64)> = HashMap::new();
// Slot → who was reported, so a stall is announced once and its end once. Keyed by
// slot, not span: what is stalled is the thread, and the span it is stuck in is only
// how we name it.
let mut reported: HashMap<usize, String> = HashMap::new();
// Per slot, the beat last seen and when it last moved. See [`Slot::beat`].
let mut beats: Vec<(u64, Instant)> = vec![(0, Instant::now()); slots.len()];
let mut mem_at = Instant::now();
@@ -456,17 +465,17 @@ fn spawn_watchdog(names: &Arc<Mutex<HashMap<u64, String>>>, slots: &Arc<Vec<Slot
// Plain atomic loads, no lock at all: a thread wedged while holding one must
// not be able to hide from the instrument meant to catch it.
let now_ns = epoch().elapsed().as_nanos() as u64;
let mut fresh: Vec<(String, f64)> = Vec::new();
let mut fresh: Vec<String> = Vec::new();
let mut done: Vec<(String, f64)> = Vec::new();
for (i, slot) in slots.iter().enumerate() {
let beat = slot.beat.load(Ordering::Relaxed);
// The thread entered or exited something since the last poll, so whatever it
// is inside now, it is not stuck in it.
if beat != beats[i].0 {
let stuck_ms = beats[i].1.elapsed().as_secs_f64() * 1000.0;
beats[i] = (beat, Instant::now());
if let Some((name, since)) = reported.remove(&i) {
#[allow(clippy::cast_precision_loss)]
done.push((name, now_ns.saturating_sub(since) as f64 / 1.0e6));
if let Some(who) = reported.remove(&i) {
done.push((who, stuck_ms));
}
continue;
}
@@ -493,24 +502,38 @@ fn spawn_watchdog(names: &Arc<Mutex<HashMap<u64, String>>>, slots: &Arc<Vec<Slot
.ok()
.and_then(|n| n.get(&span).cloned())
.unwrap_or_else(|| format!("span #{span}"));
reported.insert(i, (name.clone(), since));
let thread = slot
.thread
.lock()
.ok()
.and_then(|t| t.clone())
.unwrap_or_else(|| format!("slot {i}"));
// Two durations, and they answer different questions. How long the thread has
// been stuck is the defect; how long the span has been open is only where it
// is stuck, and for an enclosing span that is the whole session. Printing the
// second as though it were the first is what the old report did.
#[allow(clippy::cast_precision_loss)]
fresh.push((name, now_ns.saturating_sub(since) as f64 / 1.0e6));
let open_ms = now_ns.saturating_sub(since) as f64 / 1.0e6;
let stuck_ms = beats[i].1.elapsed().as_secs_f64() * 1000.0;
reported.insert(i, format!("{thread} in {name}"));
fresh.push(format!(
"thread {thread:?} has made no progress for {stuck_ms:.0} ms — inside {name}, open {open_ms:.0} ms"
));
}
for (name, ms) in fresh {
for sentence in fresh {
// RSS beside the stall: a process-wide stop and a climbing resident set in the
// same breath is the memory answer; a stall with flat memory is not.
let mem = process_memory()
.map(|(rss, _, _)| format!(" · rss {rss:.0} MiB"))
.unwrap_or_default();
eprintln!("[sys-timing] STALL: {name} has been running {ms:.0} ms and has not returned{mem}");
eprintln!("[sys-timing] STALL: {sentence}{mem}");
let states = thread_states();
if !states.is_empty() {
eprintln!("[sys-timing] STALL threads: {states}");
}
}
for (name, ms) in done {
eprintln!("[sys-timing] STALL ended: {name} was in there at least {ms:.0} ms");
for (who, ms) in done {
eprintln!("[sys-timing] STALL ended: {who} moved again after {ms:.0} ms stuck");
}
}
});