chore(animation): trace what ghosts and animation frames cost

Time the picture a ghost takes of its window (allocating, PrintWindow and
turning it into a picture), the render a window is asked for to lay itself
out (paint_now), how long a ghost takes to make, and what the frames of a
group of animations cost: how long drawing them takes, how far apart they
come and how many are late. All at trace level, the frame statistics at
debug.

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<Instant> = 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<Duration>, 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<dyn RenderDispatcher + Send>,
     duration: Duration,

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<Self> {
+        let start = std::time::Instant::now();
         let snapshot = Snapshot::capture(src_hwnd)?;
+        let captured = start.elapsed();
 
         let (reply_tx, reply_rx) = bounded::<eyre::Result<(isize, (i32, i32))>>(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,

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
             })();