Very high CPU usage with empty example using just default plugins

[nehalem501]

Bevy version

Tested on both 0.4 and recent master a895256.

Operating system & version

macOS 10.14 x86_64 (MacBook Pro 2014, 2c/4t 2.8GHz Intel Core i5).
Latest nightly rustc, with the default rust linker (I haven't installed lld).

What you did

I tested the following code on both versions mentioned above, in debug and release modes.

main.rs:

use bevy::prelude::*;

fn main() {
    App::build()
        .add_plugins(DefaultPlugins)
        .add_plugin(bevy::diagnostic::FrameTimeDiagnosticsPlugin::default())
        .add_plugin(bevy::diagnostic::LogDiagnosticsPlugin::default())
        .run();
}

Cargo.toml:

[package]
name = "city_simulator"
version = "0.1.0"
authors = ["nehalem501"]
edition = "2018"

[dependencies]
bevy = { git = "https://github.com/bevyengine/bevy", rev = "a8952569253c5712e890e250cd10c999c1a6b379" }

What you expected to happen

Have the app window show app with low CPU usage.

What actually happened

I have 100% CPU usage with this code when compiled in debug mode, and around 50% CPU usage in release mode. This seems very excessive for drawing an empty window and displaying a few log lines in a terminal.
Am I doing something wrong ?

Additional information

These are the logs in debug mode, vsync seems to work:

Feb 17 09:27:18.040  INFO bevy_diagnostic::log_diagnostics_plugin: frame_time  : 0.017584    (avg 0.016661)
Feb 17 09:27:18.040  INFO bevy_diagnostic::log_diagnostics_plugin: fps         : 59.463637   (avg 59.926370)
Feb 17 09:27:18.040  INFO bevy_diagnostic::log_diagnostics_plugin: frame_count : 227.000000  (avg 227.000000)

And these the logs in release mode:

Feb 17 09:44:54.987  INFO bevy_diagnostic::log_diagnostics_plugin: frame_time  : 0.017124    (avg 0.016655)
Feb 17 09:44:54.987  INFO bevy_diagnostic::log_diagnostics_plugin: fps         : 60.254282   (avg 60.020315)
Feb 17 09:44:54.987  INFO bevy_diagnostic::log_diagnostics_plugin: frame_count : 1605.000000  (avg 1605.000000)

Screenshot of System Monitor with the debug version:

Screenshot of System Monitor with the release version:

[nehalem501]

This is what the "Instruments" app outputs when running the Time Profiler on my release binary, might be helpful.

[malj]

Similar issue on Windows 10.0.19042 Build 19042 with Bevy 4.0: around 30-40% CPU usage and 40-50% integrated Intel GPU usage (instead of using dedicated Nvidia GPU) on a blank window, causing laptop fans to start spinning like crazy:

use bevy::prelude::*;

fn main() {
    App::build().add_plugins(DefaultPlugins).run();
}

[nehalem501]

After further testing, I seem to have similar symptoms when just using MinimalPlugins.

use bevy::prelude::*;

fn main() {
    App::build().add_plugins(MinimalPlugins).run();
}

[cart]

Can you add the frame time and log diagnostic plugins and respond with your framerate? I have a feeling that you aren't getting frame limited and so the cpu is just spinning:

bevy/examples/diagnostics/log_diagnostics.rs

Line 10 in fa73036

.add_plugin(FrameTimeDiagnosticsPlugin::default())

When bevy is frame limited (and built in release mode) it is much kinder to cpus.

[cart]

Oh wait you already did that :)

[cart]

Just ran the code in this issue's description (using the master branch) and got the following results:

@malj I expect Bevy 0.4 to not be frame limited with the example you posted due to us moving to Mailbox vsync instead of Fifo vsync. We have since reverted that change on master until we can sort out a better frame limiting approach.

However @nehalem501 clearly has frame limiting, so something else is going on there. Maybe it related to macs? If I find time i'll try testing that out.

[nehalem501]

I actually have similar results on my Linux machine. According to the logs, frame limiting seems to work.

Same code as in my initial bug report, running a release build with git bevy revision a895256.

Ubuntu 20.04 x86_64 with a 16t/8c AMD CPU, Nvidia proprietary GPU drivers, X11 (Unity DE).

Rust version:

nightly-x86_64-unknown-linux-gnu (default)
rustc 1.52.0-nightly (a143517d4 2021-02-16)

What top -i displays:

top - 21:24:06 up 14 days,  3:21,  4 users,  load average: 1,07, 2,81, 1,89
Tasks: 404 total,   2 running, 402 sleeping,   0 stopped,   0 zombie
%Cpu(s):  5,3 us,  1,1 sy,  0,0 ni, 93,6 id,  0,0 wa,  0,0 hi,  0,0 si,  0,0 st
MiB Mem :  16025,8 total,   1943,8 free,  11102,8 used,   2979,1 buff/cache
MiB Swap:      0,0 total,      0,0 free,      0,0 used.   3865,4 avail Mem 

    PID USER      PR  NI    VIRT    RES    SHR S  %CPU  %MEM     TIME+ COMMAND                                                                                                    
2856197 tomek     20   0 1906112 211756 191644 R  71,1   1,3   1:58.92 bevy_test   

logs:

Feb 19 21:26:57.014  INFO bevy_diagnostic::log_diagnostics_plugin: frame_time   : 0.016570    (avg 0.016663)
Feb 19 21:26:57.014  INFO bevy_diagnostic::log_diagnostics_plugin: fps          : 59.994043   (avg 59.985289)
Feb 19 21:26:57.014  INFO bevy_diagnostic::log_diagnostics_plugin: frame_count  : 18939.000000  (avg 18939.000000)

[samnm]

I have been experiencing the same thing on OSX.

This seems to be the biggest problem area:

Note this is running on bevy-ecs-v2 and I also updated futures-lite, async-executor, and async-channel just in case.

I would love to help but I have no idea what the source of the problem could be. Happy to continue investigating if anyone wants to point me in the right direction.

[samnm]

On @cart's recommendation I am testing performance for task_pool pre #932 and #892.

Here is my diff on main:

index db98543b..ecc5f457 100644
--- a/crates/bevy_tasks/src/task_pool.rs
+++ b/crates/bevy_tasks/src/task_pool.rs
@@ -205,22 +205,15 @@ impl TaskPool {
                 // this so we must convert to 'static here to appease the compiler as it is unable to
                 // validate safety.
                 let fut: Pin<&mut (dyn Future<Output = Vec<T>>)> = fut;
-                let fut: Pin<&'static mut (dyn Future<Output = Vec<T>> + 'static)> =
+                let fut: Pin<&'static mut (dyn Future<Output = Vec<T>> + Send + 'static)> =
                     unsafe { mem::transmute(fut) };

                 // The thread that calls scope() will participate in driving tasks in the pool forward
                 // until the tasks that are spawned by this scope() call complete. (If the caller of scope()
                 // happens to be a thread in this thread pool, and we only have one thread in the pool, then
                 // simply calling future::block_on(spawned) would deadlock.)
-                let mut spawned = local_executor.spawn(fut);
-                loop {
-                    if let Some(result) = future::block_on(future::poll_once(&mut spawned)) {
-                        break result;
-                    };
-
-                    self.executor.try_tick();
-                    local_executor.try_tick();
-                }
+                let spawned = executor.spawn(fut);
+                future::block_on(spawned)
             }
         })
     }

And performance for default plugins does improve - not as much as I hoped - from ~130% of CPU to ~75%. Good news is that bevy_render::render_graph::render_graph_schedule_executor_system went from 40% of CPU time to 0.6%!

I will try to find the other offenders considering how much CPU time an empty project is still using.

Note: I am not sure of the significance of changing local_executor.spawn(fut) to executor.spawn(fut) but it was required to stop the app from locking.

[cart]

I'm still not fully convinced that "combined os-reported cpu usage percentage" is by itself a good metric to optimize for. Ex: if we do multi-threading each frame, work will be spread out across all cores. That means each frame we're using 800% cpu on an 8 core machine when all cores are being utilized (vs 100% cpu if we only single thread). Depending on how the os samples and aggregates these numbers, we might have a situation where multithreading is faster / less power hungry / consumes fewer resources overall across a given slice of time, but the opposite is reported.

Before making design decisions based on these numbers, we might want to determine how these metrics are calculated and whether or not they are a good measure for realtime multithreaded apps.

[cart]

briefly puts on world-weary project owner hat
however given the frequency of percent-cpu-usage-related issues, maybe we should optimize for public perception anyway, despite the facts of the situation

[samnm]

How about CPU temps? 😝

I am definitely not getting 60 fps on a high end macbook pro with really simple bevy projects so something is wrong.

[cart]

What is "really simple" in this context? Can you share a link or describe your use case? There are a number of knowm performance limitations that wouldn't surface in "empty projects", which is what this issue is specifically about.