chore(border): say what the border manager is stuck on

A recording had the thread that handles border notifications stop answering
after it put a border in place, while the channel it reads from filled up and
every animation that landed after that waited for its full two seconds.
Nothing said where it was.

Say what step the thread is in, warn once when it has been in one for two
seconds, say when a border has been put in place, and name the animations that
did not land, with what each of them was doing.

komorebi/src/animation/engine.rs

@@ -209,19 +209,23 @@ impl AnimationEngine {
 
         let (landed_tx, landed_rx) = std::sync::mpsc::channel();
         let count = animations.len();
+        let keys: Vec<String> = animations.iter().map(|(key, _)| key.clone()).collect();
 
         for (key, animation) in animations {
             let landed_tx = landed_tx.clone();
 
             std::thread::spawn(move || {
+                tracing::trace!("landing {key}: drawing the last frame");
                 // limit progress to 1.0 if animation took longer, and process
                 // the animation for 1.0 to set the target position
                 animation.dispatcher.render(1.0).ok();
 
+                tracing::trace!("landing {key}: finishing");
                 if let Err(error) = animation.dispatcher.post_render() {
                     tracing::warn!("animation {key} could not be completed: {error}");
                 }
 
+                tracing::trace!("landing {key}: landed");
                 let _ = landed_tx.send(key);
             });
         }
@@ -230,19 +234,24 @@ impl AnimationEngine {
 
         let deadline = Instant::now() + LANDING_DEADLINE;
         let mut landed = 0;
+        let mut not_landed = keys;
 
         while landed < count {
             match landed_rx.recv_timeout(deadline.saturating_duration_since(Instant::now())) {
-                Ok(_) => landed += 1,
+                Ok(key) => {
+                    landed += 1;
+                    not_landed.retain(|not_landed| *not_landed != key);
+                }
                 Err(_) => break,
             }
         }
 
         if landed < count {
             tracing::warn!(
-                "{} of {count} animations did not land in {} ms; they are left to land on their own",
+                "{} of {count} animations did not land in {} ms; they are left to land on their own: {}",
                 count - landed,
-                LANDING_DEADLINE.as_millis()
+                LANDING_DEADLINE.as_millis(),
+                not_landed.join(", ")
             );
         }
     }

komorebi/src/animation/ghost_dispatcher.rs

@@ -610,19 +610,24 @@ impl RenderDispatcher for GhostDispatcher {
         // over it, and then faded out of the way a little more quickly than
         // it otherwise would be.
         if self.reveals() && !self.revealed.load(Ordering::SeqCst) {
+            tracing::trace!("landing hwnd {}: revealing it", self.hwnd);
             self.reveal(1.0);
+            tracing::trace!("landing hwnd {}: fading its ghost out", self.hwnd);
             ghost.fade_out(self.target_rect, self.clip());
         }
 
         // a window that was laid out after it was shown is done being by now, or is
         // waited for, so that nothing is left running when the animation is over
         if matches!(self.mode, Mode::SlideIn { .. }) {
+            tracing::trace!("landing hwnd {}: waiting for its layout", self.hwnd);
             let _ = self.finish_resize();
         }
 
+        tracing::trace!("landing hwnd {}: disposing of its ghost", self.hwnd);
         border_manager::set_ghosted(self.hwnd, false);
         let _ = ghost.dispose();
 
+        tracing::trace!("landing hwnd {}: finalising", self.hwnd);
         self.finalise_managers();
 
         Ok(())

komorebi/src/border_manager/border.rs

@@ -481,6 +481,7 @@ impl Border {
             self.hwnd
         );
         WindowsApi::set_border_pos(self.hwnd, &rect, reference_hwnd, show)?;
+        tracing::trace!("border {}: put in place", self.hwnd);
 
         Ok(())
     }

komorebi/src/border_manager/mod.rs

@@ -330,7 +330,57 @@ fn window_kind_colour(focus_kind: WindowKind) -> u32 {
     }
 }
 
+lazy_static! {
+    /// What the thread that handles notifications is doing, and since when
+    static ref STEP: Mutex<(&'static str, std::time::Instant)> =
+        Mutex::new(("waiting", std::time::Instant::now()));
+}
+
+/// Say what the thread that handles notifications is doing, for the watchdog to say when it has
+/// been doing it for too long, and for the log to say what it was when it stopped
+fn step(name: &'static str) {
+    tracing::trace!("border manager: {name}");
+    *STEP.lock() = (name, std::time::Instant::now());
+}
+
+/// Says that the thread that handles notifications is waiting for one, when it goes out of scope
+struct Waiting;
+
+impl Drop for Waiting {
+    fn drop(&mut self) {
+        step("waiting");
+    }
+}
+
+/// Warn about the thread that handles notifications, once, when it has not got past one step in
+/// two seconds. It is not heard from again after that when it is stuck, and the notifications
+/// pile up until they are dropped.
+fn watch_steps() {
+    std::thread::spawn(|| {
+        let mut warned: Option<std::time::Instant> = None;
+
+        loop {
+            std::thread::sleep(std::time::Duration::from_secs(1));
+
+            let (name, since) = *STEP.lock();
+
+            if name != "waiting"
+                && since.elapsed() >= std::time::Duration::from_secs(2)
+                && warned != Some(since)
+            {
+                tracing::warn!(
+                    "border manager: stuck for {} ms in `{name}`",
+                    since.elapsed().as_millis()
+                );
+                warned = Some(since);
+            }
+        }
+    });
+}
+
 pub fn listen_for_notifications(wm: Arc<Mutex<WindowManager>>) {
+    watch_steps();
+
     std::thread::spawn(move || {
         loop {
             match handle_notifications(wm.clone()) {
@@ -358,6 +408,9 @@ pub fn handle_notifications(wm: Arc<Mutex<WindowManager>>) -> color_eyre::Result
     let mut previous_layer = WorkspaceLayer::default();
 
     'receiver: for notification in receiver {
+        step("locking the window manager");
+        // however this pass ends, `continue` included, the thread is waiting for the next
+        let _waiting = Waiting;
         // Check the wm state every time we receive a notification
         let state = wm.lock();
         let is_paused = state.is_paused;
@@ -524,8 +577,10 @@ pub fn handle_notifications(wm: Arc<Mutex<WindowManager>>) -> color_eyre::Result
                     continue 'receiver;
                 }
 
+                step("locking the borders");
                 let mut borders = BORDER_STATE.lock();
                 let mut windows_borders = WINDOWS_BORDERS.lock();
+                step("handling the notification");
 
                 // If borders are disabled
                 if !BORDER_ENABLED.load_consume()
@@ -733,6 +788,7 @@ pub fn handle_notifications(wm: Arc<Mutex<WindowManager>>) -> color_eyre::Result
                             let border = match borders.entry(id.clone()) {
                                 Entry::Occupied(entry) => entry.into_mut(),
                                 Entry::Vacant(entry) => {
+                                    step("creating a border");
                                     if let Ok(border) =
                                         Border::create(&c.id, focused_window_hwnd, monitor_idx)
                                     {
@@ -822,13 +878,17 @@ pub fn handle_notifications(wm: Arc<Mutex<WindowManager>>) -> color_eyre::Result
                                     // thread mid-render holding a reference to it.
                                     border.request_brush_update();
                                 }
+                                step("putting a border in place");
                                 border.set_position(&rect, focused_window_hwnd)?;
+                                step("invalidating a border");
                                 border.invalidate();
+                                step("handling the notification");
                             }
 
                             windows_borders.insert(focused_window_hwnd, id);
                         }
 
+                        step("handling floating borders");
                         handle_floating_borders(
                             &mut borders,
                             &mut windows_borders,