perf+debug: gate the per-frame blur traces, add CCE_FRAME_DEBUG

The add_blur / add_optimized_blur wlr_log calls were ungated WLR_INFO in the
per-node, per-frame render path: ~600 synchronous formatted writes/second at
60Hz on the same thread that composites and delivers frame callbacks. Both now
sit behind CCE_BLUR_DEBUG. Note for future readers: `optimized: N` on add_blur
is the flag saying that node SAMPLES the cached buffer — it is not a re-bake.
The bake is add_optimized_blur, and a healthy session bakes only at startup
(~357 times, all in the first two minutes).

CCE_FRAME_DEBUG traces frame-callback delivery: per output frame, whether each
scene buffer passed the visible gate in wlr_scene_buffer_send_frame_done, plus
an output-frame tick carrying the render_and_commit duration. Accepts WxH to
match one window, a bare W to match on width only, or any other value to trace
every buffer — the filtered form is what to use while measuring, since tracing
all buffers adds writes to the very thread whose latency is under test. Time
base is epoch ms mod 100000, matching cce-ui's CCE_PRESENT_DEBUG and
cce-system-interface's CCE_HOVER_DEBUG so the three logs interleave.

First results: the visible gate is exonerated (zero sent=0 in a full session;
emits run 1:1 with output frames at 58/s) and render_and_commit is ~2.2ms p50,
while the client still receives callbacks only ~10-20/s during hover.

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

 scenefx/render/fx_renderer/fx_pass.c | 33 ++++++++++++++++++----
 scenefx/types/scene/wlr_scene.c      | 55 +++++++++++++++++++++++++++++++++++-
 src/server/output.rs                 | 28 ++++++++++++++++++
 3 files changed, 109 insertions(+), 7 deletions(-)

diff --git a/scenefx/render/fx_renderer/fx_pass.c b/scenefx/render/fx_renderer/fx_pass.c
index 115b751..38eefad 100644
--- a/scenefx/render/fx_renderer/fx_pass.c
+++ b/scenefx/render/fx_renderer/fx_pass.c
@@ -19,10 +19,24 @@
 #include "scenefx/render/fx_renderer/fx_offscreen_buffers.h"
 #include "scenefx/render/fx_renderer/fx_renderer.h"
 #include "scenefx/types/fx/blur_data.h"
+#include "util/env.h"
 #include "util/matrix.h"
 
 #define MAX_QUADS 86 // 4kb
 
+// The blur traces below sit in the per-node, per-frame render path: at ~10 blur
+// nodes and 60Hz that is ~600 synchronous formatted writes/second on the same
+// thread that composites and delivers frame callbacks. Gate them.
+static bool cce_blur_debug(void) {
+	static bool initialized = false;
+	static bool enabled = false;
+	if (!initialized) {
+		enabled = env_parse_bool("CCE_BLUR_DEBUG");
+		initialized = true;
+	}
+	return enabled;
+}
+
 struct fx_render_texture_options fx_render_texture_options_default(
 		const struct wlr_render_texture_options *base) {
 	struct fx_render_texture_options options = {
@@ -1115,10 +1129,14 @@ void fx_render_pass_add_blur(struct fx_gles_render_pass *pass,
 	TRACY_BOTH_ZONES_START(renderer);
 	push_fx_debug(renderer);
 
-	wlr_log(WLR_INFO, "[scenefx] add_blur dst_box: %dx%d at (%d, %d), optimized: %d strength: %f",
-			tex_options->base.dst_box.width, tex_options->base.dst_box.height,
-			tex_options->base.dst_box.x, tex_options->base.dst_box.y,
-			fx_options->use_optimized_blur, fx_options->blur_strength);
+	// NOTE: `optimized` here is the flag saying this node SAMPLES the cached
+	// buffer — it is not a re-bake. The bake is add_optimized_blur, below.
+	if (cce_blur_debug()) {
+		wlr_log(WLR_INFO, "[scenefx] add_blur dst_box: %dx%d at (%d, %d), optimized: %d strength: %f",
+				tex_options->base.dst_box.width, tex_options->base.dst_box.height,
+				tex_options->base.dst_box.x, tex_options->base.dst_box.y,
+				fx_options->use_optimized_blur, fx_options->blur_strength);
+	}
 
 	const bool has_strength = fx_options->blur_strength < 1.0;
 	struct fx_framebuffer *buffer = pass->fx_offscreen_buffers->optimized_blur_buffer;
@@ -1224,8 +1242,11 @@ bool fx_render_pass_add_optimized_blur(struct fx_gles_render_pass *pass,
 	TRACY_ZONE_TEXT_f("\tSaturation: %f", fx_options->blur_data->saturation);
 	push_fx_debug(renderer);
 
-	wlr_log(WLR_INFO, "[scenefx] add_optimized_blur dst_box: %dx%d at (%d, %d)",
-			dst_box.width, dst_box.height, dst_box.x, dst_box.y);
+	// The actual cache re-bake (rare: a healthy session bakes only at startup).
+	if (cce_blur_debug()) {
+		wlr_log(WLR_INFO, "[scenefx] add_optimized_blur dst_box: %dx%d at (%d, %d)",
+				dst_box.width, dst_box.height, dst_box.x, dst_box.y);
+	}
 
 	pixman_region32_t clip;
 	pixman_region32_init_rect(&clip,
diff --git a/scenefx/types/scene/wlr_scene.c b/scenefx/types/scene/wlr_scene.c
index fc0f487..aa83cc6 100644
--- a/scenefx/types/scene/wlr_scene.c
+++ b/scenefx/types/scene/wlr_scene.c
@@ -1,8 +1,10 @@
 #include <assert.h>
 #include <pixman.h>
+#include <stdint.h>
 #include <stdio.h>
 #include <stdlib.h>
 #include <string.h>
+#include <time.h>
 #include <wlr/backend.h>
 #include <wlr/render/swapchain.h>
 #include <wlr/render/drm_syncobj.h>
@@ -1661,9 +1663,60 @@ void wlr_scene_buffer_set_transform(struct wlr_scene_buffer *scene_buffer,
 	scene_node_update(&scene_buffer->node, NULL);
 }
 
+// Frame-callback delivery tracer. A demand-driven client cannot repaint while
+// it waits on a frame callback, so a surface silently skipped by the visible
+// gate below stalls until the next output frame that does reach it. Set
+// CCE_FRAME_DEBUG=1 to trace every buffer, or CCE_FRAME_DEBUG=WxH (the dst
+// size, e.g. 504x1032) to trace one window — the filtered form is what to use
+// while measuring, since tracing every buffer adds writes to the very thread
+// whose latency is under test.
+static bool cce_frame_debug_match(int dst_width, int dst_height) {
+	static bool initialized = false;
+	static bool enabled = false;
+	static int want_w = -1, want_h = -1;
+	if (!initialized) {
+		const char *value = getenv("CCE_FRAME_DEBUG");
+		if (value && *value) {
+			enabled = true;
+			// "WxH" matches one size exactly; a bare "W" matches on width only
+			// (a window's height can change under it); anything else traces all.
+			int parsed = sscanf(value, "%dx%d", &want_w, &want_h);
+			if (parsed == 1) {
+				want_h = -1;
+			} else if (parsed != 2) {
+				want_w = want_h = -1;
+			}
+		}
+		initialized = true;
+	}
+	if (!enabled) {
+		return false;
+	}
+	if (want_w < 0) {
+		return true;
+	}
+	return dst_width == want_w && (want_h < 0 || dst_height == want_h);
+}
+
+// Same time base as cce-ui's CCE_PRESENT_DEBUG and cce-system-interface's
+// CCE_HOVER_DEBUG (epoch ms mod 100000) so the three logs interleave directly.
+static int64_t cce_now_ms(void) {
+	struct timespec ts;
+	clock_gettime(CLOCK_REALTIME, &ts);
+	return ((int64_t)ts.tv_sec * 1000 + ts.tv_nsec / 1000000) % 100000;
+}
+
 void wlr_scene_buffer_send_frame_done(struct wlr_scene_buffer *scene_buffer,
 		struct wlr_scene_frame_done_event *event) {
-	if (!pixman_region32_empty(&scene_buffer->node.visible)) {
+	bool visible = !pixman_region32_empty(&scene_buffer->node.visible);
+	if (cce_frame_debug_match(scene_buffer->dst_width, scene_buffer->dst_height)) {
+		pixman_box32_t *extents = pixman_region32_extents(&scene_buffer->node.visible);
+		wlr_log(WLR_INFO, "[cce-frame] t=%lld send_frame_done dst=%dx%d sent=%d visible_extents=(%d,%d %dx%d)",
+				(long long)cce_now_ms(), scene_buffer->dst_width, scene_buffer->dst_height,
+				visible, extents->x1, extents->y1,
+				extents->x2 - extents->x1, extents->y2 - extents->y1);
+	}
+	if (visible) {
 		wl_signal_emit_mutable(&scene_buffer->events.frame_done, event);
 	}
 }
diff --git a/src/server/output.rs b/src/server/output.rs
index 83bd62b..2f66ebb 100644
--- a/src/server/output.rs
+++ b/src/server/output.rs
@@ -897,11 +897,39 @@ unsafe extern "C" fn handle_request_state(listener: *mut ffi::wl_listener, data:
     (*output.server).wm.dirty_windowing();
 }
 
+/// `CCE_FRAME_DEBUG` (any value) also ticks every output frame, so a client's
+/// 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 {
+    static FLAG: std::sync::OnceLock<bool> = std::sync::OnceLock::new();
+    *FLAG.get_or_init(|| std::env::var_os("CCE_FRAME_DEBUG").is_some())
+}
+
 unsafe extern "C" fn handle_frame(listener: *mut ffi::wl_listener, _data: *mut std::ffi::c_void) {
     let output = &mut *crate::container_of!(listener, Output, frame);
+    let render_start = if frame_debug() {
+        Some(std::time::Instant::now())
+    } else {
+        None
+    };
     if let Err(e) = output.render_and_commit() {
         log::error!("{}", e);
     }
+    if let Some(start) = render_start {
+        // Epoch ms mod 100000 — the shared tracer time base (see cce-ui's
+        // CCE_PRESENT_DEBUG), so compositor and client logs interleave.
+        let t = std::time::SystemTime::now()
+            .duration_since(std::time::UNIX_EPOCH)
+            .unwrap()
+            .as_millis()
+            % 100000;
+        log::info!(
+            "[cce-frame] t={} output frame (render_and_commit {}us)",
+            t,
+            start.elapsed().as_micros()
+        );
+    }
     let now = util::timestamp();
     let mut ffi_now = ffi::timespec {
         tv_sec: now.tv_sec,