diff --git a/Cargo.lock b/Cargo.lock index 58b7176035..92d63ce3d1 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -4644,6 +4644,35 @@ dependencies = [ "tracing-log", ] +[[package]] +name = "tracing-tracy" +version = "0.1.2" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "5f4c1889876942b9084677f5892b0bcf356e5265613e8a9834e7a7a30aa328ce" +dependencies = [ + "tracing-core", + "tracing-subscriber", + "tracy-client", +] + +[[package]] +name = "tracy-client" +version = "0.7.3" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "691a51a61f793699b6f2cd0e2dc1e803c29c757a5ef3159a2c1ace8bc6efbebc" +dependencies = [ + "tracy-client-sys", +] + +[[package]] +name = "tracy-client-sys" +version = "0.8.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "ba2668b37da9ba8981788b141037ef31f0e05af06addfdf75c3dd8cc0f2ce475" +dependencies = [ + "cc", +] + [[package]] name = "treeculler" version = "0.1.0" @@ -5008,6 +5037,7 @@ dependencies = [ "tracing-appender", "tracing-log", "tracing-subscriber", + "tracing-tracy", "treeculler", "uvth 3.1.1", "vek 0.12.0", diff --git a/common/src/util/mod.rs b/common/src/util/mod.rs index 21fe9a89ac..1922ee5014 100644 --- a/common/src/util/mod.rs +++ b/common/src/util/mod.rs @@ -10,3 +10,20 @@ lazy_static::lazy_static! { pub use color::*; pub use dir::*; + +// https://discordapp.com/channels/676678179678715904/676685797524766720/723358438943621151 +#[macro_export] +macro_rules! span { + ($guard_name:tt, $level:ident, $name:expr, $($fields:tt)*) => { + let span = tracing::span!(tracing::Level::$level, $name, $($fields)*); + let $guard_name = span.enter(); + }; + ($guard_name:tt, $level:ident, $name:expr) => { + let span = tracing::span!(tracing::Level::$level, $name); + let $guard_name = span.enter(); + }; + ($guard_name:tt, $name:expr) => { + let span = tracing::span!(tracing::Level::INFO, $name); + let $guard_name = span.enter(); + }; +} diff --git a/voxygen/Cargo.toml b/voxygen/Cargo.toml index ec61346b9a..47b11f6f3a 100644 --- a/voxygen/Cargo.toml +++ b/voxygen/Cargo.toml @@ -12,6 +12,7 @@ version = "0.7.0" gl = ["gfx_device_gl", "gfx_gl"] hot-anim = ["anim/use-dyn-lib"] singleplayer = ["server"] +tracy = ["tracing-tracy"] tweak = ["const-tweaker"] default = ["gl", "singleplayer", "msgbox"] @@ -81,6 +82,9 @@ tracing-appender = "0.1" tracing-log = "0.1.1" tracing-subscriber = {version = "0.2.3", default-features = false, features = ["env-filter", "fmt", "chrono", "ansi", "smallvec", "tracing-log"]} +# Tracy +tracing-tracy = { version = "0.1.2", optional = true } + [target.'cfg(target_os = "macos")'.dependencies] dispatch = "0.1.4" diff --git a/voxygen/src/logging.rs b/voxygen/src/logging.rs index 3d52b98a3a..2455dedf97 100644 --- a/voxygen/src/logging.rs +++ b/voxygen/src/logging.rs @@ -77,11 +77,13 @@ pub fn init(settings: &Settings) -> Vec { tracing_appender::rolling::daily(&settings.log.logs_path, LOG_FILENAME); let (non_blocking_file, _file_guard) = tracing_appender::non_blocking(file_appender); _guards.push(_file_guard); - registry() + let subscriber = registry() .with(tracing_subscriber::fmt::layer().with_writer(non_blocking)) .with(tracing_subscriber::fmt::layer().with_writer(non_blocking_file)) - .with(filter) - .init(); + .with(filter); + #[cfg(feature = "tracy")] + let subscriber = subscriber.with(tracing_tracy::TracyLayer::new()); + subscriber.init(); let logdir = &settings.log.logs_path; info!(?logdir, "Setup terminal and file logging."); }, @@ -91,10 +93,12 @@ pub fn init(settings: &Settings) -> Vec { ?e, "Failed to create log file!. Falling back to terminal logging only.", ); - registry() + let subscriber = registry() .with(tracing_subscriber::fmt::layer().with_writer(non_blocking)) - .with(filter) - .init(); + .with(filter); + #[cfg(feature = "tracy")] + let subscriber = subscriber.with(tracing_tracy::TracyLayer::new()); + subscriber.init(); info!("Setup terminal logging."); }, }; diff --git a/voxygen/src/run.rs b/voxygen/src/run.rs index 6f0d3a954a..8b3a28d76a 100644 --- a/voxygen/src/run.rs +++ b/voxygen/src/run.rs @@ -4,6 +4,7 @@ use crate::{ window::{Event, EventLoop}, Direction, GlobalState, PlayState, PlayStateResult, }; +use common::span; use std::{mem, time::Duration}; use tracing::debug; @@ -22,6 +23,12 @@ pub fn run(mut global_state: GlobalState, event_loop: EventLoop) { // See: https://github.com/rust-windowing/winit/issues/1418 let mut polled_twice = false; + let mut poll_span = None::; + let mut event_span = None::; + // Assumes dispatcher does not change + let dispatcher = tracing::dispatcher::get_default(|d| d.clone()); + tracing::info_span!("Process Events"); + event_loop.run(move |event, _, control_flow| { // Continuously run loop since we handle sleeping *control_flow = winit::event_loop::ControlFlow::Poll; @@ -32,16 +39,36 @@ pub fn run(mut global_state: GlobalState, event_loop: EventLoop) { } match event { + winit::event::Event::NewEvents(_) => { + if event_span.is_none() { + let span = tracing::info_span!("Proccess Events"); + span.id().map(|id| dispatcher.enter(&id)); + event_span = Some(span); + } + }, winit::event::Event::MainEventsCleared => { + event_span + .take() + .map(|s| s.id().map(|id| dispatcher.exit(&id))); + poll_span + .take() + .map(|s| s.id().map(|id| dispatcher.exit(&id))); if polled_twice { handle_main_events_cleared(&mut states, control_flow, &mut global_state); } + let span = tracing::info_span!("Poll Winit"); + span.id().map(|id| dispatcher.enter(&id)); + poll_span = Some(span); polled_twice = !polled_twice; }, - winit::event::Event::WindowEvent { event, .. } => global_state - .window - .handle_window_event(event, &mut global_state.settings), + winit::event::Event::WindowEvent { event, .. } => { + span!(_guard, "Handle WindowEvent"); + global_state + .window + .handle_window_event(event, &mut global_state.settings) + }, winit::event::Event::DeviceEvent { event, .. } => { + span!(_guard, "Handle DeviceEvent"); global_state.window.handle_device_event(event) }, winit::event::Event::LoopDestroyed => { @@ -59,6 +86,7 @@ fn handle_main_events_cleared( control_flow: &mut winit::event_loop::ControlFlow, global_state: &mut GlobalState, ) { + span!(guard, "Handle MainEventsCleared"); // Screenshot / Fullscreen toggle global_state .window @@ -77,16 +105,20 @@ fn handle_main_events_cleared( let mut exit = true; while let Some(state_result) = states.last_mut().map(|last| { let events = global_state.window.fetch_events(); + span!(_guard, "Tick current playstate"); last.tick(global_state, events) }) { // Implement state transfer logic. match state_result { PlayStateResult::Continue => { // Wait for the next tick. + drop(guard); + span!(_guard, "Main thread sleep"); global_state.clock.tick(Duration::from_millis( 1000 / global_state.settings.graphics.max_fps as u64, )); + span!(_guard, "Maintain global state"); // Maintain global state. global_state.maintain(global_state.clock.get_last_delta().as_secs_f32()); @@ -137,6 +169,7 @@ fn handle_main_events_cleared( } if let Some(last) = states.last_mut() { + span!(_guard, "Render"); let renderer = global_state.window.renderer_mut(); // Clear the shadow maps. renderer.clear_shadows();