diff --git a/komorebi/src/animation/engine.rs b/komorebi/src/animation/engine.rs index ddce2093..98093c74 100644 --- a/komorebi/src/animation/engine.rs +++ b/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 = 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(", ") ); } } diff --git a/komorebi/src/animation/ghost_dispatcher.rs b/komorebi/src/animation/ghost_dispatcher.rs index 5e5c035a..e91a1639 100644 --- a/komorebi/src/animation/ghost_dispatcher.rs +++ b/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(()) diff --git a/komorebi/src/border_manager/border.rs b/komorebi/src/border_manager/border.rs index ff3809ec..193ef9eb 100644 --- a/komorebi/src/border_manager/border.rs +++ b/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(()) } diff --git a/komorebi/src/border_manager/mod.rs b/komorebi/src/border_manager/mod.rs index 64e7f732..7e757d99 100644 --- a/komorebi/src/border_manager/mod.rs +++ b/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 = 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>) { + watch_steps(); + std::thread::spawn(move || { loop { match handle_notifications(wm.clone()) { @@ -358,6 +408,9 @@ pub fn handle_notifications(wm: Arc>) -> 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>) -> 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>) -> 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>) -> 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,