From 8140d3f8b3c5dc1be880edf52c154ae9163bb87c Mon Sep 17 00:00:00 2001 From: enricobuehler Date: Thu, 30 Jul 2026 22:22:05 +0200 Subject: [PATCH] feat(capture/windows): a degraded stretch logs one summary line at recovery MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Per-hole stall lines gate on prior ACTIVE flow, so inside a sustained ~2 fps phase only the first hole is reported and the log goes quiet exactly while the user suffers — the field shape (deep 15 s stretches at 2 fps) was invisible without a stats recording. StallWatch now tracks the stretch: opened by a reported stall, fed by every stall-sized hole while the activity gate stays broken, closed when sustained flow returns (or a ring recreate cuts it — its holes predate the recreate and still count). Closure surfaces one INFO line: span, hole count, summed hole time, worst hole. One-hole stretches dissolve silently (the stall's own line covers them), and a ≥10 s gap closes the stretch first so a quit-to-desktop pause never folds into the tally. Co-Authored-By: Claude Fable 5 --- crates/pf-capture/src/windows/idd_push.rs | 92 ++++++++++++++++++ .../pf-capture/src/windows/idd_push/stall.rs | 94 ++++++++++++++++++- 2 files changed, 185 insertions(+), 1 deletion(-) diff --git a/crates/pf-capture/src/windows/idd_push.rs b/crates/pf-capture/src/windows/idd_push.rs index 3f60bf32..4f442579 100644 --- a/crates/pf-capture/src/windows/idd_push.rs +++ b/crates/pf-capture/src/windows/idd_push.rs @@ -1669,6 +1669,20 @@ impl IddPushCapturer { self.stall_watch.report(&stall, now, &evidence); } if !regen { + // A degraded stretch just ended (or was cut by a ring recreate): the one line that + // makes a sustained ~2 fps phase log-visible — per-hole stall lines gate on prior + // ACTIVE flow and go quiet exactly while the stretch runs. + if let Some(r) = self.stall_watch.take_recovery() { + tracing::info!( + degraded_ms = r.degraded.as_millis() as u64, + holes = r.holes, + hole_time_ms = r.hole_time.as_millis() as u64, + worst_hole_ms = r.worst.as_millis() as u64, + "IDD-push capture recovered from a degraded stretch — fresh frames arrived \ + only between stall-sized holes for its whole span; the per-stall lines \ + above cover at most its first hole" + ); + } // A fresh driver frame: feed the driver-death watch and roll the stall-evidence // trackers (a regen re-encodes OLD content — it is not evidence of driver progress). self.last_fresh = now; @@ -2137,6 +2151,84 @@ mod tests { assert!(out[10].is_some(), "30 fps flow must pass the activity gate"); } + /// Feed a [`StallWatch`] frames at the given offsets and return the first degraded-stretch + /// summary it parks (checking after every frame, the way the capture loop does). + fn watch_recovery(offsets_ms: &[u64]) -> (StallWatch, Option) { + let base = Instant::now(); + let mut w = StallWatch::new(); + let mut recovery = None; + for ms in offsets_ms { + w.note_fresh(base + Duration::from_millis(*ms)); + if let Some(r) = w.take_recovery() { + recovery.get_or_insert(r); + } + } + (w, recovery) + } + + #[test] + fn a_degraded_stretch_summarizes_on_recovery() { + // Active flow, then a ~2 fps phase (10 holes of 500 ms — the sustained-degradation + // shape whose holes the activity gate keeps out of the per-stall log), then recovery + // flow. One summary, carrying the whole stretch. + let mut t = Vec::new(); + flow(&mut t, 0, 20); // last frame at 304 ms + t.extend((1..=10).map(|i| 304 + i * 500)); // 804..5304: ten 500 ms holes + t.extend((1..=12).map(|i| 5304 + i * 16)); // sustained flow is back + let (_, r) = watch_recovery(&t); + let r = r.expect("a multi-hole degraded stretch summarizes at recovery"); + assert_eq!(r.holes, 10); + assert_eq!(r.hole_time.as_millis(), 5000); + assert_eq!(r.worst.as_millis(), 500); + assert_eq!(r.degraded.as_millis(), 5000); + } + + #[test] + fn a_single_stall_never_summarizes() { + // One hole inside otherwise-healthy flow: its own stall line covers it — a + // one-hole "stretch" dissolving silently is what keeps the summary meaningful. + let mut t = Vec::new(); + flow(&mut t, 0, 20); + t.push(604); // the lone 300 ms hole + t.extend((1..=12).map(|i| 604 + i * 16)); + let (_, r) = watch_recovery(&t); + assert!( + r.is_none(), + "single stall must not produce a stretch summary" + ); + } + + #[test] + fn a_recreate_cut_stretch_still_summarizes() { + // A ring recreate resets the flow history mid-stretch; the holes accumulated BEFORE it + // are real evidence and must still surface. + let mut t = Vec::new(); + flow(&mut t, 0, 20); + t.extend((1..=3).map(|i| 304 + i * 500)); + let (mut w, r) = watch_recovery(&t); + assert!(r.is_none(), "stretch still open — no summary yet"); + w.reset(); + let r = w + .take_recovery() + .expect("reset closes and summarizes the open stretch"); + assert_eq!(r.holes, 3); + assert_eq!(r.hole_time.as_millis(), 1500); + } + + #[test] + fn a_content_stop_closes_the_stretch_without_folding_the_pause_in() { + // Two degraded holes, then the content plainly STOPS (a 20 s pause — quit to desktop). + // The summary covers the stretch only; the legitimate pause never joins the tally. + let mut t = Vec::new(); + flow(&mut t, 0, 20); + t.extend([804, 1304, 21_304]); + let (_, r) = watch_recovery(&t); + let r = r.expect("the content stop closes the stretch"); + assert_eq!(r.holes, 2); + assert_eq!(r.hole_time.as_millis(), 1000); + assert_eq!(r.degraded.as_millis(), 1000); + } + #[test] fn metronomic_stalls_self_diagnose() { // The field signature: ~300 ms DWM holes every 4 s inside 60 fps flow. Stalls land at the diff --git a/crates/pf-capture/src/windows/idd_push/stall.rs b/crates/pf-capture/src/windows/idd_push/stall.rs index 2845f143..3d69bda4 100644 --- a/crates/pf-capture/src/windows/idd_push/stall.rs +++ b/crates/pf-capture/src/windows/idd_push/stall.rs @@ -16,6 +16,31 @@ pub(super) struct Stall { pub(super) metronomic: Option, } +/// One degraded stretch, summarized at recovery ([`StallWatch::take_recovery`]). Per-hole stall +/// lines gate on prior ACTIVE flow, so inside a sustained ~2 fps phase only the first hole is +/// reported and the log goes quiet exactly while the user suffers — this summary is the stretch's +/// one visible line. +#[derive(Debug, PartialEq, Eq)] +pub(super) struct Recovery { + /// First hole's start → last hole's end. + pub(super) degraded: Duration, + /// Stall-sized (≥ [`StallWatch::STALL_MIN`]) holes inside the stretch. + pub(super) holes: u32, + /// Their summed length. + pub(super) hole_time: Duration, + /// The longest single hole. + pub(super) worst: Duration, +} + +/// [`StallWatch`]'s in-flight degraded stretch (see [`Recovery`]). +struct Episode { + started: Instant, + last_hole_end: Instant, + holes: u32, + hole_time: Duration, + worst: Duration, +} + /// Driver-telemetry evidence for one stall window (the v2 header tail — see /// `pf_driver_proto::frame::SharedHeader`), sampled by the capturer between the last pre-gap /// frame and the frame that ended the stall. @@ -281,6 +306,11 @@ pub(super) struct StallWatch { /// compositor-blocked, content-silence, frame-generation, unattributed) — the verdict /// matrix's session summary. classes: [u32; 7], + /// The degraded stretch currently being accumulated, opened by a reported stall and fed by + /// every stall-sized hole until sustained flow returns. + episode: Option, + /// A closed episode's summary, parked for the caller ([`Self::take_recovery`]). + pending_recovery: Option, } impl StallWatch { @@ -293,6 +323,12 @@ impl StallWatch { /// The smallest hole that counts as a stall (~9 missed frames at 60 Hz) — well below the /// reported 300–700 ms freezes, above encode/present jitter. const STALL_MIN: Duration = Duration::from_millis(150); + /// A hole this long is a content STOP, not a degraded stretch — an open episode is closed + /// (and summarized) before it, so a quit-to-idle pause never folds into the tally. + const EPISODE_BREAK: Duration = Duration::from_secs(10); + /// Episodes with fewer holes than this dissolve silently — the single stall's own report + /// line already covers them. + const EPISODE_MIN_HOLES: u32 = 2; pub(super) fn new() -> Self { Self { @@ -302,13 +338,38 @@ impl StallWatch { with_os_events: 0, verdicts: [0; 4], classes: [0; 7], + episode: None, + pending_recovery: None, } } /// Forget the flow history (a ring recreate's gap is self-inflicted, not a DWM stall — without - /// the reset the first post-recreate frame would read as one). + /// the reset the first post-recreate frame would read as one). An open episode is closed and + /// summarized: its holes predate the recreate and are real evidence. pub(super) fn reset(&mut self) { self.recent.clear(); + self.close_episode(); + } + + /// Close an open episode into [`Self::pending_recovery`] (kept only past the noise bar). + fn close_episode(&mut self) { + if let Some(ep) = self.episode.take() { + if ep.holes >= Self::EPISODE_MIN_HOLES { + self.pending_recovery = Some(Recovery { + degraded: ep.last_hole_end.duration_since(ep.started), + holes: ep.holes, + hole_time: ep.hole_time, + worst: ep.worst, + }); + } + } + } + + /// A closed degraded stretch's summary, if one is waiting — the caller logs it. Check after + /// every [`Self::note_fresh`]/[`Self::reset`]: closure rides frames that are NOT stalls (the + /// first sustained-flow frame after recovery). + pub(super) fn take_recovery(&mut self) -> Option { + self.pending_recovery.take() } /// Record a fresh driver frame at `now`; `Some` exactly when it ended a stall. @@ -325,6 +386,37 @@ impl StallWatch { self.recent.pop_front(); } let gap = gap?; + if gap >= Self::EPISODE_BREAK { + // The content plainly STOPPED (quit to desktop, long idle) — summarize what came + // before rather than folding a legitimate pause into the degraded tally. + self.close_episode(); + } + if gap >= Self::STALL_MIN { + match &mut self.episode { + // Inside a degraded stretch every stall-sized hole accumulates — the activity + // gate below keeps per-hole reports quiet here (the pre-gap window spans the + // slow frames), which is exactly why the episode summary exists. + Some(ep) => { + ep.holes += 1; + ep.hole_time += gap; + ep.worst = ep.worst.max(gap); + ep.last_hole_end = now; + } + None if was_active => { + self.episode = Some(Episode { + started: now - gap, + last_hole_end: now, + holes: 1, + hole_time: gap, + worst: gap, + }); + } + None => {} + } + } else if was_active { + // Sustained flow is back ([`Self::RECENT`] tight frames) — the stretch is over. + self.close_episode(); + } if !was_active || gap < Self::STALL_MIN { return None; }