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

sys-timing: a stall is a thread that stopped, not a span that is open

Browse Source 
The watchdog keyed on "a span has been open past the threshold". Spans nest, and `on_exit`
republishes the enclosing one deliberately — so between any two inner spans the slot shows a span
that has been open since the first frame, and the watchdog said so.

In a 105-second play session that was 13,658 of the log's 15,335 lines: `STALL: span
#2473901162497 has been running 209147 ms`, alternating with `STALL ended`, every ~75 ms, each one
re-reading /proc for 39 threads — inside the session it was there to measure. The instrument whose
whole job is to be trustworthy when nothing else is was the loudest liar in the log, and it could
not even name what it was accusing, because an enclosing span has no entry in `names`.

So `Slot::beat`, bumped on every enter and every exit. A stall is now a thread that has not entered
or exited anything for the threshold — which is what "wedged" means and what the module header
already claimed to be reporting. The end line also gets the real total rather than the duration at
first sighting, which is why both lines used to print the same number.

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 18:16:52 -06:00
co-authored by Claude Opus 5
parent 112647b919
commit 21c0befdca
1 changed files with 106 additions and 39 deletions
Download Patch File Download Diff File Expand all files Collapse all files
crates/benilla-world/src/sys_timing.rs
+106 -39
View File
@@ -41,6 +41,11 @@ struct Slot {
span: AtomicU64,
/// Nanoseconds since [`epoch`] at which it was entered.
since_ns: AtomicU64,
/// Bumped on every enter and every exit: proof of progress. An open span is not a stall —
/// every enclosing span is open by construction, and `on_exit` republishes the parent, so the
/// 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,
}
/// The process clock every [`Slot::since_ns`] is measured against.
@@ -264,6 +269,7 @@ impl<S: Subscriber> Layer<S> for SystemTiming {
Ordering::Relaxed,
);
slot.span.store(raw, Ordering::Relaxed);
slot.beat.fetch_add(1, Ordering::Relaxed);
}
});
}
@@ -314,6 +320,7 @@ impl<S: Subscriber> Layer<S> for SystemTiming {
}
None => slot.span.store(0, Ordering::Relaxed),
}
slot.beat.fetch_add(1, Ordering::Relaxed);
}
let due = local
.merged_at
@@ -400,9 +407,15 @@ fn thread_states() -> String {
/// so profiles read from the moments *between* freezes, and those look healthy — which is exactly
/// how a session that was plainly stuttering produced a clean profile over and over.
///
/// This thread does not wait for anything. It wakes on its own clock, reads the open spans, and
/// prints the ones that have outstayed the threshold, then prints again when one finally returns
/// with the full duration it took. A wedged client therefore narrates itself.
/// This thread does not wait for anything. It wakes on its own clock, reads what each thread is
/// inside, and prints the ones that have stopped making progress, then prints again when one
/// finally moves with the full duration it was in there. A wedged client therefore narrates itself.
///
/// "Stopped making progress" is [`Slot::beat`], not "has an open span". An open span is the normal
/// case: spans nest, `on_exit` republishes the enclosing one, and the outermost is open from the
/// first frame to the last. Keying on openness alone reported a 200-second-old parent as a stall
/// every time an inner span returned — 13k lines in one session's log, about a span that was never
/// in trouble, from the instrument whose whole job is to be trustworthy when nothing else is.
fn spawn_watchdog(names: &Arc<Mutex<HashMap<u64, String>>>, slots: &Arc<Vec<Slot>>) {
let threshold_ms: f64 = std::env::var("WOW_STALL_MS")
.ok()
@@ -413,8 +426,12 @@ 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 || {
// Span id → what was reported, so a stall is announced once and its end once.
let mut reported: HashMap<u64, (String, f64)> = HashMap::new();
// 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();
// 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();
let mut was = process_memory();
loop {
@@ -439,47 +456,47 @@ 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 open: Vec<(u64, f64)> = slots
.iter()
.filter_map(|slot| {
let span = slot.span.load(Ordering::Relaxed);
if span == 0 {
return None;
}
let since = slot.since_ns.load(Ordering::Relaxed);
// Written timestamp-then-id, read id-then-timestamp-then-id: if the id
// moved under us the timestamp may belong to the other span, so drop the
// sample rather than report a duration nobody spent.
if slot.span.load(Ordering::Relaxed) != span {
return None;
}
#[allow(clippy::cast_precision_loss)]
Some((span, now_ns.saturating_sub(since) as f64 / 1.0e6))
})
.collect();
let mut fresh: Vec<(String, f64)> = Vec::new();
for (id, ms) in &open {
if *ms < threshold_ms || reported.contains_key(id) {
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 {
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));
}
continue;
}
if beats[i].1.elapsed().as_secs_f64() * 1000.0 < threshold_ms
|| reported.contains_key(&i)
{
continue;
}
let span = slot.span.load(Ordering::Relaxed);
if span == 0 {
// An idle worker with nothing entered. It is not inside anything, so
// there is nothing to name and nothing is wrong.
continue;
}
let since = slot.since_ns.load(Ordering::Relaxed);
// Written timestamp-then-id, read id-then-timestamp-then-id: if the id moved
// under us the timestamp may belong to the other span, so drop the sample
// rather than report a duration nobody spent.
if slot.span.load(Ordering::Relaxed) != span {
continue;
}
let name = names
.lock()
.ok()
.and_then(|n| n.get(id).cloned())
.unwrap_or_else(|| format!("span #{id}"));
reported.insert(*id, (name.clone(), *ms));
fresh.push((name, *ms));
.and_then(|n| n.get(&span).cloned())
.unwrap_or_else(|| format!("span #{span}"));
reported.insert(i, (name.clone(), since));
#[allow(clippy::cast_precision_loss)]
fresh.push((name, now_ns.saturating_sub(since) as f64 / 1.0e6));
}
// A span that is no longer open has returned: say how long it took in total.
let still_open: Vec<u64> = open.into_iter().map(|(id, _)| id).collect();
let done: Vec<(String, f64)> = reported
.keys()
.filter(|id| !still_open.contains(id))
.cloned()
.collect::<Vec<_>>()
.into_iter()
.filter_map(|id| reported.remove(&id))
.collect();
for (name, ms) 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.
@@ -654,4 +671,54 @@ mod tests {
"the worst single run cannot exceed the window's total"
);
}
/// What tells a working thread from a wedged one. A thread inside a long-lived outer span
/// publishes that span, and its start, for as long as it lives: `on_exit` republishes the
/// parent, so between two inner spans the slot shows one that has been open since the first
/// frame. The watchdog used to read that as a stall and said so every 75 ms for the length of
/// a session.
///
/// So the published span is asserted to hold *still* across the inner work — the false
/// positive, reproduced — while [`Slot::beat`] is asserted to move, which is the only thing
/// separating the two cases.
#[test]
fn an_enclosing_span_holds_still_while_the_beat_moves() {
let timing = armed();
let subscriber =
bevy::log::tracing_subscriber::registry().with(Shared(Arc::clone(&timing)));
let (before, after, span_held, since_held) =
tracing::subscriber::with_default(subscriber, || {
let outer = tracing::info_span!(parent: None, "system", name = "the::whole::frame");
let _held = outer.enter();
// Whatever slot this thread took; `claim_slot` hands them out in order, but a
// thread that entered a span under some other instance keeps the slot it had.
let slot = |t: &SystemTiming| {
let i = (0..SLOTS)
.max_by_key(|&i| t.slots[i].beat.load(Ordering::Relaxed))
.expect("SLOTS is not zero");
(
t.slots[i].beat.load(Ordering::Relaxed),
t.slots[i].span.load(Ordering::Relaxed),
t.slots[i].since_ns.load(Ordering::Relaxed),
)
};
let (before, span_was, since_was) = slot(&timing);
for _ in 0..5 {
let inner = tracing::info_span!(parent: None, "system", name = "a::system");
drop(inner.enter());
}
let (after, span_now, since_now) = slot(&timing);
(before, after, span_was == span_now, since_was == since_now)
});
assert!(
span_held && since_held,
"the enclosing span and its start should be republished unchanged — without that \
there is no false positive left to guard against"
);
assert!(
after > before,
"five enter/exit pairs moved the beat {before} -> {after}: a thread that is working \
must be distinguishable from one stuck in the same span"
);
}
}