kms: Add tracy profiling

Cargo.lock

@@ -859,6 +859,7 @@ dependencies = [
  "tracing",
  "tracing-journald",
  "tracing-subscriber",
+ "tracy-client 0.18.0",
  "wayland-backend",
  "wayland-scanner",
  "xcursor",
@@ -1482,7 +1483,7 @@ source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "33d852cb9b869c2a9b3df2f71a3074817f01e1844f839a144f5fcef059a4eb5d"
 dependencies = [
  "libc",
- "windows-sys 0.52.0",
+ "windows-sys 0.59.0",
 ]
 
 [[package]]
@@ -2939,7 +2940,7 @@ source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "fc2f4eb4bc735547cfed7c0a4922cbd04a4655978c09b54f1f7b228750664c34"
 dependencies = [
  "cfg-if",
- "windows-targets 0.48.5",
+ "windows-targets 0.52.6",
 ]
 
 [[package]]
@@ -4094,7 +4095,7 @@ source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "afbdc74edc00b6f6a218ca6a5364d6226a259d4b8ea1af4a0ea063f27e179f4d"
 dependencies = [
  "profiling-procmacros",
- "tracy-client",
+ "tracy-client 0.17.6",
 ]
 
 [[package]]
@@ -4449,7 +4450,7 @@ dependencies = [
  "errno",
  "libc",
  "linux-raw-sys 0.4.15",
- "windows-sys 0.52.0",
+ "windows-sys 0.59.0",
 ]
 
 [[package]]
@@ -5051,7 +5052,7 @@ dependencies = [
  "getrandom 0.2.15",
  "once_cell",
  "rustix",
- "windows-sys 0.52.0",
+ "windows-sys 0.59.0",
 ]
 
 [[package]]
@@ -5337,6 +5338,17 @@ dependencies = [
  "tracy-client-sys",
 ]
 
+[[package]]
+name = "tracy-client"
+version = "0.18.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "d90a2c01305b02b76fdd89ac8608bae27e173c829a35f7d76a345ab5d33836db"
+dependencies = [
+ "loom",
+ "once_cell",
+ "tracy-client-sys",
+]
+
 [[package]]
 name = "tracy-client-sys"
 version = "0.24.3"
@@ -5344,7 +5356,7 @@ source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "69fff37da548239c3bf9e64a12193d261e8b22b660991c6fd2df057c168f435f"
 dependencies = [
  "cc",
- "windows-targets 0.48.5",
+ "windows-targets 0.52.6",
 ]
 
 [[package]]
@@ -6033,7 +6045,7 @@ version = "0.1.9"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "cf221c93e13a30d793f7645a0e7762c55d169dbb0a49671918a2319d289b10bb"
 dependencies = [
- "windows-sys 0.48.0",
+ "windows-sys 0.59.0",
 ]
 
 [[package]]

Cargo.toml

@@ -49,6 +49,7 @@ tiny-skia = "0.11"
 tracing = { version = "0.1.37", features = ["max_level_debug", "release_max_level_info"] }
 tracing-journald = "0.3.0"
 tracing-subscriber = {version = "0.3.16", features = ["env-filter", "tracing-log"]}
+tracy-client = { version = "0.18.0", default-features = false }
 wayland-backend = "0.3.3"
 wayland-scanner = "0.31.1"
 xcursor = "0.3.3"
@@ -100,7 +101,7 @@ rev = "e720136"
 debug = ["egui", "egui_plot", "smithay-egui", "anyhow/backtrace"]
 default = ["systemd"]
 systemd = ["libsystemd"]
-profile-with-tracy = ["profiling/profile-with-tracy"]
+profile-with-tracy = ["profiling/profile-with-tracy", "tracy-client/default"]
 
 [profile.dev.package.tiny-skia]
 opt-level = 2

src/backend/kms/device.rs

@@ -47,6 +47,7 @@ use std::{
     fmt,
     path::{Path, PathBuf},
     sync::{atomic::AtomicBool, mpsc::Receiver, Arc, RwLock},
+    time::Duration,
 };
 
 use super::{drm_helpers, socket::Socket, surface::Surface};
@@ -64,6 +65,7 @@ pub type GbmDrmOutputManager = DrmOutputManager<
     Option<(
         OutputPresentationFeedback,
         Receiver<(ScreencopyFrame, Vec<Rectangle<i32, BufferCoords>>)>,
+        Duration,
     )>,
     DrmDeviceFd,
 >;

src/backend/kms/surface/mod.rs

@@ -146,6 +146,17 @@ pub struct SurfaceThreadState {
 
     #[cfg(feature = "debug")]
     egui: EguiState,
+
+    last_sequence: Option<u32>,
+    /// Tracy frame that goes from vblank to vblank.
+    vblank_frame: Option<tracy_client::Frame>,
+    /// Frame name for the VBlank frame.
+    vblank_frame_name: tracy_client::FrameName,
+    /// Plot name for the time since presentation plot.
+    time_since_presentation_plot_name: tracy_client::PlotName,
+    /// Plot name for the presentation misprediction plot.
+    presentation_misprediction_plot_name: tracy_client::PlotName,
+    sequence_delta_plot_name: tracy_client::PlotName,
 }
 
 pub type GbmDrmOutput = DrmOutput<
@@ -154,6 +165,7 @@ pub type GbmDrmOutput = DrmOutput<
     Option<(
         OutputPresentationFeedback,
         Receiver<(ScreencopyFrame, Vec<Rectangle<i32, BufferCoords>>)>,
+        Duration,
     )>,
     DrmDeviceFd,
 >;
@@ -469,7 +481,8 @@ fn surface_thread(
     thread_receiver: Channel<ThreadCommand>,
     startup_done: Arc<AtomicBool>,
 ) -> Result<()> {
-    profiling::register_thread!(&format!("Surface Thread {}", output.name()));
+    let name = output.name();
+    profiling::register_thread!(&format!("Surface Thread {}", name));
 
     let mut event_loop = EventLoop::try_new().unwrap();
 
@@ -492,6 +505,14 @@ fn surface_thread(
         state
     };
 
+    let vblank_frame_name = tracy_client::FrameName::new_leak(format!("vblank on {name}"));
+    let time_since_presentation_plot_name =
+        tracy_client::PlotName::new_leak(format!("{name} time since presentation, ms"));
+    let presentation_misprediction_plot_name =
+        tracy_client::PlotName::new_leak(format!("{name} presentation misprediction, ms"));
+    let sequence_delta_plot_name =
+        tracy_client::PlotName::new_leak(format!("{name} sequence delta"));
+
     let mut state = SurfaceThreadState {
         api,
         primary_node,
@@ -516,6 +537,13 @@ fn surface_thread(
         clock: Clock::new(),
         #[cfg(feature = "debug")]
         egui,
+
+        last_sequence: None,
+        vblank_frame: None,
+        vblank_frame_name,
+        time_since_presentation_plot_name,
+        presentation_misprediction_plot_name,
+        sequence_delta_plot_name,
     };
 
     let signal = event_loop.get_signal();
@@ -716,9 +744,46 @@ impl SurfaceThreadState {
         };
         let sequence = metadata.as_ref().map(|data| data.sequence).unwrap_or(0);
 
+        // finish tracy frame
+        let _ = self.vblank_frame.take();
+
         // mark last frame completed
-        if let Ok(Some(Some((mut feedback, frames)))) = compositor.frame_submitted() {
+        if let Ok(Some(Some((mut feedback, frames, estimated_presentation_time)))) =
+            compositor.frame_submitted()
+        {
             if self.mirroring.is_none() {
+                let name = self.output.name();
+                let message = if let Some(presentation_time) = presentation_time {
+                    let misprediction_s =
+                        presentation_time.as_secs_f64() - estimated_presentation_time.as_secs_f64();
+                    tracy_client::Client::running().unwrap().plot(
+                        self.presentation_misprediction_plot_name,
+                        misprediction_s * 1000.,
+                    );
+
+                    let now = Duration::from(now);
+                    if presentation_time > now {
+                        let diff = presentation_time - now;
+                        tracy_client::Client::running().unwrap().plot(
+                            self.time_since_presentation_plot_name,
+                            -diff.as_secs_f64() * 1000.,
+                        );
+                        format!("vblank on {name}, presentation is {diff:?} later")
+                    } else {
+                        let diff = now - presentation_time;
+                        tracy_client::Client::running().unwrap().plot(
+                            self.time_since_presentation_plot_name,
+                            diff.as_secs_f64() * 1000.,
+                        );
+                        format!("vblank on {name}, presentation was {diff:?} ago")
+                    }
+                } else {
+                    format!("vblank on {name}, presentation time unknown")
+                };
+                tracy_client::Client::running()
+                    .unwrap()
+                    .message(&message, 0);
+
                 let (clock, flags) = if let Some(tp) = presentation_time {
                     (
                         tp.into(),
@@ -751,6 +816,14 @@ impl SurfaceThreadState {
                     None => Refresh::Unknown,
                 };
 
+                if let Some(last_sequence) = self.last_sequence {
+                    let delta = sequence as f64 - last_sequence as f64;
+                    tracy_client::Client::running()
+                        .unwrap()
+                        .plot(self.sequence_delta_plot_name, delta);
+                }
+                self.last_sequence = Some(sequence);
+
                 feedback.presented(clock, refresh, sequence as u64, flags);
 
                 self.timings.presented(clock);
@@ -770,6 +843,11 @@ impl SurfaceThreadState {
         };
 
         if redraw_needed || self.shell.read().unwrap().animations_going() {
+            let vblank_frame = tracy_client::Client::running()
+                .unwrap()
+                .non_continuous_frame(self.vblank_frame_name);
+            self.vblank_frame = Some(vblank_frame);
+
             self.queue_redraw(false);
         } else {
             self.send_frame_callbacks();
@@ -1332,6 +1410,7 @@ impl SurfaceThreadState {
                             .unwrap()
                             .take_presentation_feedback(&self.output, &frame_result.states),
                         rx,
+                        estimated_presentation,
                     ))
                 } else {
                     None
@@ -1628,6 +1707,9 @@ impl SurfaceThreadState {
                                 self.send_frame_callbacks();
                             }
                         } else {
+                            // we don't expect a vblank
+                            let _ = self.vblank_frame.take();
+
                             self.queue_estimated_vblank(
                                 estimated_presentation,
                                 // Make sure we redraw to reevaluate, if we intentionally missed content

src/main.rs

@@ -127,9 +127,9 @@ fn main() -> Result<(), Box<dyn Error>> {
     logger::init_logger()?;
     info!("Cosmic starting up!");
 
-    #[cfg(feature = "profile-with-tracy")]
-    profiling::tracy_client::Client::start();
     profiling::register_thread!("Main Thread");
+    #[cfg(feature = "profile-with-tracy")]
+    tracy_client::Client::start();
 
     utils::rlimit::increase_nofile_limit();