Merge pull request #1565 from bungoboingo/feat/tracing

[Feature] Profiling

.gitignore

@@ -4,3 +4,4 @@ pkg/
 Cargo.lock
 .cargo/
 dist/
+traces/

Cargo.toml

@@ -39,6 +39,13 @@ smol = ["iced_futures/smol"]
 palette = ["iced_core/palette"]
 # Enables querying system information
 system = ["iced_winit/system"]
+# Enables chrome traces
+chrome-trace = [
+    "iced_winit/chrome-trace",
+    "iced_glutin?/trace",
+    "iced_wgpu?/tracing",
+    "iced_glow?/tracing",
+]
 
 [badges]
 maintenance = { status = "actively-developed" }

glow/Cargo.toml

@@ -42,6 +42,10 @@ version = "0.5"
 path = "../graphics"
 features = ["font-fallback", "font-icons", "opengl"]
 
+[dependencies.tracing]
+version = "0.1.6"
+optional = true
+
 [package.metadata.docs.rs]
 rustdoc-args = ["--cfg", "docsrs"]
 all-features = true

glow/src/image.rs

@@ -21,6 +21,9 @@ use glow::HasContext;
 
 use std::cell::RefCell;
 
+#[cfg(feature = "tracing")]
+use tracing::info_span;
+
 #[derive(Debug)]
 pub(crate) struct Pipeline {
     program: <glow::Context as HasContext>::Program,
@@ -148,6 +151,9 @@ impl Pipeline {
         images: &[layer::Image],
         layer_bounds: Rectangle<u32>,
     ) {
+        #[cfg(feature = "tracing")]
+        let _ = info_span!("Glow::Image", "DRAW").entered();
+
         unsafe {
             gl.use_program(Some(self.program));
             gl.bind_vertex_array(Some(self.vertex_array));

glow/src/quad.rs

@@ -7,6 +7,9 @@ use glow::HasContext;
 use iced_graphics::layer;
 use iced_native::Rectangle;
 
+#[cfg(feature = "tracing")]
+use tracing::info_span;
+
 #[derive(Debug)]
 pub enum Pipeline {
     Core(core::Pipeline),
@@ -42,6 +45,9 @@ impl Pipeline {
         scale: f32,
         bounds: Rectangle<u32>,
     ) {
+        #[cfg(feature = "tracing")]
+        let _ = info_span!("Glow::Quad", "DRAW").enter();
+
         match self {
             Pipeline::Core(pipeline) => {
                 pipeline.draw(

glow/src/triangle.rs

@@ -9,6 +9,9 @@ use iced_graphics::triangle::{ColoredVertex2D, Vertex2D};
 use glow::HasContext;
 use std::marker::PhantomData;
 
+#[cfg(feature = "tracing")]
+use tracing::info_span;
+
 const DEFAULT_VERTICES: usize = 1_000;
 const DEFAULT_INDICES: usize = 1_000;
 
@@ -58,6 +61,9 @@ impl Pipeline {
         transformation: Transformation,
         scale_factor: f32,
     ) {
+        #[cfg(feature = "tracing")]
+        let _ = info_span!("Glow::Triangle", "DRAW").enter();
+
         unsafe {
             gl.enable(glow::MULTISAMPLE);
             gl.enable(glow::SCISSOR_TEST);

glutin/Cargo.toml

@@ -11,6 +11,7 @@ keywords = ["gui", "ui", "graphics", "interface", "widgets"]
 categories = ["gui"]
 
 [features]
+trace = ["iced_winit/trace"]
 debug = ["iced_winit/debug"]
 system = ["iced_winit/system"]
 
@@ -35,3 +36,7 @@ features = ["application"]
 version = "0.5"
 path = "../graphics"
 features = ["opengl"]
+
+[dependencies.tracing]
+version = "0.1.6"
+optional = true

glutin/src/application.rs

@@ -17,6 +17,9 @@ use iced_winit::{Clipboard, Command, Debug, Proxy, Settings};
 use glutin::window::Window;
 use std::mem::ManuallyDrop;
 
+#[cfg(feature = "tracing")]
+use tracing::{info_span, instrument::Instrument};
+
 /// Runs an [`Application`] with an executor, compositor, and the provided
 /// settings.
 pub fn run<A, E, C>(
@@ -35,9 +38,15 @@ where
     use glutin::platform::run_return::EventLoopExtRunReturn;
     use glutin::ContextBuilder;
 
+    #[cfg(feature = "trace")]
+    let _guard = iced_winit::Profiler::init();
+
     let mut debug = Debug::new();
     debug.startup_started();
 
+    #[cfg(feature = "tracing")]
+    let _ = info_span!("Application::Glutin", "RUN").entered();
+
     let mut event_loop = EventLoopBuilder::with_user_event().build();
     let proxy = event_loop.create_proxy();
 
@@ -124,18 +133,26 @@ where
 
     let (mut sender, receiver) = mpsc::unbounded();
 
-    let mut instance = Box::pin(run_instance::<A, E, C>(
-        application,
-        compositor,
-        renderer,
-        runtime,
-        proxy,
-        debug,
-        receiver,
-        context,
-        init_command,
-        settings.exit_on_close_request,
-    ));
+    let mut instance = Box::pin({
+        let run_instance = run_instance::<A, E, C>(
+            application,
+            compositor,
+            renderer,
+            runtime,
+            proxy,
+            debug,
+            receiver,
+            context,
+            init_command,
+            settings.exit_on_close_request,
+        );
+
+        #[cfg(feature = "tracing")]
+        let run_instance =
+            run_instance.instrument(info_span!("Application", "LOOP"));
+
+        run_instance
+    });
 
     let mut context = task::Context::from_waker(task::noop_waker_ref());
 
@@ -333,6 +350,9 @@ async fn run_instance<A, E, C>(
                 messages.push(message);
             }
             event::Event::RedrawRequested(_) => {
+                #[cfg(feature = "tracing")]
+                let _ = info_span!("Application", "FRAME").entered();
+
                 debug.render_started();
 
                 #[allow(unsafe_code)]

wgpu/Cargo.toml

@@ -50,6 +50,10 @@ version = "0.5"
 path = "../graphics"
 features = ["font-fallback", "font-icons"]
 
+[dependencies.tracing]
+version = "0.1.6"
+optional = true
+
 [dependencies.encase]
 version = "0.3.0"
 features = ["glam"]

wgpu/src/backend.rs

@@ -10,6 +10,9 @@ use iced_graphics::{Primitive, Viewport};
 use iced_native::alignment;
 use iced_native::{Font, Size};
 
+#[cfg(feature = "tracing")]
+use tracing::info_span;
+
 #[cfg(any(feature = "image", feature = "svg"))]
 use crate::image;
 
@@ -77,6 +80,8 @@ impl Backend {
         overlay_text: &[T],
     ) {
         log::debug!("Drawing");
+        #[cfg(feature = "tracing")]
+        let _ = info_span!("Wgpu::Backend", "PRESENT").entered();
 
         let target_size = viewport.physical_size();
         let scale_factor = viewport.scale_factor() as f32;

wgpu/src/image.rs

@@ -23,6 +23,9 @@ use iced_native::image;
 #[cfg(feature = "svg")]
 use iced_native::svg;
 
+#[cfg(feature = "tracing")]
+use tracing::info_span;
+
 #[derive(Debug)]
 pub struct Pipeline {
     #[cfg(feature = "image")]
@@ -289,6 +292,9 @@ impl Pipeline {
         target: &wgpu::TextureView,
         _scale: f32,
     ) {
+        #[cfg(feature = "tracing")]
+        let _ = info_span!("Wgpu::Image", "DRAW").entered();
+
         let instances: &mut Vec<Instance> = &mut Vec::new();
 
         #[cfg(feature = "image")]

wgpu/src/quad.rs

@@ -6,6 +6,9 @@ use bytemuck::{Pod, Zeroable};
 use std::mem;
 use wgpu::util::DeviceExt;
 
+#[cfg(feature = "tracing")]
+use tracing::info_span;
+
 #[derive(Debug)]
 pub struct Pipeline {
     pipeline: wgpu::RenderPipeline,
@@ -173,6 +176,9 @@ impl Pipeline {
         bounds: Rectangle<u32>,
         target: &wgpu::TextureView,
     ) {
+        #[cfg(feature = "tracing")]
+        let _ = info_span!("Wgpu::Quad", "DRAW").entered();
+
         let uniforms = Uniforms::new(transformation, scale);
 
         {
@@ -207,6 +213,9 @@ impl Pipeline {
 
             instance_buffer.copy_from_slice(instance_bytes);
 
+            #[cfg(feature = "tracing")]
+            let _ = info_span!("Wgpu::Quad", "BEGIN_RENDER_PASS").enter();
+
             {
                 let mut render_pass =
                     encoder.begin_render_pass(&wgpu::RenderPassDescriptor {

wgpu/src/triangle.rs

@@ -8,6 +8,8 @@ use crate::Transformation;
 use iced_graphics::layer::mesh::{self, Mesh};
 use iced_graphics::triangle::ColoredVertex2D;
 use iced_graphics::Size;
+#[cfg(feature = "tracing")]
+use tracing::info_span;
 
 #[derive(Debug)]
 pub struct Pipeline {
@@ -53,6 +55,9 @@ impl Pipeline {
         scale_factor: f32,
         meshes: &[Mesh<'_>],
     ) {
+        #[cfg(feature = "tracing")]
+        let _ = info_span!("Wgpu::Triangle", "DRAW").entered();
+
         // Count the total amount of vertices & indices we need to handle
         let count = mesh::attribute_count_of(meshes);
 
@@ -247,6 +252,9 @@ impl Pipeline {
                 (target, None, wgpu::LoadOp::Load)
             };
 
+            #[cfg(feature = "tracing")]
+            let _ = info_span!("Wgpu::Triangle", "BEGIN_RENDER_PASS").enter();
+
             let mut render_pass =
                 encoder.begin_render_pass(&wgpu::RenderPassDescriptor {
                     label: Some("iced_wgpu::triangle render pass"),

winit/Cargo.toml

@@ -11,6 +11,8 @@ keywords = ["gui", "ui", "graphics", "interface", "widgets"]
 categories = ["gui"]
 
 [features]
+trace = ["tracing", "tracing-core", "tracing-subscriber"]
+chrome-trace = ["trace", "tracing-chrome"]
 debug = ["iced_native/debug"]
 system = ["sysinfo"]
 application = []
@@ -37,6 +39,24 @@ path = "../graphics"
 version = "0.5"
 path = "../futures"
 
+[dependencies.tracing]
+version = "0.1.37"
+optional = true
+features = ["std"]
+
+[dependencies.tracing-core]
+version = "0.1.30"
+optional = true
+
+[dependencies.tracing-subscriber]
+version = "0.3.16"
+optional = true
+features = ["registry"]
+
+[dependencies.tracing-chrome]
+version = "0.7.0"
+optional = true
+
 [target.'cfg(target_os = "windows")'.dependencies.winapi]
 version = "0.3.6"
 

winit/src/application.rs

@@ -1,4 +1,6 @@
 //! Create interactive, native cross-platform applications.
+#[cfg(feature = "trace")]
+mod profiler;
 mod state;
 
 pub use state::State;
@@ -24,6 +26,11 @@ pub use iced_native::application::{Appearance, StyleSheet};
 
 use std::mem::ManuallyDrop;
 
+#[cfg(feature = "trace")]
+pub use profiler::Profiler;
+#[cfg(feature = "trace")]
+use tracing::{info_span, instrument::Instrument};
+
 /// An interactive, native cross-platform application.
 ///
 /// This trait is the main entrypoint of Iced. Once implemented, you can run
@@ -111,9 +118,15 @@ where
     use futures::Future;
     use winit::event_loop::EventLoopBuilder;
 
+    #[cfg(feature = "trace")]
+    let _guard = Profiler::init();
+
     let mut debug = Debug::new();
     debug.startup_started();
 
+    #[cfg(feature = "trace")]
+    let _ = info_span!("Application", "RUN").entered();
+
     let event_loop = EventLoopBuilder::with_user_event().build();
     let proxy = event_loop.create_proxy();
 
@@ -175,18 +188,26 @@ where
 
     let (mut sender, receiver) = mpsc::unbounded();
 
-    let mut instance = Box::pin(run_instance::<A, E, C>(
-        application,
-        compositor,
-        renderer,
-        runtime,
-        proxy,
-        debug,
-        receiver,
-        init_command,
-        window,
-        settings.exit_on_close_request,
-    ));
+    let mut instance = Box::pin({
+        let run_instance = run_instance::<A, E, C>(
+            application,
+            compositor,
+            renderer,
+            runtime,
+            proxy,
+            debug,
+            receiver,
+            init_command,
+            window,
+            settings.exit_on_close_request,
+        );
+
+        #[cfg(feature = "trace")]
+        let run_instance =
+            run_instance.instrument(info_span!("Application", "LOOP"));
+
+        run_instance
+    });
 
     let mut context = task::Context::from_waker(task::noop_waker_ref());
 
@@ -391,6 +412,9 @@ async fn run_instance<A, E, C>(
                 messages.push(message);
             }
             event::Event::RedrawRequested(_) => {
+                #[cfg(feature = "trace")]
+                let _ = info_span!("Application", "FRAME").entered();
+
                 let physical_size = state.physical_size();
 
                 if physical_size.width == 0 || physical_size.height == 0 {
@@ -529,12 +553,24 @@ pub fn build_user_interface<'a, A: Application>(
 where
     <A::Renderer as crate::Renderer>::Theme: StyleSheet,
 {
+    #[cfg(feature = "trace")]
+    let view_span = info_span!("Application", "VIEW").entered();
+
     debug.view_started();
     let view = application.view();
+
+    #[cfg(feature = "trace")]
+    let _ = view_span.exit();
     debug.view_finished();
 
+    #[cfg(feature = "trace")]
+    let layout_span = info_span!("Application", "LAYOUT").entered();
+
     debug.layout_started();
     let user_interface = UserInterface::build(view, size, cache, renderer);
+
+    #[cfg(feature = "trace")]
+    let _ = layout_span.exit();
     debug.layout_finished();
 
     user_interface
@@ -559,10 +595,16 @@ pub fn update<A: Application, E: Executor>(
     <A::Renderer as crate::Renderer>::Theme: StyleSheet,
 {
     for message in messages.drain(..) {
+        #[cfg(feature = "trace")]
+        let update_span = info_span!("Application", "UPDATE").entered();
+
         debug.log_message(&message);
 
         debug.update_started();
         let command = runtime.enter(|| application.update(message));
+
+        #[cfg(feature = "trace")]
+        let _ = update_span.exit();
         debug.update_finished();
 
         run_command(

winit/src/application/profiler.rs

@@ -0,0 +1,101 @@
+//! A simple profiler for Iced.
+use std::ffi::OsStr;
+use std::path::Path;
+use std::time::Duration;
+use tracing_subscriber::prelude::*;
+use tracing_subscriber::Registry;
+#[cfg(feature = "chrome-trace")]
+use {
+    tracing_chrome::FlushGuard,
+    tracing_subscriber::fmt::{format::DefaultFields, FormattedFields},
+};
+
+/// Profiler state. This will likely need to be updated or reworked when adding new tracing backends.
+#[allow(missing_debug_implementations)]
+pub struct Profiler {
+    #[cfg(feature = "chrome-trace")]
+    /// [`FlushGuard`] must not be dropped until the application scope is dropped for accurate tracing.
+    _guard: FlushGuard,
+}
+
+impl Profiler {
+    /// Initializes the [`Profiler`].
+    pub fn init() -> Self {
+        // Registry stores the spans & generates unique span IDs
+        let subscriber = Registry::default();
+
+        let default_path = Path::new(env!("CARGO_MANIFEST_DIR"));
+        let curr_exe = std::env::current_exe()
+            .unwrap_or_else(|_| default_path.to_path_buf());
+        let out_dir = curr_exe.parent().unwrap_or(default_path).join("traces");
+
+        #[cfg(feature = "chrome-trace")]
+        let (chrome_layer, guard) = {
+            let mut layer = tracing_chrome::ChromeLayerBuilder::new();
+
+            // Optional configurable env var: CHROME_TRACE_FILE=/path/to/trace_file/file.json,
+            // for uploading to chrome://tracing (old) or ui.perfetto.dev (new).
+            if let Ok(path) = std::env::var("CHROME_TRACE_FILE") {
+                layer = layer.file(path);
+            } else if std::fs::create_dir_all(&out_dir).is_ok() {
+                let time = std::time::SystemTime::now()
+                    .duration_since(std::time::UNIX_EPOCH)
+                    .unwrap_or(Duration::from_millis(0))
+                    .as_millis();
+
+                let curr_exe_name = curr_exe
+                    .file_name()
+                    .unwrap_or_else(|| OsStr::new("trace"))
+                    .to_str()
+                    .unwrap_or("trace");
+
+                let path = out_dir
+                    .join(format!("{}_trace_{}.json", curr_exe_name, time));
+
+                layer = layer.file(path);
+            } else {
+                layer = layer.file(env!("CARGO_MANIFEST_DIR"))
+            }
+
+            let (chrome_layer, guard) = layer
+                .name_fn(Box::new(|event_or_span| match event_or_span {
+                    tracing_chrome::EventOrSpan::Event(event) => {
+                        event.metadata().name().into()
+                    }
+                    tracing_chrome::EventOrSpan::Span(span) => {
+                        if let Some(fields) = span
+                            .extensions()
+                            .get::<FormattedFields<DefaultFields>>()
+                        {
+                            format!(
+                                "{}: {}",
+                                span.metadata().name(),
+                                fields.fields.as_str()
+                            )
+                        } else {
+                            span.metadata().name().into()
+                        }
+                    }
+                }))
+                .build();
+
+            (chrome_layer, guard)
+        };
+
+        let fmt_layer = tracing_subscriber::fmt::Layer::default();
+        let subscriber = subscriber.with(fmt_layer);
+
+        #[cfg(feature = "chrome-trace")]
+        let subscriber = subscriber.with(chrome_layer);
+
+        // create dispatcher which will forward span events to the subscriber
+        // this can only be set once or will panic
+        tracing::subscriber::set_global_default(subscriber)
+            .expect("Tracer could not set the global default subscriber.");
+
+        Profiler {
+            #[cfg(feature = "chrome-trace")]
+            _guard: guard,
+        }
+    }
+}

winit/src/lib.rs

@@ -51,6 +51,8 @@ mod proxy;
 
 #[cfg(feature = "application")]
 pub use application::Application;
+#[cfg(feature = "trace")]
+pub use application::Profiler;
 pub use clipboard::Clipboard;
 pub use error::Error;
 pub use position::Position;