diff --git a/packaging/windows/drivers/pf-vdisplay/src/callbacks.rs b/packaging/windows/drivers/pf-vdisplay/src/callbacks.rs index a3e245390..b69e8a656 100644 --- a/packaging/windows/drivers/pf-vdisplay/src/callbacks.rs +++ b/packaging/windows/drivers/pf-vdisplay/src/callbacks.rs @@ -253,19 +253,67 @@ pub unsafe extern "C" fn monitor_query_modes2( STATUS_SUCCESS } -/// Diagnostic only — assign drives everything. STEP 4 logs the committed paths. +/// Read an `IDDCX_PATH*`'s `Flags` field as its underlying `u32`, without depending on the bindgen +/// enum shape (newtype vs constified int): the field is a 4-byte `#[repr]` over `u32` either way, so +/// a byte-read of it is the flag bits. `IDDCX_PATH_FLAGS_CHANGED = 0x1`, `_ACTIVE = 0x2` (IddCx.h). +/// +/// # Safety +/// `flags` must point at a live `IDDCX_PATH{,2}::Flags` field (4 readable bytes). +unsafe fn path_flag_bits(flags: &T) -> u32 { + // SAFETY: the caller passes a live `Flags` field; every IDDCX_PATH_FLAGS binding is a 4-byte + // scalar over u32, so reading it as u32 yields the flag bits regardless of the wrapper shape. + unsafe { core::ptr::read((flags as *const T).cast::()) } +} + +/// Commit is a no-op for assign to drive — but the OS stamps each path ACTIVE/CHANGED here, and an +/// active→inactive flip on OUR head (while a sibling stays active) is the driver-visible form of +/// Enrico's hypothesis: the OS idles the virtual head like a physical one and the drain loop then +/// sees only E_PENDING with no unassign. Log every commit's per-path flags so a hole can be lined +/// up against a path the OS just deactivated. Low frequency (topology changes only). pub unsafe extern "C" fn adapter_commit_modes( _adapter: iddcx::IDDCX_ADAPTER, - _p_in: *const iddcx::IDARG_IN_COMMITMODES, + p_in: *const iddcx::IDARG_IN_COMMITMODES, ) -> NTSTATUS { + // SAFETY: the framework supplies a valid, live input-args pointer for the call. + let in_args = unsafe { &*p_in }; + let count = in_args.PathCount; + for i in 0..count as usize { + // SAFETY: `pPaths` points to `PathCount` valid `IDDCX_PATH` entries (framework contract). + let path = unsafe { &*in_args.pPaths.add(i) }; + // SAFETY: `path.Flags` is a live IDDCX_PATH_FLAGS field on the framework's path array. + let bits = unsafe { path_flag_bits(&path.Flags) }; + dbglog!( + "[pf-vd] commit_modes: path[{i}/{count}] monitor={:?} active={} changed={} flags={bits:#x}", + path.MonitorObject, + bits & 0x2 != 0, + bits & 0x1 != 0 + ); + } STATUS_SUCCESS } -/// HDR (`*2`) commit over `IDDCX_PATH2`. Mandatory under FP16. +/// HDR (`*2`) commit over `IDDCX_PATH2`. Mandatory under FP16, and the one the OS actually calls +/// once `CAN_PROCESS_FP16` is set — so this is where the ACTIVE/CHANGED flags land in practice. +/// Same per-path logging as [`adapter_commit_modes`] (see its doc for why the flip matters). pub unsafe extern "C" fn adapter_commit_modes2( _adapter: iddcx::IDDCX_ADAPTER, - _p_in: *const iddcx::IDARG_IN_COMMITMODES2, + p_in: *const iddcx::IDARG_IN_COMMITMODES2, ) -> NTSTATUS { + // SAFETY: the framework supplies a valid, live input-args pointer for the call. + let in_args = unsafe { &*p_in }; + let count = in_args.PathCount; + for i in 0..count as usize { + // SAFETY: `pPaths` points to `PathCount` valid `IDDCX_PATH2` entries (framework contract). + let path = unsafe { &*in_args.pPaths.add(i) }; + // SAFETY: `path.Flags` is a live IDDCX_PATH_FLAGS field on the framework's path array. + let bits = unsafe { path_flag_bits(&path.Flags) }; + dbglog!( + "[pf-vd] commit_modes2: path[{i}/{count}] monitor={:?} active={} changed={} flags={bits:#x}", + path.MonitorObject, + bits & 0x2 != 0, + bits & 0x1 != 0 + ); + } STATUS_SUCCESS } diff --git a/packaging/windows/drivers/pf-vdisplay/src/swap_chain_processor.rs b/packaging/windows/drivers/pf-vdisplay/src/swap_chain_processor.rs index c64222a62..65d8ab2b7 100644 --- a/packaging/windows/drivers/pf-vdisplay/src/swap_chain_processor.rs +++ b/packaging/windows/drivers/pf-vdisplay/src/swap_chain_processor.rs @@ -44,7 +44,7 @@ use windows::{ Direct3D11::{D3D11_TEXTURE2D_DESC, ID3D11Texture2D}, Dxgi::{IDXGIDevice, IDXGIResource}, }, - System::Performance::QueryPerformanceCounter, + System::Performance::{QueryPerformanceCounter, QueryPerformanceFrequency}, System::Threading::{ AvRevertMmThreadCharacteristics, AvSetMmThreadCharacteristicsW, GetCurrentThread, SetThreadPriority, THREAD_PRIORITY_TIME_CRITICAL, WaitForSingleObject, @@ -202,6 +202,26 @@ fn qpc() -> u64 { } } +/// QPC ticks → whole milliseconds. Signed: a frame's display time can sit AFTER our acquire. +fn qpc_ms(ticks: i64) -> i64 { + use std::sync::OnceLock; + static FREQ: OnceLock = OnceLock::new(); + let f = *FREQ.get_or_init(|| { + let mut f = 0i64; + // SAFETY: out-pointer to a valid local; the frequency is fixed at boot. + let _ = unsafe { QueryPerformanceFrequency(&mut f) }; + f.max(1) + }); + ticks.saturating_mul(1000) / f +} + +/// Wall-clock milliseconds since the Unix epoch — lines a driver-log witness up with host.log. +fn unix_ms() -> u128 { + std::time::SystemTime::now() + .duration_since(std::time::UNIX_EPOCH) + .map_or(0, |d| d.as_millis()) +} + /// A minimal newtype to move a raw pointer / handle across the thread boundary. The wrapped value is a /// raw IddCx swap-chain handle or an event HANDLE (both raw pointers, framework-managed) — sending them /// to the worker is sound because only this thread touches them and the framework synchronises lifetime. @@ -475,6 +495,11 @@ impl SwapChainProcessor { // First `IddCxSwapChainReportFrameStatistics` outcome, logged once (the rest of the // session reports silently) so a field log answers "did the stats path engage". let mut logged_stats = false; + // Frame witness (see the success branch): the previous acquire's OS frame number and + // wall time, plus the last late-frame line's time (its throttle). + let mut last_pfn: u32 = 0; + let mut last_frame_at: Option = None; + let mut last_late_log: Option = None; // The frame-channel delivery gate (see `monitor::frame_channel_gen`): the loop only takes // the monitors mutex when a delivery LANDED since it last looked. Seeded one behind the // current generation so a delivery that arrived before this worker started (host delivered @@ -621,6 +646,35 @@ impl SwapChainProcessor { break; } else if hr_success(hr) { let acquire_qpc = qpc(); + // Frame witness: the two stamps the OS puts on every frame (`IDDCX_METADATA2`), + // which split a FRAME-GENERATION hole from inside the swap-chain. Logged when a + // frame ends >= 1 s of silence, or arrives >= 250 ms after its display time (at + // most one line per 2 s). Read the line as: a PresentationFrameNumber JUMP = DWM + // composed frames this swap-chain never received; +1 with a large `late` = the + // frames were composed on time and delivered late; +1 and fresh = DWM composed + // nothing for this head. `dirty=1` on a static desktop is the OS's no-update repeat. + let pfn = buffer.MetaData.PresentationFrameNumber; + let display_qpc = buffer.MetaData.PresentDisplayQPCTime; + #[allow(clippy::cast_possible_wrap)] + let late_ms = + (display_qpc != 0).then(|| qpc_ms(acquire_qpc as i64 - display_qpc as i64)); + let silence = last_frame_at.map_or(Duration::ZERO, |t| t.elapsed()); + if silence >= Duration::from_secs(1) + || (late_ms.is_some_and(|l| l >= 250) + && last_late_log.is_none_or(|t| t.elapsed() >= Duration::from_secs(2))) + { + dbglog!( + "[pf-vd] frame-witness (target={target_id}) t={} silence={}ms pfn={pfn} (+{}) late={} dirty={}", + unix_ms(), + silence.as_millis(), + pfn.wrapping_sub(last_pfn), + late_ms.map_or("n/a".to_string(), |l| format!("{l}ms")), + buffer.MetaData.DirtyRectCount + ); + last_late_log = Some(Instant::now()); + } + last_pfn = pfn; + last_frame_at = Some(Instant::now()); if !logged_frame { dbglog!( "[pf-vd] swap-chain run_core: FIRST FRAME acquired (target={target_id}) — DWM IS compositing the virtual display!"