From cd6ceb98e389e062f191616c8c1910fc4f99a8a8 Mon Sep 17 00:00:00 2001 From: enricobuehler Date: Thu, 30 Jul 2026 21:57:56 +0200 Subject: [PATCH] feat(capture/windows): stall lines say whether the content or the display path went silent MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit A compose-silence hole used to be blamed on the frame-generation path by default — mislabeling benign content pauses (menus, loading, game hitches) as display-path bugs. The corrected discriminator convicts on witnesses: - Microsoft-Windows-DXGI Present/PresentMPO (ids 42/55) rides the host's filtered ETW session — one event per swapchain present, stamped with the presenting pid (named in the stall line). - BltQueueAddEntry/CompleteIndirectPresent (ids 1071/1068) witness frames entering/leaving the virtual display's kernel present queue (the modern IDD path; anatomy proven on-glass via xperf, 2026-07-30). - classify() now reads the window counts: presents flowing while the queue starved = FRAME-GENERATION (the OS dropped composed frames — the real bug class, never yet observed); no presents anywhere = CONTENT-SILENCE (benign for the display path); no working witness = UNATTRIBUTED, never a guess. - DWM_TIMING_INFO.cFrame is demoted to an advisory dwm_frames_frozen= print: on Win11 it is refresh-synthesized and advances without real composes (proven against a kernel trace), so it convicts nothing. - DxgKrnl legacy Present (id 184) is retired — it never fires on the redirected BltQueue path. Stall lines carry etw_presents=/etw_queue_adds= plus named presenters; compiled and validated on-glass (a quit-transition stall correctly labeled CONTENT-SILENCE presents=0). Co-Authored-By: Claude Fable 5 --- crates/pf-capture/src/windows/idd_push.rs | 106 +++++- .../src/windows/idd_push/dxgkrnl_etw.rs | 315 ++++++++++++++---- .../pf-capture/src/windows/idd_push/probes.rs | 26 +- .../pf-capture/src/windows/idd_push/stall.rs | 101 ++++-- 4 files changed, 453 insertions(+), 95 deletions(-) diff --git a/crates/pf-capture/src/windows/idd_push.rs b/crates/pf-capture/src/windows/idd_push.rs index b06204db..999f5884 100644 --- a/crates/pf-capture/src/windows/idd_push.rs +++ b/crates/pf-capture/src/windows/idd_push.rs @@ -1618,6 +1618,14 @@ impl IddPushCapturer { now.checked_sub(stall.gap + Duration::from_millis(300)) .map(|from| w.summary(from, now)) }), + // The discriminator counts span the GAP ONLY — no lead-in: presents from the + // healthy flow right before the hole would falsely acquit the content. The + // stall-ending frame's own present lands at the window edge and stays well + // under the acquit bar. + etw_counts: self.etw.as_ref().and_then(|w| { + now.checked_sub(stall.gap) + .map(|from| w.window_counts(from, now)) + }), }; self.stall_watch.report(&stall, now, &evidence); } @@ -2146,6 +2154,7 @@ mod tests { max_heartbeat_age_ms: hb_age_ms, probes: None, etw: None, + etw_counts: None, }, ) }; @@ -2167,10 +2176,12 @@ mod tests { assert_eq!(verdict(3_000, Some(2), 1_600), StallVerdict::WorkerStalled); } - /// [`stall::classify`]'s verdict matrix — how the micro-probe window refines (or declines to - /// refine) the driver-telemetry verdict into a named disturbance class. + /// [`stall::classify`]'s verdict matrix — how the micro-probe window and the ETW + /// present-vs-queue counts refine (or decline to refine) the driver-telemetry verdict into + /// a named disturbance class. #[test] fn stall_classification_matrix() { + use super::dxgkrnl_etw::EtwWindowCounts; use super::stall::{classify, ProbeWindow, StallClass, StallVerdict}; let gap = Duration::from_millis(600); let probes = |fence: Option, dwm: Option, flush: Option| ProbeWindow { @@ -2179,22 +2190,29 @@ mod tests { dwm_flush_max_us: flush, ..ProbeWindow::default() }; + let counts = |presents: u32, queue_adds: u32| EtwWindowCounts { + presents, + queue_adds, + present_history: true, + queue_history: true, + }; // The driver's own verdicts win outright — probes can't overrule "we lost the frames". assert_eq!( classify( gap, &StallVerdict::WorkerStalled, - Some(&probes(Some(500_000), None, None)) + Some(&probes(Some(500_000), None, None)), + None ), StallClass::OursWorker ); assert_eq!( - classify(gap, &StallVerdict::DeliveryLeg, None), + classify(gap, &StallVerdict::DeliveryLeg, None, None), StallClass::OursDelivery ); // No probes: compose-silence alone can't name a class. assert_eq!( - classify(gap, &StallVerdict::ComposeSilence, None), + classify(gap, &StallVerdict::ComposeSilence, None, None), StallClass::Unattributed ); // Fences stalled ≥ gap/2 → the adapter froze — Class 1 (even without driver telemetry). @@ -2202,7 +2220,8 @@ mod tests { classify( gap, &StallVerdict::ComposeSilence, - Some(&probes(Some(400_000), Some(400_000), None)) + Some(&probes(Some(400_000), Some(400_000), None)), + None ), StallClass::AdapterFreeze ); @@ -2210,7 +2229,8 @@ mod tests { classify( gap, &StallVerdict::NoTelemetry, - Some(&probes(Some(400_000), None, None)) + Some(&probes(Some(400_000), None, None)), + None ), StallClass::AdapterFreeze ); @@ -2219,7 +2239,8 @@ mod tests { classify( gap, &StallVerdict::ComposeSilence, - Some(&probes(Some(16_000), Some(500_000), None)) + Some(&probes(Some(16_000), Some(500_000), None)), + None ), StallClass::CompositorBlocked ); @@ -2227,36 +2248,91 @@ mod tests { classify( gap, &StallVerdict::ComposeSilence, - Some(&probes(Some(16_000), Some(20_000), Some(450_000))) + Some(&probes(Some(16_000), Some(20_000), Some(450_000))), + None ), StallClass::CompositorBlocked ); - // Everything alive + the driver swears E_PENDING → the frame-generation path. + // Everything alive + the driver swears E_PENDING, but NO working present witness: + // the silence cannot be pinned on either side — UNATTRIBUTED, never a guess. (The + // pre-2026-07-30 default of FRAME-GENERATION here mislabeled benign content pauses.) assert_eq!( classify( gap, &StallVerdict::ComposeSilence, - Some(&probes(Some(16_000), Some(20_000), Some(30_000))) + Some(&probes(Some(16_000), Some(20_000), Some(30_000))), + None + ), + StallClass::Unattributed + ); + // A witness that exists but has never produced an event is NOT a working witness. + assert_eq!( + classify( + gap, + &StallVerdict::ComposeSilence, + Some(&probes(Some(16_000), Some(20_000), Some(30_000))), + Some(&EtwWindowCounts { + present_history: false, + ..EtwWindowCounts::default() + }) + ), + StallClass::Unattributed + ); + // The present witness splits the silence. Presents flowing through the hole while the + // virtual display's queue starved → the OS display path dropped composed frames: the + // frame-generation leg, POSITIVELY convicted. + assert_eq!( + classify( + gap, + &StallVerdict::ComposeSilence, + Some(&probes(Some(16_000), Some(20_000), Some(30_000))), + Some(&counts(54, 0)) ), StallClass::FrameGeneration ); + // (Essentially) no presents anywhere across the hole — the stall-ending frame and a + // caret blink stay under the bar → the CONTENT stopped presenting: benign for the + // display path. + assert_eq!( + classify( + gap, + &StallVerdict::ComposeSilence, + Some(&probes(Some(16_000), Some(20_000), Some(30_000))), + Some(&counts(2, 1)) + ), + StallClass::ContentSilence + ); + // The present witness does NOT overrule the driver's own verdicts or the harder + // classes — it only refines compose-silence. + assert_eq!( + classify( + gap, + &StallVerdict::ComposeSilence, + Some(&probes(Some(400_000), Some(400_000), None)), + Some(&counts(54, 0)) + ), + StallClass::AdapterFreeze + ); // Healthy probes but a pre-telemetry driver: delivery-leg is equally possible — honest. assert_eq!( classify( gap, &StallVerdict::NoTelemetry, - Some(&probes(Some(16_000), Some(20_000), None)) + Some(&probes(Some(16_000), Some(20_000), None)), + Some(&counts(54, 0)) ), StallClass::Unattributed ); - // An absent probe (None) never reads as "stalled" — absence is stated, not guessed. + // An absent probe (None) never reads as "stalled" — absence is stated, not guessed; + // with the present witness working, the silence still splits correctly. assert_eq!( classify( gap, &StallVerdict::ComposeSilence, - Some(&probes(None, Some(20_000), Some(30_000))) + Some(&probes(None, Some(20_000), Some(30_000))), + Some(&counts(1, 0)) ), - StallClass::FrameGeneration + StallClass::ContentSilence ); } } diff --git a/crates/pf-capture/src/windows/idd_push/dxgkrnl_etw.rs b/crates/pf-capture/src/windows/idd_push/dxgkrnl_etw.rs index fabbc28a..42cee561 100644 --- a/crates/pf-capture/src/windows/idd_push/dxgkrnl_etw.rs +++ b/crates/pf-capture/src/windows/idd_push/dxgkrnl_etw.rs @@ -8,14 +8,30 @@ //! - 154/155 `SetPowerState` start/stop — monitor/link power transitions (Class-1 servicing), //! - 430 `SetTimingsFromVidPn` — modeset-class commits (Level-Two "hardware is idle" freezes), //! - 1096/1097 `DisplayDetectControl` start/stop — present on newer builds; filtered in -//! unconditionally, harmless where absent. +//! unconditionally, harmless where absent, +//! - 1071 `BltQueueAddEntry` — one event per frame ENTERING the virtual display's kernel present +//! queue (the modern IDD path: DWM present → PresentRedirected → BltQueue → soft-vsync → +//! `BltQueueCompleteIndirectPresent` → IddCx → our driver; anatomy proven on-glass via xperf, +//! 2026-07-30 — its gaps matched our capture holes to the millisecond), +//! - 1068 `BltQueueCompleteIndirectPresent` — one event per frame COMPLETED to IddCx. +//! +//! A second provider rides the same session: `Microsoft-Windows-DXGI` (user-mode), filtered to +//! `Present`/`PresentMultiplaneOverlay` starts (ids 42/55) — one event per swapchain present, +//! stamped with the PRESENTING process id. Together they are the compose-silence discriminator +//! ([`EtwWatch::window_counts`]): DXGI presents flowing while `BltQueueAddEntry` gaps = the OS +//! display path dropped composed frames (the real display-path bug); BOTH silent = the content +//! stopped presenting (benign pause — menus/loading/game hitch). The predecessor witnesses are +//! retired for cause: DxgKrnl id 184 `Present` never fires on the modern redirected path, and +//! `DWM_TIMING_INFO.cFrame` is refresh-synthesized on Win11 (advances without composes) — both +//! proven on-glass 2026-07-30. //! //! Kernel-side event-id filtering (`EVENT_FILTER_TYPE_EVENT_ID`) keeps the per-vblank firehose -//! off; the session costs a few events per minute. Starting a real-time session needs admin / -//! Performance Log Users — the packaged host (service, SYSTEM) has it; a plain dev run degrades -//! to `None` and every report says `etw=unavailable` instead of guessing. The session's -//! `FlushTimer` is 1 s, so a bracket from the trailing second of a gap can land AFTER that -//! stall's report line — the next report (and the metronomic tally) still carries it. +//! off; the DDI families cost a few events per minute, and the present/queue streams a few +//! hundred per second (bounded by the ring + the 64 KB session buffers). Starting a real-time +//! session needs admin / Performance Log Users — the packaged host (service, SYSTEM) has it; a +//! plain dev run degrades to `None` and every report says `etw=unavailable` instead of guessing. +//! The session's `FlushTimer` is 1 s, so a bracket from the trailing second of a gap can land +//! AFTER that stall's report line — the next report (and the metronomic tally) still carries it. // Every `unsafe` block in this file carries a `// SAFETY:` proof; enforce it (unsafe-proof program). #![deny(clippy::undocumented_unsafe_blocks)] @@ -25,7 +41,7 @@ use std::sync::{Arc, Mutex, OnceLock, Weak}; use std::time::{Duration, Instant}; use windows::core::{GUID, PWSTR}; -use windows::Win32::Foundation::ERROR_SUCCESS; +use windows::Win32::Foundation::{CloseHandle, ERROR_SUCCESS}; use windows::Win32::System::Diagnostics::Etw::{ CloseTrace, ControlTraceW, EnableTraceEx2, OpenTraceW, ProcessTrace, StartTraceW, CONTROLTRACE_HANDLE, ENABLE_TRACE_PARAMETERS, ENABLE_TRACE_PARAMETERS_VERSION_2, @@ -35,21 +51,59 @@ use windows::Win32::System::Diagnostics::Etw::{ PROCESS_TRACE_MODE_REAL_TIME, TRACE_LEVEL_INFORMATION, WNODE_FLAG_TRACED_GUID, }; use windows::Win32::System::Performance::{QueryPerformanceCounter, QueryPerformanceFrequency}; +use windows::Win32::System::Threading::{ + OpenProcess, QueryFullProcessImageNameW, PROCESS_NAME_WIN32, PROCESS_QUERY_LIMITED_INFORMATION, +}; /// `Microsoft-Windows-DxgKrnl` (`{802EC45A-1E99-4B83-9920-87C98277BA9D}`). const DXGKRNL: GUID = GUID::from_u128(0x802EC45A_1E99_4B83_9920_87C98277BA9D); -/// The event ids the session filters IN (see the module docs). -const FILTER_IDS: [u16; 8] = [150, 151, 272, 154, 155, 430, 1096, 1097]; +/// `Microsoft-Windows-DXGI` (`{CA11C036-0102-4A2D-A6AD-F03CFED5D3C9}`) — the user-mode swapchain +/// runtime; its `Present` events fire in the presenting process's context. +const DXGI: GUID = GUID::from_u128(0xCA11C036_0102_4A2D_A6AD_F03CFED5D3C9); + +/// The DxgKrnl event ids the session filters IN (see the module docs). +const FILTER_IDS: [u16; 10] = [ + 150, + 151, + 272, + 154, + 155, + 430, + 1096, + 1097, + BLT_ADD_ID, + BLT_COMPLETE_ID, +]; + +/// `BltQueueAddEntry` — a frame ENTERED the virtual display's kernel present queue. Event id +/// resolved from the 26200 manifest (task 1105) and count-verified against an on-glass capture. +const BLT_ADD_ID: u16 = 1071; + +/// `BltQueueCompleteIndirectPresent` — a frame COMPLETED from the queue to IddCx (task 1059). +const BLT_COMPLETE_ID: u16 = 1068; + +/// The DXGI event ids the session filters IN: `Present` start (42) and +/// `PresentMultiplaneOverlay` start (55) — one per app/DWM present call. +const DXGI_FILTER_IDS: [u16; 2] = [DXGI_PRESENT_ID, DXGI_PRESENT_MPO_ID]; +const DXGI_PRESENT_ID: u16 = 42; +const DXGI_PRESENT_MPO_ID: u16 = 55; /// Session name — ours, stopped-if-stale at start (a crashed host leaves the session behind; /// real-time sessions are machine-global named objects). const SESSION: &str = "punktfunk-stallwatch-dxgkrnl"; -/// The consumer callback's destination: `(event QPC, event id)`, capped. A few events per minute -/// in the field; the cap only matters under a detection storm — exactly when the tail is the -/// least interesting part. -static RING: Mutex> = Mutex::new(VecDeque::new()); +/// The consumer callback's destination: `(event QPC, event id, process id)`, capped. The DDI +/// families are a few events per minute; the DXGI present stream and the two BltQueue streams +/// each run at compose rate, so the cap sizes the history: 16384 entries ≈ 15–60 s at a +/// 90–240 Hz desktop under a game + DWM — comfortably more than any single stall window the +/// reporter asks about (a deeper hole's counts read as floors, which is still evidence). +/// Event-id spaces of the two providers are disjoint (42/55 vs 15x/2xx/4xx/10xx/1071/1068), so +/// one ring holds both without a provider tag. +static RING: Mutex> = Mutex::new(VecDeque::new()); + +/// [`RING`]'s cap (see its doc for the sizing math). +const RING_CAP: usize = 16384; fn qpc_now() -> i64 { let mut v = 0i64; @@ -75,17 +129,18 @@ unsafe extern "system" fn on_event(record: *mut EVENT_RECORD) { return; } // SAFETY: `record` is the live event the consumer is delivering for the duration of this call. - let (id, ts) = unsafe { + let (id, ts, pid) = unsafe { ( (*record).EventHeader.EventDescriptor.Id, (*record).EventHeader.TimeStamp, + (*record).EventHeader.ProcessId, ) }; let mut ring = RING.lock().unwrap(); - if ring.len() == 2048 { + if ring.len() == RING_CAP { ring.pop_front(); } - ring.push_back((ts, id)); + ring.push_back((ts, id, pid)); } /// A live DxgKrnl watch: the controller handle (stops the session on drop) + the consumer handle. @@ -171,45 +226,10 @@ impl EtwWatch { } // Enable DxgKrnl with a kernel-side event-id filter — the whole point: the provider's - // vblank/DPC keywords never reach us. - let mut filter = Vec::with_capacity(4 + FILTER_IDS.len() * 2); - filter.extend_from_slice(&[1u8, 0u8]); // FilterIn = TRUE, Reserved - filter.extend_from_slice(&(FILTER_IDS.len() as u16).to_le_bytes()); - for id in FILTER_IDS { - filter.extend_from_slice(&id.to_le_bytes()); - } - let mut desc = EVENT_FILTER_DESCRIPTOR { - Ptr: filter.as_ptr() as u64, - Size: filter.len() as u32, - Type: EVENT_FILTER_TYPE_EVENT_ID, - }; - let params = ENABLE_TRACE_PARAMETERS { - Version: ENABLE_TRACE_PARAMETERS_VERSION_2, - EnableProperty: 0, - ControlFlags: 0, - SourceId: GUID::zeroed(), - EnableFilterDesc: &mut desc, - FilterDescCount: 1, - }; - // SAFETY: `session` is the live handle just started; `params`/`desc`/`filter` are live - // locals for this synchronous call (the kernel copies the filter). - let rc = unsafe { - EnableTraceEx2( - session, - &DXGKRNL, - EVENT_CONTROL_CODE_ENABLE_PROVIDER.0, - TRACE_LEVEL_INFORMATION as u8, - 0, - 0, - 0, - Some(¶ms), - ) - }; - if rc != ERROR_SUCCESS { - tracing::debug!( - rc = rc.0, - "DxgKrnl ETW enable failed — stopping the session" - ); + // vblank/DPC keywords never reach us. Fatal on failure (the DDI families + queue + // witnesses are this watch's reason to exist). + if !enable_provider(session, &DXGKRNL, &FILTER_IDS) { + tracing::debug!("DxgKrnl ETW enable failed — stopping the session"); let (mut buf, _) = properties_buffer(); // SAFETY: live handle + valid properties allocation, stopped exactly once on this path. unsafe { @@ -219,6 +239,14 @@ impl EtwWatch { } return None; } + // The DXGI (user-mode) present witness rides the same session. Degraded-not-fatal: a + // refusal only costs the per-process present counts — `window_counts` then reports + // no present history and classification stays honest (Unattributed, never a guess). + if !enable_provider(session, &DXGI, &DXGI_FILTER_IDS) { + tracing::debug!( + "DXGI ETW enable failed — present-vs-queue discrimination unavailable this session" + ); + } let mut log = EVENT_TRACE_LOGFILEW { LoggerName: PWSTR(name.as_ptr() as *mut _), @@ -283,9 +311,12 @@ impl EtwWatch { let (now_i, now_q, freq) = (Instant::now(), qpc_now(), qpc_freq()); let to_q = now_q - duration_qpc(now_i.saturating_duration_since(to), freq); let from_q = now_q - duration_qpc(now_i.saturating_duration_since(from), freq); - let events: Vec<(i64, u16)> = { + let events: Vec<(i64, u16, u32)> = { let ring = RING.lock().unwrap(); - ring.iter().filter(|(ts, _)| *ts <= to_q).copied().collect() + ring.iter() + .filter(|(ts, _, _)| *ts <= to_q) + .copied() + .collect() }; let ms = |dq: i64| dq.max(0) * 1_000 / freq; let mut parts = Vec::new(); @@ -298,7 +329,7 @@ impl EtwWatch { let mut count = 0u32; let mut max_ms = 0i64; let mut still_open = false; - for &(ts, id) in &events { + for &(ts, id, _) in &events { if id == start_id { open = Some(ts); } else if id == stop_id { @@ -331,18 +362,184 @@ impl EtwWatch { ] { let count = events .iter() - .filter(|(ts, i)| *i == id && *ts >= from_q && *ts <= to_q) + .filter(|(ts, i, _)| *i == id && *ts >= from_q && *ts <= to_q) .count(); if count > 0 { parts.push(format!("{label}×{count}")); } } + // Present + queue accounting (DXGI 42/55 + BltQueueAddEntry/Complete): total presents + // inside the window plus the top presenters, NAMED — the line that splits a + // compose-silence hole into "the content stopped presenting" (no presents anywhere) + // versus "presents flowed and the display path dropped them" (presents at rate while + // the queue starves). "Present×0" is printed explicitly when the stream has history + // but the window is empty — silence is a finding, not an absence. + let mut per_pid: Vec<(u32, u32)> = Vec::new(); + let mut have_present_history = false; + let (mut adds, mut completes) = (0u32, 0u32); + let mut have_queue_history = false; + for &(ts, id, pid) in &events { + match id { + DXGI_PRESENT_ID | DXGI_PRESENT_MPO_ID => { + have_present_history = true; + if ts >= from_q && ts <= to_q { + match per_pid.iter_mut().find(|(p, _)| *p == pid) { + Some((_, c)) => *c += 1, + None => per_pid.push((pid, 1)), + } + } + } + BLT_ADD_ID | BLT_COMPLETE_ID => { + have_queue_history = true; + if ts >= from_q && ts <= to_q { + if id == BLT_ADD_ID { + adds += 1; + } else { + completes += 1; + } + } + } + _ => {} + } + } + if !per_pid.is_empty() { + per_pid.sort_by_key(|&(_, c)| std::cmp::Reverse(c)); + let total: u32 = per_pid.iter().map(|(_, c)| c).sum(); + let top = per_pid + .iter() + .take(2) + .map(|(pid, c)| { + let name = process_name(*pid).unwrap_or_else(|| format!("pid{pid}")); + format!("{name}:{c}") + }) + .collect::>() + .join(","); + parts.push(format!("Present×{total}({top})")); + } else if have_present_history { + parts.push("Present×0".to_string()); + } + if have_queue_history { + parts.push(format!("blt-queue add×{adds} complete×{completes}")); + } if parts.is_empty() { "none".to_string() } else { parts.join(" ") } } + + /// The structured discriminator read for `[from, to]` (the stall classifier's evidence): + /// how many swapchain presents (DXGI 42/55, any process) and how many virtual-display + /// queue entries (`BltQueueAddEntry`) landed in the window, plus whether each stream has + /// EVER produced an event (distinguishing a true zero from a witness that is not working — + /// e.g. the DXGI enable was refused, or an OS build renumbered the BltQueue events). + pub(super) fn window_counts(&self, from: Instant, to: Instant) -> EtwWindowCounts { + let (now_i, now_q, freq) = (Instant::now(), qpc_now(), qpc_freq()); + let to_q = now_q - duration_qpc(now_i.saturating_duration_since(to), freq); + let from_q = now_q - duration_qpc(now_i.saturating_duration_since(from), freq); + let ring = RING.lock().unwrap(); + let mut out = EtwWindowCounts::default(); + for &(ts, id, _) in ring.iter() { + match id { + DXGI_PRESENT_ID | DXGI_PRESENT_MPO_ID => { + out.present_history = true; + if ts >= from_q && ts <= to_q { + out.presents += 1; + } + } + BLT_ADD_ID => { + out.queue_history = true; + if ts >= from_q && ts <= to_q { + out.queue_adds += 1; + } + } + _ => {} + } + } + out + } +} + +/// [`EtwWatch::window_counts`]'s read: the compose-silence discriminator's structured evidence. +#[derive(Debug, Default, Clone, Copy, PartialEq, Eq)] +pub(super) struct EtwWindowCounts { + /// Swapchain presents (any process — the game AND dwm both count) inside the window. + pub(super) presents: u32, + /// `BltQueueAddEntry` events (frames entering the virtual display's kernel queue) inside it. + pub(super) queue_adds: u32, + /// The present stream has produced at least one event EVER (witness known-working). + pub(super) present_history: bool, + /// The queue stream has produced at least one event EVER (witness known-working). + pub(super) queue_history: bool, +} + +/// Enable `guid` on `session` with a kernel-side event-id allowlist. `true` on success. +fn enable_provider(session: CONTROLTRACE_HANDLE, guid: &GUID, ids: &[u16]) -> bool { + let mut filter = Vec::with_capacity(4 + ids.len() * 2); + filter.extend_from_slice(&[1u8, 0u8]); // FilterIn = TRUE, Reserved + filter.extend_from_slice(&(ids.len() as u16).to_le_bytes()); + for id in ids { + filter.extend_from_slice(&id.to_le_bytes()); + } + let mut desc = EVENT_FILTER_DESCRIPTOR { + Ptr: filter.as_ptr() as u64, + Size: filter.len() as u32, + Type: EVENT_FILTER_TYPE_EVENT_ID, + }; + let params = ENABLE_TRACE_PARAMETERS { + Version: ENABLE_TRACE_PARAMETERS_VERSION_2, + EnableProperty: 0, + ControlFlags: 0, + SourceId: GUID::zeroed(), + EnableFilterDesc: &mut desc, + FilterDescCount: 1, + }; + // SAFETY: `session` is a live handle owned by the caller; `params`/`desc`/`filter` are live + // locals for this synchronous call (the kernel copies the filter before returning). + let rc = unsafe { + EnableTraceEx2( + session, + guid, + EVENT_CONTROL_CODE_ENABLE_PROVIDER.0, + TRACE_LEVEL_INFORMATION as u8, + 0, + 0, + 0, + Some(¶ms), + ) + }; + rc == ERROR_SUCCESS +} + +/// Best-effort image base name for `pid` (Present attribution); `None` when the process is gone +/// or protected. Runs only at stall-report time — a rare, already-degraded moment. +fn process_name(pid: u32) -> Option { + // SAFETY: plain FFI; a refused open returns Err (checked via `ok()?`), and the returned + // handle is closed exactly once below. + let process = unsafe { OpenProcess(PROCESS_QUERY_LIMITED_INFORMATION, false, pid) }.ok()?; + let mut buf = [0u16; 512]; + let mut len = buf.len() as u32; + // SAFETY: `process` is the live handle just opened with QUERY_LIMITED (what this API needs); + // `buf`/`len` are a valid out-buffer and its capacity, `len` updated to the written UTF-16 + // length (no NUL) on success. + let ok = unsafe { + QueryFullProcessImageNameW( + process, + PROCESS_NAME_WIN32, + PWSTR(buf.as_mut_ptr()), + &mut len, + ) + } + .is_ok(); + // SAFETY: `process` is the handle opened above, closed exactly once here. + unsafe { + let _ = CloseHandle(process); + } + if !ok { + return None; + } + let path = String::from_utf16_lossy(&buf[..len as usize]); + Some(path.rsplit(['\\', '/']).next().unwrap_or(&path).to_string()) } /// A `Duration` in QPC ticks (saturating; diagnostic precision). diff --git a/crates/pf-capture/src/windows/idd_push/probes.rs b/crates/pf-capture/src/windows/idd_push/probes.rs index 3129c3e7..6042bf52 100644 --- a/crates/pf-capture/src/windows/idd_push/probes.rs +++ b/crates/pf-capture/src/windows/idd_push/probes.rs @@ -7,6 +7,10 @@ //! for the freeze's duration on EVERY engine of that adapter. //! - **dwm-tick**: `DwmGetCompositionTimingInfo(NULL)` `cRefresh` advance — the compositor's own //! clock. Frozen tick with live fences = DWM (or something it waits on) is blocked, not the GPU. +//! The same sample also tracks `cFrame` (the COMPOSED-frame counter) — the compose-silence +//! discriminator: a clock that ticks while `cFrame` freezes means DWM had NOTHING to compose +//! (the foreground content stopped presenting); a `cFrame` that keeps advancing through a hole +//! means DWM built frames that never reached OUR swap-chain (the OS frame-generation leg). //! - **dwm-flush**: a watchdogged `DwmFlush` — its latency IS the composition-wait measurement. //! - **scanline**: `D3DKMTGetScanLine` on an active output (Level-Zero reentrant — documented safe //! against every miniport lock, so a BLOCKED call here convicts the KMD itself). Prefers a @@ -155,6 +159,8 @@ struct Inner { /// One per hardware adapter, labelled by LUID (hybrids run two). fences: Vec<(String, BlockingProbe)>, dwm_tick: Ring, + /// `cFrame` (composed-frame counter) frozen spans, sampled by the same dwm-tick thread. + dwm_frame: Ring, dwm_flush: BlockingProbe, scanline: BlockingProbe, /// Whether the scanline probe currently targets a PHYSICAL head (see the module docs). @@ -201,6 +207,7 @@ impl ProbeEngine { .filter_map(|(_, p)| p.window_max(from, to)) .max(), dwm_tick_frozen_us: i.dwm_tick.window_max(from, to), + dwm_frame_frozen_us: i.dwm_frame.window_max(from, to), dwm_flush_max_us: i.dwm_flush.window_max(from, to), scanline_max_us: if i.scanline_running.load(Ordering::Relaxed) { i.scanline.window_max(from, to) @@ -221,6 +228,7 @@ impl ProbeEngine { stop: AtomicBool::new(false), fences, dwm_tick: Ring::new(), + dwm_frame: Ring::new(), dwm_flush: BlockingProbe::new(), scanline: BlockingProbe::new(), scanline_physical: AtomicBool::new(false), @@ -397,11 +405,17 @@ fn fence_probe_setup( Some((context, ctx4, fence, event, (a, b))) } -/// `cRefresh` advance sampling: each tick records how long the compositor's frame counter has been -/// unchanged. A frozen span covering a stall (with live fences) = DWM blocked, not the GPU. +/// `cRefresh` + `cFrame` advance sampling: each tick records how long the compositor's refresh +/// counter and its COMPOSED-frame counter have been unchanged. A frozen refresh span covering a +/// stall (with live fences) = DWM blocked, not the GPU. A LIVE refresh with a frozen `cFrame` = +/// DWM ticked but composed nothing — no damage anywhere, i.e. the foreground content itself +/// stopped presenting; a `cFrame` that advances through a capture hole = DWM composed frames the +/// IDD swap-chain never received (the OS frame-generation leg dropped them). fn dwm_tick_loop(inner: &Inner) { let mut last_refresh = 0u64; let mut last_change = Instant::now(); + let mut last_frame = 0u64; + let mut last_frame_change = Instant::now(); while !inner.stop.load(Ordering::Relaxed) { let mut info = DWM_TIMING_INFO { cbSize: std::mem::size_of::() as u32, @@ -417,6 +431,14 @@ fn dwm_tick_loop(inner: &Inner) { } let frozen = now.duration_since(last_change); inner.dwm_tick.push(now, frozen, frozen.as_micros() as u64); + if info.cFrame != last_frame { + last_frame = info.cFrame; + last_frame_change = now; + } + let frame_frozen = now.duration_since(last_frame_change); + inner + .dwm_frame + .push(now, frame_frozen, frame_frozen.as_micros() as u64); } std::thread::sleep(Duration::from_millis(50)); } diff --git a/crates/pf-capture/src/windows/idd_push/stall.rs b/crates/pf-capture/src/windows/idd_push/stall.rs index 838abea1..2845f143 100644 --- a/crates/pf-capture/src/windows/idd_push/stall.rs +++ b/crates/pf-capture/src/windows/idd_push/stall.rs @@ -32,6 +32,11 @@ pub(super) struct StallEvidence { /// The DxgKrnl DDI activity inside the window (Phase A.3 ETW summary); `None` when the /// session is unavailable (non-admin dev run). pub(super) etw: Option, + /// The structured present-vs-queue counts for the window ([`EtwWatch::window_counts`]) — + /// the compose-silence discriminator: presents flowing while the queue starves = the OS + /// display path dropped composed frames; both silent = the content stopped presenting. + /// `None` when the ETW session is unavailable. + pub(super) etw_counts: Option, } /// The micro-probes' window read (Phase A.2, built by `probes::ProbeEngine::window`): per-leg @@ -43,6 +48,12 @@ pub(super) struct ProbeWindow { pub(super) fence_max_us: Option, /// Longest span (µs) with no `DwmGetCompositionTimingInfo` `cRefresh` advance. pub(super) dwm_tick_frozen_us: Option, + /// Longest span (µs) with no `cFrame` (composed-frame counter) advance. ADVISORY ONLY — + /// never classification evidence: on Win11 `DWM_TIMING_INFO.cFrame` is refresh-synthesized + /// and advances without real composes (proven on-glass 2026-07-30 against a kernel trace + /// where DWM verifiably presented nothing for 1.6 s while cFrame ticked). The line keeps + /// reporting it for older builds' sake; [`classify`] ignores it. + pub(super) dwm_frame_frozen_us: Option, /// Worst watchdogged `DwmFlush` latency (µs). pub(super) dwm_flush_max_us: Option, /// Worst `D3DKMTGetScanLine` CALL latency (µs) — Level-Zero, so blocking convicts the KMD. @@ -62,9 +73,11 @@ impl std::fmt::Display for ProbeWindow { }; write!( f, - "fence={} dwm_tick_frozen={} dwm_flush={} scanline={}({}) cpu_overshoot={}", + "fence={} dwm_tick_frozen={} dwm_frames_frozen={} dwm_flush={} scanline={}({}) \ + cpu_overshoot={}", ms(self.fence_max_us), ms(self.dwm_tick_frozen_us), + ms(self.dwm_frame_frozen_us), ms(self.dwm_flush_max_us), ms(self.scanline_max_us), if self.scanline_physical { @@ -92,9 +105,17 @@ pub(super) enum StallClass { /// Engines alive but DWM's own tick froze: the compositor is blocked on something (DDC/child /// I/O vendor lock, win32k display-config queue). Class 2. CompositorBlocked, - /// Engines alive, DWM ticking, driver drained E_PENDING — composition happened for OTHER - /// surfaces but produced no frame for OUR display: the frame-generation path - /// (IddCx/dirty-tracking/divider). Ours to chase with IddCx WPP. + /// Engines alive, DWM's clock ticking, driver drained E_PENDING, and the ETW present witness + /// saw (essentially) NO swapchain presents from ANY process across the hole: the content + /// stopped presenting — no damage, DWM correctly composed nothing (a game hitch, a loading + /// screen, a menu). Benign for the display path; the content side is where to look if the + /// user FELT it. + ContentSilence, + /// Engines alive, DWM ticking, driver drained E_PENDING — and the ETW present witness saw + /// presents FLOWING through the hole while the virtual display's kernel queue + /// (`BltQueueAddEntry`) starved: composed frames existed and the OS display path dropped + /// them before our swap-chain. The real display-path bug class — never yet observed in the + /// field; a report with this label (counts attached) is the specimen we want. FrameGeneration, /// Not enough evidence to name a class (pre-telemetry driver and/or probes absent). Unattributed, @@ -111,21 +132,39 @@ impl std::fmt::Display for StallClass { Self::CompositorBlocked => { "CLASS-2 compositor blocked (engines alive, DWM tick frozen — vendor lock / DDC)" } + Self::ContentSilence => { + "CONTENT-SILENCE (no swapchain presents from any process across the hole — the content stopped presenting; not the display path)" + } Self::FrameGeneration => { - "FRAME-GENERATION (DWM ticked, engines alive, no frame for THIS display — IddCx/dirty/divider)" + "FRAME-GENERATION (presents FLOWED while the virtual display's kernel queue starved — the OS display path dropped composed frames)" } Self::Unattributed => "UNATTRIBUTED (insufficient telemetry)", }) } } -/// The verdict matrix: fold the driver-telemetry verdict and the probe window into a class. -/// Pure — unit-tested beside the [`StallWatch`] tests. A leg is "stalled for the hole" when its -/// worst reading covers at least half the gap (the same proportional bar as [`attribute`]). +/// How many window presents acquit the content: ≥8 presents across the hole mirrors +/// [`attribute`]'s offered-frames bar and [`StallWatch::RECENT`]'s sustained-flow definition — +/// a caret blink or a stall-ending frame stays under it, a game presenting through the hole +/// clears it by an order of magnitude. +const PRESENTS_ACQUIT_CONTENT: u32 = 8; + +/// The verdict matrix: fold the driver-telemetry verdict, the probe window and the ETW +/// present-vs-queue counts into a class. Pure — unit-tested beside the [`StallWatch`] tests. +/// A leg is "stalled for the hole" when its worst reading covers at least half the gap (the +/// same proportional bar as [`attribute`]). +/// +/// Compose-silence is split by the ETW witnesses ONLY (`DWM_TIMING_INFO.cFrame` is +/// refresh-synthesized on Win11 and convicts nothing — see [`ProbeWindow::dwm_frame_frozen_us`]): +/// presents flowing while the hole ran = the OS display path dropped them (FRAME-GENERATION, +/// positively convicted); no presents anywhere = the content stopped (CONTENT-SILENCE). With no +/// working witness the class stays UNATTRIBUTED — the pre-2026-07-30 default of blaming the +/// frame-generation path mislabeled benign content pauses and is retired. pub(super) fn classify( gap: Duration, verdict: &StallVerdict, probes: Option<&ProbeWindow>, + etw_counts: Option<&super::dxgkrnl_etw::EtwWindowCounts>, ) -> StallClass { match verdict { StallVerdict::WorkerStalled => return StallClass::OursWorker, @@ -144,10 +183,21 @@ pub(super) fn classify( return StallClass::CompositorBlocked; } // Engines alive and DWM ticking: only the driver's own E_PENDING testimony can pin the - // frame-generation path — without it (pre-telemetry driver) the delivery leg is equally - // possible, so stay honest. + // silence on the present path — without it (pre-telemetry driver) the delivery leg is + // equally possible, so stay honest. if matches!(verdict, StallVerdict::ComposeSilence) { - StallClass::FrameGeneration + match etw_counts { + Some(c) if c.present_history => { + if c.presents >= PRESENTS_ACQUIT_CONTENT { + StallClass::FrameGeneration + } else { + StallClass::ContentSilence + } + } + // No working present witness (session refused / DXGI enable failed / renumbered + // events): the silence cannot be attributed to either side. + _ => StallClass::Unattributed, + } } else { StallClass::Unattributed } @@ -228,8 +278,9 @@ pub(super) struct StallWatch { /// whole session's beat, not just the stall that tripped the metronome. verdicts: [u32; 4], /// Running per-class tally ([`StallClass`] order: ours-worker, ours-delivery, adapter-freeze, - /// compositor-blocked, frame-generation, unattributed) — the verdict matrix's session summary. - classes: [u32; 6], + /// compositor-blocked, content-silence, frame-generation, unattributed) — the verdict + /// matrix's session summary. + classes: [u32; 7], } impl StallWatch { @@ -250,7 +301,7 @@ impl StallWatch { seen: 0, with_os_events: 0, verdicts: [0; 4], - classes: [0; 6], + classes: [0; 7], } } @@ -312,14 +363,20 @@ impl StallWatch { StallVerdict::ComposeSilence => 2, StallVerdict::DeliveryLeg => 3, }] += 1; - let class = classify(stall.gap, &verdict, evidence.probes.as_ref()); + let class = classify( + stall.gap, + &verdict, + evidence.probes.as_ref(), + evidence.etw_counts.as_ref(), + ); self.classes[match class { StallClass::OursWorker => 0, StallClass::OursDelivery => 1, StallClass::AdapterFreeze => 2, StallClass::CompositorBlocked => 3, - StallClass::FrameGeneration => 4, - StallClass::Unattributed => 5, + StallClass::ContentSilence => 4, + StallClass::FrameGeneration => 5, + StallClass::Unattributed => 6, }] += 1; // debug (not warn): a single hole also happens when content legitimately pauses; // the reportable signal is the metronomic cycle below. Mounjay-class triage runs @@ -331,6 +388,11 @@ impl StallWatch { class = %class, probes = evidence.probes.as_ref().map(tracing::field::display), etw = evidence.etw.as_deref().unwrap_or("unavailable"), + // The discriminator's numeric read (also embedded in `etw` as prose): swapchain + // presents from ANY process vs frames entering the virtual display's kernel queue, + // inside the gap window. presents≥bar with adds≈0 = FRAME-GENERATION conviction. + etw_presents = evidence.etw_counts.map(|c| c.presents), + etw_queue_adds = evidence.etw_counts.map(|c| c.queue_adds), offered_during_gap = evidence.offered_delta, max_heartbeat_age_ms = evidence.max_heartbeat_age_ms, "IDD-push capture stall — the desktop was composing at speed, then the ring \ @@ -351,13 +413,14 @@ impl StallWatch { ); let class_tally = format!( "ours-worker {}, ours-delivery {}, adapter-freeze {}, compositor-blocked {}, \ - frame-generation {}, unattributed {}", + content-silence {}, frame-generation {}, unattributed {}", self.classes[0], self.classes[1], self.classes[2], self.classes[3], self.classes[4], - self.classes[5] + self.classes[5], + self.classes[6] ); // Half-or-more of the stalls carrying a coinciding OS event = the reaction // cascade is OS-visible; otherwise the disturbance never surfaces above the