diff --git a/Cargo.lock b/Cargo.lock index 92d63ce3d1..cf7c15526c 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -4646,9 +4646,9 @@ dependencies = [ [[package]] name = "tracing-tracy" -version = "0.1.2" +version = "0.2.0" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "5f4c1889876942b9084677f5892b0bcf356e5265613e8a9834e7a7a30aa328ce" +checksum = "d4f1c3ed7f680cf645838f62e8dd1f64cd3820ad1af0b8d9585fd69d97f0feab" dependencies = [ "tracing-core", "tracing-subscriber", @@ -4657,18 +4657,18 @@ dependencies = [ [[package]] name = "tracy-client" -version = "0.7.3" +version = "0.8.0" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "691a51a61f793699b6f2cd0e2dc1e803c29c757a5ef3159a2c1ace8bc6efbebc" +checksum = "650c280019cd1a841752d50f6a834216a2c8a810aeb18bdd48054be23cacd8a6" dependencies = [ "tracy-client-sys", ] [[package]] name = "tracy-client-sys" -version = "0.8.0" +version = "0.9.0" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "ba2668b37da9ba8981788b141037ef31f0e05af06addfdf75c3dd8cc0f2ce475" +checksum = "c07e4636dad390858d247cf2633eaea90e67d7e21151cd476bbfd070d321279f" dependencies = [ "cc", ] @@ -4939,6 +4939,7 @@ dependencies = [ "specs-idvs", "sum_type", "tracing", + "tracy-client", "vek 0.12.0", ] @@ -4986,6 +4987,7 @@ dependencies = [ "lazy_static", "tracing", "tracing-subscriber", + "tracing-tracy", "tui", "veloren-common", "veloren-server", @@ -5038,6 +5040,7 @@ dependencies = [ "tracing-log", "tracing-subscriber", "tracing-tracy", + "tracy-client", "treeculler", "uvth 3.1.1", "vek 0.12.0", diff --git a/common/Cargo.toml b/common/Cargo.toml index 37037b9aec..b91d8e398a 100644 --- a/common/Cargo.toml +++ b/common/Cargo.toml @@ -6,6 +6,7 @@ edition = "2018" [features] no-assets = [] +tracy = ["tracy-client"] [dependencies] arraygen = "0.1.13" @@ -34,6 +35,9 @@ authc = { git = "https://gitlab.com/veloren/auth.git", rev = "b943c85e4a38f5ec60 slab = "0.4.2" enum-iterator = "0.6" +# Tracy +tracy-client = { version = "0.8.0", optional = true } + [dev-dependencies] criterion = "0.3" diff --git a/common/src/clock.rs b/common/src/clock.rs index 10f9d7601c..e819b5d17d 100644 --- a/common/src/clock.rs +++ b/common/src/clock.rs @@ -1,3 +1,4 @@ +use crate::span; use std::{ thread, time::{Duration, Instant}, @@ -31,6 +32,7 @@ impl Clock { pub fn get_avg_delta(&self) -> Duration { Duration::from_secs_f64(self.running_tps_average) } pub fn tick(&mut self, tgt: Duration) { + span!(_guard, "Clock::tick"); let delta = Instant::now().duration_since(self.last_sys_time); // Attempt to sleep to fill the gap. diff --git a/common/src/sys/agent.rs b/common/src/sys/agent.rs index 48cdfd66c1..aa4b89e413 100644 --- a/common/src/sys/agent.rs +++ b/common/src/sys/agent.rs @@ -84,6 +84,7 @@ impl<'a> System<'a> for Sys { invites, ): Self::SystemData, ) { + span!(_guard, "agent::Sys::run"); for ( entity, pos, @@ -117,7 +118,6 @@ impl<'a> System<'a> for Sys { ) .join() { - span!(_guard, "agent::Sys::run"); // Hack, replace with better system when groups are more sophisticated // Override alignment if in a group unless entity is owned already let alignment = if !matches!(alignment, Some(Alignment::Owned(_))) { diff --git a/common/src/util/mod.rs b/common/src/util/mod.rs index 80bd2ed934..c17e88f832 100644 --- a/common/src/util/mod.rs +++ b/common/src/util/mod.rs @@ -23,8 +23,20 @@ macro_rules! span { let $guard_name = span.enter(); }; ($guard_name:tt, $name:expr) => { + #[cfg(not(feature = "tracy"))] let span = tracing::span!(tracing::Level::TRACE, $name); + #[cfg(not(feature = "tracy"))] let $guard_name = span.enter(); + // Directly use `tracy_client` to decrease overhead for better timing + #[cfg(feature = "tracy")] + let $guard_name = tracy_client::Span::new( + $name, + "", + module_path!(), + line!(), + // No callstack since this has significant overhead + 0, + ); }; } diff --git a/server-cli/Cargo.toml b/server-cli/Cargo.toml index cdb05ded2a..4065998b8d 100644 --- a/server-cli/Cargo.toml +++ b/server-cli/Cargo.toml @@ -7,20 +7,24 @@ edition = "2018" [features] worldgen = ["server/worldgen"] default = ["worldgen"] +tracy = ["common/tracy", "tracing-tracy"] [dependencies] server = { package = "veloren-server", path = "../server", default-features = false } common = { package = "veloren-common", path = "../common" } -tracing = { version = "0.1", default-features = false } -tracing-subscriber = { version = "0.2.3", default-features = false, features = ["env-filter", "fmt", "chrono", "ansi", "smallvec"] } -crossterm = "0.17" -lazy_static = "1" ansi-parser = "0.6" clap = "2.33" +crossterm = "0.17" +lazy_static = "1" +tracing = { version = "0.1", default-features = false } +tracing-subscriber = { version = "0.2.3", default-features = false, features = ["env-filter", "fmt", "chrono", "ansi", "smallvec"] } + +# Tracy +tracing-tracy = { version = "0.2.0", optional = true } [dependencies.tui] git = "https://github.com/fdehau/tui-rs.git" branch="paragraph-scroll" default-features = false -features = ['crossterm'] \ No newline at end of file +features = ['crossterm'] diff --git a/server-cli/src/main.rs b/server-cli/src/main.rs index 526c1be55d..e111f645b7 100644 --- a/server-cli/src/main.rs +++ b/server-cli/src/main.rs @@ -12,7 +12,9 @@ use crate::{ use common::clock::Clock; use server::{Event, Input, Server, ServerSettings}; use tracing::{info, Level}; -use tracing_subscriber::{filter::LevelFilter, EnvFilter, FmtSubscriber}; +use tracing_subscriber::{ + filter::LevelFilter, layer::SubscriberExt, prelude::*, EnvFilter, FmtSubscriber, +}; use clap::{App, Arg}; use std::{io, sync::mpsc, time::Duration}; @@ -49,6 +51,7 @@ fn main() -> io::Result<()> { let (mut tui, msg_r) = Tui::new(); // Init logging + #[cfg(not(feature = "tracy"))] let filter = match std::env::var_os(RUST_LOG_ENV).map(|s| s.into_string()) { Some(Ok(env)) => { let mut filter = EnvFilter::new("veloren_world::sim=info") @@ -68,14 +71,22 @@ fn main() -> io::Result<()> { .add_directive(LevelFilter::INFO.into()), }; - let subscriber = FmtSubscriber::builder() - .with_max_level(Level::ERROR) - .with_env_filter(filter); + #[cfg(feature = "tracy")] + tracing_subscriber::registry() + .with(tracing_tracy::TracyLayer::new().with_stackdepth(0)) + .init(); - if basic { - subscriber.init(); - } else { - subscriber.with_writer(|| LOG.clone()).init(); + #[cfg(not(feature = "tracy"))] + { + let subscriber = FmtSubscriber::builder() + .with_max_level(Level::ERROR) + .with_env_filter(filter); + + if basic { + subscriber.init(); + } else { + subscriber.with_writer(|| LOG.clone()).init(); + } } tui.run(basic); @@ -111,6 +122,7 @@ fn main() -> io::Result<()> { // Clean up the server after a tick. server.cleanup(); + tracing::trace!(tracy.frame_mark = true); match msg_r.try_recv() { Ok(msg) => match msg { diff --git a/voxygen/Cargo.toml b/voxygen/Cargo.toml index 47b11f6f3a..b2764f4910 100644 --- a/voxygen/Cargo.toml +++ b/voxygen/Cargo.toml @@ -12,7 +12,7 @@ version = "0.7.0" gl = ["gfx_device_gl", "gfx_gl"] hot-anim = ["anim/use-dyn-lib"] singleplayer = ["server"] -tracy = ["tracing-tracy"] +tracy = ["tracing-tracy", "tracy-client", "common/tracy"] tweak = ["const-tweaker"] default = ["gl", "singleplayer", "msgbox"] @@ -83,7 +83,8 @@ 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 } +tracing-tracy = { version = "0.2.0", optional = true } +tracy-client = { version = "0.8.0", 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 672b796f6d..95bc5678ad 100644 --- a/voxygen/src/logging.rs +++ b/voxygen/src/logging.rs @@ -93,7 +93,9 @@ pub fn init(settings: &Settings) -> Vec { .init(); #[cfg(feature = "tracy")] registry() - .with(tracing_tracy::TracyLayer::new()) + // NOTE: collecting stacks has a significant overhead (x6 overhead of + // starting/stopping a span through the layer interface) + .with(tracing_tracy::TracyLayer::new().with_stackdepth(0)) .with(filter) .init(); let logdir = &settings.log.logs_path; @@ -111,7 +113,7 @@ pub fn init(settings: &Settings) -> Vec { .with(filter); #[cfg(feature = "tracy")] registry() - .with(tracing_tracy::TracyLayer::new()) + .with(tracing_tracy::TracyLayer::new().with_stackdepth(0)) .with(filter) .init(); info!("Setup terminal logging.");