CommandTrace debug utility to log command metadata

[djeedai]

Following up on an idea briefly mentioned in Discord, I'd like to propose a new debugging feature : a CommandTrace buffer optionally (if enabled) populated in parallel of Commands, and recording metadata about the commands.

Motivation

I had some issue with the internal parenting system running after my own, and trying to access a parent entity already deleted, causing a panic. To make things worse, as discovered later, the entity ID was being immediately reused, such that looking at it alone appeared like it was still available. In this kind of scenario, there's very little information available to developers, and I had to resort to checking out the Bevy codebase and add some println!() everywhere. This worked for a tiny project (<20 entities) but I can't imagine a larger one.

Initial workaround

This episode led to #2943 which adds the entity ID and generation to the panic message, allowing a dev to reason about which entity the issue is about. However, this approach is fairly limited in that there's no information about when/where the entity was spawned nor destroyed, making the investigation difficult especially when an internal system is involved.

Proposal

The proposal allows recording command metadata not usually useful for the functioning of the engine, but largely helpful for the developers.

Metadata

Examples of metadata I'm thinking of, which are up for individual discussion, include:

• Name of the system which spawned/despawned an entity
• Some debug entity name EDIT: There's actually a Name component for that
• Frame ID and/or timestamp
• Thread ID and/or name
• State changes and their initiating system
• ...

Interface

The entire feature can be being a feature flag to generate no code in a release build. Additionally it should be explicitly enabled, due to potential overhead, with some call. Maybe AppBuilder::with_debug_commands()?

@DJMcNab already suggested adding SystemState to the Command trait to allow retrieving the system name.

Entity debug name can be supported on creation with an EntityCommand::with_debug_name().

Thread ID/name are accessible from std::thread.current(). They can be recorded with a flag set when enabling the overall feature itself.

To be continued...

[mockersf]

Alternatively, we could just record an Event for each command in our logs / tracing feature. If creating the event at the same time as the command, it will automatically be linked to the system span.

[djeedai]

Yes this proposal is indeed quite close to a profiling/tracing system. I'm not sure yet of the advantages and drawbacks of each, but I'd be worried a priori of the difficulty to match tracing events to commands in an unambiguous way, though I have not looked into that. This is definitely worth discussing and maybe worth a trial impl too. Thanks for pointing out.

[mirkoRainer]

Would standard log levels be enough for this? Or would a bevy specific log level be appropriate for filtering purposes? Or maybe a tag/flag on a log entry to show its from bevy internals?

[djeedai]

From my limited experience, logging via e.g. debug! only get you so far in a large (game) project. The logging provided by the log facade is easy to use but not particularly well suited for heavy logging due to its nature of being strings only. For example logging metadata for each component each frame will quickly blow up memory if saved as string, as opposed to binary.

I didn't try using tracing too much so maybe this is better. Although this covers a slightly different purpose.