feat: report optional render performance metrics

README.md

@@ -24,6 +24,10 @@ cargo run -p ferese -- foot
 
 Set `RUST_LOG=ferese=debug` for detailed compositor logging.
 
+Set `FERESE_TRACE_PERFORMANCE=1` to emit five-second per-output summaries under
+the `ferese::render` tracing target. Summaries include rendered frames, damaged
+pixels, average and longest render time, and DRM missed-deadline totals.
+
 Ferese reads `$XDG_CONFIG_HOME/ferese/config.toml`, or
 `~/.config/ferese/config.toml` when `XDG_CONFIG_HOME` is unset. New scrolling
 columns use half the viewport by default. To make every newly opened column use

compositor/src/backends/direct.rs

@@ -3,7 +3,7 @@ use std::{
     error::Error,
     io,
     path::Path,
-    time::Duration,
+    time::{Duration, Instant},
 };
 
 use smithay::{
@@ -41,6 +41,7 @@ use smithay::{
 
 use crate::{
     Ferese,
+    metrics::RenderMetrics,
     winit::{animated_window_elements, cursorless_window_elements, redraw_output},
 };
 
@@ -73,6 +74,7 @@ struct DirectOutput {
     global: GlobalId,
     surface: GbmBufferedSurface<GbmAllocator<DrmDeviceFd>, OutputPresentationFeedback>,
     damage_tracker: OutputDamageTracker,
+    render_metrics: RenderMetrics,
     frame_pending: bool,
 }
 
@@ -357,6 +359,11 @@ pub fn switch_vt(state: &mut Ferese, vt: i32) {
 }
 
 fn render_output(state: &mut Ferese, node: DrmNode, crtc: crtc::Handle) {
+    let missed_deadlines = state
+        .direct_backend
+        .as_ref()
+        .and_then(|backend| backend.presentation.get(&(node, crtc)))
+        .map_or(0, |clock| clock.missed_deadlines);
     let Some(mut device) = state
         .direct_backend
         .as_mut()
@@ -374,6 +381,7 @@ fn render_output(state: &mut Ferese, node: DrmNode, crtc: crtc::Handle) {
         return;
     }
 
+    let render_started = Instant::now();
     let rendered = (|| -> Result<bool, Box<dyn Error>> {
         state.process_dmabuf_imports(&mut device.renderer);
         let (mut buffer, age) = output.surface.next_buffer()?;
@@ -445,7 +453,10 @@ fn render_output(state: &mut Ferese, node: DrmNode, crtc: crtc::Handle) {
         });
         output
             .surface
-            .queue_buffer(Some(result.sync), Some(damage), presentation)?;
+            .queue_buffer(Some(result.sync), Some(damage.clone()), presentation)?;
+        output
+            .render_metrics
+            .record_frame(render_started.elapsed(), &damage, missed_deadlines);
         output.frame_pending = true;
         Ok(true)
     })();
@@ -692,6 +703,7 @@ fn create_direct_output(
         renderer.dmabuf_formats(),
     )?;
     let damage_tracker = OutputDamageTracker::from_output(&output);
+    let render_metrics = RenderMetrics::from_environment(output.name());
 
     tracing::info!(?crtc, connector = %connector, "initialized DRM output");
     Ok(DirectOutput {
@@ -701,6 +713,7 @@ fn create_direct_output(
         global,
         surface,
         damage_tracker,
+        render_metrics,
         frame_pending: false,
     })
 }

compositor/src/main.rs

@@ -7,6 +7,7 @@ mod grabs;
 mod handlers;
 mod input;
 mod ipc;
+mod metrics;
 mod state;
 mod window_rules;
 mod winit;

compositor/src/metrics.rs

@@ -0,0 +1,126 @@
+use std::time::{Duration, Instant};
+
+use smithay::utils::{Physical, Rectangle};
+
+const REPORT_INTERVAL: Duration = Duration::from_secs(5);
+
+#[derive(Debug)]
+pub(crate) struct RenderMetrics {
+    enabled: bool,
+    output: String,
+    interval_started: Instant,
+    rendered_frames: u64,
+    damaged_pixels: u64,
+    total_render_time: Duration,
+    longest_render_time: Duration,
+}
+
+impl RenderMetrics {
+    pub(crate) fn from_environment(output: impl Into<String>) -> Self {
+        Self::new(
+            output,
+            std::env::var_os("FERESE_TRACE_PERFORMANCE").is_some(),
+            Instant::now(),
+        )
+    }
+
+    fn new(output: impl Into<String>, enabled: bool, now: Instant) -> Self {
+        Self {
+            enabled,
+            output: output.into(),
+            interval_started: now,
+            rendered_frames: 0,
+            damaged_pixels: 0,
+            total_render_time: Duration::ZERO,
+            longest_render_time: Duration::ZERO,
+        }
+    }
+
+    pub(crate) fn record_frame(
+        &mut self,
+        render_time: Duration,
+        damage: &[Rectangle<i32, Physical>],
+        missed_deadlines: u64,
+    ) {
+        if !self.enabled {
+            return;
+        }
+
+        self.rendered_frames += 1;
+        self.damaged_pixels += damage.iter().map(rectangle_area).sum::<u64>();
+        self.total_render_time += render_time;
+        self.longest_render_time = self.longest_render_time.max(render_time);
+
+        let now = Instant::now();
+        let elapsed = now.saturating_duration_since(self.interval_started);
+        if elapsed < REPORT_INTERVAL {
+            return;
+        }
+
+        let average_render_us = self
+            .total_render_time
+            .as_micros()
+            .checked_div(u128::from(self.rendered_frames))
+            .unwrap_or(0);
+        tracing::info!(
+            target: "ferese::render",
+            output = %self.output,
+            interval_ms = elapsed.as_millis(),
+            frames = self.rendered_frames,
+            damaged_pixels = self.damaged_pixels,
+            average_render_us,
+            longest_render_us = self.longest_render_time.as_micros(),
+            missed_deadlines,
+            "render performance"
+        );
+
+        self.interval_started = now;
+        self.rendered_frames = 0;
+        self.damaged_pixels = 0;
+        self.total_render_time = Duration::ZERO;
+        self.longest_render_time = Duration::ZERO;
+    }
+}
+
+fn rectangle_area(rectangle: &Rectangle<i32, Physical>) -> u64 {
+    u64::try_from(rectangle.size.w.max(0)).unwrap_or(0)
+        * u64::try_from(rectangle.size.h.max(0)).unwrap_or(0)
+}
+
+#[cfg(test)]
+mod tests {
+    use super::*;
+
+    #[test]
+    fn disabled_metrics_do_not_accumulate() {
+        let mut metrics = RenderMetrics::new("test", false, Instant::now());
+
+        metrics.record_frame(
+            Duration::from_millis(2),
+            &[Rectangle::new((0, 0).into(), (100, 50).into())],
+            0,
+        );
+
+        assert_eq!(metrics.rendered_frames, 0);
+        assert_eq!(metrics.damaged_pixels, 0);
+    }
+
+    #[test]
+    fn enabled_metrics_count_frames_pixels_and_render_time() {
+        let mut metrics = RenderMetrics::new("test", true, Instant::now());
+
+        metrics.record_frame(
+            Duration::from_millis(2),
+            &[
+                Rectangle::new((0, 0).into(), (100, 50).into()),
+                Rectangle::new((10, 10).into(), (20, 10).into()),
+            ],
+            0,
+        );
+
+        assert_eq!(metrics.rendered_frames, 1);
+        assert_eq!(metrics.damaged_pixels, 5_200);
+        assert_eq!(metrics.total_render_time, Duration::from_millis(2));
+        assert_eq!(metrics.longest_render_time, Duration::from_millis(2));
+    }
+}

compositor/src/winit.rs

@@ -48,7 +48,7 @@ use smithay::{
     wayland::{compositor::with_states, presentation::Refresh},
 };
 
-use crate::Ferese;
+use crate::{Ferese, metrics::RenderMetrics};
 
 type SurfaceRenderElement = CropRenderElement<
     RelocateRenderElement<RescaleRenderElement<WaylandSurfaceRenderElement<GlesRenderer>>>,
@@ -379,6 +379,7 @@ pub fn init(event_loop: &mut EventLoop<Ferese>, state: &mut Ferese) -> Result<()
     let clock = Clock::<Monotonic>::new();
     let mut sequence = 0_u64;
     let mut output_scale = initial_scale;
+    let mut render_metrics = RenderMetrics::from_environment(output.name());
 
     event_loop
         .handle()
@@ -407,6 +408,7 @@ pub fn init(event_loop: &mut EventLoop<Ferese>, state: &mut Ferese) -> Result<()
             WinitEvent::Redraw => {
                 state.advance_animations(Instant::now());
                 let age = backend.buffer_age().unwrap_or(0);
+                let render_started = Instant::now();
                 let rendered = (|| -> DamageRenderResult {
                     {
                         let (renderer, mut framebuffer) = backend.bind()?;
@@ -470,6 +472,7 @@ pub fn init(event_loop: &mut EventLoop<Ferese>, state: &mut Ferese) -> Result<()
                     state.loop_signal.stop();
                     return;
                 }
+                render_metrics.record_frame(render_started.elapsed(), &damage, 0);
 
                 let mut presentation = OutputPresentationFeedback::new(&output);
                 state.space.elements().for_each(|window| {