diff --git a/.cargo/config b/.cargo/config index 6184721f7e..745130059d 100644 --- a/.cargo/config +++ b/.cargo/config @@ -6,6 +6,8 @@ rustflags = [ [alias] generate = "run --package tools --" test-server = "-Zpackage-features run --bin veloren-server-cli --no-default-features" +tracy-server = "-Zunstable-options -Zpackage-features run --bin veloren-server-cli --no-default-features --features tracy --profile no_overflow" test-voxygen = "-Zpackage-features run --bin veloren-voxygen --no-default-features --features gl" +tracy-voxygen = "-Zunstable-options -Zpackage-features run --bin veloren-voxygen --no-default-features --features tracy,gl --profile no_overflow" server = "run --bin veloren-server-cli" diff --git a/Cargo.lock b/Cargo.lock index c39b6fc757..98b7f50da7 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -4357,6 +4357,35 @@ dependencies = [ "tracing-serde", ] +[[package]] +name = "tracing-tracy" +version = "0.2.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "d4f1c3ed7f680cf645838f62e8dd1f64cd3820ad1af0b8d9585fd69d97f0feab" +dependencies = [ + "tracing-core", + "tracing-subscriber", + "tracy-client", +] + +[[package]] +name = "tracy-client" +version = "0.8.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "650c280019cd1a841752d50f6a834216a2c8a810aeb18bdd48054be23cacd8a6" +dependencies = [ + "tracy-client-sys", +] + +[[package]] +name = "tracy-client-sys" +version = "0.9.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "c07e4636dad390858d247cf2633eaea90e67d7e21151cd476bbfd070d321279f" +dependencies = [ + "cc", +] + [[package]] name = "treeculler" version = "0.1.0" @@ -4623,6 +4652,7 @@ dependencies = [ "specs-idvs", "sum_type", "tracing", + "tracy-client", "vek 0.12.0", ] @@ -4670,6 +4700,7 @@ dependencies = [ "lazy_static", "tracing", "tracing-subscriber", + "tracing-tracy", "tui", "veloren-common", "veloren-server", @@ -4721,6 +4752,7 @@ dependencies = [ "tracing-appender", "tracing-log", "tracing-subscriber", + "tracing-tracy", "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..02d4946e5f 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, "tick", "Clock::tick"); let delta = Instant::now().duration_since(self.last_sys_time); // Attempt to sleep to fill the gap. diff --git a/common/src/path.rs b/common/src/path.rs index cf02e684ae..f065f5f2db 100644 --- a/common/src/path.rs +++ b/common/src/path.rs @@ -1,5 +1,6 @@ use crate::{ astar::{Astar, PathResult}, + span, terrain::Block, vol::{BaseVol, ReadVol}, }; @@ -327,6 +328,7 @@ impl Chaser { where V: BaseVol + ReadVol, { + span!(_guard, "chase", "Chaser::chase"); let pos_to_tgt = pos.distance(tgt); // If we're already close to the target then there's nothing to do diff --git a/common/src/ray.rs b/common/src/ray.rs index f0e412975e..7f58dc3926 100644 --- a/common/src/ray.rs +++ b/common/src/ray.rs @@ -1,4 +1,7 @@ -use crate::vol::{ReadVol, Vox}; +use crate::{ + span, + vol::{ReadVol, Vox}, +}; use vek::*; pub trait RayUntil = FnMut(&V) -> bool; @@ -52,6 +55,7 @@ impl<'a, V: ReadVol, F: RayUntil, G: RayForEach> Ray<'a, V, F, G } pub fn cast(mut self) -> (f32, Result, V::Error>) { + span!(_guard, "cast", "Ray::cast"); // TODO: Fully test this! const PLANCK: f32 = 0.001; diff --git a/common/src/region.rs b/common/src/region.rs index 4a36a49179..23428ba63b 100644 --- a/common/src/region.rs +++ b/common/src/region.rs @@ -1,4 +1,7 @@ -use crate::comp::{Pos, Vel}; +use crate::{ + comp::{Pos, Vel}, + span, +}; use hashbrown::{hash_map::DefaultHashBuilder, HashSet}; use indexmap::IndexMap; use specs::{hibitset::BitSetLike, BitSet, Entities, Join, ReadStorage}; @@ -104,6 +107,7 @@ impl RegionMap { // TODO maintain within a system? // TODO special case large entities pub fn tick(&mut self, pos: ReadStorage, vel: ReadStorage, entities: Entities) { + span!(_guard, "tick", "Region::tick"); self.tick += 1; // Clear events within each region for i in 0..self.regions.len() { diff --git a/common/src/sys/agent.rs b/common/src/sys/agent.rs index 6078121477..f6e7099e51 100644 --- a/common/src/sys/agent.rs +++ b/common/src/sys/agent.rs @@ -11,6 +11,7 @@ use crate::{ }, event::{EventBus, ServerEvent}, path::{Chaser, TraversalConfig}, + span, state::{DeltaTime, Time}, sync::{Uid, UidAllocator}, terrain::TerrainGrid, @@ -83,6 +84,7 @@ impl<'a> System<'a> for Sys { invites, ): Self::SystemData, ) { + span!(_guard, "run", "agent::Sys::run"); for ( entity, pos, diff --git a/common/src/sys/character_behavior.rs b/common/src/sys/character_behavior.rs index 591a46e227..d193bc6853 100644 --- a/common/src/sys/character_behavior.rs +++ b/common/src/sys/character_behavior.rs @@ -4,6 +4,7 @@ use crate::{ Loadout, Mounting, Ori, PhysicsState, Pos, StateUpdate, Stats, Vel, }, event::{EventBus, LocalEvent, ServerEvent}, + span, state::DeltaTime, states, sync::{Uid, UidAllocator}, @@ -183,6 +184,7 @@ impl<'a> System<'a> for Sys { mountings, ): Self::SystemData, ) { + span!(_guard, "run", "character_behavior::Sys::run"); let mut server_emitter = server_bus.emitter(); let mut local_emitter = local_bus.emitter(); diff --git a/common/src/sys/combat.rs b/common/src/sys/combat.rs index 2495fc8062..98d340f162 100644 --- a/common/src/sys/combat.rs +++ b/common/src/sys/combat.rs @@ -4,6 +4,7 @@ use crate::{ Loadout, Ori, Pos, Scale, Stats, }, event::{EventBus, LocalEvent, ServerEvent}, + span, sync::Uid, util::Dir, }; @@ -52,6 +53,7 @@ impl<'a> System<'a> for Sys { character_states, ): Self::SystemData, ) { + span!(_guard, "run", "combat::Sys::run"); let mut server_emitter = server_bus.emitter(); let mut local_emitter = local_bus.emitter(); // Attacks diff --git a/common/src/sys/controller.rs b/common/src/sys/controller.rs index 055f7e8dd4..ba76d3c949 100644 --- a/common/src/sys/controller.rs +++ b/common/src/sys/controller.rs @@ -4,6 +4,7 @@ use crate::{ CharacterState, ControlEvent, Controller, InventoryManip, }, event::{EventBus, LocalEvent, ServerEvent}, + span, state::DeltaTime, sync::{Uid, UidAllocator}, }; @@ -43,6 +44,7 @@ impl<'a> System<'a> for Sys { uids, ): Self::SystemData, ) { + span!(_guard, "run", "controller::Sys::run"); let mut server_emitter = server_bus.emitter(); for (entity, _uid, controller, character_state) in diff --git a/common/src/sys/mount.rs b/common/src/sys/mount.rs index e40a77be0b..a6fbfb8c9d 100644 --- a/common/src/sys/mount.rs +++ b/common/src/sys/mount.rs @@ -1,5 +1,6 @@ use crate::{ comp::{Controller, MountState, Mounting, Ori, Pos, Vel}, + span, sync::UidAllocator, }; use specs::{ @@ -36,6 +37,7 @@ impl<'a> System<'a> for Sys { mut orientations, ): Self::SystemData, ) { + span!(_guard, "run", "mount::Sys::run"); // Mounted entities. for (entity, mut mount_states) in (&entities, &mut mount_state.restrict_mut()).join() { match mount_states.get_unchecked() { diff --git a/common/src/sys/phys.rs b/common/src/sys/phys.rs index 9294c6c869..09b110fc46 100644 --- a/common/src/sys/phys.rs +++ b/common/src/sys/phys.rs @@ -4,6 +4,7 @@ use crate::{ Sticky, Vel, }, event::{EventBus, ServerEvent}, + span, state::DeltaTime, sync::{Uid, UidAllocator}, terrain::{Block, BlockKind, TerrainGrid}, @@ -94,9 +95,11 @@ impl<'a> System<'a> for Sys { projectiles, ): Self::SystemData, ) { + span!(_guard, "run", "phys::Sys::run"); let mut event_emitter = event_bus.emitter(); // Add/reset physics state components + span!(guard, "Add/reset physics state components"); for (entity, _, _, _, _) in ( &entities, &colliders, @@ -110,6 +113,7 @@ impl<'a> System<'a> for Sys { .entry(entity) .map(|e| e.or_insert_with(Default::default)); } + drop(guard); // Apply pushback // @@ -124,6 +128,7 @@ impl<'a> System<'a> for Sys { // terrain collision code below, although that's not trivial to do since // it means the step needs to take into account the speeds of both // entities. + span!(guard, "Apply pushback"); for (entity, pos, scale, mass, collider, _, _, physics, projectile) in ( &entities, &positions, @@ -244,8 +249,10 @@ impl<'a> System<'a> for Sys { .get_mut(entity) .map(|vel| vel.0 += vel_delta * dt.0); } + drop(guard); // Apply movement inputs + span!(guard, "Apply movement and terrain collision"); let land_on_grounds = ( &entities, scales.maybe(), @@ -646,6 +653,7 @@ impl<'a> System<'a> for Sys { land_on_grounds_a.append(&mut land_on_grounds_b); land_on_grounds_a }); + drop(guard); land_on_grounds.into_iter().for_each(|(entity, vel)| { event_emitter.emit(ServerEvent::LandOnGround { entity, vel: vel.0 }); diff --git a/common/src/sys/projectile.rs b/common/src/sys/projectile.rs index 342ee6050d..f0254e6b13 100644 --- a/common/src/sys/projectile.rs +++ b/common/src/sys/projectile.rs @@ -4,6 +4,7 @@ use crate::{ Loadout, Ori, PhysicsState, Pos, Projectile, Vel, }, event::{EventBus, LocalEvent, ServerEvent}, + span, state::DeltaTime, sync::UidAllocator, util::Dir, @@ -48,6 +49,7 @@ impl<'a> System<'a> for Sys { loadouts, ): Self::SystemData, ) { + span!(_guard, "run", "projectile::Sys::run"); let mut local_emitter = local_bus.emitter(); let mut server_emitter = server_bus.emitter(); diff --git a/common/src/sys/stats.rs b/common/src/sys/stats.rs index 8576754f59..b35dc02e26 100644 --- a/common/src/sys/stats.rs +++ b/common/src/sys/stats.rs @@ -1,6 +1,7 @@ use crate::{ comp::{CharacterState, Energy, EnergySource, HealthSource, Stats}, event::{EventBus, ServerEvent}, + span, state::DeltaTime, }; use specs::{Entities, Join, Read, ReadStorage, System, WriteStorage}; @@ -24,6 +25,7 @@ impl<'a> System<'a> for Sys { &mut self, (entities, dt, server_event_bus, character_states, mut stats, mut energies): Self::SystemData, ) { + span!(_guard, "run", "stats::Sys::run"); let mut server_event_emitter = server_event_bus.emitter(); // Increment last change timer diff --git a/common/src/util/mod.rs b/common/src/util/mod.rs index 21fe9a89ac..1c6940a201 100644 --- a/common/src/util/mod.rs +++ b/common/src/util/mod.rs @@ -10,3 +10,77 @@ lazy_static::lazy_static! { pub use color::*; pub use dir::*; + +#[cfg(feature = "tracy")] pub use tracy_client; + +// 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) => { + #[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 = $crate::util::tracy_client::Span::new( + $name, + "", + module_path!(), + line!(), + // No callstack since this has significant overhead + 0, + ); + }; + ($guard_name:tt, $no_tracy_name:expr, $tracy_name:expr) => { + #[cfg(not(feature = "tracy"))] + $crate::span!($guard_name, $no_tracy_name); + #[cfg(feature = "tracy")] + $crate::span!($guard_name, $tracy_name); + }; +} + +/// There's no guard, but really this is actually the guard +pub struct GuardlessSpan { + span: tracing::Span, + subscriber: tracing::Dispatch, +} + +impl GuardlessSpan { + pub fn new(span: tracing::Span) -> Self { + let subscriber = tracing::dispatcher::get_default(|d| d.clone()); + span.id().map(|id| subscriber.enter(&id)); + Self { span, subscriber } + } +} + +impl Drop for GuardlessSpan { + fn drop(&mut self) { self.span.id().map(|id| self.subscriber.exit(&id)); } +} + +#[macro_export] +macro_rules! no_guard_span { + ($level:ident, $name:expr, $($fields:tt)*) => { + GuardlessSpan::new( + tracing::span!(tracing::Level::$level, $name, $($fields)*) + ) + }; + ($level:ident, $name:expr) => { + GuardlessSpan::new( + tracing::span!(tracing::Level::$level, $name) + ) + }; + ($name:expr) => { + GuardlessSpan::new( + tracing::span!(tracing::Level::TRACE, $name) + ) + }; +} 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 64cb986618..1c327fa847 100644 --- a/server-cli/src/main.rs +++ b/server-cli/src/main.rs @@ -13,6 +13,8 @@ use common::clock::Clock; use server::{Event, Input, Server, ServerSettings}; use tracing::{info, Level}; use tracing_subscriber::{filter::LevelFilter, EnvFilter, FmtSubscriber}; +#[cfg(feature = "tracy")] +use tracing_subscriber::{layer::SubscriberExt, prelude::*}; 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,24 @@ 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"))] + // TODO: when tracing gets per Layer filters re-enable this when the tracy feature is being + // used (and do the same in voxygen) + { + 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 +124,8 @@ fn main() -> io::Result<()> { // Clean up the server after a tick. server.cleanup(); + #[cfg(feature = "tracy")] + common::util::tracy_client::finish_continuous_frame!(); match msg_r.try_recv() { Ok(msg) => match msg { diff --git a/server/src/events/mod.rs b/server/src/events/mod.rs index 948fbc6355..d56c4fa8c4 100644 --- a/server/src/events/mod.rs +++ b/server/src/events/mod.rs @@ -1,5 +1,8 @@ use crate::{state_ext::StateExt, Server}; -use common::event::{EventBus, ServerEvent}; +use common::{ + event::{EventBus, ServerEvent}, + span, +}; use entity_creation::{ handle_create_npc, handle_create_waypoint, handle_initialize_character, handle_loaded_character_data, handle_shoot, @@ -36,6 +39,7 @@ pub enum Event { impl Server { pub fn handle_events(&mut self) -> Vec { + span!(_guard, "handle_events", "Server::handle_events"); let mut frontend_events = Vec::new(); let mut requested_chunks = Vec::new(); diff --git a/server/src/events/player.rs b/server/src/events/player.rs index d9fb034144..486b826982 100644 --- a/server/src/events/player.rs +++ b/server/src/events/player.rs @@ -6,6 +6,7 @@ use common::{ comp, comp::{group, Player}, msg::{ClientState, PlayerListUpdate, ServerMsg}, + span, sync::{Uid, UidAllocator}, }; use futures_executor::block_on; @@ -13,6 +14,7 @@ use specs::{saveload::MarkerAllocator, Builder, Entity as EcsEntity, WorldExt}; use tracing::{debug, error, trace, warn}; pub fn handle_exit_ingame(server: &mut Server, entity: EcsEntity) { + span!(_guard, "handle_exit_ingame"); let state = server.state_mut(); // Create new entity with just `Client`, `Uid`, and `Player` components @@ -78,6 +80,7 @@ pub fn handle_exit_ingame(server: &mut Server, entity: EcsEntity) { } pub fn handle_client_disconnect(server: &mut Server, entity: EcsEntity) -> Event { + span!(_guard, "handle_client_disconnect"); if let Some(client) = server.state().read_storage::().get(entity) { let participant = match client.participant.try_lock() { Ok(mut p) => p.take().unwrap(), diff --git a/server/src/sys/entity_sync.rs b/server/src/sys/entity_sync.rs index 171c5bb7db..1dfd92e4aa 100644 --- a/server/src/sys/entity_sync.rs +++ b/server/src/sys/entity_sync.rs @@ -11,6 +11,7 @@ use common::{ msg::ServerMsg, outcome::Outcome, region::{Event as RegionEvent, RegionMap}, + span, state::TimeOfDay, sync::{CompSyncPackage, Uid}, terrain::TerrainChunkSize, @@ -77,6 +78,7 @@ impl<'a> System<'a> for Sys { trackers, ): Self::SystemData, ) { + span!(_guard, "run", "entity_sync::Sys::run"); timer.start(); let tick = tick.0; diff --git a/server/src/sys/invite_timeout.rs b/server/src/sys/invite_timeout.rs index 7a701b03a4..834f812a84 100644 --- a/server/src/sys/invite_timeout.rs +++ b/server/src/sys/invite_timeout.rs @@ -3,6 +3,7 @@ use crate::client::Client; use common::{ comp::group::{Invite, PendingInvites}, msg::{InviteAnswer, ServerMsg}, + span, sync::Uid, }; use specs::{Entities, Join, ReadStorage, System, Write, WriteStorage}; @@ -24,6 +25,7 @@ impl<'a> System<'a> for Sys { &mut self, (entities, mut invites, mut pending_invites, mut clients, uids, mut timer): Self::SystemData, ) { + span!(_guard, "run", "invite_timeout::Sys::run"); timer.start(); let now = std::time::Instant::now(); diff --git a/server/src/sys/message.rs b/server/src/sys/message.rs index b2d6ea97dc..31fa9dffbf 100644 --- a/server/src/sys/message.rs +++ b/server/src/sys/message.rs @@ -13,6 +13,7 @@ use common::{ validate_chat_msg, CharacterInfo, ChatMsgValidationError, ClientMsg, ClientState, PlayerInfo, PlayerListUpdate, RequestStateError, ServerMsg, MAX_BYTES_CHAT_MSG, }, + span, state::{BlockChange, Time}, sync::Uid, terrain::{Block, TerrainChunkSize, TerrainGrid}, @@ -454,6 +455,7 @@ impl<'a> System<'a> for Sys { alias_validator, ): Self::SystemData, ) { + span!(_guard, "run", "message::Sys::run"); timer.start(); let mut server_emitter = server_event_bus.emitter(); diff --git a/server/src/sys/object.rs b/server/src/sys/object.rs index 8a59fd32a6..d6deafad3e 100644 --- a/server/src/sys/object.rs +++ b/server/src/sys/object.rs @@ -1,6 +1,7 @@ use common::{ comp::{HealthSource, Object, PhysicsState, Pos, Vel}, event::{EventBus, ServerEvent}, + span, state::DeltaTime, }; use specs::{Entities, Join, Read, ReadStorage, System, WriteStorage}; @@ -23,6 +24,7 @@ impl<'a> System<'a> for Sys { &mut self, (entities, _dt, server_bus, positions, velocities, physics_states, mut objects): Self::SystemData, ) { + span!(_guard, "run", "object::Sys::run"); let mut server_emitter = server_bus.emitter(); // Objects diff --git a/server/src/sys/persistence.rs b/server/src/sys/persistence.rs index bc6d8fc493..c1dd0982b4 100644 --- a/server/src/sys/persistence.rs +++ b/server/src/sys/persistence.rs @@ -2,7 +2,10 @@ use crate::{ persistence::character, sys::{SysScheduler, SysTimer}, }; -use common::comp::{Inventory, Loadout, Player, Stats}; +use common::{ + comp::{Inventory, Loadout, Player, Stats}, + span, +}; use specs::{Join, ReadExpect, ReadStorage, System, Write}; pub struct Sys; @@ -31,6 +34,7 @@ impl<'a> System<'a> for Sys { mut timer, ): Self::SystemData, ) { + span!(_guard, "run", "persistence::Sys::run"); if scheduler.should_run() { timer.start(); updater.batch_update( diff --git a/server/src/sys/sentinel.rs b/server/src/sys/sentinel.rs index adcc76bd30..5fb64ddd5f 100644 --- a/server/src/sys/sentinel.rs +++ b/server/src/sys/sentinel.rs @@ -5,6 +5,7 @@ use common::{ Loadout, Mass, MountState, Mounting, Ori, Player, Pos, Scale, Stats, Sticky, Vel, }, msg::EcsCompPacket, + span, sync::{CompSyncPackage, EntityPackage, EntitySyncPackage, Uid, UpdateTracker, WorldSyncExt}, }; use hashbrown::HashMap; @@ -26,6 +27,7 @@ impl<'a> System<'a> for Sys { ); fn run(&mut self, (mut timer, comps, mut trackers): Self::SystemData) { + span!(_guard, "run", "sentinel::Sys::run"); timer.start(); record_changes(&comps, &mut trackers); diff --git a/server/src/sys/subscription.rs b/server/src/sys/subscription.rs index f494b30f49..1e0df762bd 100644 --- a/server/src/sys/subscription.rs +++ b/server/src/sys/subscription.rs @@ -7,6 +7,7 @@ use common::{ comp::{Ori, Player, Pos, Vel}, msg::ServerMsg, region::{region_in_vd, regions_in_vd, Event as RegionEvent, RegionMap}, + span, sync::Uid, terrain::TerrainChunkSize, vol::RectVolSize, @@ -55,6 +56,7 @@ impl<'a> System<'a> for Sys { tracked_comps, ): Self::SystemData, ) { + span!(_guard, "run", "subscription::Sys::run"); timer.start(); // To update subscriptions diff --git a/server/src/sys/terrain.rs b/server/src/sys/terrain.rs index 2270807410..ace7d43814 100644 --- a/server/src/sys/terrain.rs +++ b/server/src/sys/terrain.rs @@ -11,6 +11,7 @@ use common::{ generation::get_npc_name, msg::ServerMsg, npc::NPC_NAMES, + span, state::TerrainChanges, terrain::TerrainGrid, LoadoutBuilder, @@ -55,6 +56,7 @@ impl<'a> System<'a> for Sys { mut clients, ): Self::SystemData, ) { + span!(_guard, "run", "terrain::Sys::run"); timer.start(); let mut server_emitter = server_event_bus.emitter(); diff --git a/server/src/sys/terrain_sync.rs b/server/src/sys/terrain_sync.rs index a9899be209..8d0e8b5f23 100644 --- a/server/src/sys/terrain_sync.rs +++ b/server/src/sys/terrain_sync.rs @@ -3,6 +3,7 @@ use crate::client::Client; use common::{ comp::{Player, Pos}, msg::ServerMsg, + span, state::TerrainChanges, terrain::TerrainGrid, }; @@ -26,6 +27,7 @@ impl<'a> System<'a> for Sys { &mut self, (terrain, terrain_changes, mut timer, positions, players, mut clients): Self::SystemData, ) { + span!(_guard, "run", "terrain_sync::Sys::run"); timer.start(); // Sync changed chunks diff --git a/server/src/sys/waypoint.rs b/server/src/sys/waypoint.rs index 9129af814a..d9b0f0e739 100644 --- a/server/src/sys/waypoint.rs +++ b/server/src/sys/waypoint.rs @@ -3,6 +3,7 @@ use crate::client::Client; use common::{ comp::{Player, Pos, Waypoint, WaypointArea}, msg::{Notification, ServerMsg}, + span, state::Time, }; use specs::{Entities, Join, Read, ReadStorage, System, Write, WriteStorage}; @@ -30,6 +31,7 @@ impl<'a> System<'a> for Sys { &mut self, (entities, positions, players, waypoint_areas, mut waypoints, mut clients, time, mut timer): Self::SystemData, ) { + span!(_guard, "run", "waypoint::Sys::run"); timer.start(); for (entity, player_pos, _, client) in diff --git a/voxygen/Cargo.toml b/voxygen/Cargo.toml index 0b3f628c5f..a5a8e5c9c2 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", "common/tracy"] tweak = ["const-tweaker"] default = ["gl", "singleplayer", "native-dialog"] @@ -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.2.0", optional = true } + [target.'cfg(target_os = "macos")'.dependencies] dispatch = "0.1.4" diff --git a/voxygen/src/hud/mod.rs b/voxygen/src/hud/mod.rs index f705dcb116..c99cef03a3 100644 --- a/voxygen/src/hud/mod.rs +++ b/voxygen/src/hud/mod.rs @@ -56,7 +56,7 @@ use crate::{ GlobalState, }; use client::Client; -use common::{assets::Asset, comp, sync::Uid, terrain::TerrainChunk, vol::RectRasterableVol}; +use common::{assets::Asset, comp, span, sync::Uid, terrain::TerrainChunk, vol::RectRasterableVol}; use conrod_core::{ text::cursor::Index, widget::{self, Button, Image, Text}, @@ -685,6 +685,7 @@ impl Hud { info: HudInfo, camera: &Camera, ) -> Vec { + span!(_guard, "update_layout", "Hud::update_layout"); let mut events = std::mem::replace(&mut self.events, Vec::new()); let (ref mut ui_widgets, ref mut tooltip_manager) = self.ui.set_widgets(); // pulse time for pulsating elements @@ -2521,6 +2522,7 @@ impl Hud { dt: Duration, info: HudInfo, ) -> Vec { + span!(_guard, "maintain", "Hud::maintain"); // conrod eats tabs. Un-eat a tabstop so tab completion can work if self.ui.ui.global_input().events().any(|event| { use conrod_core::{event, input}; @@ -2565,6 +2567,7 @@ impl Hud { } pub fn render(&self, renderer: &mut Renderer, globals: &Consts) { + span!(_guard, "render", "Hud::render"); // Don't show anything if the UI is toggled off. if self.show.ui { self.ui.render(renderer, Some(globals)); diff --git a/voxygen/src/logging.rs b/voxygen/src/logging.rs index 3d52b98a3a..583127e527 100644 --- a/voxygen/src/logging.rs +++ b/voxygen/src/logging.rs @@ -47,6 +47,7 @@ pub fn init(settings: &Settings) -> Vec { .add_directive(LevelFilter::INFO.into()) }; + #[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 = base_exceptions(EnvFilter::new("")); @@ -61,6 +62,9 @@ pub fn init(settings: &Settings) -> Vec { _ => base_exceptions(EnvFilter::from_env(RUST_LOG_ENV)), }; + #[cfg(feature = "tracy")] + let filter = base_exceptions(EnvFilter::new("")).add_directive(LevelFilter::TRACE.into()); + // Create the terminal writer layer. let (non_blocking, _stdio_guard) = tracing_appender::non_blocking(std::io::stdout()); _guards.push(_stdio_guard); @@ -77,11 +81,19 @@ 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); + #[cfg(not(feature = "tracy"))] registry() .with(tracing_subscriber::fmt::layer().with_writer(non_blocking)) .with(tracing_subscriber::fmt::layer().with_writer(non_blocking_file)) .with(filter) .init(); + #[cfg(feature = "tracy")] + registry() + // 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; info!(?logdir, "Setup terminal and file logging."); }, @@ -91,8 +103,13 @@ pub fn init(settings: &Settings) -> Vec { ?e, "Failed to create log file!. Falling back to terminal logging only.", ); + #[cfg(not(feature = "tracy"))] registry() .with(tracing_subscriber::fmt::layer().with_writer(non_blocking)) + .with(filter); + #[cfg(feature = "tracy")] + registry() + .with(tracing_tracy::TracyLayer::new().with_stackdepth(0)) .with(filter) .init(); info!("Setup terminal logging."); diff --git a/voxygen/src/menu/char_selection/mod.rs b/voxygen/src/menu/char_selection/mod.rs index e405f78b8d..6846bbdf92 100644 --- a/voxygen/src/menu/char_selection/mod.rs +++ b/voxygen/src/menu/char_selection/mod.rs @@ -10,7 +10,7 @@ use crate::{ Direction, GlobalState, PlayState, PlayStateResult, }; use client::{self, Client}; -use common::{assets::Asset, comp, msg::ClientState, state::DeltaTime}; +use common::{assets::Asset, comp, msg::ClientState, span, state::DeltaTime}; use specs::WorldExt; use std::{cell::RefCell, rc::Rc}; use tracing::error; @@ -60,6 +60,7 @@ impl PlayState for CharSelectionState { } fn tick(&mut self, global_state: &mut GlobalState, events: Vec) -> PlayStateResult { + span!(_guard, "tick", "::tick"); let client_state = self.client.borrow().get_client_state(); if let ClientState::Pending | ClientState::Registered = client_state { // Handle window events diff --git a/voxygen/src/menu/main/mod.rs b/voxygen/src/menu/main/mod.rs index bbc11c846e..8f65cc0c12 100644 --- a/voxygen/src/menu/main/mod.rs +++ b/voxygen/src/menu/main/mod.rs @@ -9,7 +9,7 @@ use crate::{ PlayStateResult, }; use client_init::{ClientInit, Error as InitError, Msg as InitMsg}; -use common::{assets::Asset, comp}; +use common::{assets::Asset, comp, span}; use tracing::{error, warn}; use ui::{Event as MainMenuEvent, MainMenuUi}; @@ -46,6 +46,7 @@ impl PlayState for MainMenuState { } fn tick(&mut self, global_state: &mut GlobalState, events: Vec) -> PlayStateResult { + span!(_guard, "tick", "::tick"); let localized_strings = crate::i18n::VoxygenLocalization::load_expect( &crate::i18n::i18n_asset_key(&global_state.settings.language.selected_language), ); diff --git a/voxygen/src/mesh/greedy.rs b/voxygen/src/mesh/greedy.rs index d1f5ec8397..13e70b639c 100644 --- a/voxygen/src/mesh/greedy.rs +++ b/voxygen/src/mesh/greedy.rs @@ -1,4 +1,5 @@ use crate::render::{self, mesh::Quad, ColLightFmt, ColLightInfo, TerrainPipeline}; +use common::span; use vek::*; type TerrainVertex = ::Vertex; @@ -101,6 +102,7 @@ impl<'a> GreedyMesh<'a> { /// most 30 bits total, meaning we are restricted to "only" at most 2^15 /// × 2^15 atlases even if the hardware supports larger ones. pub fn new(max_size: guillotiere::Size) -> Self { + span!(_guard, "new", "GreedyMesh::new"); let min_max_dim = max_size.width.min(max_size.height); assert!( min_max_dim >= 4, @@ -148,6 +150,7 @@ impl<'a> GreedyMesh<'a> { FS: for<'r> FnMut(&'r mut D, Vec3, Vec3, Vec2>) -> Option<(bool, M)>, FP: FnMut(Vec2, Vec2>, Vec3, Vec2>, Vec3, &M), { + span!(_guard, "push", "GreedyMesh::push"); let cont = greedy_mesh( &mut self.atlas, &mut self.col_lights_size, @@ -167,6 +170,7 @@ impl<'a> GreedyMesh<'a> { /// /// Returns the ColLightsInfo corresponding to the constructed atlas. pub fn finalize(self) -> ColLightInfo { + span!(_guard, "finalize", "GreedyMesh::finalize"); let cur_size = self.col_lights_size; let col_lights = vec![ TerrainVertex::make_col_light(254, Rgb::broadcast(254)); @@ -205,6 +209,7 @@ where FS: for<'r> FnMut(&'r mut D, Vec3, Vec3, Vec2>) -> Option<(bool, M)>, FP: FnMut(Vec2, Vec2>, Vec3, Vec2>, Vec3, &M), { + span!(_guard, "greedy_mesh"); // TODO: Collect information to see if we can choose a good value here. let mut todo_rects = Vec::with_capacity(1024); @@ -367,6 +372,7 @@ fn greedy_mesh_cross_section( // Vertex, width and height, and meta information about the block. mut push_quads: impl FnMut(Vec3, Vec2, &M), ) { + span!(_guard, "greedy_mesh_cross_section"); // mask represents which faces are either set while the other is unset, or unset // while the other is set. let mut mask = (0..dims.y * dims.x).map(|_| None).collect::>(); diff --git a/voxygen/src/mesh/terrain.rs b/voxygen/src/mesh/terrain.rs index a95809bfbf..05725ff629 100644 --- a/voxygen/src/mesh/terrain.rs +++ b/voxygen/src/mesh/terrain.rs @@ -6,6 +6,7 @@ use crate::{ render::{self, ColLightInfo, FluidPipeline, Mesh, ShadowPipeline, TerrainPipeline}, }; use common::{ + span, terrain::{Block, BlockKind}, vol::{ReadVol, RectRasterableVol, Vox}, volumes::vol_grid_2d::{CachedVolGrid2d, VolGrid2d}, @@ -47,6 +48,7 @@ fn calc_light + ReadVol + Debug>( vol: &VolGrid2d, lit_blocks: impl Iterator, u8)>, ) -> impl FnMut(Vec3) -> f32 + '_ { + span!(_guard, "calc_light"); const UNKNOWN: u8 = 255; const OPAQUE: u8 = 254; @@ -240,6 +242,11 @@ impl<'a, V: RectRasterableVol + ReadVol + Debug> self, (range, max_texture_size): Self::Supplement, ) -> MeshGen { + span!( + _guard, + "generate_mesh", + "<&VolGrid2d as Meshable<_, _>>::generate_mesh" + ); // Find blocks that should glow // FIXME: Replace with real lit blocks when we actually have blocks that glow. let lit_blocks = core::iter::empty(); @@ -256,6 +263,7 @@ impl<'a, V: RectRasterableVol + ReadVol + Debug> let mut lowest_air = range.size().d; let mut highest_air = 0; let flat_get = { + span!(_guard, "copy to flat array"); let (w, h, d) = range.size().into_tuple(); // z can range from -1..range.size().d + 1 let d = d + 2; diff --git a/voxygen/src/render/renderer.rs b/voxygen/src/render/renderer.rs index b37a86bd23..96b43753cf 100644 --- a/voxygen/src/render/renderer.rs +++ b/voxygen/src/render/renderer.rs @@ -12,7 +12,10 @@ use super::{ AaMode, CloudMode, FilterMethod, FluidMode, LightingMode, Pipeline, RenderError, RenderMode, ShadowMapMode, ShadowMode, WrapMode, }; -use common::assets::{self, watch::ReloadIndicator, Asset}; +use common::{ + assets::{self, watch::ReloadIndicator, Asset}, + span, +}; use core::convert::TryFrom; use gfx::{ self, @@ -603,6 +606,7 @@ impl Renderer { /// Queue the clearing of the shadow targets ready for a new frame to be /// rendered. pub fn clear_shadows(&mut self) { + span!(_guard, "clear_shadows", "Renderer::clear_shadows"); if !self.mode.shadow.is_map() { return; } @@ -675,6 +679,7 @@ impl Renderer { /// Queue the clearing of the depth target ready for a new frame to be /// rendered. pub fn clear(&mut self) { + span!(_guard, "clear", "Renderer::clear"); self.encoder.clear_depth(&self.tgt_depth_stencil_view, 1.0); // self.encoder.clear_stencil(&self.tgt_depth_stencil_view, 0); self.encoder.clear_depth(&self.win_depth_view, 1.0); @@ -710,6 +715,7 @@ impl Renderer { /// Perform all queued draw calls for this frame and clean up discarded /// items. pub fn flush(&mut self) { + span!(_guard, "flush", "Renderer::flush"); self.encoder.flush(&mut self.device); self.device.cleanup(); diff --git a/voxygen/src/run.rs b/voxygen/src/run.rs index 6f0d3a954a..ee9004fa1d 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::{no_guard_span, span, util::GuardlessSpan}; use std::{mem, time::Duration}; use tracing::debug; @@ -22,6 +23,9 @@ 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; + event_loop.run(move |event, _, control_flow| { // Continuously run loop since we handle sleeping *control_flow = winit::event_loop::ControlFlow::Poll; @@ -32,16 +36,26 @@ pub fn run(mut global_state: GlobalState, event_loop: EventLoop) { } match event { + winit::event::Event::NewEvents(_) => { + event_span = Some(no_guard_span!("Process Events")); + }, winit::event::Event::MainEventsCleared => { + event_span.take(); + poll_span.take(); if polled_twice { handle_main_events_cleared(&mut states, control_flow, &mut global_state); } + poll_span = Some(no_guard_span!("Poll Winit")); 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 +73,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 @@ -82,14 +97,6 @@ fn handle_main_events_cleared( // Implement state transfer logic. match state_result { PlayStateResult::Continue => { - // Wait for the next tick. - global_state.clock.tick(Duration::from_millis( - 1000 / global_state.settings.graphics.max_fps as u64, - )); - - // Maintain global state. - global_state.maintain(global_state.clock.get_last_delta().as_secs_f32()); - exit = false; break; }, @@ -136,7 +143,9 @@ fn handle_main_events_cleared( *control_flow = winit::event_loop::ControlFlow::Exit; } + drop(guard); if let Some(last) = states.last_mut() { + span!(guard, "Render"); let renderer = global_state.window.renderer_mut(); // Clear the shadow maps. renderer.clear_shadows(); @@ -151,5 +160,20 @@ fn handle_main_events_cleared( .window .swap_buffers() .expect("Failed to swap window buffers!"); + drop(guard); + #[cfg(feature = "tracy")] + common::util::tracy_client::finish_continuous_frame!(); + } + + if !exit { + // Wait for the next tick. + 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()); } } diff --git a/voxygen/src/scene/camera.rs b/voxygen/src/scene/camera.rs index a0fa8af2be..f48db8a7f3 100644 --- a/voxygen/src/scene/camera.rs +++ b/voxygen/src/scene/camera.rs @@ -1,4 +1,7 @@ -use common::vol::{ReadVol, Vox}; +use common::{ + span, + vol::{ReadVol, Vox}, +}; use std::f32::consts::PI; use treeculler::Frustum; use vek::*; @@ -78,6 +81,7 @@ impl Camera { /// Compute the transformation matrices (view matrix and projection matrix) /// and position of the camera. pub fn compute_dependents(&mut self, terrain: &impl ReadVol) { + span!(_guard, "compute_dependents", "Camera::compute_dependents"); let dist = { let (start, end) = (self.focus - self.forward() * self.dist, self.focus); diff --git a/voxygen/src/scene/figure/mod.rs b/voxygen/src/scene/figure/mod.rs index c871582ca4..15e14f6998 100644 --- a/voxygen/src/scene/figure/mod.rs +++ b/voxygen/src/scene/figure/mod.rs @@ -28,6 +28,7 @@ use common::{ item::ItemKind, Body, CharacterState, Item, Last, LightAnimation, LightEmitter, Loadout, Ori, PhysicsState, Pos, Scale, Stats, Vel, }, + span, state::{DeltaTime, State}, states::triple_strike, terrain::TerrainChunk, @@ -195,6 +196,7 @@ impl FigureMgrStates { } fn retain(&mut self, mut f: impl FnMut(&EcsEntity, &mut FigureStateMeta) -> bool) { + span!(_guard, "retain", "FigureManagerStates::retain"); self.character_states.retain(|k, v| f(k, &mut *v)); self.quadruped_small_states.retain(|k, v| f(k, &mut *v)); self.quadruped_medium_states.retain(|k, v| f(k, &mut *v)); @@ -337,6 +339,7 @@ impl FigureMgr { pub fn col_lights(&self) -> &FigureColLights { &self.col_lights } pub fn clean(&mut self, tick: u64) { + span!(_guard, "clean", "FigureManager::clean"); self.model_cache.clean(&mut self.col_lights, tick); self.critter_model_cache.clean(&mut self.col_lights, tick); self.quadruped_small_model_cache @@ -363,6 +366,7 @@ impl FigureMgr { #[allow(clippy::redundant_pattern_matching)] // TODO: Pending review in #587 pub fn update_lighting(&mut self, scene_data: &SceneData) { + span!(_guard, "update_lighting", "FigureManager::update_lighting"); let ecs = scene_data.state.ecs(); for (entity, body, light_emitter) in ( &ecs.entities(), @@ -451,6 +455,7 @@ impl FigureMgr { visible_psr_bounds: math::Aabr, camera: &Camera, ) -> anim::vek::Aabb { + span!(_guard, "maintain", "FigureManager::maintain"); let state = scene_data.state; let time = state.get_time(); let tick = scene_data.tick; @@ -2130,6 +2135,7 @@ impl FigureMgr { (is_daylight, _light_data): super::LightData, (camera, figure_lod_render_distance): CameraData, ) { + span!(_guard, "render_shadows", "FigureManager::render_shadows"); let ecs = state.ecs(); if is_daylight && renderer.render_mode().shadow.is_map() { @@ -2181,6 +2187,7 @@ impl FigureMgr { lod: &LodData, (camera, figure_lod_render_distance): CameraData, ) { + span!(_guard, "render", "FigureManager::render"); let ecs = state.ecs(); let character_state_storage = state.read_storage::(); @@ -2231,6 +2238,7 @@ impl FigureMgr { lod: &LodData, (camera, figure_lod_render_distance): CameraData, ) { + span!(_guard, "render_player", "FigureManager::render_player"); let ecs = state.ecs(); let character_state_storage = state.read_storage::(); @@ -2614,6 +2622,7 @@ impl FigureColLights { (opaque, bounds): (Mesh, math::Aabb), vertex_range: [Range; N], ) -> Result, RenderError> { + span!(_guard, "create_figure", "FigureColLights::create_figure"); let atlas = &mut self.atlas; let allocation = atlas .allocate(guillotiere::Size::new( diff --git a/voxygen/src/scene/mod.rs b/voxygen/src/scene/mod.rs index 8eda9080de..537ed1c5d6 100644 --- a/voxygen/src/scene/mod.rs +++ b/voxygen/src/scene/mod.rs @@ -28,6 +28,7 @@ use client::Client; use common::{ comp, outcome::Outcome, + span, state::{DeltaTime, State}, terrain::{BlockKind, TerrainChunk}, vol::ReadVol, @@ -379,6 +380,7 @@ impl Scene { scene_data: &SceneData, audio: &mut AudioFrontend, ) { + span!(_guard, "handle_outcome", "Scene::handle_outcome"); self.particle_mgr.handle_outcome(&outcome, &scene_data); self.sfx_mgr.handle_outcome(&outcome, audio); @@ -422,6 +424,7 @@ impl Scene { audio: &mut AudioFrontend, scene_data: &SceneData, ) { + span!(_guard, "maintain", "Scene::maintain"); // Get player position. let ecs = scene_data.state.ecs(); @@ -973,6 +976,7 @@ impl Scene { tick: u64, scene_data: &SceneData, ) { + span!(_guard, "render", "Scene::render"); let sun_dir = scene_data.get_sun_dir(); let is_daylight = sun_dir.z < 0.0; let focus_pos = self.camera.get_focus_pos(); diff --git a/voxygen/src/scene/particle.rs b/voxygen/src/scene/particle.rs index 407e2d4ef2..127530d541 100644 --- a/voxygen/src/scene/particle.rs +++ b/voxygen/src/scene/particle.rs @@ -11,6 +11,7 @@ use common::{ comp::{item::Reagent, object, Body, CharacterState, Pos}, figure::Segment, outcome::Outcome, + span, spiral::Spiral2d, state::DeltaTime, terrain::TerrainChunk, @@ -48,6 +49,7 @@ impl ParticleMgr { } pub fn handle_outcome(&mut self, outcome: &Outcome, scene_data: &SceneData) { + span!(_guard, "handle_outcome", "ParticleMgr::handle_outcome"); let time = scene_data.state.get_time(); let mut rng = rand::thread_rng(); @@ -98,6 +100,7 @@ impl ParticleMgr { scene_data: &SceneData, terrain: &Terrain, ) { + span!(_guard, "maintain", "ParticleMgr::maintain"); if scene_data.particles_enabled { // update timings self.scheduler.maintain(scene_data.state.get_time()); @@ -122,6 +125,11 @@ impl ParticleMgr { } fn maintain_body_particles(&mut self, scene_data: &SceneData) { + span!( + _guard, + "body_particles", + "ParticleMgr::maintain_body_particles" + ); let ecs = scene_data.state.ecs(); for (body, pos) in (&ecs.read_storage::(), &ecs.read_storage::()).join() { match body { @@ -148,6 +156,11 @@ impl ParticleMgr { } fn maintain_campfirelit_particles(&mut self, scene_data: &SceneData, pos: &Pos) { + span!( + _guard, + "campfirelit_particles", + "ParticleMgr::maintain_campfirelit_particles" + ); let time = scene_data.state.get_time(); for _ in 0..self.scheduler.heartbeats(Duration::from_millis(10)) { @@ -168,6 +181,11 @@ impl ParticleMgr { } fn maintain_boltfire_particles(&mut self, scene_data: &SceneData, pos: &Pos) { + span!( + _guard, + "boltfire_particles", + "ParticleMgr::maintain_boltfire_particles" + ); let time = scene_data.state.get_time(); for _ in 0..self.scheduler.heartbeats(Duration::from_millis(10)) { @@ -187,6 +205,11 @@ impl ParticleMgr { } fn maintain_boltfirebig_particles(&mut self, scene_data: &SceneData, pos: &Pos) { + span!( + _guard, + "boltfirebig_particles", + "ParticleMgr::maintain_boltfirebig_particles" + ); let time = scene_data.state.get_time(); // fire @@ -217,6 +240,11 @@ impl ParticleMgr { } fn maintain_bomb_particles(&mut self, scene_data: &SceneData, pos: &Pos) { + span!( + _guard, + "bomb_particles", + "ParticleMgr::maintain_bomb_particles" + ); let time = scene_data.state.get_time(); for _ in 0..self.scheduler.heartbeats(Duration::from_millis(10)) { @@ -239,6 +267,11 @@ impl ParticleMgr { } fn maintain_boost_particles(&mut self, scene_data: &SceneData) { + span!( + _guard, + "boost_particles", + "ParticleMgr::maintain_boost_particles" + ); let state = scene_data.state; let ecs = state.ecs(); let time = state.get_time(); @@ -272,6 +305,11 @@ impl ParticleMgr { scene_data: &SceneData, terrain: &Terrain, ) { + span!( + _guard, + "block_particles", + "ParticleMgr::maintain_block_particles" + ); let dt = scene_data.state.ecs().fetch::().0; let time = scene_data.state.get_time(); let player_pos = scene_data @@ -383,6 +421,7 @@ impl ParticleMgr { } fn upload_particles(&mut self, renderer: &mut Renderer) { + span!(_guard, "upload_particles", "ParticleMgr::upload_particles"); let all_cpu_instances = self .particles .iter() @@ -404,6 +443,7 @@ impl ParticleMgr { global: &GlobalModel, lod: &LodData, ) { + span!(_guard, "render", "ParticleMgr::render"); if scene_data.particles_enabled { let model = &self .model_cache @@ -489,6 +529,7 @@ impl HeartbeatScheduler { /// updates the last elapsed times and elapsed counts /// this should be called once, and only once per tick. pub fn maintain(&mut self, now: f64) { + span!(_guard, "maintain", "HeartbeatScheduler::maintain"); self.last_known_time = now; for (frequency, (last_update, heartbeats)) in self.timers.iter_mut() { @@ -520,6 +561,7 @@ impl HeartbeatScheduler { /// - if it's equal to the tick rate, it could be between 2 and 0, due to /// delta time variance. pub fn heartbeats(&mut self, frequency: Duration) -> u8 { + span!(_guard, "HeartbeatScheduler::heartbeats"); let last_known_time = self.last_known_time; self.timers diff --git a/voxygen/src/scene/terrain.rs b/voxygen/src/scene/terrain.rs index 04dccd9558..9530f78a8f 100644 --- a/voxygen/src/scene/terrain.rs +++ b/voxygen/src/scene/terrain.rs @@ -15,6 +15,7 @@ use super::{math, LodData, SceneData}; use common::{ assets::{Asset, Ron}, figure::Segment, + span, spiral::Spiral2d, terrain::{block, Block, BlockKind, TerrainChunk}, vol::{BaseVol, ReadVol, RectRasterableVol, SampleVol, Vox}, @@ -124,6 +125,7 @@ fn mesh_worker + RectRasterableVol + ReadVol + Debug>( sprite_data: &HashMap<(BlockKind, usize), Vec>, sprite_config: &SpriteSpec, ) -> MeshWorkerResponse { + span!(_guard, "mesh_worker"); let (opaque_mesh, fluid_mesh, _shadow_mesh, (bounds, col_lights_info)) = volume.generate_mesh((range, Vec2::new(max_texture_size, max_texture_size))); MeshWorkerResponse { @@ -134,6 +136,7 @@ fn mesh_worker + RectRasterableVol + ReadVol + Debug>( col_lights_info, // Extract sprite locations from volume sprite_instances: { + span!(_guard, "extract sprite_instances"); let mut instances = HashMap::new(); for x in 0..V::RECT_SIZE.x as i32 { @@ -382,6 +385,7 @@ impl Terrain { fn make_atlas( renderer: &mut Renderer, ) -> Result<(AtlasAllocator, Texture), RenderError> { + span!(_guard, "male_atlas", "Terrain::make_atlas"); let max_texture_size = renderer.max_texture_size(); let atlas_size = guillotiere::Size::new(i32::from(max_texture_size), i32::from(max_texture_size)); @@ -449,12 +453,14 @@ impl Terrain { view_mat: Mat4, proj_mat: Mat4, ) -> (Aabb, Vec>, math::Aabr) { + span!(_guard, "maintain", "Terrain::maintain"); let current_tick = scene_data.tick; let current_time = scene_data.state.get_time(); let mut visible_bounding_box: Option> = None; // Add any recently created or changed chunks to the list of chunks to be // meshed. + span!(guard, "Add new/modified chunks to mesh todo list"); for (modified, pos) in scene_data .state .terrain_changes() @@ -501,9 +507,12 @@ impl Terrain { } } } + drop(guard); // Add the chunks belonging to recently changed blocks to the list of chunks to // be meshed + span!(guard, "Add chunks with modified blocks to mesh todo list"); + // TODO: would be useful if modified blocks were grouped by chunk for pos in scene_data .state .terrain_changes() @@ -542,6 +551,7 @@ impl Terrain { } } } + drop(guard); // Remove any models for chunks that have been recently removed. for &pos in &scene_data.state.terrain_changes().removed_chunks { @@ -551,6 +561,7 @@ impl Terrain { // Limit ourselves to u16::MAX even if larger textures are supported. let max_texture_size = renderer.max_texture_size(); + span!(guard, "Queue meshing from todo list"); for (todo, chunk) in self .mesh_todo .values_mut() @@ -637,11 +648,13 @@ impl Terrain { }); todo.active_worker = Some(todo.started_tick); } + drop(guard); // Receive a chunk mesh from a worker thread and upload it to the GPU, then // store it. Only pull out one chunk per frame to avoid an unacceptable // amount of blocking lag due to the GPU upload. That still gives us a // 60 chunks / second budget to play with. + span!(guard, "Get/upload meshed chunk"); if let Ok(response) = self.mesh_recv.recv_timeout(Duration::new(0, 0)) { match self.mesh_todo.get(&response.pos) { // It's the mesh we want, insert the newly finished model into the terrain model @@ -739,14 +752,18 @@ impl Terrain { None => {}, } } + drop(guard); // Construct view frustum + span!(guard, "Construct view frustum"); let focus_off = focus_pos.map(|e| e.trunc()); let frustum = Frustum::from_modelview_projection( (proj_mat * view_mat * Mat4::translation_3d(-focus_off)).into_col_arrays(), ); + drop(guard); // Update chunk visibility + span!(guard, "Update chunk visibility"); let chunk_sz = V::RECT_SIZE.x as f32; for (pos, chunk) in &mut self.chunks { let chunk_pos = pos.as_::() * chunk_sz; @@ -796,7 +813,9 @@ impl Terrain { // (and hardcodes the shadow distance). Should ideally exist per-light, too. chunk.can_shadow_point = distance_2 < (128.0 * 128.0); } + drop(guard); + span!(guard, "Shadow magic"); // PSRs: potential shadow receivers let visible_bounding_box = visible_bounding_box.unwrap_or(Aabb { min: focus_pos - 2.0, @@ -901,6 +920,7 @@ impl Terrain { max: math::Vec2::zero(), }) }; + drop(guard); ( visible_bounding_box, @@ -931,6 +951,7 @@ impl Terrain { (is_daylight, light_data): super::LightData, focus_pos: Vec3, ) { + span!(_guard, "render_shadows", "Terrain::render_shadows"); if !renderer.render_mode().shadow.is_map() { return; }; @@ -992,6 +1013,7 @@ impl Terrain { lod: &LodData, focus_pos: Vec3, ) { + span!(_guard, "render", "Terrain::render"); let focus_chunk = Vec2::from(focus_pos).map2(TerrainChunk::RECT_SIZE, |e: f32, sz| { (e as i32).div_euclid(sz as i32) }); @@ -1025,6 +1047,7 @@ impl Terrain { cam_pos: Vec3, sprite_render_distance: f32, ) { + span!(_guard, "render_translucent", "Terrain::render_translucent"); let focus_chunk = Vec2::from(focus_pos).map2(TerrainChunk::RECT_SIZE, |e: f32, sz| { (e as i32).div_euclid(sz as i32) }); @@ -1038,6 +1061,8 @@ impl Terrain { .take(self.chunks.len()); // Terrain sprites + // TODO: move to separate functions + span!(guard, "Terrain sprites"); let chunk_size = V::RECT_SIZE.map(|e| e as f32); let chunk_mag = (chunk_size * (f32::consts::SQRT_2 * 0.5)).magnitude_squared(); for (pos, chunk) in chunk_iter.clone() { @@ -1096,6 +1121,7 @@ impl Terrain { } } } + drop(guard); // Translucent chunk_iter diff --git a/voxygen/src/scene/terrain/watcher.rs b/voxygen/src/scene/terrain/watcher.rs index 016a847b62..4e1fed21d9 100644 --- a/voxygen/src/scene/terrain/watcher.rs +++ b/voxygen/src/scene/terrain/watcher.rs @@ -1,4 +1,5 @@ use common::{ + span, terrain::{BlockKind, TerrainChunk}, vol::{IntoVolIterator, RectRasterableVol}, }; @@ -16,6 +17,7 @@ pub struct BlocksOfInterest { impl BlocksOfInterest { pub fn from_chunk(chunk: &TerrainChunk) -> Self { + span!(_guard, "from_chunk", "BlocksOfInterest::from_chunk"); let mut leaves = Vec::new(); let mut grass = Vec::new(); let mut embers = Vec::new(); diff --git a/voxygen/src/session.rs b/voxygen/src/session.rs index 817e2e99c4..69c43df27b 100644 --- a/voxygen/src/session.rs +++ b/voxygen/src/session.rs @@ -22,6 +22,7 @@ use common::{ event::EventBus, msg::ClientState, outcome::Outcome, + span, terrain::{Block, BlockKind}, util::Dir, vol::ReadVol, @@ -111,6 +112,7 @@ impl SessionState { global_state: &mut GlobalState, outcomes: &mut Vec, ) -> Result { + span!(_guard, "tick", "Session::tick"); self.inputs.tick(dt); let mut client = self.client.borrow_mut(); @@ -195,6 +197,7 @@ impl PlayState for SessionState { } fn tick(&mut self, global_state: &mut GlobalState, events: Vec) -> PlayStateResult { + span!(_guard, "tick", "::tick"); // NOTE: Not strictly necessary, but useful for hotloading translation changes. self.voxygen_i18n = VoxygenLocalization::load_expect(&i18n_asset_key( &global_state.settings.language.selected_language, @@ -1084,6 +1087,7 @@ impl PlayState for SessionState { /// /// This method should be called once per frame. fn render(&mut self, renderer: &mut Renderer, settings: &Settings) { + span!(_guard, "render", "::render"); // Render the screen using the global renderer { let client = self.client.borrow(); diff --git a/voxygen/src/ui/mod.rs b/voxygen/src/ui/mod.rs index 3faf645eb9..960d35d52f 100644 --- a/voxygen/src/ui/mod.rs +++ b/voxygen/src/ui/mod.rs @@ -32,7 +32,7 @@ use crate::{ #[rustfmt::skip] use ::image::GenericImageView; use cache::Cache; -use common::{assets, util::srgba_to_linear}; +use common::{assets, span, util::srgba_to_linear}; use conrod_core::{ event::Input, graph::{self, Graph}, @@ -293,6 +293,7 @@ impl Ui { #[allow(clippy::float_cmp)] // TODO: Pending review in #587 pub fn maintain(&mut self, renderer: &mut Renderer, view_projection_mat: Option>) { + span!(_guard, "maintain", "Ui::maintain"); // Maintain tooltip manager self.tooltip_manager .maintain(self.ui.global_input(), self.scale.scale_factor_logical()); @@ -334,6 +335,7 @@ impl Ui { view_projection_mat: Option>, retry: &mut bool, ) { + span!(_guard, "internal", "Ui::maintain_internal"); let (graphic_cache, text_cache, glyph_cache, cache_tex) = self.cache.cache_mut_and_tex(); let mut primitives = if *retry { @@ -978,6 +980,7 @@ impl Ui { } pub fn render(&self, renderer: &mut Renderer, maybe_globals: Option<&Consts>) { + span!(_guard, "render", "Ui::render"); let mut scissor = default_scissor(renderer); let globals = maybe_globals.unwrap_or(&self.default_globals); let mut locals = &self.interface_locals; diff --git a/voxygen/src/window.rs b/voxygen/src/window.rs index dc3e56fcc3..d0215f2934 100644 --- a/voxygen/src/window.rs +++ b/voxygen/src/window.rs @@ -4,6 +4,7 @@ use crate::{ settings::{ControlSettings, Settings}, ui, Error, }; +use common::span; use crossbeam::channel; use gilrs::{EventType, Gilrs}; use hashbrown::HashMap; @@ -1043,6 +1044,7 @@ impl Window { } pub fn swap_buffers(&self) -> Result<(), Error> { + span!(_guard, "swap_buffers", "Window::swap_buffers"); self.window .swap_buffers() .map_err(|err| Error::BackendError(Box::new(err)))