feat(capture/windows): a degraded stretch logs one summary line at 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 — 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 <noreply@anthropic.com>
This commit is contained in:
@@ -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<super::stall::Recovery>) {
|
||||
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
|
||||
|
||||
@@ -16,6 +16,31 @@ pub(super) struct Stall {
|
||||
pub(super) metronomic: Option<Duration>,
|
||||
}
|
||||
|
||||
/// 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<Episode>,
|
||||
/// A closed episode's summary, parked for the caller ([`Self::take_recovery`]).
|
||||
pending_recovery: Option<Recovery>,
|
||||
}
|
||||
|
||||
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<Recovery> {
|
||||
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;
|
||||
}
|
||||
|
||||
Reference in New Issue
Block a user