add system profile data to Diagnostics (opt in feature)

Cargo.toml

@@ -7,6 +7,7 @@ edition = "2018"
 [features]
 default = ["bevy_wgpu", "bevy_winit"]
 more-system-fns = ["legion/more-system-fns"]
+profiler = ["bevy_app/profiler", "bevy_diagnostic/profiler"]
 
 [workspace]
 members = [

crates/bevy_app/Cargo.toml

@@ -4,6 +4,9 @@ version = "0.1.0"
 authors = ["Carter Anderson <mcanders1@gmail.com>"]
 edition = "2018"
 
+[features]
+profiler = ["legion/profiler"]
+
 [dependencies]
 bevy_derive = { path = "../bevy_derive" }
 legion = { path = "../bevy_legion", features = ["serialize"] }

crates/bevy_app/src/app_builder.rs

@@ -1,7 +1,7 @@
 use crate::{
     plugin::{load_plugin, AppPlugin},
     schedule_plan::SchedulePlan,
-    stage, App, AppExit, Events, FromResources, System, startup_stage,
+    stage, startup_stage, App, AppExit, Events, FromResources, System,
 };
 
 use legion::prelude::{IntoSystem, Resources, World};

crates/bevy_diagnostic/Cargo.toml

@@ -4,6 +4,9 @@ version = "0.1.0"
 authors = ["Carter Anderson <mcanders1@gmail.com>"]
 edition = "2018"
 
+[features]
+profiler = []
+
 [dependencies]
 bevy_app = { path = "../bevy_app" }
 bevy_core = { path = "../bevy_core" }

crates/bevy_diagnostic/src/diagnostic.rs

@@ -13,6 +13,13 @@ impl DiagnosticId {
     }
 }
 
+impl Default for DiagnosticId {
+    fn default() -> Self {
+        DiagnosticId(Uuid::new_v4())
+    }
+    
+}
+
 #[derive(Debug)]
 pub struct DiagnosticMeasurement {
     pub time: SystemTime,

crates/bevy_diagnostic/src/lib.rs

@@ -1,6 +1,8 @@
 mod diagnostic;
 mod frame_time_diagnostics_plugin;
 mod print_diagnostics_plugin;
+#[cfg(feature = "profiler")]
+mod system_profiler;
 pub use diagnostic::*;
 pub use frame_time_diagnostics_plugin::FrameTimeDiagnosticsPlugin;
 pub use print_diagnostics_plugin::PrintDiagnosticsPlugin;
@@ -15,5 +17,11 @@ pub struct DiagnosticsPlugin;
 impl AppPlugin for DiagnosticsPlugin {
     fn build(&self, app: &mut AppBuilder) {
         app.init_resource::<Diagnostics>();
+        #[cfg(feature = "profiler")]
+        {
+            use legion::prelude::IntoSystem;
+            app.add_resource::<Box<dyn legion::systems::profiler::Profiler>>(Box::new(system_profiler::SystemProfiler::default()))
+                .add_system_to_stage(bevy_app::stage::LAST, system_profiler::profiler_diagnostic_system.system());
+        }
     }
 }

crates/bevy_diagnostic/src/print_diagnostics_plugin.rs

@@ -53,7 +53,7 @@ impl PrintDiagnosticsPlugin {
 
     fn print_diagnostic(diagnostic: &Diagnostic) {
         if let Some(value) = diagnostic.value() {
-            print!("{:<20}: {:<19.6}", diagnostic.name, value);
+            print!("{:<65}: {:<10.6}", diagnostic.name, value);
             if let Some(average) = diagnostic.average() {
                 print!("  (avg {:.6})", average);
             }
@@ -70,7 +70,7 @@ impl PrintDiagnosticsPlugin {
         state.timer.tick(time.delta_seconds);
         if state.timer.finished {
             println!("Diagnostics:");
-            println!("{}", "-".repeat(60));
+            println!("{}", "-".repeat(93));
             if let Some(ref filter) = state.filter {
                 for diagnostic in filter.iter().map(|id| diagnostics.get(*id).unwrap()) {
                     Self::print_diagnostic(diagnostic);
@@ -93,7 +93,7 @@ impl PrintDiagnosticsPlugin {
         state.timer.tick(time.delta_seconds);
         if state.timer.finished {
             println!("Diagnostics (Debug):");
-            println!("{}", "-".repeat(60));
+            println!("{}", "-".repeat(93));
             if let Some(ref filter) = state.filter {
                 for diagnostic in filter.iter().map(|id| diagnostics.get(*id).unwrap()) {
                     println!("{:#?}\n", diagnostic);

crates/bevy_diagnostic/src/system_profiler.rs

@@ -0,0 +1,73 @@
+use crate::{Diagnostic, DiagnosticId, Diagnostics};
+use legion::{
+    systems::{profiler::Profiler, Res, ResMut},
+};
+use std::{
+    collections::HashMap,
+    sync::{Arc, RwLock},
+    time::Instant, borrow::Cow,
+};
+
+#[derive(Debug)]
+struct SystemRunInfo {
+    start: Instant,
+    stop: Instant,
+}
+
+#[derive(Default)]
+struct SystemProfiles {
+    diagnostic_id: DiagnosticId,
+    history: Vec<SystemRunInfo>,
+    current_start: Option<Instant>,
+}
+
+#[derive(Default)]
+pub struct SystemProfiler {
+    system_profiles: Arc<RwLock<HashMap<Cow<'static, str>, SystemProfiles>>>,
+}
+
+impl Profiler for SystemProfiler {
+    fn start(&self, scope: Cow<'static, str>) {
+        let mut system_profiles = self.system_profiles.write().unwrap();
+        let profiles = system_profiles
+            .entry(scope.clone())
+            .or_insert_with(|| SystemProfiles::default());
+
+        profiles.current_start = Some(Instant::now());
+    }
+
+    fn stop(&self, scope: Cow<'static, str>) {
+        let now = Instant::now();
+        let mut system_profiles = self.system_profiles.write().unwrap();
+        let profiles = system_profiles.get_mut(&scope).unwrap();
+        if let Some(current_start) = profiles.current_start.take() {
+            profiles.history.push(SystemRunInfo {
+                start: current_start,
+                stop: now,
+            });
+        }
+    }
+}
+
+pub fn profiler_diagnostic_system(
+    mut diagnostics: ResMut<Diagnostics>,
+    system_profiler: Res<Box<dyn Profiler>>,
+) {
+    let system_profiler = system_profiler.downcast_ref::<SystemProfiler>().unwrap();
+    let mut system_profiles = system_profiler.system_profiles.write().unwrap();
+    for (scope, profiles) in system_profiles.iter_mut() {
+        if diagnostics.get(profiles.diagnostic_id).is_none() {
+            diagnostics.add(Diagnostic::new(
+                profiles.diagnostic_id,
+                &scope,
+                20,
+            ))
+        }
+        for profile in profiles.history.drain(..) {
+            diagnostics.add_measurement(
+                profiles.diagnostic_id,
+                (profile.stop - profile.start).as_secs_f64(),
+            );
+        }
+    }
+}

crates/bevy_legion/Cargo.toml

@@ -22,6 +22,7 @@ ffi = ["legion-core/ffi"]
 serialize = ["legion-core/serialize"]
 metrics = ["legion-core/metrics"]
 more-system-fns = ["legion-systems/more-system-fns"]
+profiler = ["legion-systems/profiler"]
 
 # [workspace]
 # members = [

crates/bevy_legion/legion_core/Cargo.toml

@@ -20,7 +20,7 @@ serialize = ["serde"]
 
 [dependencies]
 parking_lot = "0.10"
-downcast-rs = "1.0"
+downcast-rs = "1.1.1"
 itertools = "0.9"
 rayon = { version = "1.2", optional = true }
 crossbeam-queue = { version = "0.2.0", optional = true }

crates/bevy_legion/legion_systems/Cargo.toml

@@ -17,12 +17,13 @@ travis-ci = { repository = "TomGillen/legion", branch = "master" }
 par-iter = ["rayon", "legion-core/par-iter"]
 par-schedule = ["rayon", "crossbeam-queue"]
 more-system-fns = []
+profiler = []
 
 [dependencies]
 legion-core = { path = "../legion_core", version = "0.2.4", default-features = false }
 legion_fn_system_macro = { path = "../legion_fn_system_macro" }
 
-downcast-rs = "1.0"
+downcast-rs = "1.1.1"
 itertools = "0.9"
 rayon = { version = "1.2", optional = true }
 crossbeam-queue = { version = "0.2.0", optional = true }

crates/bevy_legion/legion_systems/src/lib.rs

@@ -1,5 +1,6 @@
 pub mod resource;
 pub mod schedule;
+pub mod profiler;
 
 mod system;
 mod system_fn;

crates/bevy_legion/legion_systems/src/profiler.rs

@@ -0,0 +1,24 @@
+use crate::{
+    resource::Resources,
+};
+use downcast_rs::{impl_downcast, Downcast};
+use std::borrow::Cow;
+
+pub trait Profiler: Downcast + Send + Sync + 'static {
+    fn start(&self, scope: Cow<'static, str>);
+    fn stop(&self, scope: Cow<'static, str>);
+}
+
+pub fn profiler_start(resources: &Resources, scope: Cow<'static, str>) {
+    if let Some(profiler) = resources.get::<Box<dyn Profiler>>() {
+        profiler.start(scope);
+    }
+}
+
+pub fn profiler_stop(resources: &Resources, scope: Cow<'static, str>) {
+    if let Some(profiler) = resources.get::<Box<dyn Profiler>>() {
+        profiler.stop(scope);
+    }
+}
+
+impl_downcast!(Profiler);

crates/bevy_legion/legion_systems/src/schedule.rs

@@ -307,8 +307,12 @@ impl Executor {
     pub fn run_systems(&mut self, world: &mut World, resources: &mut Resources) {
         self.systems.iter_mut().for_each(|system| {
             let system = unsafe { system.get_mut() };
+            #[cfg(feature = "profiler")]
+            crate::profiler::profiler_start(resources, system.name().name());
             system.prepare(world);
             system.run(world, resources);
+            #[cfg(feature = "profiler")]
+            crate::profiler::profiler_stop(resources, system.name().name());
         });
     }
 
@@ -328,8 +332,12 @@ impl Executor {
                         // safety: we have exlusive access to all systems, world and resources here
                         unsafe {
                             let system = self.systems[0].get_mut();
+                            #[cfg(feature = "profiler")]
+                            crate::profiler::profiler_start(resources, system.name().name());
                             system.prepare(world);
                             system.run(world, resources);
+                            #[cfg(feature = "profiler")]
+                            crate::profiler::profiler_stop(resources, system.name().name());
                         };
                     }
                     _ => {
@@ -415,7 +423,11 @@ impl Executor {
     #[cfg(feature = "par-schedule")]
     unsafe fn run_recursive(&self, i: usize, world: &World, resources: &Resources) {
         // safety: the caller ensures nothing else is accessing systems[i]
+        #[cfg(feature = "profiler")]
+        crate::profiler::profiler_start(resources, self.systems[i].get().name().name());
         self.systems[i].get_mut().run_unsafe(world, resources);
+        #[cfg(feature = "profiler")]
+        crate::profiler::profiler_stop(resources, self.systems[i].get().name().name());
 
         self.static_dependants[i].par_iter().for_each(|dep| {
             if self.awaiting[*dep].fetch_sub(1, Ordering::Relaxed) == 1 {
@@ -550,10 +562,20 @@ impl Schedule {
                         ToFlush::System(mut cmd) => cmd.write(world),
                     });
                 }
-                Step::ThreadLocalFn(function) => function(world, resources),
+                Step::ThreadLocalFn(function) => {
+                    #[cfg(feature = "profiler")]
+                    crate::profiler::profiler_start(resources, std::borrow::Cow::Borrowed("thread_local"));
+                    function(world, resources);
+                    #[cfg(feature = "profiler")]
+                    crate::profiler::profiler_stop(resources, std::borrow::Cow::Borrowed("thread_local"));
+                },
                 Step::ThreadLocalSystem(system) => {
+                    #[cfg(feature = "profiler")]
+                    crate::profiler::profiler_start(resources, system.name().name());
                     system.prepare(world);
                     system.run(world, resources);
+                    #[cfg(feature = "profiler")]
+                    crate::profiler::profiler_stop(resources, system.name().name());
                     if let Some(cmd) = system.command_buffer_mut(world.id()) {
                         waiting_flush.push(ToFlush::System(cmd));
                     }