git.lucas.co / cce-compositor
Wayland compositor (wlroots)
git clone https://git.lucas.co/cce-compositor.git

commita6abc7d72b598d70055f1d7427d2d20e0c9d9b28
parent0f0348fc65
authorLucas Galante <[email protected]>
date2026-08-12 23:33
debug: time each stage of handle_motion under CCE_FRAME_DEBUG

Real libinput motion collapsed hover feedback to ~3 rebuilds/s while an
injected warp at the same 60/s event rate sustained 27/s, so the input handler
was the obvious suspect. It is not: total p50 is 10us (cursor_move 3us,
update_hovered 0us, drag_icons 0us, passthrough 7us), and across nine seconds
of continuous motion the handler consumed 7ms — 0.08% of the thread.

Keeping the instrumentation because it also corrected a misattribution: the
"output frame rate collapses 58->3fps during motion" reading was the idle floor
in the seconds before the sweep, inferred from client timestamps rather than
from the compositor's own record of input events. Correlating compositor-logged
motion against output frames shows 58 motion/s -> 40 frames/s; the compositor
is healthy while the pointer moves.

The remaining latency is client-side: arm -> compositor fires is p50 16ms, but
compositor fires -> client sees is p50 0ms with a 493ms tail, and a callback
fired at t=62818 was processed by the client at t=62909, after six motion
events generated later.

Co-Authored-By: Claude Opus 5 <[email protected]>

 src/server/cursor.rs | 28 ++++++++++++++++++++++++++++
 src/server/output.rs |  2 +-
 2 files changed, 29 insertions(+), 1 deletion(-)

diff --git a/src/server/cursor.rs b/src/server/cursor.rs
index 9323724..44edd6a 100644
--- a/src/server/cursor.rs
+++ b/src/server/cursor.rs
@@ -727,19 +727,47 @@ unsafe extern "C" fn handle_motion(listener: *mut ffi::wl_listener, data: *mut s
         (*cursor.constraint).confine(&mut dx, &mut dy);
     }
 
+    // Real libinput motion collapses the compositor to ~3fps, while an injected
+    // warp at the SAME event rate sustains ~58fps — so the cost is somewhere in
+    // this handler rather than in rendering or the scene. Time each stage.
+    let t_start = if crate::output::frame_debug() {
+        Some(std::time::Instant::now())
+    } else {
+        None
+    };
+
     ffi::wlr_cursor_move(cursor.wlr_cursor, std::ptr::null_mut(), dx, dy);
+    let t_move = t_start.map(|s| s.elapsed().as_micros());
     cursor.update_hovered();
+    let t_hovered = t_start.map(|s| s.elapsed().as_micros());
     cursor.update_drag_icons();
+    let t_drag = t_start.map(|s| s.elapsed().as_micros());
 
     let seat = &mut *cursor.seat;
     if (*seat).op.is_some() {
         let lx = (*cursor.wlr_cursor).x as i32;
         let ly = (*cursor.wlr_cursor).y as i32;
         (*seat).op_update(lx, ly);
+        if let (Some(s), Some(m), Some(h), Some(d)) = (t_start, t_move, t_hovered, t_drag) {
+            log::info!(
+                "[cce-frame] t={} motion(op) total={}us move={}us hovered={}us drag={}us",
+                crate::util::msec_timestamp() % 100000,
+                s.elapsed().as_micros(), m, h - m, d - h
+            );
+        }
         return;
     }
 
     cursor.passthrough((*event).time_msec);
+
+    if let (Some(s), Some(m), Some(h), Some(d)) = (t_start, t_move, t_hovered, t_drag) {
+        let total = s.elapsed().as_micros();
+        log::info!(
+            "[cce-frame] t={} motion total={}us move={}us hovered={}us drag={}us passthrough={}us",
+            crate::util::msec_timestamp() % 100000,
+            total, m, h - m, d - h, total - d
+        );
+    }
 }
 
 unsafe extern "C" fn handle_motion_absolute(listener: *mut ffi::wl_listener, data: *mut std::ffi::c_void) {
diff --git a/src/server/output.rs b/src/server/output.rs
index 2f66ebb..ef62046 100644
--- a/src/server/output.rs
+++ b/src/server/output.rs
@@ -901,7 +901,7 @@ unsafe extern "C" fn handle_request_state(listener: *mut ffi::wl_listener, data:
 /// frame-callback interval can be compared against the rate the output is
 /// actually rendering at — the two diverging is the signature of a surface
 /// being skipped by the scene's visible gate in `wlr_scene_buffer_send_frame_done`.
-fn frame_debug() -> bool {
+pub(crate) fn frame_debug() -> bool {
     static FLAG: std::sync::OnceLock<bool> = std::sync::OnceLock::new();
     *FLAG.get_or_init(|| std::env::var_os("CCE_FRAME_DEBUG").is_some())
 }