From 8252c06bf66000408ec702c976a6ca172a7a380a Mon Sep 17 00:00:00 2001 From: Imbris Date: Tue, 25 Aug 2020 04:18:41 -0400 Subject: [PATCH 1/8] Intial setup of tracy --- Cargo.lock | 30 ++++++++++++++++++++++++++++++ common/src/util/mod.rs | 17 +++++++++++++++++ voxygen/Cargo.toml | 4 ++++ voxygen/src/logging.rs | 16 ++++++++++------ voxygen/src/run.rs | 39 ++++++++++++++++++++++++++++++++++++--- 5 files changed, 97 insertions(+), 9 deletions(-) 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(); From da4788e78be78979c4502e220b23295591aeab4c Mon Sep 17 00:00:00 2001 From: Imbris Date: Wed, 26 Aug 2020 02:11:56 -0400 Subject: [PATCH 2/8] Add workaround for spans with winit loop, configure filtering when the tracy feature is on, spinkle some spans in the codebase --- common/src/sys/phys.rs | 2 + common/src/util/mod.rs | 39 ++++++++++++++++++- voxygen/src/hud/mod.rs | 5 ++- voxygen/src/logging.rs | 29 ++++++++++---- voxygen/src/mesh/greedy.rs | 6 +++ voxygen/src/mesh/terrain.rs | 4 ++ voxygen/src/render/renderer.rs | 8 +++- voxygen/src/run.rs | 57 ++++++++++++---------------- voxygen/src/scene/camera.rs | 6 ++- voxygen/src/scene/figure/mod.rs | 9 +++++ voxygen/src/scene/mod.rs | 4 ++ voxygen/src/scene/particle.rs | 14 +++++++ voxygen/src/scene/terrain.rs | 26 +++++++++++++ voxygen/src/scene/terrain/watcher.rs | 2 + voxygen/src/session.rs | 4 ++ voxygen/src/ui/mod.rs | 5 ++- voxygen/src/window.rs | 2 + 17 files changed, 177 insertions(+), 45 deletions(-) diff --git a/common/src/sys/phys.rs b/common/src/sys/phys.rs index 9294c6c869..dd2f99af4e 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,6 +95,7 @@ impl<'a> System<'a> for Sys { projectiles, ): Self::SystemData, ) { + span!(_guard, "::run"); let mut event_emitter = event_bus.emitter(); // Add/reset physics state components diff --git a/common/src/util/mod.rs b/common/src/util/mod.rs index 1922ee5014..80bd2ed934 100644 --- a/common/src/util/mod.rs +++ b/common/src/util/mod.rs @@ -23,7 +23,44 @@ macro_rules! span { let $guard_name = span.enter(); }; ($guard_name:tt, $name:expr) => { - let span = tracing::span!(tracing::Level::INFO, $name); + let span = tracing::span!(tracing::Level::TRACE, $name); let $guard_name = span.enter(); }; } + +/// 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/voxygen/src/hud/mod.rs b/voxygen/src/hud/mod.rs index 01a68eb1d0..9d1ecb5369 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}, @@ -688,6 +688,7 @@ impl Hud { info: HudInfo, camera: &Camera, ) -> Vec { + span!(_guard, "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 @@ -2532,6 +2533,7 @@ impl Hud { dt: Duration, info: HudInfo, ) -> Vec { + span!(_guard, "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}; @@ -2576,6 +2578,7 @@ impl Hud { } pub fn render(&self, renderer: &mut Renderer, globals: &Consts) { + span!(_guard, "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 2455dedf97..672b796f6d 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,13 @@ pub fn init(settings: &Settings) -> Vec { _ => base_exceptions(EnvFilter::from_env(RUST_LOG_ENV)), }; + #[cfg(feature = "tracy")] + let filter = EnvFilter::new("dot_vox::parser=warn") + .add_directive("gfx_device_gl=warn".parse().unwrap()) + .add_directive("uvth=warn".parse().unwrap()) + .add_directive("tiny_http=warn".parse().unwrap()) + .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,13 +85,17 @@ 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); - let subscriber = registry() + #[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); + .with(filter) + .init(); #[cfg(feature = "tracy")] - let subscriber = subscriber.with(tracing_tracy::TracyLayer::new()); - subscriber.init(); + registry() + .with(tracing_tracy::TracyLayer::new()) + .with(filter) + .init(); let logdir = &settings.log.logs_path; info!(?logdir, "Setup terminal and file logging."); }, @@ -93,12 +105,15 @@ pub fn init(settings: &Settings) -> Vec { ?e, "Failed to create log file!. Falling back to terminal logging only.", ); - let subscriber = registry() + #[cfg(not(feature = "tracy"))] + registry() .with(tracing_subscriber::fmt::layer().with_writer(non_blocking)) .with(filter); #[cfg(feature = "tracy")] - let subscriber = subscriber.with(tracing_tracy::TracyLayer::new()); - subscriber.init(); + registry() + .with(tracing_tracy::TracyLayer::new()) + .with(filter) + .init(); info!("Setup terminal logging."); }, }; diff --git a/voxygen/src/mesh/greedy.rs b/voxygen/src/mesh/greedy.rs index d1f5ec8397..cfd8d4b143 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, "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, "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, "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..7abcb15e0b 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,7 @@ impl<'a, V: RectRasterableVol + ReadVol + Debug> self, (range, max_texture_size): Self::Supplement, ) -> MeshGen { + span!(_guard, "<&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 +259,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..eb3246cc3e 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, "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, "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, "Renderer::flush"); self.encoder.flush(&mut self.device); self.device.cleanup(); diff --git a/voxygen/src/run.rs b/voxygen/src/run.rs index 8b3a28d76a..c21af359bd 100644 --- a/voxygen/src/run.rs +++ b/voxygen/src/run.rs @@ -4,7 +4,7 @@ use crate::{ window::{Event, EventLoop}, Direction, GlobalState, PlayState, PlayStateResult, }; -use common::span; +use common::{no_guard_span, span, util::GuardlessSpan}; use std::{mem, time::Duration}; use tracing::debug; @@ -23,11 +23,8 @@ 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"); + let mut poll_span = None; + let mut event_span = None; event_loop.run(move |event, _, control_flow| { // Continuously run loop since we handle sleeping @@ -40,25 +37,15 @@ 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); - } + event_span = Some(no_guard_span!("Process Events")); }, 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))); + event_span.take(); + poll_span.take(); 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); + poll_span = Some(no_guard_span!("Poll Winit")); polled_twice = !polled_twice; }, winit::event::Event::WindowEvent { event, .. } => { @@ -105,23 +92,12 @@ 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"); + span!(_guard, "PlayState::tick"); 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()); - exit = false; break; }, @@ -168,8 +144,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"); + span!(guard, "Render"); let renderer = global_state.window.renderer_mut(); // Clear the shadow maps. renderer.clear_shadows(); @@ -184,5 +161,19 @@ fn handle_main_events_cleared( .window .swap_buffers() .expect("Failed to swap window buffers!"); + drop(guard); + tracing::trace!(tracy.frame_mark = true); + } + + 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..d5b747efd9 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, "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..1480262b81 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, "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, "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, "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, "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, "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, "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, "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, "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..dceac65b85 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, "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, "Scene::maintain"); // Get player position. let ecs = scene_data.state.ecs(); @@ -973,6 +976,7 @@ impl Scene { tick: u64, scene_data: &SceneData, ) { + span!(_guard, "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..4ec3df2161 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, "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, "ParticleMgr::maintain"); if scene_data.particles_enabled { // update timings self.scheduler.maintain(scene_data.state.get_time()); @@ -122,6 +125,7 @@ impl ParticleMgr { } fn maintain_body_particles(&mut self, scene_data: &SceneData) { + span!(_guard, "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 +152,7 @@ impl ParticleMgr { } fn maintain_campfirelit_particles(&mut self, scene_data: &SceneData, pos: &Pos) { + span!(_guard, "ParticleMgr::maintain_campfirelit_particles"); let time = scene_data.state.get_time(); for _ in 0..self.scheduler.heartbeats(Duration::from_millis(10)) { @@ -168,6 +173,7 @@ impl ParticleMgr { } fn maintain_boltfire_particles(&mut self, scene_data: &SceneData, pos: &Pos) { + span!(_guard, "ParticleMgr::maintain_boltfire_particles"); let time = scene_data.state.get_time(); for _ in 0..self.scheduler.heartbeats(Duration::from_millis(10)) { @@ -187,6 +193,7 @@ impl ParticleMgr { } fn maintain_boltfirebig_particles(&mut self, scene_data: &SceneData, pos: &Pos) { + span!(_guard, "ParticleMgr::maintain_boltfirebig_particles"); let time = scene_data.state.get_time(); // fire @@ -217,6 +224,7 @@ impl ParticleMgr { } fn maintain_bomb_particles(&mut self, scene_data: &SceneData, pos: &Pos) { + span!(_guard, "ParticleMgr::maintain_bomb_particles"); let time = scene_data.state.get_time(); for _ in 0..self.scheduler.heartbeats(Duration::from_millis(10)) { @@ -239,6 +247,7 @@ impl ParticleMgr { } fn maintain_boost_particles(&mut self, scene_data: &SceneData) { + span!(_guard, "ParticleMgr::maintain_boost_particles"); let state = scene_data.state; let ecs = state.ecs(); let time = state.get_time(); @@ -272,6 +281,7 @@ impl ParticleMgr { scene_data: &SceneData, terrain: &Terrain, ) { + span!(_guard, "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 +393,7 @@ impl ParticleMgr { } fn upload_particles(&mut self, renderer: &mut Renderer) { + span!(_guard, "ParticleMgr::upload_particles"); let all_cpu_instances = self .particles .iter() @@ -404,6 +415,7 @@ impl ParticleMgr { global: &GlobalModel, lod: &LodData, ) { + span!(_guard, "ParticleMgr::render"); if scene_data.particles_enabled { let model = &self .model_cache @@ -489,6 +501,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, "HeartbeatScheduler::maintain"); self.last_known_time = now; for (frequency, (last_update, heartbeats)) in self.timers.iter_mut() { @@ -520,6 +533,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..8449ce7e3c 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, "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, "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, "Terrain::render_shadows"); if !renderer.render_mode().shadow.is_map() { return; }; @@ -992,6 +1013,7 @@ impl Terrain { lod: &LodData, focus_pos: Vec3, ) { + span!(_guard, "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, "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..981d95a9a1 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, "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 f6bafd4804..40edad0338 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, "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"); // 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, @@ -1113,6 +1116,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 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 23f1d608e4..b63956a72b 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}, @@ -292,6 +292,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, "Ui::maintain"); // Maintain tooltip manager self.tooltip_manager .maintain(self.ui.global_input(), self.scale.scale_factor_logical()); @@ -333,6 +334,7 @@ impl Ui { view_projection_mat: Option>, retry: &mut bool, ) { + span!(_guard, "Ui::maintain_internal"); let (graphic_cache, text_cache, glyph_cache, cache_tex) = self.cache.cache_mut_and_tex(); let mut primitives = if *retry { @@ -977,6 +979,7 @@ impl Ui { } pub fn render(&self, renderer: &mut Renderer, maybe_globals: Option<&Consts>) { + span!(_guard, "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 2a53eb5328..1adc1a1a13 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; @@ -1048,6 +1049,7 @@ impl Window { } pub fn swap_buffers(&self) -> Result<(), Error> { + span!(_guard, "Window::swap_buffers"); self.window .swap_buffers() .map_err(|err| Error::BackendError(Box::new(err))) From 705ebae697b5503655f210735d979f7b4bd57aa8 Mon Sep 17 00:00:00 2001 From: Imbris Date: Wed, 26 Aug 2020 04:11:31 -0400 Subject: [PATCH 3/8] Sprinkle instrumentation in common crate,in particular in the ecs systems --- common/src/path.rs | 2 ++ common/src/ray.rs | 6 +++++- common/src/region.rs | 6 +++++- common/src/sys/agent.rs | 2 ++ common/src/sys/character_behavior.rs | 2 ++ common/src/sys/combat.rs | 2 ++ common/src/sys/controller.rs | 2 ++ common/src/sys/mount.rs | 2 ++ common/src/sys/phys.rs | 9 ++++++++- common/src/sys/projectile.rs | 2 ++ common/src/sys/stats.rs | 2 ++ voxygen/src/mesh/terrain.rs | 2 +- 12 files changed, 35 insertions(+), 4 deletions(-) diff --git a/common/src/path.rs b/common/src/path.rs index cf02e684ae..cdad9bdbc9 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, "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..91588e8d1f 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, "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..34ca7e2130 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, "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..48cdfd66c1 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, @@ -116,6 +117,7 @@ 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/sys/character_behavior.rs b/common/src/sys/character_behavior.rs index 591a46e227..d8865b2b89 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, "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 e8d83e9847..770051ae02 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, "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..d24f5f0912 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, "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..9133743bac 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, "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 dd2f99af4e..4083c74514 100644 --- a/common/src/sys/phys.rs +++ b/common/src/sys/phys.rs @@ -95,10 +95,11 @@ impl<'a> System<'a> for Sys { projectiles, ): Self::SystemData, ) { - span!(_guard, "::run"); + span!(_guard, "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, @@ -112,6 +113,7 @@ impl<'a> System<'a> for Sys { .entry(entity) .map(|e| e.or_insert_with(Default::default)); } + drop(guard); // Apply pushback // @@ -126,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, @@ -246,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(), @@ -349,6 +354,7 @@ impl<'a> System<'a> for Sys { radius: f32, z_range: Range, ) -> impl Iterator> + 'a { + span!(_guard, "collision_iter"); near_iter.filter_map(move |(i, j, k)| { let block_pos = pos.map(|e| e.floor() as i32) + Vec3::new(i, j, k); @@ -648,6 +654,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 3d70aa18fc..35425df8a0 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, "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..d262d0fc04 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, "stats::Sys::run"); let mut server_event_emitter = server_event_bus.emitter(); // Increment last change timer diff --git a/voxygen/src/mesh/terrain.rs b/voxygen/src/mesh/terrain.rs index 7abcb15e0b..c9242df5a1 100644 --- a/voxygen/src/mesh/terrain.rs +++ b/voxygen/src/mesh/terrain.rs @@ -242,7 +242,7 @@ impl<'a, V: RectRasterableVol + ReadVol + Debug> self, (range, max_texture_size): Self::Supplement, ) -> MeshGen { - span!(_guard, "<&VolGrid2d as Meshable<_, _>::generate_mesh"); + span!(_guard, "<&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(); From f5fc9d67221e2dc7845a8e10a6eb97ec31ce1e60 Mon Sep 17 00:00:00 2001 From: Imbris Date: Sat, 29 Aug 2020 00:33:20 -0400 Subject: [PATCH 4/8] Update tracy crates, reduce overhead of timing, add more misc instrumentation --- Cargo.lock | 15 +++++++++------ common/Cargo.toml | 4 ++++ common/src/clock.rs | 2 ++ common/src/sys/agent.rs | 2 +- common/src/util/mod.rs | 12 ++++++++++++ server-cli/Cargo.toml | 14 +++++++++----- server-cli/src/main.rs | 28 ++++++++++++++++++++-------- voxygen/Cargo.toml | 5 +++-- voxygen/src/logging.rs | 6 ++++-- 9 files changed, 64 insertions(+), 24 deletions(-) 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."); From b916d25eb32a83658004d3ee442a9dfd6aa1dd2a Mon Sep 17 00:00:00 2001 From: Imbris Date: Sat, 29 Aug 2020 02:39:16 -0400 Subject: [PATCH 5/8] Add spans to server systems --- common/src/sys/phys.rs | 1 - server/src/events/mod.rs | 6 +++++- server/src/events/player.rs | 3 +++ server/src/sys/entity_sync.rs | 2 ++ server/src/sys/invite_timeout.rs | 2 ++ server/src/sys/message.rs | 2 ++ server/src/sys/object.rs | 2 ++ server/src/sys/persistence.rs | 6 +++++- server/src/sys/sentinel.rs | 2 ++ server/src/sys/subscription.rs | 2 ++ server/src/sys/terrain.rs | 2 ++ server/src/sys/terrain_sync.rs | 2 ++ server/src/sys/waypoint.rs | 2 ++ 13 files changed, 31 insertions(+), 3 deletions(-) diff --git a/common/src/sys/phys.rs b/common/src/sys/phys.rs index 4083c74514..405adea302 100644 --- a/common/src/sys/phys.rs +++ b/common/src/sys/phys.rs @@ -354,7 +354,6 @@ impl<'a> System<'a> for Sys { radius: f32, z_range: Range, ) -> impl Iterator> + 'a { - span!(_guard, "collision_iter"); near_iter.filter_map(move |(i, j, k)| { let block_pos = pos.map(|e| e.floor() as i32) + Vec3::new(i, j, k); diff --git a/server/src/events/mod.rs b/server/src/events/mod.rs index 948fbc6355..5adaaec801 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, "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..d3dc15b2ea 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, "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..8c725d976e 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, "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..a25c23f622 100644 --- a/server/src/sys/message.rs +++ b/server/src/sys/message.rs @@ -4,6 +4,7 @@ use crate::{ persistence::character::CharacterLoader, ServerSettings, }; use common::{ + span, comp::{ Admin, AdminList, CanBuild, ChatMode, ChatType, ControlEvent, Controller, ForceUpdate, Ori, Player, Pos, Stats, UnresolvedChatMsg, Vel, @@ -454,6 +455,7 @@ impl<'a> System<'a> for Sys { alias_validator, ): Self::SystemData, ) { + span!(_guard, "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..f044c198fc 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, "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..444754b79c 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, "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..8f67f2d03c 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, "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..a29243df18 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, "subscription::Sys::run"); timer.start(); // To update subscriptions diff --git a/server/src/sys/terrain.rs b/server/src/sys/terrain.rs index 2270807410..dc8b77347b 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, "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..1398a2b1af 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, "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..870dacf8ab 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, "waypoint::Sys::run"); timer.start(); for (entity, player_pos, _, client) in From 5b96b0aa933dd94089408298c95df0df87043a12 Mon Sep 17 00:00:00 2001 From: Imbris Date: Sat, 29 Aug 2020 03:00:26 -0400 Subject: [PATCH 6/8] Use finish_continuous_frame directly --- .cargo/config | 2 ++ Cargo.lock | 1 - common/src/util/mod.rs | 2 ++ server-cli/src/main.rs | 11 +++++++---- server/src/sys/message.rs | 2 +- voxygen/Cargo.toml | 3 +-- voxygen/src/run.rs | 3 ++- 7 files changed, 15 insertions(+), 9 deletions(-) diff --git a/.cargo/config b/.cargo/config index 6184721f7e..d07f71d5cc 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 cf7c15526c..ff7699bcc6 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -5040,7 +5040,6 @@ dependencies = [ "tracing-log", "tracing-subscriber", "tracing-tracy", - "tracy-client", "treeculler", "uvth 3.1.1", "vek 0.12.0", diff --git a/common/src/util/mod.rs b/common/src/util/mod.rs index c17e88f832..a3ca02bc19 100644 --- a/common/src/util/mod.rs +++ b/common/src/util/mod.rs @@ -11,6 +11,8 @@ 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 { diff --git a/server-cli/src/main.rs b/server-cli/src/main.rs index e111f645b7..0b03d3913a 100644 --- a/server-cli/src/main.rs +++ b/server-cli/src/main.rs @@ -12,9 +12,9 @@ use crate::{ use common::clock::Clock; use server::{Event, Input, Server, ServerSettings}; use tracing::{info, Level}; -use tracing_subscriber::{ - filter::LevelFilter, layer::SubscriberExt, prelude::*, EnvFilter, FmtSubscriber, -}; +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}; @@ -77,6 +77,8 @@ fn main() -> io::Result<()> { .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) @@ -122,7 +124,8 @@ fn main() -> io::Result<()> { // Clean up the server after a tick. server.cleanup(); - tracing::trace!(tracy.frame_mark = true); + #[cfg(feature = "tracy")] + common::util::tracy_client::finish_continuous_frame!(); match msg_r.try_recv() { Ok(msg) => match msg { diff --git a/server/src/sys/message.rs b/server/src/sys/message.rs index a25c23f622..c61ad7dc5a 100644 --- a/server/src/sys/message.rs +++ b/server/src/sys/message.rs @@ -4,7 +4,6 @@ use crate::{ persistence::character::CharacterLoader, ServerSettings, }; use common::{ - span, comp::{ Admin, AdminList, CanBuild, ChatMode, ChatType, ControlEvent, Controller, ForceUpdate, Ori, Player, Pos, Stats, UnresolvedChatMsg, Vel, @@ -14,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}, diff --git a/voxygen/Cargo.toml b/voxygen/Cargo.toml index b2764f4910..ced96e496d 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-client", "common/tracy"] +tracy = ["tracing-tracy", "common/tracy"] tweak = ["const-tweaker"] default = ["gl", "singleplayer", "msgbox"] @@ -84,7 +84,6 @@ tracing-subscriber = {version = "0.2.3", default-features = false, features = [" # Tracy 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/run.rs b/voxygen/src/run.rs index c21af359bd..1d22384c6e 100644 --- a/voxygen/src/run.rs +++ b/voxygen/src/run.rs @@ -162,7 +162,8 @@ fn handle_main_events_cleared( .swap_buffers() .expect("Failed to swap window buffers!"); drop(guard); - tracing::trace!(tracy.frame_mark = true); + #[cfg(feature = "tracy")] + common::util::tracy_client::finish_continuous_frame!(); } if !exit { From 75faa13fd223f77dc93281703e84845f895e378e Mon Sep 17 00:00:00 2001 From: Imbris Date: Sun, 6 Sep 2020 15:51:04 -0400 Subject: [PATCH 7/8] remove duplicate tracing filter code, fix compiling voxygen with the tracy feature --- .cargo/config | 2 +- common/src/util/mod.rs | 2 +- voxygen/src/logging.rs | 6 +----- 3 files changed, 3 insertions(+), 7 deletions(-) diff --git a/.cargo/config b/.cargo/config index d07f71d5cc..745130059d 100644 --- a/.cargo/config +++ b/.cargo/config @@ -8,6 +8,6 @@ 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" +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/common/src/util/mod.rs b/common/src/util/mod.rs index a3ca02bc19..bd9b18b91a 100644 --- a/common/src/util/mod.rs +++ b/common/src/util/mod.rs @@ -31,7 +31,7 @@ macro_rules! span { 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( + let $guard_name = $crate::util::tracy_client::Span::new( $name, "", module_path!(), diff --git a/voxygen/src/logging.rs b/voxygen/src/logging.rs index 95bc5678ad..583127e527 100644 --- a/voxygen/src/logging.rs +++ b/voxygen/src/logging.rs @@ -63,11 +63,7 @@ pub fn init(settings: &Settings) -> Vec { }; #[cfg(feature = "tracy")] - let filter = EnvFilter::new("dot_vox::parser=warn") - .add_directive("gfx_device_gl=warn".parse().unwrap()) - .add_directive("uvth=warn".parse().unwrap()) - .add_directive("tiny_http=warn".parse().unwrap()) - .add_directive(LevelFilter::TRACE.into()); + 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()); From 0a057ba4d01003316c828d618693ce6aa2372c5a Mon Sep 17 00:00:00 2001 From: Imbris Date: Mon, 7 Sep 2020 00:59:16 -0400 Subject: [PATCH 8/8] Use less verbose span names when the tracy feature is off --- common/src/clock.rs | 2 +- common/src/path.rs | 2 +- common/src/ray.rs | 2 +- common/src/region.rs | 2 +- common/src/sys/agent.rs | 2 +- common/src/sys/character_behavior.rs | 2 +- common/src/sys/combat.rs | 2 +- common/src/sys/controller.rs | 2 +- common/src/sys/mount.rs | 2 +- common/src/sys/phys.rs | 2 +- common/src/sys/projectile.rs | 2 +- common/src/sys/stats.rs | 2 +- common/src/util/mod.rs | 6 +++ server/src/events/mod.rs | 2 +- server/src/sys/entity_sync.rs | 2 +- server/src/sys/invite_timeout.rs | 2 +- server/src/sys/message.rs | 2 +- server/src/sys/object.rs | 2 +- server/src/sys/persistence.rs | 2 +- server/src/sys/sentinel.rs | 2 +- server/src/sys/subscription.rs | 2 +- server/src/sys/terrain.rs | 2 +- server/src/sys/terrain_sync.rs | 2 +- server/src/sys/waypoint.rs | 2 +- voxygen/src/hud/mod.rs | 6 +-- voxygen/src/menu/char_selection/mod.rs | 3 +- voxygen/src/menu/main/mod.rs | 3 +- voxygen/src/mesh/greedy.rs | 6 +-- voxygen/src/mesh/terrain.rs | 6 ++- voxygen/src/render/renderer.rs | 6 +-- voxygen/src/run.rs | 1 - voxygen/src/scene/camera.rs | 2 +- voxygen/src/scene/figure/mod.rs | 16 ++++---- voxygen/src/scene/mod.rs | 6 +-- voxygen/src/scene/particle.rs | 52 ++++++++++++++++++++------ voxygen/src/scene/terrain.rs | 10 ++--- voxygen/src/scene/terrain/watcher.rs | 2 +- voxygen/src/session.rs | 6 +-- voxygen/src/ui/mod.rs | 6 +-- voxygen/src/window.rs | 2 +- 40 files changed, 112 insertions(+), 73 deletions(-) diff --git a/common/src/clock.rs b/common/src/clock.rs index e819b5d17d..02d4946e5f 100644 --- a/common/src/clock.rs +++ b/common/src/clock.rs @@ -32,7 +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"); + 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 cdad9bdbc9..f065f5f2db 100644 --- a/common/src/path.rs +++ b/common/src/path.rs @@ -328,7 +328,7 @@ impl Chaser { where V: BaseVol + ReadVol, { - span!(_guard, "Chaser::chase"); + 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 91588e8d1f..7f58dc3926 100644 --- a/common/src/ray.rs +++ b/common/src/ray.rs @@ -55,7 +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, "Ray::cast"); + 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 34ca7e2130..23428ba63b 100644 --- a/common/src/region.rs +++ b/common/src/region.rs @@ -107,7 +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, "Region::tick"); + 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 aa4b89e413..f6e7099e51 100644 --- a/common/src/sys/agent.rs +++ b/common/src/sys/agent.rs @@ -84,7 +84,7 @@ impl<'a> System<'a> for Sys { invites, ): Self::SystemData, ) { - span!(_guard, "agent::Sys::run"); + 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 d8865b2b89..d193bc6853 100644 --- a/common/src/sys/character_behavior.rs +++ b/common/src/sys/character_behavior.rs @@ -184,7 +184,7 @@ impl<'a> System<'a> for Sys { mountings, ): Self::SystemData, ) { - span!(_guard, "character_behavior::Sys::run"); + 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 770051ae02..12e485ec47 100644 --- a/common/src/sys/combat.rs +++ b/common/src/sys/combat.rs @@ -53,7 +53,7 @@ impl<'a> System<'a> for Sys { character_states, ): Self::SystemData, ) { - span!(_guard, "combat::Sys::run"); + 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 d24f5f0912..ba76d3c949 100644 --- a/common/src/sys/controller.rs +++ b/common/src/sys/controller.rs @@ -44,7 +44,7 @@ impl<'a> System<'a> for Sys { uids, ): Self::SystemData, ) { - span!(_guard, "controller::Sys::run"); + 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 9133743bac..a6fbfb8c9d 100644 --- a/common/src/sys/mount.rs +++ b/common/src/sys/mount.rs @@ -37,7 +37,7 @@ impl<'a> System<'a> for Sys { mut orientations, ): Self::SystemData, ) { - span!(_guard, "mount::Sys::run"); + 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 405adea302..09b110fc46 100644 --- a/common/src/sys/phys.rs +++ b/common/src/sys/phys.rs @@ -95,7 +95,7 @@ impl<'a> System<'a> for Sys { projectiles, ): Self::SystemData, ) { - span!(_guard, "phys::Sys::run"); + span!(_guard, "run", "phys::Sys::run"); let mut event_emitter = event_bus.emitter(); // Add/reset physics state components diff --git a/common/src/sys/projectile.rs b/common/src/sys/projectile.rs index 35425df8a0..df4f4f1684 100644 --- a/common/src/sys/projectile.rs +++ b/common/src/sys/projectile.rs @@ -49,7 +49,7 @@ impl<'a> System<'a> for Sys { loadouts, ): Self::SystemData, ) { - span!(_guard, "projectile::Sys::run"); + 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 d262d0fc04..b35dc02e26 100644 --- a/common/src/sys/stats.rs +++ b/common/src/sys/stats.rs @@ -25,7 +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, "stats::Sys::run"); + 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 bd9b18b91a..1c6940a201 100644 --- a/common/src/util/mod.rs +++ b/common/src/util/mod.rs @@ -40,6 +40,12 @@ macro_rules! span { 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 diff --git a/server/src/events/mod.rs b/server/src/events/mod.rs index 5adaaec801..d56c4fa8c4 100644 --- a/server/src/events/mod.rs +++ b/server/src/events/mod.rs @@ -39,7 +39,7 @@ pub enum Event { impl Server { pub fn handle_events(&mut self) -> Vec { - span!(_guard, "Server::handle_events"); + span!(_guard, "handle_events", "Server::handle_events"); let mut frontend_events = Vec::new(); let mut requested_chunks = Vec::new(); diff --git a/server/src/sys/entity_sync.rs b/server/src/sys/entity_sync.rs index d3dc15b2ea..1dfd92e4aa 100644 --- a/server/src/sys/entity_sync.rs +++ b/server/src/sys/entity_sync.rs @@ -78,7 +78,7 @@ impl<'a> System<'a> for Sys { trackers, ): Self::SystemData, ) { - span!(_guard, "entity_sync::Sys::run"); + 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 8c725d976e..834f812a84 100644 --- a/server/src/sys/invite_timeout.rs +++ b/server/src/sys/invite_timeout.rs @@ -25,7 +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, "invite_timeout::Sys::run"); + 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 c61ad7dc5a..31fa9dffbf 100644 --- a/server/src/sys/message.rs +++ b/server/src/sys/message.rs @@ -455,7 +455,7 @@ impl<'a> System<'a> for Sys { alias_validator, ): Self::SystemData, ) { - span!(_guard, "message::Sys::run"); + 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 f044c198fc..d6deafad3e 100644 --- a/server/src/sys/object.rs +++ b/server/src/sys/object.rs @@ -24,7 +24,7 @@ impl<'a> System<'a> for Sys { &mut self, (entities, _dt, server_bus, positions, velocities, physics_states, mut objects): Self::SystemData, ) { - span!(_guard, "object::Sys::run"); + 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 444754b79c..c1dd0982b4 100644 --- a/server/src/sys/persistence.rs +++ b/server/src/sys/persistence.rs @@ -34,7 +34,7 @@ impl<'a> System<'a> for Sys { mut timer, ): Self::SystemData, ) { - span!(_guard, "persistence::Sys::run"); + 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 8f67f2d03c..5fb64ddd5f 100644 --- a/server/src/sys/sentinel.rs +++ b/server/src/sys/sentinel.rs @@ -27,7 +27,7 @@ impl<'a> System<'a> for Sys { ); fn run(&mut self, (mut timer, comps, mut trackers): Self::SystemData) { - span!(_guard, "sentinel::Sys::run"); + 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 a29243df18..1e0df762bd 100644 --- a/server/src/sys/subscription.rs +++ b/server/src/sys/subscription.rs @@ -56,7 +56,7 @@ impl<'a> System<'a> for Sys { tracked_comps, ): Self::SystemData, ) { - span!(_guard, "subscription::Sys::run"); + 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 dc8b77347b..ace7d43814 100644 --- a/server/src/sys/terrain.rs +++ b/server/src/sys/terrain.rs @@ -56,7 +56,7 @@ impl<'a> System<'a> for Sys { mut clients, ): Self::SystemData, ) { - span!(_guard, "terrain::Sys::run"); + 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 1398a2b1af..8d0e8b5f23 100644 --- a/server/src/sys/terrain_sync.rs +++ b/server/src/sys/terrain_sync.rs @@ -27,7 +27,7 @@ impl<'a> System<'a> for Sys { &mut self, (terrain, terrain_changes, mut timer, positions, players, mut clients): Self::SystemData, ) { - span!(_guard, "terrain_sync::Sys::run"); + 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 870dacf8ab..d9b0f0e739 100644 --- a/server/src/sys/waypoint.rs +++ b/server/src/sys/waypoint.rs @@ -31,7 +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, "waypoint::Sys::run"); + span!(_guard, "run", "waypoint::Sys::run"); timer.start(); for (entity, player_pos, _, client) in diff --git a/voxygen/src/hud/mod.rs b/voxygen/src/hud/mod.rs index 9d1ecb5369..f6202d87d5 100644 --- a/voxygen/src/hud/mod.rs +++ b/voxygen/src/hud/mod.rs @@ -688,7 +688,7 @@ impl Hud { info: HudInfo, camera: &Camera, ) -> Vec { - span!(_guard, "Hud::update_layout"); + 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 @@ -2533,7 +2533,7 @@ impl Hud { dt: Duration, info: HudInfo, ) -> Vec { - span!(_guard, "Hud::maintain"); + 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}; @@ -2578,7 +2578,7 @@ impl Hud { } pub fn render(&self, renderer: &mut Renderer, globals: &Consts) { - span!(_guard, "Hud::render"); + 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/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 cfd8d4b143..13e70b639c 100644 --- a/voxygen/src/mesh/greedy.rs +++ b/voxygen/src/mesh/greedy.rs @@ -102,7 +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, "GreedyMesh::new"); + span!(_guard, "new", "GreedyMesh::new"); let min_max_dim = max_size.width.min(max_size.height); assert!( min_max_dim >= 4, @@ -150,7 +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, "GreedyMesh::push"); + span!(_guard, "push", "GreedyMesh::push"); let cont = greedy_mesh( &mut self.atlas, &mut self.col_lights_size, @@ -170,7 +170,7 @@ impl<'a> GreedyMesh<'a> { /// /// Returns the ColLightsInfo corresponding to the constructed atlas. pub fn finalize(self) -> ColLightInfo { - span!(_guard, "GreedyMesh::finalize"); + span!(_guard, "finalize", "GreedyMesh::finalize"); let cur_size = self.col_lights_size; let col_lights = vec![ TerrainVertex::make_col_light(254, Rgb::broadcast(254)); diff --git a/voxygen/src/mesh/terrain.rs b/voxygen/src/mesh/terrain.rs index c9242df5a1..05725ff629 100644 --- a/voxygen/src/mesh/terrain.rs +++ b/voxygen/src/mesh/terrain.rs @@ -242,7 +242,11 @@ impl<'a, V: RectRasterableVol + ReadVol + Debug> self, (range, max_texture_size): Self::Supplement, ) -> MeshGen { - span!(_guard, "<&VolGrid2d as Meshable<_, _>>::generate_mesh"); + 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(); diff --git a/voxygen/src/render/renderer.rs b/voxygen/src/render/renderer.rs index eb3246cc3e..96b43753cf 100644 --- a/voxygen/src/render/renderer.rs +++ b/voxygen/src/render/renderer.rs @@ -606,7 +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, "Renderer::clear_shadows"); + span!(_guard, "clear_shadows", "Renderer::clear_shadows"); if !self.mode.shadow.is_map() { return; } @@ -679,7 +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, "Renderer::clear"); + 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); @@ -715,7 +715,7 @@ impl Renderer { /// Perform all queued draw calls for this frame and clean up discarded /// items. pub fn flush(&mut self) { - span!(_guard, "Renderer::flush"); + 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 1d22384c6e..ee9004fa1d 100644 --- a/voxygen/src/run.rs +++ b/voxygen/src/run.rs @@ -92,7 +92,6 @@ 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, "PlayState::tick"); last.tick(global_state, events) }) { // Implement state transfer logic. diff --git a/voxygen/src/scene/camera.rs b/voxygen/src/scene/camera.rs index d5b747efd9..f48db8a7f3 100644 --- a/voxygen/src/scene/camera.rs +++ b/voxygen/src/scene/camera.rs @@ -81,7 +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, "Camera::compute_dependents"); + 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 1480262b81..15e14f6998 100644 --- a/voxygen/src/scene/figure/mod.rs +++ b/voxygen/src/scene/figure/mod.rs @@ -196,7 +196,7 @@ impl FigureMgrStates { } fn retain(&mut self, mut f: impl FnMut(&EcsEntity, &mut FigureStateMeta) -> bool) { - span!(_guard, "FigureManagerStates::retain"); + 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)); @@ -339,7 +339,7 @@ impl FigureMgr { pub fn col_lights(&self) -> &FigureColLights { &self.col_lights } pub fn clean(&mut self, tick: u64) { - span!(_guard, "FigureManager::clean"); + 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 @@ -366,7 +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, "FigureManager::update_lighting"); + span!(_guard, "update_lighting", "FigureManager::update_lighting"); let ecs = scene_data.state.ecs(); for (entity, body, light_emitter) in ( &ecs.entities(), @@ -455,7 +455,7 @@ impl FigureMgr { visible_psr_bounds: math::Aabr, camera: &Camera, ) -> anim::vek::Aabb { - span!(_guard, "FigureManager::maintain"); + span!(_guard, "maintain", "FigureManager::maintain"); let state = scene_data.state; let time = state.get_time(); let tick = scene_data.tick; @@ -2135,7 +2135,7 @@ impl FigureMgr { (is_daylight, _light_data): super::LightData, (camera, figure_lod_render_distance): CameraData, ) { - span!(_guard, "FigureManager::render_shadows"); + span!(_guard, "render_shadows", "FigureManager::render_shadows"); let ecs = state.ecs(); if is_daylight && renderer.render_mode().shadow.is_map() { @@ -2187,7 +2187,7 @@ impl FigureMgr { lod: &LodData, (camera, figure_lod_render_distance): CameraData, ) { - span!(_guard, "FigureManager::render"); + span!(_guard, "render", "FigureManager::render"); let ecs = state.ecs(); let character_state_storage = state.read_storage::(); @@ -2238,7 +2238,7 @@ impl FigureMgr { lod: &LodData, (camera, figure_lod_render_distance): CameraData, ) { - span!(_guard, "FigureManager::render_player"); + span!(_guard, "render_player", "FigureManager::render_player"); let ecs = state.ecs(); let character_state_storage = state.read_storage::(); @@ -2622,7 +2622,7 @@ impl FigureColLights { (opaque, bounds): (Mesh, math::Aabb), vertex_range: [Range; N], ) -> Result, RenderError> { - span!(_guard, "FigureColLights::create_figure"); + 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 dceac65b85..537ed1c5d6 100644 --- a/voxygen/src/scene/mod.rs +++ b/voxygen/src/scene/mod.rs @@ -380,7 +380,7 @@ impl Scene { scene_data: &SceneData, audio: &mut AudioFrontend, ) { - span!(_guard, "Scene::handle_outcome"); + span!(_guard, "handle_outcome", "Scene::handle_outcome"); self.particle_mgr.handle_outcome(&outcome, &scene_data); self.sfx_mgr.handle_outcome(&outcome, audio); @@ -424,7 +424,7 @@ impl Scene { audio: &mut AudioFrontend, scene_data: &SceneData, ) { - span!(_guard, "Scene::maintain"); + span!(_guard, "maintain", "Scene::maintain"); // Get player position. let ecs = scene_data.state.ecs(); @@ -976,7 +976,7 @@ impl Scene { tick: u64, scene_data: &SceneData, ) { - span!(_guard, "Scene::render"); + 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 4ec3df2161..127530d541 100644 --- a/voxygen/src/scene/particle.rs +++ b/voxygen/src/scene/particle.rs @@ -49,7 +49,7 @@ impl ParticleMgr { } pub fn handle_outcome(&mut self, outcome: &Outcome, scene_data: &SceneData) { - span!(_guard, "ParticleMgr::handle_outcome"); + span!(_guard, "handle_outcome", "ParticleMgr::handle_outcome"); let time = scene_data.state.get_time(); let mut rng = rand::thread_rng(); @@ -100,7 +100,7 @@ impl ParticleMgr { scene_data: &SceneData, terrain: &Terrain, ) { - span!(_guard, "ParticleMgr::maintain"); + span!(_guard, "maintain", "ParticleMgr::maintain"); if scene_data.particles_enabled { // update timings self.scheduler.maintain(scene_data.state.get_time()); @@ -125,7 +125,11 @@ impl ParticleMgr { } fn maintain_body_particles(&mut self, scene_data: &SceneData) { - span!(_guard, "ParticleMgr::maintain_body_particles"); + 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 { @@ -152,7 +156,11 @@ impl ParticleMgr { } fn maintain_campfirelit_particles(&mut self, scene_data: &SceneData, pos: &Pos) { - span!(_guard, "ParticleMgr::maintain_campfirelit_particles"); + 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)) { @@ -173,7 +181,11 @@ impl ParticleMgr { } fn maintain_boltfire_particles(&mut self, scene_data: &SceneData, pos: &Pos) { - span!(_guard, "ParticleMgr::maintain_boltfire_particles"); + 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)) { @@ -193,7 +205,11 @@ impl ParticleMgr { } fn maintain_boltfirebig_particles(&mut self, scene_data: &SceneData, pos: &Pos) { - span!(_guard, "ParticleMgr::maintain_boltfirebig_particles"); + span!( + _guard, + "boltfirebig_particles", + "ParticleMgr::maintain_boltfirebig_particles" + ); let time = scene_data.state.get_time(); // fire @@ -224,7 +240,11 @@ impl ParticleMgr { } fn maintain_bomb_particles(&mut self, scene_data: &SceneData, pos: &Pos) { - span!(_guard, "ParticleMgr::maintain_bomb_particles"); + 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)) { @@ -247,7 +267,11 @@ impl ParticleMgr { } fn maintain_boost_particles(&mut self, scene_data: &SceneData) { - span!(_guard, "ParticleMgr::maintain_boost_particles"); + span!( + _guard, + "boost_particles", + "ParticleMgr::maintain_boost_particles" + ); let state = scene_data.state; let ecs = state.ecs(); let time = state.get_time(); @@ -281,7 +305,11 @@ impl ParticleMgr { scene_data: &SceneData, terrain: &Terrain, ) { - span!(_guard, "ParticleMgr::maintain_block_particles"); + 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 @@ -393,7 +421,7 @@ impl ParticleMgr { } fn upload_particles(&mut self, renderer: &mut Renderer) { - span!(_guard, "ParticleMgr::upload_particles"); + span!(_guard, "upload_particles", "ParticleMgr::upload_particles"); let all_cpu_instances = self .particles .iter() @@ -415,7 +443,7 @@ impl ParticleMgr { global: &GlobalModel, lod: &LodData, ) { - span!(_guard, "ParticleMgr::render"); + span!(_guard, "render", "ParticleMgr::render"); if scene_data.particles_enabled { let model = &self .model_cache @@ -501,7 +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, "HeartbeatScheduler::maintain"); + span!(_guard, "maintain", "HeartbeatScheduler::maintain"); self.last_known_time = now; for (frequency, (last_update, heartbeats)) in self.timers.iter_mut() { diff --git a/voxygen/src/scene/terrain.rs b/voxygen/src/scene/terrain.rs index 8449ce7e3c..9530f78a8f 100644 --- a/voxygen/src/scene/terrain.rs +++ b/voxygen/src/scene/terrain.rs @@ -385,7 +385,7 @@ impl Terrain { fn make_atlas( renderer: &mut Renderer, ) -> Result<(AtlasAllocator, Texture), RenderError> { - span!(_guard, "Terrain::make_atlas"); + 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)); @@ -453,7 +453,7 @@ impl Terrain { view_mat: Mat4, proj_mat: Mat4, ) -> (Aabb, Vec>, math::Aabr) { - span!(_guard, "Terrain::maintain"); + 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; @@ -951,7 +951,7 @@ impl Terrain { (is_daylight, light_data): super::LightData, focus_pos: Vec3, ) { - span!(_guard, "Terrain::render_shadows"); + span!(_guard, "render_shadows", "Terrain::render_shadows"); if !renderer.render_mode().shadow.is_map() { return; }; @@ -1013,7 +1013,7 @@ impl Terrain { lod: &LodData, focus_pos: Vec3, ) { - span!(_guard, "Terrain::render"); + 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) }); @@ -1047,7 +1047,7 @@ impl Terrain { cam_pos: Vec3, sprite_render_distance: f32, ) { - span!(_guard, "Terrain::render_translucent"); + 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) }); diff --git a/voxygen/src/scene/terrain/watcher.rs b/voxygen/src/scene/terrain/watcher.rs index 981d95a9a1..4e1fed21d9 100644 --- a/voxygen/src/scene/terrain/watcher.rs +++ b/voxygen/src/scene/terrain/watcher.rs @@ -17,7 +17,7 @@ pub struct BlocksOfInterest { impl BlocksOfInterest { pub fn from_chunk(chunk: &TerrainChunk) -> Self { - span!(_guard, "BlocksOfInterest::from_chunk"); + 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 40edad0338..259e526dd9 100644 --- a/voxygen/src/session.rs +++ b/voxygen/src/session.rs @@ -112,7 +112,7 @@ impl SessionState { global_state: &mut GlobalState, outcomes: &mut Vec, ) -> Result { - span!(_guard, "Session::tick"); + span!(_guard, "tick", "Session::tick"); self.inputs.tick(dt); let mut client = self.client.borrow_mut(); @@ -197,7 +197,7 @@ impl PlayState for SessionState { } fn tick(&mut self, global_state: &mut GlobalState, events: Vec) -> PlayStateResult { - span!(_guard, "::tick"); + 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, @@ -1116,7 +1116,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"); + 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 b63956a72b..cc9f6ca2b2 100644 --- a/voxygen/src/ui/mod.rs +++ b/voxygen/src/ui/mod.rs @@ -292,7 +292,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, "Ui::maintain"); + span!(_guard, "maintain", "Ui::maintain"); // Maintain tooltip manager self.tooltip_manager .maintain(self.ui.global_input(), self.scale.scale_factor_logical()); @@ -334,7 +334,7 @@ impl Ui { view_projection_mat: Option>, retry: &mut bool, ) { - span!(_guard, "Ui::maintain_internal"); + 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 { @@ -979,7 +979,7 @@ impl Ui { } pub fn render(&self, renderer: &mut Renderer, maybe_globals: Option<&Consts>) { - span!(_guard, "Ui::render"); + 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 1adc1a1a13..bfec6aa8c7 100644 --- a/voxygen/src/window.rs +++ b/voxygen/src/window.rs @@ -1049,7 +1049,7 @@ impl Window { } pub fn swap_buffers(&self) -> Result<(), Error> { - span!(_guard, "Window::swap_buffers"); + span!(_guard, "swap_buffers", "Window::swap_buffers"); self.window .swap_buffers() .map_err(|err| Error::BackendError(Box::new(err)))