feat(capture/windows): stall lines say whether the content or the display path went silent

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 <noreply@anthropic.com>
This commit is contained in:
2026-07-30 23:35:28 +02:00
co-authored by Claude Fable 5
parent f87c1e6cec
commit cd6ceb98e3
4 changed files with 453 additions and 95 deletions
+91 -15
View File
@@ -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<u64>, dwm: Option<u64>, flush: Option<u64>| 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
);
}
}
@@ -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<VecDeque<(i64, u16)>> = 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 ≈ 1560 s at a
/// 90240 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<VecDeque<(i64, u16, u32)>> = 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(&params),
)
};
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::<Vec<_>>()
.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(&params),
)
};
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<String> {
// 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).
@@ -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::<DWM_TIMING_INFO>() 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));
}
+82 -19
View File
@@ -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<String>,
/// 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<super::dxgkrnl_etw::EtwWindowCounts>,
}
/// 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<u64>,
/// Longest span (µs) with no `DwmGetCompositionTimingInfo` `cRefresh` advance.
pub(super) dwm_tick_frozen_us: Option<u64>,
/// 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<u64>,
/// Worst watchdogged `DwmFlush` latency (µs).
pub(super) dwm_flush_max_us: Option<u64>,
/// 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