Flexible, non-graphical way of getting at system timing

[ndarilek]

What problem does this solve or what need does it fill?

I'm having some performance issues with my game. While I suspect I know where they are, I'd rather get some exact numbers that I can crunch to determine which systems are slowing things down. I'm also blind, and unfortunately chrome://tracing doesn't appear accessible to me.

What solution would you like?

I'd like some way of either programatically or textually getting at system execution timing, in some way that I can spit out a textual report to get something like average/minimum/maximum execution time broken down by system.

What alternative(s) have you considered?

I'm not sure if the trace JSON reports do what I want, but either they don't or chrome://tracing is inaccessible. If this data is already available internally, I'd love to know about it so I can perhaps put together and contribute back some custom diagnostics.

Thanks.

[cart]

Yeah in addition to improving accessibility, this would also enable future editor tools to show things like "dynamic system performance graphs". I think this will likely be something like adding a new tracing subscriber that feeds data relevant to bevy into an ECS resource (probably the current Diagnostics abstraction).

Alternatively if that proves to be overly complicated, we could just manually instrument system schedulers to feed data into Diagnostics. But I'd like a generic tracing solution if possible, as that opens the doors to users instrumenting anything using normal tracing scopes and it showing up in our editor tooling.

[ndarilek]

I'm actually struggling through this in #help right now. I don't want to take up too much of your time, but just to make sure I'm not going down the wrong rabbit hole or doing work I don't need to, I assume the only solution right now is to manually annotate all my systems with `span!`? I'm doing that, and I can't get anything logging using something like: ``` app.insert_resource(bevy::log::LogSettings { filter: "rampage=trace".into(), ..Default::default()     }); ``` where my crate is named "rampage" and I'm inserting that `LogConfig` first. I'm getting bunches of other logs, but: ``` letspan=span!(Level::TRACE, "copy_coordinates_to_transform"); //#[cfg(feature = "trace")] let_=span.enter(); ``` in a running system never puts the string "copy_coordinates_to_transform" in the output logs. Given that what I want is timing information for these spans, I'm wondering if I should be looking elsewhere? Also, related, it seems that log levels higher than info are compiled out of release builds, and I'm wondering if debug vs. release performance might have an effect on the trace results? There seems to be a feature gating this, but it's enabled in bevy_utils' use of tracing and I'm not sure if my game can disable it. Thanks.

[cart]

Hmm it looks like we lost the "automatic system spans" in Bevy 0.5's executor rewrite. Thats not awesome and we should add them back asap. We still have "stage spans" though.

So yeah in the short term you'll unfortunately need to annotate each system with a span manually.

I also don't think spans write anything to the console by default. That likely needs some additional tracing configuration and/or a different tracing subscriber.

On the topic of "release log level filtering" I do think we'll need to make that easier to configure. I don't want the production of trace and debug logs to slow down release builds by default, but we should:

1. Make that easily configurable via feature flags
2. Run some benchmarks to see how expensive leaving in trace/debug logs actually is. Maybe we don't need to filter them out by default.

[ndarilek]

Got it, thanks for letting me know I'm on the right track. Mind pinging this issue when the automatic system spans return? I'll likely switch back to main when that lands.

[mockersf]

@ndarilek automatic system spans are back 👍

[Ratysz]

Hmm it looks like we lost the "automatic system spans" in Bevy 0.5's executor rewrite.

... yeah. I didn't note it down early on, so I plain forgot they even were a thing by the time all of that was done. Looks like it wasn't a hard fix, though.

[ndarilek]

Awesome, thanks for bringing those back! Had an amazing bit of luck and identified my performance issues as one bad query, which were easy to fix. But I'm sure I'll need that data again soon enough. :)