diff --git a/crates/benilla-world/src/sys_timing.rs b/crates/benilla-world/src/sys_timing.rs index 144df164..7fe95f78 100644 --- a/crates/benilla-world/src/sys_timing.rs +++ b/crates/benilla-world/src/sys_timing.rs @@ -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 Layer for SystemTiming { Ordering::Relaxed, ); slot.span.store(raw, Ordering::Relaxed); + slot.beat.fetch_add(1, Ordering::Relaxed); } }); } @@ -314,6 +320,7 @@ impl Layer 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>>, slots: &Arc>) { let threshold_ms: f64 = std::env::var("WOW_STALL_MS") .ok() @@ -413,8 +426,12 @@ fn spawn_watchdog(names: &Arc>>, slots: &Arc = 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 = 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>>, slots: &Arc = 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 = open.into_iter().map(|(id, _)| id).collect(); - let done: Vec<(String, f64)> = reported - .keys() - .filter(|id| !still_open.contains(id)) - .cloned() - .collect::>() - .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" + ); + } }