From b5f7793870ddc098b102a4b3e8ff3118f197fb5e Mon Sep 17 00:00:00 2001 From: Samuel Onoja Date: Wed, 14 Oct 2026 13:29:33 +0100 Subject: [PATCH] feat(render): add per-output DRM outcome diagnostics (#52) Co-authored-by: Samuel Onoja --- compositor/src/backends/direct.rs | 74 +++-- compositor/src/backends/direct/diagnostics.rs | 294 ++++++++++++++++++ docs/README.md | 1 + docs/development.md | 1 + docs/rendering-performance.md | 90 ++++++ 5 files changed, 442 insertions(+), 18 deletions(-) create mode 100644 compositor/src/backends/direct/diagnostics.rs create mode 100644 docs/rendering-performance.md diff --git a/compositor/src/backends/direct.rs b/compositor/src/backends/direct.rs index 8c285e1..5ea993f 100644 --- a/compositor/src/backends/direct.rs +++ b/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, capture_texture: Option, render_metrics: RenderMetrics, + diagnostics: Diagnostics, frame_pending: bool, completion: recovery::Completion, completion_timer: Option, @@ -838,11 +841,15 @@ fn open_device(state: &mut Ferese, path: &Path) -> Result 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( + &mut self, + result: &Result, + 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 { + (self.enabled && pending()).then(Instant::now) + } + + pub fn capture_finished(&mut self, start: Option) { + 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()); + } +} diff --git a/docs/README.md b/docs/README.md index 17f9008..ae3848a 100644 --- a/docs/README.md +++ b/docs/README.md @@ -45,6 +45,7 @@ and [guides at that tag](https://github.com/ferese-wm/ferese/tree/v0.1.0-beta/do - [Publishing activities](development/activities.md): IPC schema, ownership, limits and templates. - [Animation model](animation-model.md): geometry, spring motion, gestures and prediction. - [Desktop reconciliation](desktop-reconciliation.md): topology publication and presentation ownership. +- [Rendering diagnostics](rendering-performance.md): outcome counters, capture cost and repeatable hardware baselines. - [Output management tests](output-management-testing.md): profiles, hotplug and DRM failures. - [Nested resize checks](nested-resize-testing.md). - [Client soak testing](native-soak-testing.md). diff --git a/docs/development.md b/docs/development.md index 421e29e..c44a64c 100644 --- a/docs/development.md +++ b/docs/development.md @@ -29,6 +29,7 @@ host. Hardware checks remain separate. - [Live Activities checks](#live-activities-checks): core, CLI, shell hooks, installer setup and native rendering. - [Desktop reconciliation](desktop-reconciliation.md): topology publication, hardware failure and presentation ownership. +- [Rendering diagnostics](rendering-performance.md): per-output outcomes and repeatable hardware baselines. - [Output management tests](output-management-testing.md): profiles, hotplug, mirroring, lid handling and failed DRM commits. - [Nested resize checks](nested-resize-testing.md): wallpaper and bar responsiveness. - [Client soak testing](native-soak-testing.md): repeated client lifecycle and resource growth. diff --git a/docs/rendering-performance.md b/docs/rendering-performance.md new file mode 100644 index 0000000..7f0fbb0 --- /dev/null +++ b/docs/rendering-performance.md @@ -0,0 +1,90 @@ +# Rendering diagnostics and hardware baselines + +Set `FERESE_TRACE_PERFORMANCE=1` in the environment of a fresh compositor process +and enable the `ferese::render` info log target. For a manual DRM session, for +example: + +```sh +FERESE_TRACE_PERFORMANCE=1 RUST_LOG=ferese::render=info ferese +``` + +Use your normal supported session launch procedure. Do not start a second DRM +compositor inside a running desktop. Setting this variable on `feresectl` does +not enable counters in an already running compositor. To disable accounting, +remove the variable and restart; any value, including `0`, enables it. + +Existing `render performance` logs describe timings and composition damage. +The direct backend additionally emits `DRM frame outcomes` per physical output, +roughly every five seconds when render or retirement activity reaches a reporting +point. Idle outputs need not emit a report. Counters reset after each report; +retirement of a submission can occur in the following interval. Output recreation +starts a new series. Mirror targets have their own series. Nested sessions do not +provide DRM outcome counters. + +## Counter meanings + +| Fields | Meaning | +| --- | --- | +| `render_attempts` | Calls to Smithay `render_frame`, after scene construction; permission to attempt scanout does not prove that a client buffer was tested. | +| `primary_allowed`, `blocked_locked`, `blocked_animation`, `blocked_not_fullscreen` | Partition of attempts under the existing primary-plane policy. When multiple blockers apply, diagnostic precedence is lock, animation, then absence of fullscreen. | +| `render_failures`, `sync_failures`, `queue_failures` | Errors returned by rendering, explicit synchronization, or queueing respectively. Failed queues never increment submission outcomes. | +| `no_damage_results` | Smithay returned `is_empty`; no display frame was queued. Capture may still run. This is independent of primary selection. | +| `submissions` | Successful `queue_frame` calls, before completion; these are not presented-frame counts. | +| `scanout_submissions` | Queued result uses `PrimaryPlaneElement::Element`, Smithay's direct primary-plane selection. | +| `composed_submissions` | Queued result uses the swapchain with composition damage since the last successfully queued primary commit. | +| `reused_swapchain_submissions` | Queued swapchain result has no new composition damage. This can accompany cursor updates or forced commits; it does not prove a cursor-only update. | +| `allowed_composition_submissions` | Primary scanout permission was set, but the queued result uses a swapchain, including reuse. The public result does not expose exact candidate/driver rejection reasons. | +| `cursor_plane_submissions`, `no_cursor_plane_submissions` | Partition of successful queues by Smithay's cursor-plane assignment. No assignment can mean a hidden, absent, or composed cursor; it is not a hardware-cursor failure count. | +| `retired_frames`, `retirement_failures` | Successful retirement with feedback, or a retirement error. Only successful retirement counts as completed; no feedback and errors do not. A completion can lack a usable monotonic timestamp. These totals do not classify presented primary/cursor paths. | +| `capture_batches`, `capture_us` | Batches with pending monitor capture requests, and their separate CPU wall time through capture scene construction, recomposition and readback processing. A batch may process cursor-included and cursor-excluded requests. Failures remain included in this cost; asynchronous encoding is excluded. | + +Primary outcomes partition submissions; cursor outcomes independently partition +submissions. A scanout/submission ratio describes queued outcomes, not the fraction +of wall time an output spent scanning out an unchanged client. Zero composition damage does not establish direct scanout. A +successful submission establishes neither kernel presentation nor a performance +improvement. Existing presentation schedule logs provide timestamps when usable; enable +`RUST_LOG=ferese::render=debug` to include them. +Capture timing is separate from submitted render timing. Existing no-damage +render timing includes capture work; do not add those overlapping totals. +These diagnostics do not change scanout flags, feedback, clipping, blur, capture +privacy, locking, gamma processing or recovery. + +Counters are opt-in and use constant-size per-output storage. With diagnostics +disabled, capture accounting does not inspect pending requests or read a clock. +The implementation does not inspect additional surfaces or perform GPU timing. + +## Repeatable hardware baseline + +1. Record the exact commit/build, GPU and driver, kernel, output modes, refresh + rates, scale, transforms, mirror layout, power state, application versions and + relevant appearance settings. Save configuration and the full diagnostic log. +2. Use a real DRM session. Warm up each workload for 10 seconds, measure a fixed + 60-second window, and repeat it three times. Use matching time windows and + sum counters across intervals; record the actual workload duration separately. + Keep idle cases separate because they may not produce periodic reports. +3. Start with an opaque settled fullscreen client, then toggle fullscreen and + exercise animations and popups. Compare it with a non-fullscreen and a rounded + or translucent scene. Move/show/hide the cursor in each case. Expect permission + and observed outcomes to differ; record both without assigning unreported + hardware rejection reasons. +4. Repeat with monitor screenshots/sharing, cursor included and excluded, + protected windows, overlapping blurs and moving content beneath blur. Check + captured pixels and privacy, not just timings. Test lock/unlock with capture + active and verify no desktop capture survives lock acquisition. +5. Repeat on mixed outputs, mirrors, fractional scaling and rotation; exercise + hotplug, gamma/night light and the recovery checks in + [Output management tests](output-management-testing.md). Check visual and + capture correctness after fallback and after returning to scanout. +6. Compare successful queue outcomes, composition damage, CPU render timings, + capture timings and presentation schedule timestamps against the same baseline. + Measure GPU work or power with an appropriate external tool and record its + method. Report variation across repetitions. Software tests and nested sessions + cannot establish physical scanout, GPU savings or presentation latency. + +Follow-on instrumentation should measure blur invalidation, clean-cache reuse, +actual framebuffer recapture counts/cost, asynchronous capture encoding and +window-capture readback separately. Current effect metrics are placeholders; +`capture_us` covers monitor capture batches only. Exact cursor-only KMS updates +and detailed scanout rejection causes require additional upstream observability. +Output/per-surface DMA-BUF feedback and eligibility expansion remain later phases, +with broader primary and overlay policies validated separately on hardware.