feat: span tracing!!!

Cargo.toml

@@ -23,7 +23,7 @@ parking_lot = "0.12.1"
 portable-atomic = {version = "0.3.0", features = ["float", "std"]}
 rustc-hash = "1.1.0"
 slab = "0.4.6"
-tokio = { version = "1", features = ["rt", "signal", "tracing"] }
+tokio = { version = "1", features = ["rt", "signal"] }
 send_wrapper = "0.6.0"
 prisma = "0.1.1"
 slog = "2.7.0"
@@ -52,12 +52,16 @@ optional = true
 version = "0.1.8"
 optional = true
 
+[dependencies.tracing-chrome]
+version = "0.7.0"
+optional = true
 [features]
 default = ["wayland"]
 wayland = ["dep:smithay", "dep:xkbcommon"]
-profile = ["dep:console-subscriber"]
+profile_tokio = ["dep:console-subscriber", "tokio/tracing"]
+profile_app = ["dep:tracing-chrome"]
 
 # [patch.crates-io.stereokit]
 # path = "../stereokit-rs"
 # [patch.crates-io.stereokit-sys]
-# path = "../stereokit-sys"
+# path = "../stereokit-sys"

src/core/client.rs

@@ -1,6 +1,6 @@
 use super::scenegraph::Scenegraph;
 use crate::{
-	core::registry::OwnedRegistry,
+	core::{registry::OwnedRegistry, task},
 	nodes::{
 		data, drawable, fields, hmd, input, items,
 		root::Root,
@@ -119,12 +119,14 @@ impl Client {
 			})
 			.unwrap_or_else(|| "??".to_string());
 		let _ = client.dispatch_join_handle.get_or_try_init(|| {
-			tokio::task::Builder::new()
-				.name(&format!(
-					"client dispatch pid={} exe={}",
-					&pid_printable, &exe_printable,
-				))
-				.spawn({
+			task::new(
+				|| {
+					format!(
+						"client dispatch pid={} exe={}",
+						&pid_printable, &exe_printable,
+					)
+				},
+				{
 					let client = client.clone();
 					async move {
 						loop {
@@ -136,15 +138,13 @@ impl Client {
 							}
 						}
 					}
-				})
+				},
+			)
 		});
 		let _ = client.flush_join_handle.get_or_try_init(|| {
-			tokio::task::Builder::new()
-				.name(&format!(
-					"client flush pid={} exe={}",
-					&pid_printable, &exe_printable,
-				))
-				.spawn({
+			task::new(
+				|| format!("client flush pid={} exe={}", &pid_printable, &exe_printable,),
+				{
 					let client = client.clone();
 					async move {
 						loop {
@@ -156,7 +156,8 @@ impl Client {
 							}
 						}
 					}
-				})
+				},
+			)
 		});
 
 		client

src/core/eventloop.rs

@@ -1,4 +1,5 @@
 use super::client::Client;
+use super::task;
 use color_eyre::eyre::Result;
 use once_cell::sync::OnceCell;
 use stardust_xr::server;
@@ -26,14 +27,12 @@ impl EventLoop {
 			join_handle: OnceCell::new(),
 		});
 
-		let join_handle = tokio::task::Builder::new()
-			.name("event loop")
-			.spawn(async move {
-				loop {
-					let Ok((socket, _)) = socket.accept().await else { continue };
-					Client::from_connection(socket);
-				}
-			})?;
+		let join_handle = task::new(|| "event loop", async move {
+			loop {
+				let Ok((socket, _)) = socket.accept().await else { continue };
+				Client::from_connection(socket);
+			}
+		})?;
 		let _ = event_loop.join_handle.set(join_handle);
 
 		Ok(event_loop)

src/core/mod.rs

@@ -6,3 +6,4 @@ pub mod node_collections;
 pub mod registry;
 pub mod resource;
 pub mod scenegraph;
+pub mod task;

src/core/task.rs

@@ -0,0 +1,22 @@
+use color_eyre::eyre::Result;
+use std::future::Future;
+use tokio::task::JoinHandle;
+
+#[allow(unused_variables)]
+pub fn new<
+	F: FnOnce() -> S,
+	S: AsRef<str>,
+	A: Future<Output = O> + Send + 'static,
+	O: Send + 'static,
+>(
+	name_fn: F,
+	async_future: A,
+) -> Result<JoinHandle<O>> {
+	#[cfg(not(feature = "profile_tokio"))]
+	let result = Ok(tokio::task::spawn(async_future));
+	#[cfg(feature = "profile_tokio")]
+	let result = tokio::task::Builder::new()
+		.name(name_fn().as_ref())
+		.spawn(async_future);
+	result
+}

src/main.rs

@@ -23,7 +23,8 @@ use stereokit::render::StereoKitRender;
 use stereokit::texture::Texture;
 use stereokit::time::StereoKitTime;
 use tokio::{runtime::Handle, sync::oneshot};
-use tracing::info;
+use tracing::{debug_span, info};
+use tracing_subscriber::{fmt, prelude::*, EnvFilter};
 
 #[derive(Parser)]
 #[clap(author, version, about, long_about = None)]
@@ -42,10 +43,25 @@ struct CliArgs {
 }
 
 fn main() -> Result<()> {
-	#[cfg(not(feature = "profile"))]
-	tracing_subscriber::fmt::init();
-	#[cfg(feature = "profile")]
-	console_subscriber::init();
+	let registry = tracing_subscriber::registry();
+	#[cfg(feature = "profile_app")]
+	let (chrome_layer, _guard) = tracing_chrome::ChromeLayerBuilder::new()
+		.include_args(true)
+		.build();
+	#[cfg(feature = "profile_app")]
+	let registry = registry.with(chrome_layer);
+
+	#[cfg(feature = "profile_tokio")]
+	let (console_layer, _) = console_subscriber::ConsoleLayer::builder().build();
+	#[cfg(feature = "profile_tokio")]
+	let registry = registry.with(console_layer);
+
+	let log_layer = fmt::Layer::new()
+		.with_thread_names(true)
+		.with_ansi(true)
+		.with_filter(EnvFilter::from_default_env());
+	registry.with(log_layer).init();
+
 	let project_dirs = ProjectDirs::from("", "", "stardust").unwrap();
 	let cli_args = Arc::new(CliArgs::parse());
 
@@ -112,35 +128,40 @@ fn main() -> Result<()> {
 	#[cfg(feature = "wayland")]
 	let mut wayland = wayland::Wayland::new()?;
 	info!("Stardust ready!");
-	stereokit.run(
-		|sk| {
-			hmd::frame(sk);
-			#[cfg(feature = "wayland")]
-			wayland.frame(sk);
-			destroy_queue::clear();
+	debug_span!("StereoKit").in_scope(|| {
+		stereokit.run(
+			|sk| {
+				let _span = debug_span!("StereoKit step");
+				let _span = _span.enter();
 
-			if let Some(mouse_pointer) = &mouse_pointer {
-				mouse_pointer.update(sk);
-			}
-			if let Some(hands) = &mut hands {
-				hands[0].update(sk);
-				hands[1].update(sk);
-			}
-			if let Some(controllers) = &mut controllers {
-				controllers[0].update(sk);
-				controllers[1].update(sk);
-			}
-			input::process_input();
-			nodes::root::Root::logic_step(sk.time_elapsed());
-			drawable::draw(sk);
+				hmd::frame(sk);
+				#[cfg(feature = "wayland")]
+				wayland.frame(sk);
+				destroy_queue::clear();
 
-			#[cfg(feature = "wayland")]
-			wayland.make_context_current();
-		},
-		|_| {
-			info!("Cleanly shut down StereoKit");
-		},
-	);
+				if let Some(mouse_pointer) = &mouse_pointer {
+					mouse_pointer.update(sk);
+				}
+				if let Some(hands) = &mut hands {
+					hands[0].update(sk);
+					hands[1].update(sk);
+				}
+				if let Some(controllers) = &mut controllers {
+					controllers[0].update(sk);
+					controllers[1].update(sk);
+				}
+				input::process_input();
+				nodes::root::Root::logic_step(sk.time_elapsed());
+				drawable::draw(sk);
+
+				#[cfg(feature = "wayland")]
+				wayland.make_context_current();
+			},
+			|_| {
+				info!("Cleanly shut down StereoKit");
+			},
+		)
+	});
 
 	#[cfg(feature = "wayland")]
 	drop(wayland);

src/nodes/drawable/mod.rs

@@ -10,6 +10,7 @@ use serde::Deserialize;
 use stardust_xr::schemas::flex::deserialize;
 use std::{path::PathBuf, sync::Arc};
 use stereokit::{lifecycle::StereoKitDraw, render::StereoKitRender, texture::Texture};
+use tracing::instrument;
 
 pub fn create_interface(client: &Arc<Client>) {
 	let node = Node::create(client, "", "drawable", false);
@@ -20,6 +21,7 @@ pub fn create_interface(client: &Arc<Client>) {
 	node.add_to_scenegraph();
 }
 
+#[instrument(level = "debug", skip(sk))]
 pub fn draw(sk: &StereoKitDraw) {
 	lines::draw_all(sk);
 	model::draw_all(sk);

src/nodes/hmd.rs

@@ -6,6 +6,7 @@ use crate::{
 use glam::{vec3, Mat4};
 use std::sync::Arc;
 use stereokit::input::StereoKitInput;
+use tracing::instrument;
 
 lazy_static::lazy_static! {
 	static ref HMD: Arc<Node> = create();
@@ -18,6 +19,7 @@ fn create() -> Arc<Node> {
 	node
 }
 
+#[instrument(level = "debug", name = "Update HMD Pose", skip(sk))]
 pub fn frame(sk: &impl StereoKitInput) {
 	let spatial = HMD.spatial.get().unwrap();
 	let hmd_pose = sk.input_head();

src/nodes/input/mod.rs

@@ -11,9 +11,9 @@ use super::{
 	spatial::{find_spatial_parent, parse_transform, Spatial},
 	Node,
 };
-use crate::core::client::Client;
 use crate::core::eventloop::FRAME;
 use crate::core::registry::Registry;
+use crate::core::{client::Client, task};
 use color_eyre::eyre::{ensure, Result};
 use glam::Mat4;
 use nanoid::nanoid;
@@ -192,25 +192,23 @@ impl InputHandler {
 		let handler = Arc::downgrade(&distance_link.handler);
 
 		if let Ok(data) = node.execute_remote_method("input", data) {
-			let _ = tokio::task::Builder::new()
-				.name("input capture")
-				.spawn(async move {
-					if let Ok(data) = data.await {
-						if frame == FRAME.load(Ordering::Relaxed) {
-							let capture = flexbuffers::Reader::get_root(data.as_slice())
-								.and_then(|data| data.get_bool())
-								.unwrap_or(false);
+			let _ = task::new(|| "input capture", async move {
+				if let Ok(data) = data.await {
+					if frame == FRAME.load(Ordering::Relaxed) {
+						let capture = flexbuffers::Reader::get_root(data.as_slice())
+							.and_then(|data| data.get_bool())
+							.unwrap_or(false);
 
-							if capture {
-								if let Some(method) = method.upgrade() {
-									if let Some(handler) = handler.upgrade() {
-										method.captures.add_raw(&handler);
-									}
+						if capture {
+							if let Some(method) = method.upgrade() {
+								if let Some(handler) = handler.upgrade() {
+									method.captures.add_raw(&handler);
 								}
 							}
 						}
 					}
-				});
+				}
+			});
 		}
 	}
 }
@@ -249,6 +247,7 @@ pub fn create_input_handler_flex(
 	InputHandler::add_to(&node, &field)?;
 	Ok(())
 }
+#[tracing::instrument(level = "debug")]
 pub fn process_input() {
 	// Iterate over all valid input methods
 	for method in INPUT_METHOD_REGISTRY

src/nodes/root.rs

@@ -5,6 +5,7 @@ use crate::core::registry::Registry;
 use color_eyre::eyre::Result;
 use glam::Mat4;
 use stardust_xr::schemas::flex::{deserialize, serialize};
+use tracing::instrument;
 
 use std::sync::atomic::{AtomicBool, Ordering};
 use std::sync::Arc;
@@ -48,6 +49,7 @@ impl Root {
 		Ok(())
 	}
 
+	#[instrument(level = "debug")]
 	pub fn logic_step(delta: f64) {
 		if let Ok(data) = serialize((delta, 0.0)) {
 			for root in ROOT_REGISTRY.get_valid_contents() {

src/objects/input/mouse_pointer.rs

@@ -13,6 +13,7 @@ use nanoid::nanoid;
 use stardust_xr::{schemas::flat::Datamap, values::Transform};
 use std::{convert::TryFrom, sync::Arc};
 use stereokit::input::{ButtonState, Key, Ray as SkRay, StereoKitInput};
+use tracing::instrument;
 
 const SK_KEYMAP: &str = include_str!("sk.kmp");
 
@@ -45,6 +46,7 @@ impl MousePointer {
 			keyboard_sender,
 		}
 	}
+	#[instrument(level = "debug", name = "Update Flatscreen Pointer Ray", skip_all)]
 	pub fn update(&self, sk: &impl StereoKitInput) {
 		let mouse = sk.input_mouse();
 

src/objects/input/sk_controller.rs

@@ -6,6 +6,7 @@ use glam::Mat4;
 use stardust_xr::{schemas::flat::Datamap, values::Transform};
 use std::sync::{Arc, Weak};
 use stereokit::input::{ButtonState, Handed, StereoKitInput};
+use tracing::instrument;
 
 pub struct SkController {
 	tip: Arc<InputMethod>,
@@ -21,6 +22,7 @@ impl SkController {
 			handed,
 		}
 	}
+	#[instrument(level = "debug", name = "Update StereoKit Tip Input Method", skip_all)]
 	pub fn update(&mut self, sk: &impl StereoKitInput) {
 		let controller = sk.input_controller(self.handed);
 		*self.tip.enabled.lock() = controller.tracked.contains(ButtonState::Active);

src/objects/input/sk_hand.rs

@@ -9,6 +9,7 @@ use stereokit::{
 	input::{ButtonState, Handed, Joint as SkJoint, StereoKitInput},
 	lifecycle::StereoKitDraw,
 };
+use tracing::instrument;
 
 fn convert_joint(joint: SkJoint) -> Joint {
 	Joint {
@@ -37,6 +38,7 @@ impl SkHand {
 			handed,
 		}
 	}
+	#[instrument(level = "debug", name = "Update Hand Input Method", skip_all)]
 	pub fn update(&mut self, sk: &StereoKitDraw) {
 		let sk_hand = sk.input_hand(self.handed);
 		if let InputType::Hand(hand) = &mut *self.hand.specialization.lock() {

src/wayland/mod.rs

@@ -10,7 +10,7 @@ mod surface;
 mod xdg_shell;
 
 use self::{state::WaylandState, surface::CORE_SURFACES};
-use crate::wayland::state::ClientState;
+use crate::{core::task, wayland::state::ClientState};
 use color_eyre::eyre::{ensure, Result};
 use global_counter::primitive::exact::CounterU32;
 use once_cell::sync::OnceCell;
@@ -31,7 +31,7 @@ use stereokit as sk;
 use tokio::{
 	io::unix::AsyncFd, net::UnixListener as AsyncUnixListener, sync::mpsc, task::JoinHandle,
 };
-use tracing::info;
+use tracing::{info, instrument};
 
 pub static SERIAL_COUNTER: CounterU32 = CounterU32::new(0);
 
@@ -123,33 +123,32 @@ impl Wayland {
 		let dh1 = display.lock().handle();
 		let mut dh2 = dh1.clone();
 
-		Ok(tokio::task::Builder::new()
-			.name("wayland loop")
-			.spawn(async move {
-				let _socket = socket; // Keep the socket alive
-				loop {
-					tokio::select! {
-						e = global_destroy_queue.recv() => { // New global to destroy
-							dh1.remove_global::<WaylandState>(e.unwrap());
-						}
-						acc = listen_async.accept() => { // New client connected
-							let (stream, _) = acc?;
-							let client = dh2.insert_client(stream.into_std()?, Arc::new(ClientState))?;
+		Ok(task::new(|| "wayland loop", async move {
+			let _socket = socket; // Keep the socket alive
+			loop {
+				tokio::select! {
+					e = global_destroy_queue.recv() => { // New global to destroy
+						dh1.remove_global::<WaylandState>(e.unwrap());
+					}
+					acc = listen_async.accept() => { // New client connected
+						let (stream, _) = acc?;
+						let client = dh2.insert_client(stream.into_std()?, Arc::new(ClientState))?;
 
-							state.lock().new_client(client.id(), &dh2);
-						}
-						e = dispatch_poll_listener.readable() => { // Dispatch
-							let mut guard = e?;
-							let mut display = display.lock();
-							display.dispatch_clients(&mut *state.lock())?;
-							display.flush_clients()?;
-							guard.clear_ready();
-						}
+						state.lock().new_client(client.id(), &dh2);
+					}
+					e = dispatch_poll_listener.readable() => { // Dispatch
+						let mut guard = e?;
+						let mut display = display.lock();
+						display.dispatch_clients(&mut *state.lock())?;
+						display.flush_clients()?;
+						guard.clear_ready();
 					}
 				}
-			})?)
+			}
+		})?)
 	}
 
+	#[instrument(level = "debug", name = "Wayland frame", skip(self, sk))]
 	pub fn frame(&mut self, sk: &StereoKitDraw) {
 		for core_surface in CORE_SURFACES.get_valid_contents() {
 			let state = self.state.lock();

src/wayland/seat.rs

@@ -1,3 +1,5 @@
+use crate::core::task;
+
 use super::{
 	panel_item::PanelItem, state::WaylandState, surface::CoreSurface, GLOBAL_DESTROY_QUEUE,
 	SERIAL_COUNTER,
@@ -148,9 +150,9 @@ impl SeatDataInner {
 impl Drop for SeatDataInner {
 	fn drop(&mut self) {
 		let id = self.global_id.take().unwrap();
-		let _ = tokio::task::Builder::new()
-			.name("global destroy queue garbage collection")
-			.spawn(async move { GLOBAL_DESTROY_QUEUE.get().unwrap().send(id).await });
+		let _ = task::new(|| "global destroy queue garbage collection", async move {
+			GLOBAL_DESTROY_QUEUE.get().unwrap().send(id).await
+		});
 	}
 }