Update tracy crates, reduce overhead of timing, add more misc instrumentation

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",

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"
 

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.

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(_))) {

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,
+        );
     };
 }
 

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']
+features = ['crossterm']

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 {

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"

voxygen/src/logging.rs

@@ -93,7 +93,9 @@ pub fn init(settings: &Settings) -> Vec<impl Drop> {
                 .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<impl Drop> {
                 .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.");