add plugin tracing spans (#20722)

# Objective

- easily diagnose startup performance issues

## Solution

- add plugin tracing spans

## Testing

- i have not been able to get any tracing to work in any of bevy. idk if
this code works, but it looks like it should. is tracing broken or do i
have a setup issue?

---------

Co-authored-by: Mike Hsu <mike.hsu@gmail.com>
Co-authored-by: François Mockers <francois.mockers@vleue.com>

Author: 3 people

crates/bevy_app/src/app.rs

@@ -255,11 +255,16 @@ impl App {
     /// Runs [`Plugin::finish`] for each plugin. This is usually called by the event loop once all
     /// plugins are ready, but can be useful for situations where you want to use [`App::update`].
     pub fn finish(&mut self) {
+        #[cfg(feature = "trace")]
+        let _finish_span = info_span!("plugin finish").entered();
         // plugins installed to main should see all sub-apps
         // do hokey pokey with a boxed zst plugin (doesn't allocate)
         let mut hokeypokey: Box<dyn Plugin> = Box::new(HokeyPokey);
         for i in 0..self.main().plugin_registry.len() {
             core::mem::swap(&mut self.main_mut().plugin_registry[i], &mut hokeypokey);
+            #[cfg(feature = "trace")]
+            let _plugin_finish_span =
+                info_span!("plugin finish", plugin = hokeypokey.name()).entered();
             hokeypokey.finish(self);
             core::mem::swap(&mut self.main_mut().plugin_registry[i], &mut hokeypokey);
         }
@@ -270,11 +275,16 @@ impl App {
     /// Runs [`Plugin::cleanup`] for each plugin. This is usually called by the event loop after
     /// [`App::finish`], but can be useful for situations where you want to use [`App::update`].
     pub fn cleanup(&mut self) {
+        #[cfg(feature = "trace")]
+        let _cleanup_span = info_span!("plugin cleanup").entered();
         // plugins installed to main should see all sub-apps
         // do hokey pokey with a boxed zst plugin (doesn't allocate)
         let mut hokeypokey: Box<dyn Plugin> = Box::new(HokeyPokey);
         for i in 0..self.main().plugin_registry.len() {
             core::mem::swap(&mut self.main_mut().plugin_registry[i], &mut hokeypokey);
+            #[cfg(feature = "trace")]
+            let _plugin_cleanup_span =
+                info_span!("plugin cleanup", plugin = hokeypokey.name()).entered();
             hokeypokey.cleanup(self);
             core::mem::swap(&mut self.main_mut().plugin_registry[i], &mut hokeypokey);
         }
@@ -481,6 +491,9 @@ impl App {
 
         self.main_mut().plugin_build_depth += 1;
 
+        #[cfg(feature = "trace")]
+        let _plugin_build_span = info_span!("plugin build", plugin = plugin.name()).entered();
+
         let f = AssertUnwindSafe(|| plugin.build(self));
 
         #[cfg(feature = "std")]

crates/bevy_app/src/sub_app.rs

@@ -405,6 +405,9 @@ impl SubApp {
         let mut hokeypokey: Box<dyn Plugin> = Box::new(crate::HokeyPokey);
         for i in 0..self.plugin_registry.len() {
             core::mem::swap(&mut self.plugin_registry[i], &mut hokeypokey);
+            #[cfg(feature = "trace")]
+            let _plugin_finish_span =
+                info_span!("plugin finish", plugin = hokeypokey.name()).entered();
             self.run_as_app(|app| {
                 hokeypokey.finish(app);
             });
@@ -419,6 +422,9 @@ impl SubApp {
         let mut hokeypokey: Box<dyn Plugin> = Box::new(crate::HokeyPokey);
         for i in 0..self.plugin_registry.len() {
             core::mem::swap(&mut self.plugin_registry[i], &mut hokeypokey);
+            #[cfg(feature = "trace")]
+            let _plugin_cleanup_span =
+                info_span!("plugin cleanup", plugin = hokeypokey.name()).entered();
             self.run_as_app(|app| {
                 hokeypokey.cleanup(app);
             });

crates/bevy_ecs/src/system/function_system.rs

@@ -43,10 +43,12 @@ impl SystemMeta {
     pub(crate) fn new<T>() -> Self {
         let name = DebugName::type_name::<T>();
         Self {
+            // These spans are initialized during plugin build, so we set the parent to `None` to prevent
+            // them from being children of the span that is measuring the plugin build time.
             #[cfg(feature = "trace")]
-            system_span: info_span!("system", name = name.clone().as_string()),
+            system_span: info_span!(parent: None, "system", name = name.clone().as_string()),
             #[cfg(feature = "trace")]
-            commands_span: info_span!("system_commands", name = name.clone().as_string()),
+            commands_span: info_span!(parent: None, "system_commands", name = name.clone().as_string()),
             name,
             flags: SystemStateFlags::empty(),
             last_run: Tick::new(0),
@@ -68,8 +70,8 @@ impl SystemMeta {
         #[cfg(feature = "trace")]
         {
             let name = new_name.as_ref();
-            self.system_span = info_span!("system", name = name);
-            self.commands_span = info_span!("system_commands", name = name);
+            self.system_span = info_span!(parent: None, "system", name = name);
+            self.commands_span = info_span!(parent: None, "system_commands", name = name);
         }
         self.name = new_name.into();
     }