Add tracing spans to schedules, stages, systems (#789)

Add tracing spans to schedules, stages, systems

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"

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

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

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 }

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 */ }
             }
         }

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

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
 

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