feat(render): add per-output DRM outcome diagnostics (#52)

Co-authored-by: Samuel Onoja <[email protected]>

compositor/src/backends/direct.rs

@@ -7,6 +7,7 @@ use std::time::{Duration, Instant};
 
 pub(crate) mod capture;
 mod crtc_assignment;
+mod diagnostics;
 pub(crate) mod gamma;
 mod lid;
 mod mirror;
@@ -17,12 +18,13 @@ mod redraw;
 mod scheduling;
 mod topology;
 mod transaction;
+use diagnostics::{Diagnostics, PrimaryOutcome};
 use output_power::{OutputPower, Power};
 use redraw::{AnimationFallback, SchedulingMetrics};
 use scheduling::*;
 use smithay::backend::allocator::Fourcc;
 use smithay::backend::allocator::gbm::{GbmAllocator, GbmBufferFlags, GbmDevice};
-use smithay::backend::drm::compositor::{DrmCompositor, PrimaryPlaneElement};
+use smithay::backend::drm::compositor::{DrmCompositor, FrameFlags, PrimaryPlaneElement};
 use smithay::backend::drm::exporter::gbm::GbmFramebufferExporter;
 use smithay::backend::drm::{DrmDevice, DrmDeviceFd, DrmEvent, DrmEventTime, DrmNode, NodeType};
 use smithay::backend::egl::{EGLContext, EGLDisplay};
@@ -274,6 +276,7 @@ struct DirectOutput {
     primary_commit: Option<CommitCounter>,
     capture_texture: Option<GlesTexture>,
     render_metrics: RenderMetrics,
+    diagnostics: Diagnostics,
     frame_pending: bool,
     completion: recovery::Completion,
     completion_timer: Option<RegistrationToken>,
@@ -838,11 +841,15 @@ fn open_device(state: &mut Ferese, path: &Path) -> Result<DrmNode, Box<dyn Error
                             if output.frame_pending && recovery::inject("retirement") {
                                 tracing::warn!(?node, ?crtc, "injecting DRM retirement failure");
                                 retirement_failed = true;
+                                output.diagnostics.retirement(false, true);
+                                output.diagnostics.report_if_due();
                                 return None;
                             }
 
                             let (feedback, completed, error) = recovery::retirement(output.surface.frame_submitted());
                             retired = completed;
+                            output.diagnostics.retirement(completed, error.is_some());
+                            output.diagnostics.report_if_due();
                             if let Some(error) = error {
                                 tracing::error!(?node, ?crtc, %error, "failed to retire DRM frame");
                                 retirement_failed = true;
@@ -1309,29 +1316,37 @@ fn render_output(
                 sampled_output_elements(state, &mut device.renderer, &output.output, true, &frame)
             };
             let effects = frame_effect_metrics(&elements, output.output.current_scale().fractional_scale());
-            let flags = planes::frame_flags(
-                state.output_has_fullscreen_for_frame(&output.output, frame.overview.is_presenting()),
-                frame.animating,
-                state.session_lock.active(),
-            );
-            let result = output.surface.render_frame(
-                &mut device.renderer,
-                &elements,
-                if output.mirror_source.is_some() {
-                    [0.0, 0.0, 0.0, 1.0]
-                } else {
-                    [0.035, 0.04, 0.055, 1.0]
-                },
-                flags,
-            )?;
+            let fullscreen = state.output_has_fullscreen_for_frame(&output.output, frame.overview.is_presenting());
+            let locked = state.session_lock.active();
+            let flags = planes::frame_flags(fullscreen, frame.animating, locked);
+            output.diagnostics.attempt(fullscreen, frame.animating, locked);
+            let result = output
+                .surface
+                .render_frame(
+                    &mut device.renderer,
+                    &elements,
+                    if output.mirror_source.is_some() {
+                        [0.0, 0.0, 0.0, 1.0]
+                    } else {
+                        [0.035, 0.04, 0.055, 1.0]
+                    },
+                    flags,
+                )
+                .inspect_err(|_| output.diagnostics.render_failed())?;
 
             if result.needs_sync()
                 && let PrimaryPlaneElement::Swapchain(primary) = &result.primary_element
             {
-                primary.sync.wait()?;
+                primary.sync.wait().inspect_err(|_| output.diagnostics.sync_failed())?;
             }
 
             if result.is_empty {
+                output.diagnostics.no_damage();
+                let capture_started = output.diagnostics.capture_start(|| {
+                    [true, false]
+                        .into_iter()
+                        .any(|cursor| state.has_pending_screencopy(&output.output, cursor))
+                });
                 if output.mirror_source.is_some() {
                     capture::capture_mirror(state, &mut device.renderer, &scene_output, &frame, &mut output);
                 } else {
@@ -1344,6 +1359,7 @@ fn render_output(
                     );
                 }
 
+                output.diagnostics.capture_finished(capture_started);
                 output
                     .render_metrics
                     .record_no_damage(render_started.elapsed(), missed_deadlines);
@@ -1388,10 +1404,22 @@ fn render_output(
                     Kind::Vsync | Kind::HwClock | Kind::HwCompletion,
                 )
             };
+            let primary_outcome = PrimaryOutcome::classify(
+                matches!(result.primary_element, PrimaryPlaneElement::Element(_)),
+                !damage.is_empty(),
+            );
+            let cursor_plane = result.cursor_element.is_some();
             let visibility = result.states.clone();
             drop(result);
 
-            capture::after_queue(output.surface.queue_frame(presentation), || {
+            let queued = output.surface.queue_frame(presentation);
+            output.diagnostics.queue_result(
+                &queued,
+                primary_outcome,
+                cursor_plane,
+                flags.contains(FrameFlags::ALLOW_PRIMARY_PLANE_SCANOUT),
+            );
+            capture::after_queue(queued, || {
                 if output.mirror_source.is_none() {
                     state.display_presentation.queued(&output.output, &visibility);
                 }
@@ -1405,6 +1433,11 @@ fn render_output(
                 }
 
                 output.lock_frame_pending = state.session_lock.active();
+                let capture_started = output.diagnostics.capture_start(|| {
+                    [true, false]
+                        .into_iter()
+                        .any(|cursor| state.has_pending_screencopy(&output.output, cursor))
+                });
 
                 if output.mirror_source.is_some() {
                     capture::capture_mirror(state, &mut device.renderer, &scene_output, &frame, &mut output);
@@ -1417,12 +1450,15 @@ fn render_output(
                         &frame,
                     );
                 }
+                output.diagnostics.capture_finished(capture_started);
             })?;
 
             Ok(true)
         })()
     };
 
+    output.diagnostics.report_if_due();
+
     // Keep the footprint of the last successful scene, including queued
     // cursor planes. Requests do not read the pointer while a grab holds it.
     if rendered.is_ok() {
@@ -2215,6 +2251,7 @@ fn create_direct_output(
     );
     surface.set_output_mode_source((&output).into());
     let render_metrics = RenderMetrics::from_environment(output.name());
+    let diagnostics = Diagnostics::from_environment(output.name());
 
     tracing::info!(?crtc, connector = %connector, "initialized DRM output");
     Ok(DirectOutput {
@@ -2236,6 +2273,7 @@ fn create_direct_output(
         primary_commit: None,
         capture_texture: None,
         render_metrics,
+        diagnostics,
         frame_pending: false,
         completion: Default::default(),
         completion_timer: None,

compositor/src/backends/direct/diagnostics.rs

@@ -0,0 +1,294 @@
+//! Opt-in accounting of observable DRM results, independent of scanout policy.
+use std::time::{Duration, Instant};
+
+#[derive(Clone, Copy, Debug, Eq, PartialEq)]
+pub(super) enum PrimaryOutcome {
+    DirectScanout,
+    Composed,
+    ReusedSwapchain,
+}
+
+impl PrimaryOutcome {
+    pub fn classify(direct: bool, composition_damage: bool) -> Self {
+        if direct {
+            Self::DirectScanout
+        } else if composition_damage {
+            Self::Composed
+        } else {
+            Self::ReusedSwapchain
+        }
+    }
+}
+
+#[derive(Debug, Default, Eq, PartialEq)]
+struct Counters {
+    render_attempts: u64,
+    primary_allowed: u64,
+    blocked_locked: u64,
+    blocked_animation: u64,
+    blocked_not_fullscreen: u64,
+    render_failures: u64,
+    sync_failures: u64,
+    no_damage_results: u64,
+    queue_failures: u64,
+    submissions: u64,
+    scanout_submissions: u64,
+    composed_submissions: u64,
+    reused_swapchain_submissions: u64,
+    allowed_composition_submissions: u64,
+    cursor_plane_submissions: u64,
+    no_cursor_plane_submissions: u64,
+    retired_frames: u64,
+    retirement_failures: u64,
+    capture_batches: u64,
+    capture_time: Duration,
+}
+
+#[derive(Debug)]
+pub(super) struct Diagnostics {
+    enabled: bool,
+    output: String,
+    started: Instant,
+    counters: Counters,
+}
+
+impl Diagnostics {
+    pub fn from_environment(output: String) -> Self {
+        Self::new(output, std::env::var_os("FERESE_TRACE_PERFORMANCE").is_some())
+    }
+
+    fn new(output: String, enabled: bool) -> Self {
+        Self {
+            enabled,
+            output,
+            started: Instant::now(),
+            counters: Counters::default(),
+        }
+    }
+
+    pub fn attempt(&mut self, fullscreen: bool, animating: bool, locked: bool) {
+        if !self.enabled {
+            return;
+        }
+        self.counters.render_attempts += 1;
+        // Exclusive diagnostic precedence only; the policy itself is unchanged.
+        if locked {
+            self.counters.blocked_locked += 1;
+        } else if animating {
+            self.counters.blocked_animation += 1;
+        } else if !fullscreen {
+            self.counters.blocked_not_fullscreen += 1;
+        } else {
+            self.counters.primary_allowed += 1;
+        }
+    }
+
+    pub fn render_failed(&mut self) {
+        if self.enabled {
+            self.counters.render_failures += 1;
+        }
+    }
+
+    pub fn sync_failed(&mut self) {
+        if self.enabled {
+            self.counters.sync_failures += 1;
+        }
+    }
+
+    pub fn no_damage(&mut self) {
+        if self.enabled {
+            self.counters.no_damage_results += 1;
+        }
+    }
+
+    pub fn queue_result<T, E>(
+        &mut self,
+        result: &Result<T, E>,
+        primary: PrimaryOutcome,
+        cursor_plane: bool,
+        primary_allowed: bool,
+    ) {
+        if !self.enabled {
+            return;
+        }
+        if result.is_err() {
+            self.counters.queue_failures += 1;
+            return;
+        }
+        self.counters.submissions += 1;
+        match primary {
+            PrimaryOutcome::DirectScanout => self.counters.scanout_submissions += 1,
+            PrimaryOutcome::Composed => self.counters.composed_submissions += 1,
+            PrimaryOutcome::ReusedSwapchain => self.counters.reused_swapchain_submissions += 1,
+        }
+        if primary_allowed && primary != PrimaryOutcome::DirectScanout {
+            // Smithay selected a swapchain despite permission. This API does not
+            // expose whether a candidate was tested, or why it was rejected.
+            self.counters.allowed_composition_submissions += 1;
+        }
+        if cursor_plane {
+            self.counters.cursor_plane_submissions += 1;
+        } else {
+            self.counters.no_cursor_plane_submissions += 1;
+        }
+    }
+
+    pub fn retirement(&mut self, completed: bool, failed: bool) {
+        if !self.enabled {
+            return;
+        }
+        self.counters.retired_frames += u64::from(completed && !failed);
+        self.counters.retirement_failures += u64::from(failed);
+    }
+
+    pub fn capture_start(&self, pending: impl FnOnce() -> bool) -> Option<Instant> {
+        (self.enabled && pending()).then(Instant::now)
+    }
+
+    pub fn capture_finished(&mut self, start: Option<Instant>) {
+        if let Some(start) = start {
+            self.record_capture(start.elapsed());
+        }
+    }
+
+    fn record_capture(&mut self, elapsed: Duration) {
+        if !self.enabled {
+            return;
+        }
+        self.counters.capture_batches += 1;
+        self.counters.capture_time += elapsed;
+    }
+
+    pub fn report_if_due(&mut self) {
+        if !self.enabled || self.started.elapsed() < Duration::from_secs(5) {
+            return;
+        }
+        let c = &self.counters;
+        tracing::info!(target: "ferese::render", output = %self.output,
+            interval_ms = self.started.elapsed().as_millis(),
+            render_attempts = c.render_attempts, primary_allowed = c.primary_allowed,
+            blocked_locked = c.blocked_locked, blocked_animation = c.blocked_animation,
+            blocked_not_fullscreen = c.blocked_not_fullscreen,
+            render_failures = c.render_failures, sync_failures = c.sync_failures,
+            no_damage_results = c.no_damage_results, queue_failures = c.queue_failures,
+            submissions = c.submissions, scanout_submissions = c.scanout_submissions,
+            composed_submissions = c.composed_submissions,
+            reused_swapchain_submissions = c.reused_swapchain_submissions,
+            allowed_composition_submissions = c.allowed_composition_submissions,
+            cursor_plane_submissions = c.cursor_plane_submissions,
+            no_cursor_plane_submissions = c.no_cursor_plane_submissions,
+            retired_frames = c.retired_frames, retirement_failures = c.retirement_failures,
+            capture_batches = c.capture_batches, capture_us = c.capture_time.as_micros(),
+            "DRM frame outcomes");
+        self.counters = Counters::default();
+        self.started = Instant::now();
+    }
+}
+
+#[cfg(test)]
+mod tests {
+    use super::*;
+
+    #[test]
+    fn primary_classification_does_not_infer_scanout_from_zero_damage() {
+        assert_eq!(PrimaryOutcome::classify(true, false), PrimaryOutcome::DirectScanout);
+        assert_eq!(PrimaryOutcome::classify(false, true), PrimaryOutcome::Composed);
+        assert_eq!(PrimaryOutcome::classify(false, false), PrimaryOutcome::ReusedSwapchain);
+    }
+
+    #[test]
+    fn policy_reasons_partition_attempts_with_documented_precedence() {
+        let mut d = Diagnostics::new("test".into(), true);
+        for fullscreen in [false, true] {
+            for animating in [false, true] {
+                for locked in [false, true] {
+                    let allowed_before = d.counters.primary_allowed;
+                    d.attempt(fullscreen, animating, locked);
+                    assert_eq!(
+                        d.counters.primary_allowed > allowed_before,
+                        super::super::planes::frame_flags(fullscreen, animating, locked)
+                            .contains(smithay::backend::drm::compositor::FrameFlags::ALLOW_PRIMARY_PLANE_SCANOUT),
+                    );
+                }
+            }
+        }
+        assert_eq!(d.counters.render_attempts, 8);
+        assert_eq!(d.counters.primary_allowed, 1);
+        assert_eq!(d.counters.blocked_locked, 4);
+        assert_eq!(d.counters.blocked_animation, 2);
+        assert_eq!(d.counters.blocked_not_fullscreen, 1);
+    }
+
+    #[test]
+    fn only_successful_queues_count_outcomes_and_retirement_is_separate() {
+        let mut d = Diagnostics::new("test".into(), true);
+        let queued = Err::<(), _>("queue failed");
+        d.queue_result(&queued, PrimaryOutcome::DirectScanout, true, true);
+        assert!(super::super::capture::after_queue(queued, || panic!("failed queues must not capture")).is_err());
+        assert_eq!(d.counters.submissions, 0);
+        assert_eq!(d.counters.scanout_submissions, 0);
+        assert_eq!(d.counters.cursor_plane_submissions, 0);
+        assert_eq!(d.counters.queue_failures, 1);
+        for (primary, cursor, allowed) in [
+            (PrimaryOutcome::DirectScanout, true, true),
+            (PrimaryOutcome::Composed, false, true),
+            (PrimaryOutcome::ReusedSwapchain, true, false),
+        ] {
+            d.queue_result(&Ok::<(), ()>(()), primary, cursor, allowed);
+        }
+        assert_eq!(d.counters.submissions, 3);
+        assert_eq!(d.counters.scanout_submissions, 1);
+        assert_eq!(d.counters.composed_submissions, 1);
+        assert_eq!(d.counters.reused_swapchain_submissions, 1);
+        assert_eq!(d.counters.allowed_composition_submissions, 1);
+        assert_eq!(d.counters.cursor_plane_submissions, 2);
+        assert_eq!(d.counters.no_cursor_plane_submissions, 1);
+        assert_eq!(d.counters.retired_frames, 0);
+        d.retirement(false, false);
+        d.retirement(false, true);
+        assert_eq!(d.counters.retired_frames, 0);
+        d.retirement(true, false);
+        assert_eq!(d.counters.retired_frames, 1);
+        assert_eq!(d.counters.retirement_failures, 1);
+    }
+
+    #[test]
+    fn no_damage_and_failures_never_count_as_submissions() {
+        let mut d = Diagnostics::new("test".into(), true);
+        d.no_damage();
+        d.render_failed();
+        d.sync_failed();
+        d.record_capture(Duration::from_micros(123));
+        assert_eq!(d.counters.no_damage_results, 1);
+        assert_eq!(d.counters.render_failures, 1);
+        assert_eq!(d.counters.sync_failures, 1);
+        assert_eq!(d.counters.submissions, 0);
+        assert_eq!(d.counters.capture_time, Duration::from_micros(123));
+        assert_eq!(d.counters.capture_batches, 1);
+    }
+
+    #[test]
+    fn disabled_accounting_is_inert_and_outputs_are_independent() {
+        let mut d = Diagnostics::new("disabled".into(), false);
+        d.attempt(true, false, false);
+        d.render_failed();
+        d.sync_failed();
+        d.no_damage();
+        d.queue_result(&Ok::<(), ()>(()), PrimaryOutcome::DirectScanout, true, true);
+        d.retirement(true, false);
+        d.record_capture(Duration::from_secs(1));
+        assert_eq!(d.counters, Counters::default());
+        assert!(
+            d.capture_start(|| panic!("disabled diagnostics must not inspect capture requests"))
+                .is_none()
+        );
+        let mut other = Diagnostics::new("other".into(), true);
+        other.no_damage();
+        assert!(other.capture_start(|| false).is_none());
+        assert_eq!(d.counters.no_damage_results, 0);
+        assert_eq!(other.counters.no_damage_results, 1);
+        other.started = Instant::now() - Duration::from_secs(6);
+        other.report_if_due();
+        assert_eq!(other.counters, Counters::default());
+    }
+}