diff --git a/komorebi/src/animation/engine.rs b/komorebi/src/animation/engine.rs index a25c35f7..73dbc11e 100644 --- a/komorebi/src/animation/engine.rs +++ b/komorebi/src/animation/engine.rs @@ -138,6 +138,9 @@ impl AnimationEngine { Duration::from_millis(1000 / ANIMATION_FPS.load(Ordering::Relaxed)); let animation_start = Instant::now(); + let mut stats = FrameStats::default(); + let mut previous_frame_start: Option = None; + while !pending.is_empty() { // check if any animation is cancelled pending.retain(|(key, animation)| { @@ -152,6 +155,8 @@ impl AnimationEngine { let frame_start = Instant::now(); let elapsed = animation_start.elapsed().as_millis() as f64; + let interval = previous_frame_start.map(|previous| frame_start - previous); + previous_frame_start = Some(frame_start); let mut finished = Vec::new(); let mut remaining = Vec::with_capacity(pending.len()); @@ -166,6 +171,8 @@ impl AnimationEngine { } pending = remaining; + stats.add(frame_start.elapsed(), interval, target_frame_time); + Self::finish(finished); // wait for the frame to be presented @@ -184,6 +191,8 @@ impl AnimationEngine { std::thread::sleep(target_frame_time - frame_time_elapsed); } } + + tracing::debug!("animations: {stats}"); }); } @@ -211,6 +220,61 @@ impl AnimationEngine { } } +/// What the frames of a group of animations cost, to see whether they keep up +#[derive(Default)] +struct FrameStats { + frames: u32, + work: Duration, + longest_work: Duration, + intervals: u32, + interval: Duration, + longest_interval: Duration, + late: u32, + target: Duration, +} + +impl FrameStats { + /// `work` is what drawing the frame took, `interval` the time from the + /// start of the frame before it + fn add(&mut self, work: Duration, interval: Option, target: Duration) { + self.frames += 1; + self.work += work; + self.longest_work = self.longest_work.max(work); + self.target = target; + + if let Some(interval) = interval { + self.intervals += 1; + self.interval += interval; + self.longest_interval = self.longest_interval.max(interval); + + if interval > target + target / 2 { + self.late += 1; + } + } + } +} + +impl std::fmt::Display for FrameStats { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + let ms = |duration: Duration| duration.as_secs_f64() * 1000.0; + let average = |total: Duration, count: u32| ms(total) / f64::from(count.max(1)); + + write!( + f, + "{} frames, drawing took {:.2} ms on average and {:.2} ms at most, frames came \ + every {:.2} ms on average and {:.2} ms at most, {} of them more than half as \ + late again as the {:.0} ms they are meant to take", + self.frames, + average(self.work, self.frames), + ms(self.longest_work), + average(self.interval, self.intervals), + ms(self.longest_interval), + self.late, + ms(self.target), + ) + } +} + struct Animation { dispatcher: Box, duration: Duration, diff --git a/komorebi/src/animation/ghost.rs b/komorebi/src/animation/ghost.rs index c054c8ff..94f91ffe 100644 --- a/komorebi/src/animation/ghost.rs +++ b/komorebi/src/animation/ghost.rs @@ -476,7 +476,9 @@ impl GhostWindow { /// Take a picture of the window and show it where the window is. The /// picture is taken before the window is touched. pub fn create(src_hwnd: isize, start_rect: Rect) -> eyre::Result { + let start = std::time::Instant::now(); let snapshot = Snapshot::capture(src_hwnd)?; + let captured = start.elapsed(); let (reply_tx, reply_rx) = bounded::>(1); ghost_owner() @@ -489,6 +491,12 @@ impl GhostWindow { .map_err(|e| eyre::eyre!("ghost owner channel send failed: {e}"))?; let (hthumb, origin) = reply_rx.recv()??; + tracing::trace!( + "ghost: created for hwnd {src_hwnd} in {:.1} ms ({:.1} ms of it the picture)", + start.elapsed().as_secs_f64() * 1000.0, + captured.as_secs_f64() * 1000.0, + ); + Ok(Self { hthumb, origin, diff --git a/komorebi/src/animation/snapshot.rs b/komorebi/src/animation/snapshot.rs index 0876cfb4..41af5ec4 100644 --- a/komorebi/src/animation/snapshot.rs +++ b/komorebi/src/animation/snapshot.rs @@ -168,7 +168,12 @@ fn round_corners(pixels: &mut [u32], width: i32, height: i32, radius: i32) { /// way to have a window that has just been resized lay itself out at its new /// size, without waiting for it to get round to it. pub fn paint_now(hwnd: isize) { + let start = std::time::Instant::now(); let _ = Snapshot::capture(hwnd); + tracing::trace!( + "snapshot: hwnd {hwnd} painted itself in {:.1} ms", + start.elapsed().as_secs_f64() * 1000.0 + ); } impl Snapshot { @@ -194,15 +199,19 @@ impl Snapshot { eyre::bail!("hwnd {hwnd} has no visible area to take a picture of"); } + let start = std::time::Instant::now(); + unsafe { let screen = GetDC(None); let dc = CreateCompatibleDC(Some(screen)); let result = (|| { let (full, full_pixels) = create_dib(dc, window_width, window_height)?; + let allocated = start.elapsed(); let previous = SelectObject(dc, full.into()); let printed = PrintWindow(handle, dc, PRINT_WINDOW_FLAGS(PW_RENDERFULLCONTENT)); SelectObject(dc, previous); + let rendered = start.elapsed(); let result = if printed.as_bool() { create_dib(dc, width, height).map(|(bitmap, pixels)| { @@ -219,6 +228,15 @@ impl Snapshot { }; let _ = DeleteObject(full.into()); + + tracing::trace!( + "snapshot: hwnd {hwnd} {window_width}x{window_height}: allocate {:.1} ms, \ + PrintWindow {:.1} ms, picture {:.1} ms", + allocated.as_secs_f64() * 1000.0, + (rendered - allocated).as_secs_f64() * 1000.0, + (start.elapsed() - rendered).as_secs_f64() * 1000.0, + ); + result })();