From 4393bde4ec2ed20cce35410e2a31de10032c209b Mon Sep 17 00:00:00 2001
From: grom <grom@gromgosh.gg>
Date: Tue, 20 Oct 2026 19:17:44 -0600
Subject: [PATCH] sys-timing: a stall report names the thread and how long it
 was stuck
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8bit

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
---
 crates/benilla-world/src/sys_timing.rs | 51 +++++++++++++++++++-------
 1 file changed, 37 insertions(+), 14 deletions(-)

diff --git a/crates/benilla-world/src/sys_timing.rs b/crates/benilla-world/src/sys_timing.rs
index 7fe95f78..022afa07 100644
--- a/crates/benilla-world/src/sys_timing.rs
+++ b/crates/benilla-world/src/sys_timing.rs
@@ -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");
                 }
             }
         });