diff --git a/Cargo.lock b/Cargo.lock index 7dc17334..2c60b353 100644 --- a/Cargo.lock +++ b/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]] diff --git a/Cargo.toml b/Cargo.toml index 53154e9e..bb1974fc 100644 --- a/Cargo.toml +++ b/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 diff --git a/src/backend/kms/device.rs b/src/backend/kms/device.rs index 19ed5818..98a1d9c8 100644 --- a/src/backend/kms/device.rs +++ b/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>)>, + Duration, )>, DrmDeviceFd, >; diff --git a/src/backend/kms/surface/mod.rs b/src/backend/kms/surface/mod.rs index 6c6b86bc..f8b873f5 100644 --- a/src/backend/kms/surface/mod.rs +++ b/src/backend/kms/surface/mod.rs @@ -146,6 +146,17 @@ pub struct SurfaceThreadState { #[cfg(feature = "debug")] egui: EguiState, + + last_sequence: Option, + /// Tracy frame that goes from vblank to vblank. + vblank_frame: Option, + /// 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>)>, + Duration, )>, DrmDeviceFd, >; @@ -469,7 +481,8 @@ fn surface_thread( thread_receiver: Channel, startup_done: Arc, ) -> 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 diff --git a/src/main.rs b/src/main.rs index 5d6d4364..961bbad8 100644 --- a/src/main.rs +++ b/src/main.rs @@ -127,9 +127,9 @@ fn main() -> Result<(), Box> { 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();