From a2665789922167afb59277b1fe988e6df0d68911 Mon Sep 17 00:00:00 2001 From: Robert Swain Date: Wed, 11 Nov 2020 03:49:49 +0100 Subject: [PATCH] Add tracing spans to schedules, stages, systems (#789) Add tracing spans to schedules, stages, systems --- Cargo.toml | 8 +++ crates/bevy_app/Cargo.toml | 4 ++ crates/bevy_app/src/app.rs | 12 +++++ crates/bevy_ecs/Cargo.toml | 2 + .../src/schedule/parallel_executor.rs | 35 ++++++++++++- crates/bevy_internal/Cargo.toml | 1 + examples/README.md | 1 + examples/app/tracing.rs | 49 +++++++++++++++++++ 8 files changed, 111 insertions(+), 1 deletion(-) create mode 100644 examples/app/tracing.rs diff --git a/Cargo.toml b/Cargo.toml index 12995ec18f..5e36929ee9 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -49,6 +49,7 @@ bevy_wgpu = ["bevy_internal/bevy_wgpu"] bevy_winit = ["bevy_internal/bevy_winit"] profiler = ["bevy_internal/profiler"] +trace = ["bevy_internal/trace"] wgpu_trace = ["bevy_internal/wgpu_trace"] # Image format support for texture loading (PNG and HDR are enabled by default) @@ -77,6 +78,9 @@ log = "0.4" rand = "0.7.3" ron = "0.6" serde = {version = "1", features = ["derive"]} +tracing = "0.1.21" +tracing-chrome = "0.2.0" +tracing-subscriber = "0.2.15" # bevy (Android) [target.'cfg(target_os = "android")'.dependencies] @@ -167,6 +171,10 @@ path = "examples/app/return_after_run.rs" name = "thread_pool_resources" path = "examples/app/thread_pool_resources.rs" +[[example]] +name = "tracing" +path = "examples/app/tracing.rs" + [[example]] name = "hot_asset_reloading" path = "examples/asset/hot_asset_reloading.rs" diff --git a/crates/bevy_app/Cargo.toml b/crates/bevy_app/Cargo.toml index 47d42ed6d3..d4838ae793 100644 --- a/crates/bevy_app/Cargo.toml +++ b/crates/bevy_app/Cargo.toml @@ -12,6 +12,9 @@ repository = "https://github.com/bevyengine/bevy" license = "MIT" keywords = ["bevy"] +[features] +trace = [ "tracing" ] + [dependencies] # bevy bevy_derive = { path = "../bevy_derive", version = "0.3.0" } @@ -21,6 +24,7 @@ bevy_utils = { path = "../bevy_utils", version = "0.3.0" } # other log = { version = "0.4", features = ["release_max_level_info"] } serde = { version = "1.0", features = ["derive"] } +tracing = { version = "0.1.21", optional = true } [target.'cfg(target_arch = "wasm32")'.dependencies] wasm-bindgen = { version = "0.2" } diff --git a/crates/bevy_app/src/app.rs b/crates/bevy_app/src/app.rs index 33a1ebbed4..e0764fe2a5 100644 --- a/crates/bevy_app/src/app.rs +++ b/crates/bevy_app/src/app.rs @@ -1,5 +1,7 @@ use crate::app_builder::AppBuilder; use bevy_ecs::{ParallelExecutor, Resources, Schedule, World}; +#[cfg(feature = "trace")] +use tracing::info_span; #[allow(clippy::needless_doctest_main)] /// Containers of app logic and data @@ -65,6 +67,10 @@ impl App { } pub fn initialize(&mut self) { + #[cfg(feature = "trace")] + let startup_schedule_span = info_span!("startup_schedule"); + #[cfg(feature = "trace")] + let _startup_schedule_guard = startup_schedule_span.enter(); self.startup_schedule .initialize(&mut self.world, &mut self.resources); self.startup_executor.initialize(&mut self.resources); @@ -76,7 +82,13 @@ impl App { } pub fn run(mut self) { + #[cfg(feature = "trace")] + let bevy_app_run_span = info_span!("bevy_app_run"); + #[cfg(feature = "trace")] + let _bevy_app_run_guard = bevy_app_run_span.enter(); + self.executor.initialize(&mut self.resources); + let runner = std::mem::replace(&mut self.runner, Box::new(run_once)); (runner)(self); } diff --git a/crates/bevy_ecs/Cargo.toml b/crates/bevy_ecs/Cargo.toml index a5efe3af53..8fcc42d6b3 100644 --- a/crates/bevy_ecs/Cargo.toml +++ b/crates/bevy_ecs/Cargo.toml @@ -15,6 +15,7 @@ categories = ["game-engines", "data-structures"] [features] profiler = [] +trace = [ "tracing" ] [dependencies] bevy_hecs = { path = "hecs", features = ["macros", "serialize"], version = "0.3.0" } @@ -26,3 +27,4 @@ fixedbitset = "0.3.1" downcast-rs = "1.2.0" parking_lot = "0.11.0" log = { version = "0.4", features = ["release_max_level_info"] } +tracing = { version = "0.1.21", optional = true } diff --git a/crates/bevy_ecs/src/schedule/parallel_executor.rs b/crates/bevy_ecs/src/schedule/parallel_executor.rs index 5f6820dbb9..225ca8344f 100644 --- a/crates/bevy_ecs/src/schedule/parallel_executor.rs +++ b/crates/bevy_ecs/src/schedule/parallel_executor.rs @@ -7,6 +7,8 @@ use bevy_hecs::{ArchetypesGeneration, TypeAccess, World}; use bevy_tasks::{ComputeTaskPool, CountdownEvent, TaskPool}; use fixedbitset::FixedBitSet; use std::ops::Range; +#[cfg(feature = "trace")] +use tracing::info_span; /// Executes each schedule stage in parallel by analyzing system dependencies. /// System execution order is undefined except under the following conditions: @@ -48,6 +50,11 @@ impl ParallelExecutor { } pub fn run(&mut self, schedule: &mut Schedule, world: &mut World, resources: &mut Resources) { + #[cfg(feature = "trace")] + let schedule_span = info_span!("schedule"); + #[cfg(feature = "trace")] + let _schedule_guard = schedule_span.enter(); + let schedule_generation = schedule.generation(); let schedule_changed = schedule.generation() != self.last_schedule_generation; if schedule_changed { @@ -57,6 +64,10 @@ impl ParallelExecutor { } for (stage_name, executor_stage) in schedule.stage_order.iter().zip(self.stages.iter_mut()) { + #[cfg(feature = "trace")] + let stage_span = info_span!("stage", name = stage_name.as_ref()); + #[cfg(feature = "trace")] + let _stage_guard = stage_span.enter(); log::trace!("run stage {:?}", stage_name); if let Some(stage_systems) = schedule.stages.get_mut(stage_name) { executor_stage.run(world, resources, stage_systems, schedule_changed); @@ -392,6 +403,11 @@ impl ExecutorStage { // Execute the system - in a scope to ensure the system lock is dropped before // triggering dependents { + #[cfg(feature = "trace")] + let system_span = info_span!("system", name = system.name().as_ref()); + #[cfg(feature = "trace")] + let _system_guard = system_span.enter(); + log::trace!("run {}", system.name()); #[cfg(feature = "profiler")] crate::profiler_start(resources, system.name().clone()); @@ -442,6 +458,11 @@ impl ExecutorStage { for (system_index, system) in systems.iter().enumerate() { if system.thread_local_execution() == ThreadLocalExecution::Immediate { + #[cfg(feature = "trace")] + let system_span = info_span!("system", name = system.name().as_ref()); + #[cfg(feature = "trace")] + let _system_guard = system_span.enter(); + self.thread_local_system_indices.push(system_index); } } @@ -483,6 +504,12 @@ impl ExecutorStage { { // if a thread local system is ready to run, run it exclusively on the main thread let system = systems[thread_local_system_index].as_mut(); + + #[cfg(feature = "trace")] + let system_span = info_span!("system", name = system.name().as_ref()); + #[cfg(feature = "trace")] + let _system_guard = system_span.enter(); + log::trace!("running thread local system {}", system.name()); system.run(world, resources); system.run_thread_local(world, resources); @@ -513,7 +540,13 @@ impl ExecutorStage { // "flush" for system in systems.iter_mut() { match system.thread_local_execution() { - ThreadLocalExecution::NextFlush => system.run_thread_local(world, resources), + ThreadLocalExecution::NextFlush => { + #[cfg(feature = "trace")] + let system_span = info_span!("system", name = system.name().as_ref()); + #[cfg(feature = "trace")] + let _system_guard = system_span.enter(); + system.run_thread_local(world, resources); + } ThreadLocalExecution::Immediate => { /* already ran */ } } } diff --git a/crates/bevy_internal/Cargo.toml b/crates/bevy_internal/Cargo.toml index 6452cd49b3..23fdc7de61 100644 --- a/crates/bevy_internal/Cargo.toml +++ b/crates/bevy_internal/Cargo.toml @@ -16,6 +16,7 @@ categories = ["game-engines", "graphics", "gui", "rendering"] [features] profiler = ["bevy_ecs/profiler", "bevy_diagnostic/profiler"] wgpu_trace = ["bevy_wgpu/trace"] +trace = [ "bevy_app/trace", "bevy_ecs/trace" ] # Image format support for texture loading (PNG and HDR are enabled by default) hdr = ["bevy_render/hdr"] diff --git a/examples/README.md b/examples/README.md index f2eb9ed257..00cd5ecd11 100644 --- a/examples/README.md +++ b/examples/README.md @@ -42,6 +42,7 @@ Example | File | Description `headless` | [`app/headless.rs`](./app/headless.rs) | An application that runs without default plugins `plugin` | [`app/plugin.rs`](./app/plugin.rs) | Demonstrates the creation and registration of a custom plugin `thread_pool_resources` | [`app/thread_pool_resources.rs`](./app/thread_pool_resources.rs) | Creates and customizes the internal thread pool +`tracing` | [`app/tracing.rs`](./app/tracing.rs) | Demonstrates `trace` feature output. Run with `RUST_LOG=info cargo run --example tracing --features trace` and then open the `trace-1234.json` file (where 1234 is a time since the beginning of the epoch) in `chrome://tracing` in Chrome. ## Assets diff --git a/examples/app/tracing.rs b/examples/app/tracing.rs new file mode 100644 index 0000000000..dbbd725a8f --- /dev/null +++ b/examples/app/tracing.rs @@ -0,0 +1,49 @@ +use bevy::{input::system::exit_on_esc_system, prelude::*}; +use std::{thread, time}; +use tracing::info; +use tracing_chrome::ChromeLayerBuilder; +use tracing_subscriber::{fmt, prelude::*, registry::Registry, EnvFilter}; + +pub fn setup_global_subscriber() -> impl Drop { + let fmt_layer = fmt::Layer::default(); + let filter_layer = EnvFilter::try_from_default_env() + .or_else(|_| EnvFilter::try_new("info,wgpu=warn")) + .unwrap(); + + let (chrome_layer, _guard) = ChromeLayerBuilder::new().build(); + + let subscriber = Registry::default() + .with(filter_layer) + .with(fmt_layer) + .with(chrome_layer); + + tracing::subscriber::set_global_default(subscriber).expect("Could not set global default"); + _guard +} + +fn main() { + let _guard = setup_global_subscriber(); + + App::build() + .add_plugins(DefaultPlugins) + .add_startup_system(a_system.system()) + .add_system(foo_bar_baz.system()) + .add_system(exit_on_esc_system.system()) + .run(); +} + +fn a_system(commands: &mut Commands) { + let ten_millis = time::Duration::from_millis(10); + thread::sleep(ten_millis); + + commands.spawn((GlobalTransform::default(), Transform::default())); +} + +fn foo_bar_baz(query: Query<&Transform>) { + for transform in query.iter() { + let five_millis = time::Duration::from_millis(5); + thread::sleep(five_millis); + + info!(?transform); + } +}