Add some profiling instrumentation

toybox-audio/Cargo.toml

@@ -9,4 +9,5 @@ edition.workspace = true
 [dependencies]
 cpal = "0.15.2"
 anyhow.workspace = true
-log.workspace = true
+log.workspace = true
+tracing.workspace = true

toybox-audio/src/lib.rs

@@ -3,6 +3,7 @@
 use cpal::traits::*;
 
 use anyhow::Context as AnyhowContext;
+use tracing::instrument;
 
 use std::sync::{Arc, Mutex};
 use std::sync::atomic::{AtomicBool, Ordering};
@@ -155,6 +156,7 @@ struct SharedState {
 // 	should be able to cope with different sample rates
 
 
+#[instrument(skip_all, name="audio build_output_stream")]
 fn build_output_stream(host: &cpal::Host, shared: &Arc<SharedState>) -> anyhow::Result<ActiveStream> {
 	let device = host.default_output_device().context("no output device available")?;
 
@@ -183,6 +185,8 @@ fn build_output_stream(host: &cpal::Host, shared: &Arc<SharedState>) -> anyhow::
 			let shared = Arc::clone(&shared);
 
 			move |data: &mut [f32], _: &cpal::OutputCallbackInfo| {
+				let _span = tracing::trace_span!("audio provider callback").entered();
+
 				let mut provider_maybe = shared.provider.lock().unwrap();
 				if let Some(provider) = &mut *provider_maybe {
 					provider.fill_buffer(data);

toybox-egui/Cargo.toml

@@ -8,6 +8,7 @@ edition.workspace = true
 
 [dependencies]
 anyhow.workspace = true
+tracing.workspace = true
 
 egui.workspace = true
 egui-winit.workspace = true

toybox-egui/src/lib.rs

@@ -4,6 +4,7 @@ use toybox_gfx as gfx;
 
 use egui_winit::winit::{self, event::WindowEvent, window::Window};
 use egui_winit::egui::{self, output::FullOutput};
+use tracing::instrument;
 use std::rc::Rc;
 
 mod renderer;
@@ -61,6 +62,7 @@ impl Integration {
 	}
 
 	// Returns whether or not egui wants to consume the event
+	#[instrument(skip_all, name="egui on_event")]
 	pub fn on_event(&mut self, event: &WindowEvent) -> bool {
 		use winit::keyboard::{Key, NamedKey};
 		use winit::event::KeyEvent;
@@ -80,12 +82,14 @@ impl Integration {
 		self.state.on_window_event(&self.window, event).consumed
 	}
 
+	#[instrument(skip_all, name="egui start_frame")]
 	pub fn start_frame(&mut self) -> egui::Context {
 		let input = self.state.take_egui_input(&self.window);
 		self.ctx.begin_frame(input);
 		self.ctx.clone()
 	}
 
+	#[instrument(skip_all, name="egui end_frame")]
 	pub fn end_frame(&mut self, gfx: &mut gfx::System) {
 		let FullOutput{platform_output, textures_delta, shapes, pixels_per_point, ..} = self.ctx.end_frame();
 		self.state.handle_platform_output(&self.window, platform_output);

toybox-gfx/Cargo.toml

@@ -8,6 +8,7 @@ edition.workspace = true
 anyhow.workspace = true
 common.workspace = true
 log.workspace = true
+tracing.workspace = true
 
 toybox-host.workspace = true
 toybox-vfs.workspace = true

toybox-gfx/src/lib.rs

@@ -2,6 +2,7 @@
 
 use toybox_host as host;
 use anyhow::Context;
+use tracing::instrument;
 
 pub mod bindings;
 pub mod command;
@@ -75,13 +76,15 @@ impl System {
 		}
 	}
 
+	#[instrument(skip_all, name="gfx start_frame")]
 	pub fn start_frame(&mut self) {
 		self.core.set_debugging_enabled(true);
 
 		self.resource_manager.start_frame(&mut self.core);
 		self.frame_encoder.start_frame();
 	}
 
+	#[instrument(skip_all, name="gfx execute_frame")]
 	pub fn execute_frame(&mut self, vfs: &toybox_vfs::Vfs) {
 		self.resource_manager.process_requests(&mut self.core, vfs)
 			.context("Error while processing resource requests")
@@ -194,6 +197,7 @@ impl System {
 		}
 	}
 
+	#[instrument(skip_all, name="gfx dispatch_commands")]
 	fn dispatch_commands(&mut self) {
 		use command::Command::*;
 

toybox-gfx/src/upload_heap.rs

@@ -1,5 +1,6 @@
 use crate::prelude::*;
 use crate::core::{Core, BufferName, BufferRange};
+use tracing::instrument;
 
 pub const UPLOAD_BUFFER_SIZE: usize = 8<<20;
 
@@ -268,6 +269,7 @@ impl UploadStage {
 		upload.alignment = upload.alignment.max(new_aligment);
 	}
 
+	#[instrument(skip_all, name="gfx UploadStage::push_to_heap")]
 	pub fn push_to_heap(&mut self, core: &mut Core, upload_heap: &mut UploadHeap) {
 		core.push_debug_group("Push Upload Heap");
 

toybox-host/Cargo.toml

@@ -8,6 +8,7 @@ edition.workspace = true
 
 [dependencies]
 anyhow.workspace = true
+
 winit.workspace = true
 glutin.workspace = true
 glutin-winit.workspace = true
@@ -17,4 +18,14 @@ common.workspace = true
 gl.workspace = true
 
 log.workspace = true
-env_logger = "0.9.0"
+env_logger = "0.9.0"
+
+
+tracing.workspace = true
+tracing-subscriber = "0.3"
+tracing-tracy = { version = "=0.11.1", optional = true }
+tracy-client = { version = "=0.17.1", optional = true }
+
+
+[features]
+tracy = ["dep:tracing-tracy", "dep:tracy-client", "tracing-tracy/enable"]

toybox-host/src/lib.rs

@@ -22,6 +22,8 @@ use glutin::surface::{WindowSurface, SwapInterval};
 
 use raw_window_handle::HasWindowHandle;
 
+use tracing::instrument;
+
 use std::num::NonZeroU32;
 
 pub mod prelude {
@@ -47,16 +49,10 @@ pub fn start<F, H>(settings: Settings<'_>, start_hostee: F) -> anyhow::Result<()
 	where F: FnOnce(&Host) -> anyhow::Result<H>
 		, H: HostedApp + 'static
 {
-	let mut log_builder = env_logger::builder();
-	log_builder.parse_default_env();
-	log_builder.format_timestamp_millis();
-	log_builder.format_indent(None);
+	init_logging();
 
-	if cfg!(debug_assertions) {
-		log_builder.filter_level(log::LevelFilter::Debug);
-	}
-
-	log_builder.init();
+	#[cfg(feature="tracy")]
+	init_tracy();
 
 	let event_loop = EventLoop::new()?;
 
@@ -66,7 +62,7 @@ pub fn start<F, H>(settings: Settings<'_>, start_hostee: F) -> anyhow::Result<()
 		.with_decorations(!settings.no_decorations)
 		.with_resizable(true)
 		.with_visible(false);
-	
+
 	let gl_config_template = ConfigTemplateBuilder::new()
 		.with_api(Api::OPENGL)
 		.with_stencil_size(8) // TODO(pat.m): don't rely on default backbuffer
@@ -106,6 +102,7 @@ impl<F, H> ApplicationHandler for ApplicationHost<F, H>
 	where F: FnOnce(&Host) -> anyhow::Result<H>
 		, H: HostedApp + 'static
 {
+	#[instrument(skip_all, name="host start")]
 	fn resumed(&mut self, event_loop: &ActiveEventLoop) {
 		let ApplicationHost::Bootstrap(state, start_hostee) = std::mem::take(self) else { return };
 
@@ -125,6 +122,8 @@ impl<F, H> ApplicationHandler for ApplicationHost<F, H>
 		host.window.pre_present_notify();
 		host.swap();
 
+		mark_tracy_frame();
+
 		host.window.set_visible(true);
 		host.window.request_redraw();
 
@@ -154,6 +153,8 @@ impl<F, H> ApplicationHandler for ApplicationHost<F, H>
 
 				host.window.pre_present_notify();
 				host.swap();
+
+				mark_tracy_frame();
 			}
 
 			event @ WindowEvent::Resized(physical_size) => {
@@ -239,6 +240,7 @@ struct BootstrapState {
 }
 
 impl BootstrapState {
+	#[instrument(skip_all, name="host bootstrap")]
 	fn bootstrap(mut self, event_loop: &ActiveEventLoop) -> anyhow::Result<Host> {
 		// Try to fit window to monitor
 		if let Some(monitor) = event_loop.primary_monitor()
@@ -371,4 +373,37 @@ impl Host {
 			self.surface.resize(&self.context, width, height);
 		}
 	}
+}
+
+fn init_logging() {
+	let mut log_builder = env_logger::builder();
+	log_builder.parse_default_env();
+	log_builder.format_timestamp_millis();
+	log_builder.format_indent(None);
+
+	if cfg!(debug_assertions) {
+		log_builder.filter_level(log::LevelFilter::Debug);
+	}
+
+	log_builder.init();
+}
+
+#[cfg(feature="tracy")]
+fn init_tracy() {
+    use tracing_subscriber::layer::SubscriberExt;
+
+    let subscriber = tracing_subscriber::registry()
+        .with(tracing_tracy::TracyLayer::default());
+
+    tracing::subscriber::set_global_default(subscriber)
+    	.expect("set up the subscriber");
+
+	println!("tracy init");
+}
+
+fn mark_tracy_frame() {
+	#[cfg(feature="tracy")]
+	if let Some(client) = tracy_client::Client::running() {
+		client.frame_mark();
+	}
 }

toybox-vfs/Cargo.toml

@@ -6,6 +6,7 @@ authors.workspace = true
 
 [dependencies]
 log.workspace = true
+tracing.workspace = true
 anyhow.workspace = true
 
 serde.workspace = true

toybox-vfs/src/lib.rs

@@ -2,6 +2,7 @@
 
 use std::path::{Path, PathBuf};
 use anyhow::Context;
+use tracing::instrument;
 
 pub mod prelude {}
 
@@ -32,11 +33,13 @@ impl Vfs {
         Ok(self.resource_root.join(clean_path))
     }
 
+    #[instrument(skip_all)]
     pub fn load_resource_data(&self, virtual_path: impl AsRef<Path>) -> anyhow::Result<Vec<u8>> {
         let path = self.resource_path(virtual_path)?;
         std::fs::read(&path).map_err(Into::into)
     }
 
+    #[instrument(skip_all)]
     pub fn save_resource_data(&self, virtual_path: impl AsRef<Path>, data: &[u8]) -> anyhow::Result<()> {
         let path = self.resource_path(virtual_path)?;
 
@@ -47,13 +50,15 @@ impl Vfs {
         std::fs::write(path, &data).map_err(Into::into)
     }
 
+    #[instrument(skip_all)]
     pub fn load_json_resource<T>(&self, virtual_path: impl AsRef<Path>) -> anyhow::Result<T>
         where T: for<'a> serde::Deserialize<'a>
     {
     	let data = self.load_resource_data(virtual_path)?;
     	serde_json::from_slice(&data).map_err(Into::into)
     }
 
+    #[instrument(skip_all)]
     pub fn save_json_resource<T>(&self, virtual_path: impl AsRef<Path>, data: &T) -> anyhow::Result<()>
         where T: serde::Serialize
     {
@@ -99,6 +104,7 @@ fn clean_virtual_path(mut components: std::path::Components<'_>) -> anyhow::Resu
 
 
 
+#[instrument]
 fn find_resource_folder() -> anyhow::Result<PathBuf> {
     let mut dirs_scanned = Vec::new();
 
@@ -120,6 +126,7 @@ fn find_resource_folder() -> anyhow::Result<PathBuf> {
     anyhow::bail!("Couldn't find 'resource' folder in any directory above the executable path or working directory.\nScanned directories: {:?}", dirs_scanned)
 }
 
+#[instrument]
 fn try_find_resource_folder_from(search_dir: &Path, dirs_scanned: &mut Vec<PathBuf>) -> anyhow::Result<Option<PathBuf>> {
     // Try scanning the current search dir first, and then one directory above.
     for search_dir in search_dir.ancestors().take(2) {

toybox/Cargo.toml

@@ -38,9 +38,6 @@ log.workspace = true
 # symphonia = "0.4"
 
 tracing.workspace = true
-tracing-subscriber = "0.3"
-tracing-tracy = { version = "0.8", optional = true }
-
 
 # [dependencies.image]
 # version = "0.24"
@@ -68,5 +65,5 @@ tracing-tracy = { version = "0.8", optional = true }
 
 
 [features]
-tracy = ["dep:tracing-tracy"]
+tracy = ["toybox-host/tracy"]
 gamepad = ["toybox-input/gamepad"]

toybox/src/context.rs

@@ -21,12 +21,14 @@ pub struct Context {
 
 impl Context {
 	// Called at the very beginning of the frame, before any events are processed.
+	#[instrument(skip_all, name="toybox prepare_frame")]
 	pub(crate) fn prepare_frame(&mut self) {
 		self.audio.update();
 		self.input.reset_tracker();
 	}
 
 	// Called after events are processed, immediately before control is passed to the app.
+	#[instrument(skip_all, name="toybox start_frame")]
 	pub(crate) fn start_frame(&mut self) {
 		self.gfx.start_frame();
 		self.input.process();
@@ -43,12 +45,14 @@ impl Context {
 		}
 	}
 
+	#[instrument(skip_all, name="toybox notify_resized")]
 	pub(crate) fn notify_resized(&mut self, new_size: Vec2i) {
 		self.gfx.resize(new_size);
 		self.input.on_resize(new_size);
 	}
 
 	// Called after app returns control, before the frame ends.
+	#[instrument(skip_all, name="toybox finalize_frame")]
 	pub(crate) fn finalize_frame(&mut self) {
 		self.egui_integration.end_frame(&mut self.gfx);