chore: Improved profiling

Cargo.toml

@@ -20,7 +20,6 @@ embed-fonts = []
 profiling = ["dep:tracy-client-sys"]
 gpu_profiling = ["profiling"]
 # Corresponds to https://github.com/nagisa/rust_tracy_client/blob/main/FEATURES.mkd
-tracy-fibers = ["tracy-client-sys?/fibers"]
 tracy-system-tracing = ["tracy-client-sys?/system-tracing"]
 tracy-context-switch-tracing = ["tracy-client-sys?/context-switch-tracing"]
 tracy-sampling = ["tracy-client-sys?/sampling"]
@@ -65,7 +64,7 @@ time = "0.3.9"
 tokio = { version = "1.25.0", features = ["full"] }
 tokio-util = { version = "0.7.4", features = ["compat"] }
 toml = "0.7.3"
-tracy-client-sys = { version = "0.22.0", optional = true, default-features = false, features = ["broadcast", "delayed-init", "enable", "manual-lifetime"] }
+tracy-client-sys = { version = "0.22.0", optional = true, default-features = false, features = ["broadcast", "delayed-init", "enable", "manual-lifetime", "fibers"] }
 unicode-segmentation = "1.9.0"
 which = "4.2.5"
 winit = { version = "=0.29.4", features = ["serde"] }

src/bridge/ui_commands.rs

@@ -9,7 +9,9 @@ use tokio::sync::mpsc::{unbounded_channel, UnboundedReceiver};
 
 use super::{show_error_message, show_intro_message};
 use crate::{
-    bridge::NeovimWriter, profiling::tracy_dynamic_zone, running_tracker::RUNNING_TRACKER,
+    bridge::NeovimWriter,
+    profiling::{tracy_dynamic_zone, tracy_fiber_enter, tracy_fiber_leave},
+    running_tracker::RUNNING_TRACKER,
     LoggingSender,
 };
 
@@ -308,10 +310,17 @@ pub fn start_ui_command_handler(nvim: Arc<Neovim<NeovimWriter>>) {
     });
 
     tokio::spawn(async move {
+        tracy_fiber_enter!("Serial command");
         while RUNNING_TRACKER.is_running() {
-            match serial_rx.recv().await {
+            tracy_fiber_leave();
+            let res = serial_rx.recv().await;
+            tracy_fiber_enter!("Serial command");
+            match res {
                 Some(serial_command) => {
+                    tracy_dynamic_zone!(serial_command.as_ref());
+                    tracy_fiber_leave();
                     serial_command.execute(&nvim).await;
+                    tracy_fiber_enter!("Serial command");
                 }
                 None => {
                     RUNNING_TRACKER.quit("serial ui command channel failed");

src/editor/mod.rs

@@ -13,7 +13,7 @@ use winit::event_loop::EventLoopProxy;
 
 use crate::{
     bridge::{GuiOption, NeovimHandler, RedrawEvent, WindowAnchor},
-    profiling::tracy_zone,
+    profiling::{tracy_named_frame, tracy_zone},
     renderer::DrawCommand,
     window::{UserEvent, WindowCommand},
 };
@@ -136,6 +136,7 @@ impl Editor {
             RedrawEvent::Flush => {
                 tracy_zone!("EditorFlush");
                 trace!("Image flushed");
+                tracy_named_frame!("neovim draw command flush");
                 self.send_cursor_info();
                 {
                     trace!("send_batch");

src/profiling/profiling_disabled.rs

@@ -2,7 +2,7 @@
 pub fn startup_profiler() {}
 
 #[inline(always)]
-pub fn emit_frame_mark() {}
+pub fn tracy_frame() {}
 
 #[inline(always)]
 pub fn tracy_create_gpu_context(_name: &str) {}
@@ -22,7 +22,26 @@ macro_rules! tracy_gpu_zone {
     ($name: expr, $color: expr) => {};
     ($name: expr) => {};
 }
+macro_rules! tracy_named_frame {
+    ($name: expr) => {};
+}
+
+#[macro_export]
+macro_rules! tracy_plot {
+    ($name: expr, $dt: expr) => {};
+}
+
+#[macro_export]
+macro_rules! tracy_fiber_enter {
+    ($name: expr) => {};
+}
+
+#[inline(always)]
+pub fn tracy_fiber_leave() {}
 
 pub(crate) use tracy_dynamic_zone;
+pub(crate) use tracy_fiber_enter;
 pub(crate) use tracy_gpu_zone;
+pub(crate) use tracy_named_frame;
+pub(crate) use tracy_plot;
 pub(crate) use tracy_zone;

src/profiling/profiling_enabled.rs

@@ -10,8 +10,9 @@ use tracy_client_sys::{
     ___tracy_alloc_srcloc_name, ___tracy_c_zone_context, ___tracy_connected,
     ___tracy_emit_frame_mark, ___tracy_emit_gpu_context_name, ___tracy_emit_gpu_new_context,
     ___tracy_emit_gpu_time_serial, ___tracy_emit_gpu_zone_begin_serial,
-    ___tracy_emit_gpu_zone_end_serial, ___tracy_emit_zone_begin, ___tracy_emit_zone_begin_alloc,
-    ___tracy_emit_zone_end, ___tracy_gpu_context_name_data, ___tracy_gpu_new_context_data,
+    ___tracy_emit_gpu_zone_end_serial, ___tracy_emit_plot, ___tracy_emit_zone_begin,
+    ___tracy_emit_zone_begin_alloc, ___tracy_emit_zone_end, ___tracy_fiber_enter,
+    ___tracy_fiber_leave, ___tracy_gpu_context_name_data, ___tracy_gpu_new_context_data,
     ___tracy_gpu_time_data, ___tracy_gpu_zone_begin_data, ___tracy_gpu_zone_end_data,
     ___tracy_source_location_data, ___tracy_startup_profiler,
 };
@@ -225,12 +226,40 @@ pub fn startup_profiler() {
 }
 
 #[inline(always)]
-pub fn emit_frame_mark() {
+pub fn tracy_frame() {
     unsafe {
         ___tracy_emit_frame_mark(null());
     }
 }
 
+#[inline(always)]
+pub fn _tracy_named_frame(name: &std::ffi::CStr) {
+    unsafe {
+        ___tracy_emit_frame_mark(name.as_ptr());
+    }
+}
+
+#[inline(always)]
+pub fn _tracy_plot(name: &std::ffi::CStr, value: f64) {
+    unsafe {
+        ___tracy_emit_plot(name.as_ptr(), value);
+    }
+}
+
+#[inline(always)]
+pub fn _tracy_fiber_enter(name: &std::ffi::CStr) {
+    unsafe {
+        ___tracy_fiber_enter(name.as_ptr());
+    }
+}
+
+#[inline(always)]
+pub fn tracy_fiber_leave() {
+    unsafe {
+        ___tracy_fiber_leave();
+    }
+}
+
 pub fn tracy_create_gpu_context(name: &str) {
     // Don't change order, only add new entries at the end, this is also used on trace dumps!
     #[allow(dead_code)]
@@ -358,9 +387,33 @@ macro_rules! tracy_gpu_zone {
     };
 }
 
+#[macro_export]
+macro_rules! tracy_named_frame {
+    ($name: expr) => {
+        $crate::profiling::_tracy_named_frame($crate::profiling::cstr!($name))
+    };
+}
+
+#[macro_export]
+macro_rules! tracy_plot {
+    ($name: expr, $dt: expr) => {
+        $crate::profiling::_tracy_plot($crate::profiling::cstr!($name), $dt)
+    };
+}
+
+#[macro_export]
+macro_rules! tracy_fiber_enter {
+    ($name: expr) => {
+        $crate::profiling::_tracy_fiber_enter($crate::profiling::cstr!($name))
+    };
+}
+
 pub(crate) use cstr;
 pub(crate) use file_cstr;
 pub(crate) use location_data;
 pub(crate) use tracy_dynamic_zone;
+pub(crate) use tracy_fiber_enter;
 pub(crate) use tracy_gpu_zone;
+pub(crate) use tracy_named_frame;
+pub(crate) use tracy_plot;
 pub(crate) use tracy_zone;

src/renderer/cursor_renderer/mod.rs

@@ -9,7 +9,7 @@ use winit::event::{Event, WindowEvent};
 use crate::{
     bridge::EditorMode,
     editor::{Cursor, CursorShape},
-    profiling::tracy_zone,
+    profiling::{tracy_plot, tracy_zone},
     renderer::animation_utils::*,
     renderer::{GridRenderer, RenderedWindow},
     settings::{ParseFromValue, SETTINGS},
@@ -422,6 +422,7 @@ impl CursorRenderer {
         if !animating {
             self.previous_editor_mode = current_mode.clone();
         }
+        tracy_plot!("cursor animating", animating as u8 as f64);
         animating
     }
 

src/renderer/mod.rs

@@ -21,7 +21,7 @@ use crate::{
     bridge::EditorMode,
     dimensions::Dimensions,
     editor::{Cursor, Style},
-    profiling::tracy_zone,
+    profiling::{tracy_named_frame, tracy_zone},
     settings::*,
     window::{ShouldRender, UserEvent},
     WindowSettings,
@@ -254,6 +254,7 @@ impl Renderer {
 
         for draw_command in batch {
             self.handle_draw_command(draw_command, &mut result);
+            tracy_named_frame!("neovim draw batch processed");
         }
         self.flush(&settings);
 

src/window/keyboard_manager.rs

@@ -10,6 +10,8 @@ use winit::{
     keyboard::{Key, KeyCode, KeyLocation, NamedKey, PhysicalKey},
 };
 
+use crate::profiling::tracy_named_frame;
+
 fn is_ascii_alphabetic_char(text: &str) -> bool {
     text.len() == 1 && text.chars().next().unwrap().is_ascii_alphabetic()
 }
@@ -42,6 +44,7 @@ impl KeyboardManager {
                 if key_event.state == ElementState::Pressed {
                     if let Some(text) = self.format_key(key_event) {
                         log::trace!("Key pressed {} {:?}", text, self.modifiers.state());
+                        tracy_named_frame!("keyboard input");
                         send_ui(SerialCommand::Keyboard(text));
                     }
                 }

src/window/update_loop.rs

@@ -10,7 +10,7 @@ use winit::{
 use super::draw_background;
 use super::{UserEvent, WindowSettings, WinitWindowWrapper};
 use crate::{
-    profiling::{tracy_create_gpu_context, tracy_zone},
+    profiling::{tracy_create_gpu_context, tracy_plot, tracy_zone},
     renderer::VSync,
     settings::SETTINGS,
 };
@@ -48,6 +48,26 @@ impl ShouldRender {
             (ShouldRender::Wait, ShouldRender::Wait) => {}
         }
     }
+
+    #[cfg(feature = "profiling")]
+    fn plot_tracy(&self) {
+        match &self {
+            ShouldRender::Immediately => {
+                tracy_plot!("should_render", 0.0);
+            }
+            ShouldRender::Wait => {
+                tracy_plot!("should_render", -1.0);
+            }
+            ShouldRender::Deadline(instant) => {
+                tracy_plot!(
+                    "should_render",
+                    instant
+                        .saturating_duration_since(Instant::now())
+                        .as_secs_f64()
+                );
+            }
+        }
+    }
 }
 
 const MAX_ANIMATION_DT: f32 = 1.0 / 120.0;
@@ -125,6 +145,7 @@ impl UpdateLoop {
         }
         // We don't really want to support less than 10 FPS
         .min(0.1);
+        tracy_plot!("Average dt", dt.into());
         self.should_render = window_wrapper.prepare_frame();
         let num_steps = (dt / MAX_ANIMATION_DT).ceil();
         let step = dt / num_steps;
@@ -195,6 +216,7 @@ impl UpdateLoop {
                 event: WindowEvent::RedrawRequested,
                 ..
             }) => {
+                tracy_zone!("render (redraw requested)");
                 self.render(window_wrapper);
             }
             _ => {}
@@ -205,6 +227,8 @@ impl UpdateLoop {
                 self.should_render = ShouldRender::Immediately;
             }
         }
+        #[cfg(feature = "profiling")]
+        self.should_render.plot_tracy();
 
         let (_, deadline) = self.get_event_wait_time(&window_wrapper.vsync);
         Ok(ControlFlow::WaitUntil(deadline))