diff --git a/crates/punktfunk-host/src/capture/windows/idd_push.rs b/crates/punktfunk-host/src/capture/windows/idd_push.rs index dd7ea675..633c55bf 100644 --- a/crates/punktfunk-host/src/capture/windows/idd_push.rs +++ b/crates/punktfunk-host/src/capture/windows/idd_push.rs @@ -565,6 +565,81 @@ impl Drop for DescriptorPoller { } } +/// A detected capture stall: a multi-hundred-ms hole in DWM's frame delivery that opened while the +/// desktop was actively composing right beforehand (see [`StallWatch`]). +struct Stall { + /// How long the hole lasted (last fresh frame → the frame that ended it). + gap: Duration, + /// `Some(mean period)` when this stall completes a metronomic cycle (see + /// [`crate::metronome::Metronome`]). + metronomic: Option, +} + +/// Capture-stall watch — the "sole virtual display" stutter diagnostic (field reports: Exclusive +/// topology = periodic double-jolt, Extend = smooth, i.e. the disturbance lives in the display/present +/// path BELOW capture and only while no physical output is active). +/// +/// On a damage-driven capture an idle desktop legitimately goes quiet (no damage → no frames), so a +/// gap only counts as a stall when the [`Self::RECENT`] frames before it all arrived within +/// [`Self::ACTIVE_SPAN`] — sustained ≥ ~20 fps flow (a game or video), not a blinking caret or a +/// mouse twitch. Each stall feeds a [`crate::metronome::Metronome`], so periodic stalls self-diagnose +/// in the log WITHOUT needing any client keyframe request — discriminating "DWM stopped composing" +/// from encode/network causes that the recovery-cadence detector covers. Pure logic — unit-tested +/// below; the caller does the logging. +struct StallWatch { + /// The last [`Self::RECENT`] fresh-frame instants (pre-gap history for the activity gate). + recent: std::collections::VecDeque, + cadence: crate::metronome::Metronome, +} + +impl StallWatch { + /// Frames of pre-gap history that must be tight for flow to count as active. Stalls are thus + /// naturally spaced ≥ RECENT frame times apart — no extra log rate limit needed. + const RECENT: usize = 8; + /// The RECENT pre-gap frames must all fit in this span (8 frames in 400 ms ≈ ≥ 20 fps flow — + /// loose enough for a 30 fps-capped game, tight enough to reject idle-desktop damage). + const ACTIVE_SPAN: Duration = Duration::from_millis(400); + /// 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); + + fn new() -> Self { + Self { + recent: std::collections::VecDeque::with_capacity(Self::RECENT + 1), + cadence: crate::metronome::Metronome::new(), + } + } + + /// 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). + fn reset(&mut self) { + self.recent.clear(); + } + + /// Record a fresh driver frame at `now`; `Some` exactly when it ended a stall. + fn note_fresh(&mut self, now: Instant) -> Option { + let was_active = self.recent.len() == Self::RECENT + && self + .recent + .back() + .zip(self.recent.front()) + .is_some_and(|(b, f)| b.duration_since(*f) <= Self::ACTIVE_SPAN); + let gap = self.recent.back().map(|last| now.duration_since(*last)); + self.recent.push_back(now); + if self.recent.len() > Self::RECENT { + self.recent.pop_front(); + } + let gap = gap?; + if !was_active || gap < Self::STALL_MIN { + return None; + } + Some(Stall { + gap, + metronomic: self.cadence.note(now), + }) + } +} + pub struct IddPushCapturer { device: ID3D11Device, context: ID3D11DeviceContext, @@ -615,6 +690,10 @@ pub struct IddPushCapturer { last_liveness: Instant, /// Rate-limits the mid-session [`kick_dwm_compose`] nudge (recovery window only). last_kick: Instant, + /// Capture-stall watch (see [`StallWatch`]): flags multi-hundred-ms DWM composition holes + /// during active flow and warns when they turn metronomic — the sole-virtual-display + /// periodic-stutter diagnostic. + stall_watch: StallWatch, /// Host-owned ROTATING output ring NVENC encodes (one YUV texture per slot). Rotating it per frame /// is the precondition for pipelining the encode loop: while NVENC encodes frame N's texture on the /// ASIC, frame N+1's convert writes a DIFFERENT texture — the two overlap. Format = `out_format()`: @@ -995,6 +1074,7 @@ impl IddPushCapturer { last_fresh: Instant::now(), last_liveness: Instant::now(), last_kick: Instant::now(), + stall_watch: StallWatch::new(), out_ring: Vec::new(), out_idx: 0, video_conv: None, @@ -1441,8 +1521,34 @@ impl IddPushCapturer { self.out_idx = (i + 1) % self.out_ring.len(); self.last_seq = seq; self.last_present = Some((out.clone(), pf)); - self.recovering_since = None; // a fresh frame resumed → recovered - self.last_fresh = Instant::now(); // feeds the driver-death watch + let now = Instant::now(); + if self.recovering_since.take().is_some() { + // A fresh frame resumed → recovered. The recovery gap is self-inflicted (ring + // recreate, already logged by the recreate path) — reset the stall watch so it + // doesn't read as a DWM stall. + self.stall_watch.reset(); + } else if let Some(stall) = self.stall_watch.note_fresh(now) { + // debug (not warn): a single hole also happens when content legitimately pauses; + // the reportable signal is the metronomic cycle below. Mounjay-class triage runs + // at debug level, and the web-console debug ring captures these. + tracing::debug!( + gap_ms = stall.gap.as_millis() as u64, + "IDD-push capture stall — the desktop was composing at speed, then DWM \ + delivered no frame for the gap; the present path stalled below capture" + ); + if let Some(period) = stall.metronomic { + tracing::warn!( + period_s = format!("{:.2}", period.as_secs_f64()), + "capture stalls are METRONOMIC — DWM stops composing the virtual display \ + on a stable period, i.e. a periodic display-path disturbance BELOW \ + capture (DWM present clock / GPU driver / display-poller software). \ + Correlate with 'slow display-descriptor poll'; if that never fires, the \ + disturbance is outside punktfunk — try display topology=primary or \ + extend (keep a physical output active), or a different refresh rate" + ); + } + } + self.last_fresh = now; // feeds the driver-death watch Ok(Some(CapturedFrame { width: self.width, height: self.height, @@ -1576,3 +1682,99 @@ impl Drop for IddPushCapturer { // `design/idd-push-security.md`). _keepalive drops after, REMOVEing the virtual display. } } + +#[cfg(test)] +mod tests { + use super::*; + + /// Feed a [`StallWatch`] fresh frames at the given offsets (ms from a common origin) and + /// return what each `note_fresh` produced. + fn watch_run(offsets_ms: &[u64]) -> Vec> { + let base = Instant::now(); + let mut w = StallWatch::new(); + offsets_ms + .iter() + .map(|ms| w.note_fresh(base + Duration::from_millis(*ms))) + .collect() + } + + /// 60 fps flow (16 ms cadence) for `frames` frames starting at `start_ms`, appended to `out`. + fn flow(out: &mut Vec, start_ms: u64, frames: u64) { + out.extend((0..frames).map(|i| start_ms + i * 16)); + } + + #[test] + fn stall_detected_after_active_flow() { + // 20 frames of 60 fps flow, then a 300 ms hole — the resuming frame reads as a stall. + let mut t = Vec::new(); + flow(&mut t, 0, 20); // last frame at 304 ms + t.push(604); + let out = watch_run(&t); + assert!(out[..20].iter().all(Option::is_none)); + let stall = out[20].as_ref().expect("hole after active flow is a stall"); + assert_eq!(stall.gap.as_millis(), 300); + assert!(stall.metronomic.is_none(), "one stall is not a cycle"); + } + + #[test] + fn idle_desktop_gaps_are_not_stalls() { + // Caret-blink damage: frames ~530 ms apart — the activity gate never opens, so neither + // the blink gaps nor a long idle hole count. + let t: Vec = (0..12).map(|i| i * 530).chain([20_000]).collect(); + assert!(watch_run(&t).iter().all(Option::is_none)); + } + + #[test] + fn thirty_fps_content_still_qualifies_as_active() { + // A 30 fps-capped game (33 ms cadence): 8 pre-gap frames span 231 ms ≤ ACTIVE_SPAN, so a + // 200 ms hole still reads as a stall. + let mut t: Vec = (0..10).map(|i| i * 33).collect(); // last at 297 ms + t.push(497); + let out = watch_run(&t); + assert!(out[10].is_some(), "30 fps flow must pass the activity gate"); + } + + #[test] + fn metronomic_stalls_self_diagnose() { + // The field signature: ~300 ms DWM holes every 4 s inside 60 fps flow. Stalls land at the + // cycle BOUNDARIES (5 cycles → 4 stalls); the 4th completes the metronome streak and + // reports the ~4 s period. + let mut t = Vec::new(); + for cycle in 0..5u64 { + // ~3.7 s of flow, then the hole to the next cycle start. + flow(&mut t, cycle * 4_000, 232); // last frame at cycle*4000 + 3696 + } + let out = watch_run(&t); + let stalls: Vec<&Stall> = out.iter().flatten().collect(); + assert_eq!(stalls.len(), 4, "each cycle boundary is one stall"); + assert!(stalls[..3].iter().all(|s| s.metronomic.is_none())); + let period = stalls[3] + .metronomic + .expect("the 4th evenly-spaced event completes the metronome streak"); + assert!( + (period.as_secs_f64() - 4.0).abs() < 0.3, + "period={period:?}" + ); + } + + #[test] + fn reset_swallows_the_recreate_gap() { + // Active flow, then a ring recreate (reset), then flow resumes 800 ms later — the resume + // frame must NOT read as a stall, and detection re-arms afterwards. + let base = Instant::now(); + let at = |ms: u64| base + Duration::from_millis(ms); + let mut w = StallWatch::new(); + for i in 0..20u64 { + assert!(w.note_fresh(at(i * 16)).is_none()); + } + w.reset(); + assert!(w.note_fresh(at(1_104)).is_none(), "recreate gap swallowed"); + for i in 1..20u64 { + assert!(w.note_fresh(at(1_104 + i * 16)).is_none()); + } + assert!( + w.note_fresh(at(1_104 + 19 * 16 + 300)).is_some(), + "detection re-armed after the reset" + ); + } +} diff --git a/crates/punktfunk-host/src/main.rs b/crates/punktfunk-host/src/main.rs index 098495e2..3d8e55bf 100644 --- a/crates/punktfunk-host/src/main.rs +++ b/crates/punktfunk-host/src/main.rs @@ -50,6 +50,7 @@ mod install; mod interactive; mod library; mod log_capture; +mod metronome; mod mgmt; mod mgmt_token; mod native_pairing; @@ -213,9 +214,9 @@ fn real_main() -> Result<()> { // Zero-copy FFI/GPU probe: init the EGL importer + CUDA context (no capture needed). #[cfg(target_os = "linux")] Some("zerocopy-probe") => zerocopy::probe(), - // Hidden: the isolated GPU-import worker the capture path spawns from /proc/self/exe - // (design/zerocopy-worker-isolation.md) — never run by hand; --fd names the inherited - // socketpair end. + // Hidden: the isolated GPU-import worker the capture path spawns from a pinned fd to its + // own executable image (design/zerocopy-worker-isolation.md) — never run by hand; --fd + // names the inherited socketpair end. #[cfg(target_os = "linux")] Some("zerocopy-worker") => zerocopy::worker::run_from_args(&args[1..]), // NV12 colour self-test (no display/capture needed): convert a known RGBA pattern to NV12 diff --git a/crates/punktfunk-host/src/metronome.rs b/crates/punktfunk-host/src/metronome.rs new file mode 100644 index 00000000..43a471a5 --- /dev/null +++ b/crates/punktfunk-host/src/metronome.rs @@ -0,0 +1,151 @@ +//! Detector for METRONOMIC event cycles — evenly-spaced disturbances repeating every few seconds. +//! +//! The "periodic double-jolt" symptom class field reports keep describing is a host/display-side +//! disturbance on a stable multi-second period (display-topology churn, display-poller software, +//! virtual-display present timing). Random network loss is bursty and irregular; a stable period is +//! a machine, and saying so in the host log turns a "nothing in the logs :/" report into a +//! self-diagnosis. Two feeds today: served client-recovery IDRs (`punktfunk1`) and IDD-push capture +//! stalls (`capture::windows::idd_push`). + +use std::collections::VecDeque; +use std::time::{Duration, Instant}; + +/// Pure evenly-spaced-events detector (unit-tested below). +/// +/// Events within [`Self::COALESCE`] count as ONE (a double-jolt's paired disturbances — e.g. the +/// cooldown re-issue of a lost keyframe ~0.7 s after the first — are one user-visible cycle). When +/// the gaps between the last [`Self::STREAK`] events are all within ±[`Self::TOLERANCE`] of their +/// mean, [`Self::note`] returns the mean period for the caller to warn with, then stays quiet for +/// [`Self::REWARN`] while the cycle persists. +pub(crate) struct Metronome { + events: VecDeque, + last_warn: Option, +} + +impl Metronome { + /// Events closer together than this are the same user-visible disturbance. + const COALESCE: Duration = Duration::from_millis(1500); + /// Consecutive evenly-spaced events before the cycle counts as metronomic. + const STREAK: usize = 4; + /// "Evenly spaced" = every gap within this fraction of the mean gap. + const TOLERANCE: f64 = 0.2; + /// Once warned, re-warn at most this often while the cycle persists. + const REWARN: Duration = Duration::from_secs(30); + + pub(crate) fn new() -> Self { + Self { + events: VecDeque::new(), + last_warn: None, + } + } + + /// Record a disturbance at `now`; `Some(mean period)` exactly when the metronomic-cycle + /// warning should fire. + pub(crate) fn note(&mut self, now: Instant) -> Option { + if self + .events + .back() + .is_some_and(|last| now.duration_since(*last) < Self::COALESCE) + { + return None; + } + self.events.push_back(now); + if self.events.len() > Self::STREAK { + self.events.pop_front(); + } + if self.events.len() < Self::STREAK { + return None; + } + let gaps: Vec = self + .events + .iter() + .zip(self.events.iter().skip(1)) + .map(|(a, b)| b.duration_since(*a).as_secs_f64()) + .collect(); + let mean = gaps.iter().sum::() / gaps.len() as f64; + if mean <= 0.0 + || gaps + .iter() + .any(|g| (g - mean).abs() > mean * Self::TOLERANCE) + { + return None; + } + if self + .last_warn + .is_some_and(|t| now.duration_since(t) < Self::REWARN) + { + return None; + } + self.last_warn = Some(now); + Some(Duration::from_secs_f64(mean)) + } +} + +#[cfg(test)] +mod tests { + use super::*; + + /// Feed a [`Metronome`] a schedule of event offsets (ms from a common origin) and return + /// what each `note` produced. + fn cadence_run(offsets_ms: &[u64]) -> Vec> { + let base = Instant::now(); + let mut c = Metronome::new(); + offsets_ms + .iter() + .map(|ms| c.note(base + Duration::from_millis(*ms))) + .collect() + } + + #[test] + fn cadence_detects_metronomic_events() { + // Four events ~4 s apart (±5%) → the fourth trips the detector at ~4 s. + let out = cadence_run(&[0, 4_000, 8_100, 11_950]); + assert_eq!(out[..3], [None, None, None]); + let period = out[3].expect("metronomic series must be detected"); + assert!( + (period.as_secs_f64() - 3.98).abs() < 0.2, + "period={period:?}" + ); + } + + #[test] + fn cadence_coalesces_double_jolt_pairs() { + // The field signature: a jolt pair (second event ~0.7 s after the first, e.g. the IDR + // cooldown re-issue) every ~4 s. Each pair is ONE event; detection still lands on the + // ~4 s cycle. + let out = cadence_run(&[ + 0, 700, // pair 1 + 4_000, 4_700, // pair 2 + 8_000, 8_650, // pair 3 + 12_000, // pair 4 (first event trips it) + ]); + assert!(out[..6].iter().all(Option::is_none)); + let period = out[6].expect("coalesced pairs must still read as a 4 s cycle"); + assert!( + (period.as_secs_f64() - 4.0).abs() < 0.2, + "period={period:?}" + ); + } + + #[test] + fn cadence_ignores_irregular_bursts() { + // Genuine Wi-Fi-style loss: irregular gaps → never flagged. + assert!(cadence_run(&[0, 2_000, 9_000, 12_500, 21_000]) + .iter() + .all(Option::is_none)); + } + + #[test] + fn cadence_rewarns_at_most_every_30s() { + // A persisting 4 s cycle: warn on the 4th event (t=12 s), then stay quiet until ≥30 s + // past the warn — the t=44 s event (index 11) is the first at or beyond t=42 s. + let offsets: Vec = (0..12).map(|i| i * 4_000).collect(); + let out = cadence_run(&offsets); + let warned: Vec = out + .iter() + .enumerate() + .filter_map(|(i, o)| o.map(|_| i)) + .collect(); + assert_eq!(warned, vec![3, 11], "warn indices"); + } +} diff --git a/crates/punktfunk-host/src/punktfunk1.rs b/crates/punktfunk-host/src/punktfunk1.rs index 73792293..27600d95 100644 --- a/crates/punktfunk-host/src/punktfunk1.rs +++ b/crates/punktfunk-host/src/punktfunk1.rs @@ -3230,82 +3230,6 @@ struct SessionContext { launch: Option, } -/// Detector for METRONOMIC client keyframe-recovery cycles — the "periodic double-jolt" symptom -/// class field reports keep describing: a host/display-side disturbance repeating every few -/// seconds (display-topology churn, display-poller software, virtual-display timing), where each -/// cycle ends in a client keyframe request the host serves. Random network loss is bursty and -/// irregular; a stable period is a machine, and saying so in the host log turns a "nothing in the -/// logs :/" report into a self-diagnosis. -/// -/// Served forced IDRs within [`Self::COALESCE`] count as ONE event (a double-jolt's paired IDRs — -/// the cooldown re-issue of a lost keyframe — are one user-visible disturbance). When the gaps -/// between the last [`Self::STREAK`] events are all within ±[`Self::TOLERANCE`] of their mean, -/// [`Self::note`] returns the mean period for the caller to warn with, then stays quiet for -/// [`Self::REWARN`] while the cycle persists. Pure logic — unit-tested below. -struct RecoveryCadence { - events: std::collections::VecDeque, - last_warn: Option, -} - -impl RecoveryCadence { - /// Serves closer together than this are the same user-visible disturbance. - const COALESCE: std::time::Duration = std::time::Duration::from_millis(1500); - /// Consecutive evenly-spaced events before the cycle counts as metronomic. - const STREAK: usize = 4; - /// "Evenly spaced" = every gap within this fraction of the mean gap. - const TOLERANCE: f64 = 0.2; - /// Once warned, re-warn at most this often while the cycle persists. - const REWARN: std::time::Duration = std::time::Duration::from_secs(30); - - fn new() -> Self { - Self { - events: std::collections::VecDeque::new(), - last_warn: None, - } - } - - /// Record a served client-recovery IDR at `now`; `Some(mean period)` exactly when the - /// metronomic-cycle warning should fire. - fn note(&mut self, now: std::time::Instant) -> Option { - if self - .events - .back() - .is_some_and(|last| now.duration_since(*last) < Self::COALESCE) - { - return None; - } - self.events.push_back(now); - if self.events.len() > Self::STREAK { - self.events.pop_front(); - } - if self.events.len() < Self::STREAK { - return None; - } - let gaps: Vec = self - .events - .iter() - .zip(self.events.iter().skip(1)) - .map(|(a, b)| b.duration_since(*a).as_secs_f64()) - .collect(); - let mean = gaps.iter().sum::() / gaps.len() as f64; - if mean <= 0.0 - || gaps - .iter() - .any(|g| (g - mean).abs() > mean * Self::TOLERANCE) - { - return None; - } - if self - .last_warn - .is_some_and(|t| now.duration_since(t) < Self::REWARN) - { - return None; - } - self.last_warn = Some(now); - Some(std::time::Duration::from_secs_f64(mean)) - } -} - fn virtual_stream(ctx: SessionContext) -> Result<()> { // This thread runs the capture+encode loop (single-process — the only topology: Linux portal / // synthetic, Windows in-process IDD-push). Elevate it so a CPU-heavy game can't deschedule our GPU @@ -3521,8 +3445,8 @@ fn virtual_stream(ctx: SessionContext) -> Result<()> { // opening GOP, instead of answering it with a redundant second IDR. let mut last_forced_idr: Option = Some(std::time::Instant::now()); // Self-diagnosis for the periodic-stutter class: warns when the served recovery IDRs settle - // into a stable multi-second rhythm (see [`RecoveryCadence`]). - let mut recovery_cadence = RecoveryCadence::new(); + // into a stable multi-second rhythm (see [`crate::metronome::Metronome`]). + let mut recovery_cadence = crate::metronome::Metronome::new(); // Per-stage latency breakdown (PUNKTFUNK_PERF): per-call µs for the GPU-bound stages so we see // exactly where the capture→encoded latency goes — cap=try_latest (ring read + colour convert), // submit=encode_picture launch, wait=lock_bitstream (the scheduling wait + ASIC encode, the one @@ -3733,7 +3657,7 @@ fn virtual_stream(ctx: SessionContext) -> Result<()> { disturbance (display-topology churn, display-poller software, \ virtual-display timing) is the likely cause, not random network loss; \ correlate with 'slow display-descriptor poll' / 'display descriptor \ - changed' lines" + changed' / 'IDD-push capture stall' lines" ); } } @@ -4425,69 +4349,6 @@ mod tests { assert_eq!(dec, snap); } - /// Feed [`RecoveryCadence`] a schedule of event offsets (ms from a common origin) and return - /// what each `note` produced. - fn cadence_run(offsets_ms: &[u64]) -> Vec> { - let base = std::time::Instant::now(); - let mut c = RecoveryCadence::new(); - offsets_ms - .iter() - .map(|ms| c.note(base + std::time::Duration::from_millis(*ms))) - .collect() - } - - #[test] - fn cadence_detects_metronomic_recoveries() { - // Four IDR serves ~4 s apart (±5%) → the fourth trips the detector at ~4 s. - let out = cadence_run(&[0, 4_000, 8_100, 11_950]); - assert_eq!(out[..3], [None, None, None]); - let period = out[3].expect("metronomic series must be detected"); - assert!( - (period.as_secs_f64() - 3.98).abs() < 0.2, - "period={period:?}" - ); - } - - #[test] - fn cadence_coalesces_double_jolt_pairs() { - // The field signature: a jolt pair (second IDR ~0.7 s after the first, the cooldown - // re-issue) every ~4 s. Each pair is ONE event; detection still lands on the ~4 s cycle. - let out = cadence_run(&[ - 0, 700, // pair 1 - 4_000, 4_700, // pair 2 - 8_000, 8_650, // pair 3 - 12_000, // pair 4 (first serve trips it) - ]); - assert!(out[..6].iter().all(Option::is_none)); - let period = out[6].expect("coalesced pairs must still read as a 4 s cycle"); - assert!( - (period.as_secs_f64() - 4.0).abs() < 0.2, - "period={period:?}" - ); - } - - #[test] - fn cadence_ignores_irregular_bursts() { - // Genuine Wi-Fi-style loss: irregular gaps → never flagged. - assert!(cadence_run(&[0, 2_000, 9_000, 12_500, 21_000]) - .iter() - .all(Option::is_none)); - } - - #[test] - fn cadence_rewarns_at_most_every_30s() { - // A persisting 4 s cycle: warn on the 4th event (t=12 s), then stay quiet until ≥30 s - // past the warn — the t=44 s event (index 11) is the first at or beyond t=42 s. - let offsets: Vec = (0..12).map(|i| i * 4_000).collect(); - let out = cadence_run(&offsets); - let warned: Vec = out - .iter() - .enumerate() - .filter_map(|(i, o)| o.map(|_| i)) - .collect(); - assert_eq!(warned, vec![3, 11], "warn indices"); - } - #[test] fn adapt_fec_maps_loss_to_recovery_band() { // A perfectly clean window (0 loss) lands on the floor.