Implement pretty component logging

crates/bevy_ecs/Cargo.toml

@@ -36,7 +36,10 @@ backtrace = ["std"]
 
 ## Enables `tracing` integration, allowing spans and other metrics to be reported
 ## through that framework.
-trace = ["std", "dep:tracing", "bevy_utils/debug"]
+trace = ["std", "dep:tracing"]
+
+# Enable collecting debug information about systems and components to help with diagnostics
+debug = ["bevy_utils/debug", "bevy_reflect?/debug"]
 
 ## Enables a more detailed set of traces which may be noisy if left on by default.
 detailed_trace = ["trace"]

crates/bevy_ecs/src/schedule/executor/single_threaded.rs

@@ -1,6 +1,8 @@
 use core::panic::AssertUnwindSafe;
 use fixedbitset::FixedBitSet;
 
+#[cfg(feature = "trace")]
+use alloc::string::ToString as _;
 #[cfg(feature = "trace")]
 use tracing::info_span;
 
@@ -78,7 +80,7 @@ impl SystemExecutor for SingleThreadedExecutor {
             #[cfg(feature = "trace")]
             let name = system.name();
             #[cfg(feature = "trace")]
-            let should_run_span = info_span!("check_conditions", name = name.as_string()).entered();
+            let should_run_span = info_span!("check_conditions", name = name.to_string()).entered();
 
             let mut should_run = !self.completed_systems.contains(system_index);
             for set_idx in schedule.sets_with_conditions_of_systems[system_index].ones() {

crates/bevy_ecs/src/system/commands/entity_command.rs

@@ -4,15 +4,19 @@
 //! It also contains functions that return closures for use with
 //! [`EntityCommands`](crate::system::EntityCommands).
 
-use alloc::vec::Vec;
+use alloc::{string::ToString, vec::Vec};
+#[cfg(not(feature = "trace"))]
 use log::info;
+#[cfg(feature = "trace")]
+use tracing::info;
 
 use crate::{
     bundle::{Bundle, InsertMode},
     change_detection::MaybeLocation,
-    component::{Component, ComponentId, ComponentInfo},
+    component::{Component, ComponentId},
     entity::{Entity, EntityClonerBuilder, OptIn, OptOut},
     event::EntityEvent,
+    name::Name,
     relationship::RelationshipHookMode,
     system::IntoObserverSystem,
     world::{error::EntityMutableFetchError, EntityWorldMut, FromWorld},
@@ -323,12 +327,53 @@ pub fn move_components<B: Bundle>(target: Entity) -> impl EntityCommand {
 /// An [`EntityCommand`] that logs the components of an entity.
 pub fn log_components() -> impl EntityCommand {
     move |entity: EntityWorldMut| {
-        let debug_infos: Vec<_> = entity
+        let name = entity.get::<Name>().map(ToString::to_string);
+        let id = entity.id();
+        let mut components: Vec<_> = entity
             .world()
-            .inspect_entity(entity.id())
+            .inspect_entity(id)
             .expect("Entity existence is verified before an EntityCommand is executed")
-            .map(ComponentInfo::name)
+            .map(|info| info.name().to_string())
             .collect();
-        info!("Entity {}: {debug_infos:?}", entity.id());
+        components.sort();
+
+        #[cfg(not(feature = "debug"))]
+        {
+            let component_count = components.len();
+            #[cfg(feature = "trace")]
+            {
+                if let Some(name) = name {
+                    info!(id=?id, name=?name, ?component_count, "log_components. Enable the `debug` feature to log component names.");
+                } else {
+                    info!(id=?id, ?component_count, "log_components. Enable the `debug` feature to log component names.");
+                }
+            }
+            #[cfg(not(feature = "trace"))]
+            {
+                let name = name
+                    .map(|name| alloc::format!(" ({name})"))
+                    .unwrap_or_default();
+                info!("Entity {id}{name}: {component_count} components. Enable the `debug` feature to log component names.");
+            }
+        }
+
+        #[cfg(feature = "debug")]
+        {
+            #[cfg(feature = "trace")]
+            {
+                if let Some(name) = name {
+                    info!(id=?id, name=?name, ?components, "log_components");
+                } else {
+                    info!(id=?id, ?components, "log_components");
+                }
+            }
+            #[cfg(not(feature = "trace"))]
+            {
+                let name = name
+                    .map(|name| alloc::format!(" ({name})"))
+                    .unwrap_or_default();
+                info!("Entity {id}{name}: {components:?}");
+            }
+        }
     }
 }

crates/bevy_ecs/src/system/function_system.rs

@@ -20,6 +20,9 @@ use variadics_please::all_tuples;
 #[cfg(feature = "trace")]
 use tracing::{info_span, Span};
 
+#[cfg(feature = "trace")]
+use alloc::string::ToString as _;
+
 use super::{
     IntoSystem, ReadOnlySystem, RunSystemError, SystemParamBuilder, SystemParamValidationError,
     SystemStateFlags,
@@ -46,9 +49,9 @@ impl SystemMeta {
             // 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!(parent: None, "system", name = name.clone().as_string()),
+            system_span: info_span!(parent: None, "system", name = name.clone().to_string()),
             #[cfg(feature = "trace")]
-            commands_span: info_span!(parent: None, "system_commands", name = name.clone().as_string()),
+            commands_span: info_span!(parent: None, "system_commands", name = name.clone().to_string()),
             name,
             flags: SystemStateFlags::empty(),
             last_run: Tick::new(0),

crates/bevy_ecs/src/system/system_name.rs

@@ -85,7 +85,7 @@ impl ExclusiveSystemParam for SystemName {
 }
 
 #[cfg(test)]
-#[cfg(feature = "trace")]
+#[cfg(all(feature = "trace", feature = "debug"))]
 mod tests {
     use crate::{
         system::{IntoSystem, RunSystemOnce, SystemName},

crates/bevy_internal/Cargo.toml

@@ -426,7 +426,7 @@ web = ["bevy_app/web", "bevy_platform/web", "bevy_reflect/web"]
 
 hotpatching = ["bevy_app/hotpatching", "bevy_ecs/hotpatching"]
 
-debug = ["bevy_utils/debug"]
+debug = ["bevy_utils/debug", "bevy_ecs/debug"]
 
 [dependencies]
 # bevy (no_std)

examples/app/log_layers.rs

@@ -3,7 +3,7 @@
 use bevy::{
     log::{
         tracing::{self, Subscriber},
-        tracing_subscriber::Layer,
+        tracing_subscriber::{field::MakeExt, Layer},
         BoxedFmtLayer, BoxedLayer,
     },
     prelude::*,
@@ -40,11 +40,13 @@ fn custom_layer(_app: &mut App) -> Option<BoxedLayer> {
 // default `tracing_subscriber::fmt::Layer` added by `LogPlugin`. To do that, you can use the
 // `fmt_layer` option.
 //
-// In this example, we're disabling the timestamp in the log output.
+// In this example, we're disabling the timestamp in the log output and enabling the alternative debugging format.
+// This formatting inserts newlines into logs that use the debug sigil (`?`) like `info!(foo=?bar)`
 fn fmt_layer(_app: &mut App) -> Option<BoxedFmtLayer> {
     Some(Box::new(
         bevy::log::tracing_subscriber::fmt::Layer::default()
             .without_time()
+            .map_fmt_fields(MakeExt::debug_alt)
             .with_writer(std::io::stderr),
     ))
 }
@@ -67,6 +69,8 @@ fn log_system() {
     error!("something failed");
     warn!("something bad happened that isn't a failure, but thats worth calling out");
     info!("helpful information that is worth printing by default");
+    let secret_message = "Bevy";
+    info!(?secret_message, "Here's a log that uses the debug sigil");
     debug!("helpful for debugging");
     trace!("very noisy");
 }