Bevy: very low performance when spawning UI nodes one inside the other

Created on 14 Oct 2020  路  6Comments  路  Source: bevyengine/bevy

When spawning every second a new node as a children of the last one that had been spawned, the application starts to slow down after 10 iterations, and becomes unresponsive after 15~20 iterations

use bevy::prelude::*;

fn main() -> Result<(), Box<dyn std::error::Error>> {
    App::build()
        .add_default_plugins()
        .add_startup_system(setup.system())
        .add_system(deep.system())
        .run();

    Ok(())
}

fn setup(mut commands: Commands) {
    commands.spawn(UiCameraComponents::default());

    commands
        .spawn(NodeComponents::default())
        .with(Timer::from_seconds(1., false));
}

fn deep(mut commands: Commands, entity: Entity, timer: &Timer) {
    if timer.just_finished {
        println!("spawning new child");
        commands
            .spawn(NodeComponents::default())
            .with(Timer::from_seconds(1., false));
        let child = commands.current_entity().unwrap();

        commands.push_children(entity, &[child]);
    }
}

with some logging and diagnostics:

Oct 14 00:19:36.576  INFO tank: spawning new child
Oct 14 00:19:36.577 DEBUG bevy_log_diagnostic: diagnostic: frame_time               : 0.0145      (avg 0.0166)
Oct 14 00:19:36.578 DEBUG bevy_log_diagnostic: diagnostic: fps                      : 60.3177     (avg 60.0176)
Oct 14 00:19:37.576 DEBUG bevy_log_diagnostic: diagnostic: frame_time               : 0.0146      (avg 0.0165)
Oct 14 00:19:37.576 DEBUG bevy_log_diagnostic: diagnostic: fps                      : 60.2317     (avg 60.1338)
Oct 14 00:19:37.592  INFO tank: spawning new child
Oct 14 00:19:38.580 DEBUG bevy_log_diagnostic: diagnostic: frame_time               : 0.0178      (avg 0.0167)
Oct 14 00:19:38.580 DEBUG bevy_log_diagnostic: diagnostic: fps                      : 60.0023     (avg 60.0193)
Oct 14 00:19:38.592  INFO tank: spawning new child
Oct 14 00:19:39.587 DEBUG bevy_log_diagnostic: diagnostic: frame_time               : 0.0180      (avg 0.0163)
Oct 14 00:19:39.587 DEBUG bevy_log_diagnostic: diagnostic: fps                      : 59.7169     (avg 60.2253)
Oct 14 00:19:39.602  INFO tank: spawning new child
Oct 14 00:19:40.589 DEBUG bevy_log_diagnostic: diagnostic: frame_time               : 0.0174      (avg 0.0168)
Oct 14 00:19:40.590 DEBUG bevy_log_diagnostic: diagnostic: fps                      : 59.9331     (avg 59.9481)
Oct 14 00:19:40.602  INFO tank: spawning new child
Oct 14 00:19:41.589 DEBUG bevy_log_diagnostic: diagnostic: frame_time               : 0.0152      (avg 0.0166)
Oct 14 00:19:41.589 DEBUG bevy_log_diagnostic: diagnostic: fps                      : 59.9631     (avg 59.9649)
Oct 14 00:19:41.621  INFO tank: spawning new child
Oct 14 00:19:42.573 DEBUG bevy_log_diagnostic: diagnostic: frame_time               : 0.0159      (avg 0.0167)
Oct 14 00:19:42.573 DEBUG bevy_log_diagnostic: diagnostic: fps                      : 60.3003     (avg 59.9682)
Oct 14 00:19:42.627  INFO tank: spawning new child
Oct 14 00:19:43.590 DEBUG bevy_log_diagnostic: diagnostic: frame_time               : 0.0157      (avg 0.0166)
Oct 14 00:19:43.590 DEBUG bevy_log_diagnostic: diagnostic: fps                      : 60.0817     (avg 60.0140)
Oct 14 00:19:43.644  INFO tank: spawning new child
Oct 14 00:19:44.584 DEBUG bevy_log_diagnostic: diagnostic: frame_time               : 0.0172      (avg 0.0168)
Oct 14 00:19:44.585 DEBUG bevy_log_diagnostic: diagnostic: fps                      : 59.9687     (avg 59.6242)
Oct 14 00:19:44.650  INFO tank: spawning new child
Oct 14 00:19:45.596 DEBUG bevy_log_diagnostic: diagnostic: frame_time               : 0.0266      (avg 0.0263)
Oct 14 00:19:45.596 DEBUG bevy_log_diagnostic: diagnostic: fps                      : 39.7056     (avg 38.1866)
Oct 14 00:19:45.664  INFO tank: spawning new child
Oct 14 00:19:46.628 DEBUG bevy_log_diagnostic: diagnostic: frame_time               : 0.0447      (avg 0.0438)
Oct 14 00:19:46.628 DEBUG bevy_log_diagnostic: diagnostic: fps                      : 34.7194     (avg 27.4654)
Oct 14 00:19:46.688  INFO tank: spawning new child
Oct 14 00:19:47.713 DEBUG bevy_log_diagnostic: diagnostic: frame_time               : 0.0438      (avg 0.0656)
Oct 14 00:19:47.713 DEBUG bevy_log_diagnostic: diagnostic: fps                      : 24.3330     (avg 20.1163)
Oct 14 00:19:47.722  INFO tank: spawning new child
Oct 14 00:19:48.738 DEBUG bevy_log_diagnostic: diagnostic: frame_time               : 0.0511      (avg 0.0981)
Oct 14 00:19:48.738 DEBUG bevy_log_diagnostic: diagnostic: fps                      : 22.6240     (avg 16.2551)
Oct 14 00:19:48.748  INFO tank: spawning new child
Oct 14 00:19:49.883 DEBUG bevy_log_diagnostic: diagnostic: frame_time               : 0.0783      (avg 0.1336)
Oct 14 00:19:49.883 DEBUG bevy_log_diagnostic: diagnostic: fps                      : 19.3643     (avg 13.7073)
Oct 14 00:19:49.893  INFO tank: spawning new child
Oct 14 00:19:51.104  INFO tank: spawning new child
Oct 14 00:19:52.276 DEBUG bevy_log_diagnostic: diagnostic: frame_time               : 0.0769      (avg 0.1966)
Oct 14 00:19:52.276 DEBUG bevy_log_diagnostic: diagnostic: fps                      : 17.5957     (avg 11.7911)
Oct 14 00:19:52.290  INFO tank: spawning new child
Oct 14 00:19:54.523 DEBUG bevy_log_diagnostic: diagnostic: frame_time               : 0.0798      (avg 0.2521)
Oct 14 00:19:54.523 DEBUG bevy_log_diagnostic: diagnostic: fps                      : 17.0662     (avg 11.1097)
Oct 14 00:19:54.540  INFO tank: spawning new child
Oct 14 00:19:58.888 DEBUG bevy_log_diagnostic: diagnostic: frame_time               : 0.0784      (avg 0.3606)
Oct 14 00:19:58.888 DEBUG bevy_log_diagnostic: diagnostic: fps                      : 16.5496     (avg 10.3950)
Oct 14 00:19:58.911  INFO tank: spawning new child
Oct 14 00:20:07.772 DEBUG bevy_log_diagnostic: diagnostic: frame_time               : 0.0784      (avg 0.5752)
Oct 14 00:20:07.772 DEBUG bevy_log_diagnostic: diagnostic: fps                      : 16.0953     (avg 9.6545)
Oct 14 00:20:07.807  INFO tank: spawning new child
Oct 14 00:20:26.534 DEBUG bevy_log_diagnostic: diagnostic: frame_time               : 0.0793      (avg 1.0161)
Oct 14 00:20:26.534 DEBUG bevy_log_diagnostic: diagnostic: fps                      : 15.6552     (avg 8.8989)
Oct 14 00:20:26.615  INFO tank: spawning new child

the FPS starts to slow down after 10 seconds, and is false after 15 seconds as some seconds are skipped.

performance third party / dependencies ui
Source
picture mockersf
👍1

Most helpful comment

Check out our profiling doc here:

https://github.com/bevyengine/bevy/blob/master/docs/profiling.md

picture cart on 14 Oct 2020
👍2

All 6 comments

Looks like stretch really explodes here for some reason:

image

cart picture cart on 14 Oct 2020

it seems this marks the root node as dirty at every step, which means stretch has everything to compute again.
I'm trying to fix it

mockersf picture mockersf on 14 Oct 2020

@cart, what did you use to create that flamegraph? Could be useful for the benchmarking stuff I'm trying to do.

zicklag picture zicklag on 14 Oct 2020

Check out our profiling doc here:

https://github.com/bevyengine/bevy/blob/master/docs/profiling.md

cart picture cart on 14 Oct 2020
👍2

https://github.com/flamegraph-rs/flamegraph

cart picture cart on 14 Oct 2020
❤1

actually this seems related to https://github.com/vislyhq/stretch/issues/71

I could reproduce by running the same calls to stretch made by bevy, but without bevy being involved

mockersf picture mockersf on 14 Oct 2020
Was this page helpful?
0 / 5 - 0 ratings

Related issues

cart picture cart  路  23Comments
NickelCoating picture NickelCoating  路  15Comments
cart picture cart  路  52Comments
coolit picture coolit  路  22Comments
cart picture cart  路  28Comments