iOS mobile windowing-related performance regression and log spam

[extrawurst]

Bevy version

3d72e08

[Optional] Relevant system information

• cargo 1.82.0 (8f40fc59f 2024-08-21)
• xcode 16.1 (16B40)

What you did

Just running the bevy_mobile_example.xcodeproj

What went wrong

Console spamming of:

Monitor removed 14v3908#16784732192782
processing non `RedrawRequested` event after the main event loop: AboutToWait
Monitor removed 4v3083#13241384173572
processing non `RedrawRequested` event after the main event loop: AboutToWait
Monitor removed 14v3909#16789027160078
processing non `RedrawRequested` event after the main event loop: AboutToWait
Monitor removed 4v3084#13245679140868
processing non `RedrawRequested` event after the main event loop: AboutToWait
Monitor removed 14v3910#16793322127374
processing non `RedrawRequested` event after the main event loop: AboutToWait
Monitor removed 4v3085#13249974108164
processing non `RedrawRequested` event after the main event loop: AboutToWait
Monitor removed 14v3911#16797617094670
processing non `RedrawRequested` event after the main event loop: AboutToWait
Monitor removed 4v3086#13254269075460
processing non `RedrawRequested` event after the main event loop: AboutToWait
Monitor removed 14v3912#16801912061966
processing non `RedrawRequested` event after the main event loop: AboutToWait
Monitor removed 4v3087#13258564042756
processing non `RedrawRequested` event after the main event loop: AboutToWait
Monitor removed 14v3913#16806207029262
processing non `RedrawRequested` event after the main event loop: AboutToWait
Monitor removed 4v3088#13262859010052

Otherwise visually the example seems to run fine in the simulator.

here is the log of the same example on bevy 14.2: https://gist.github.com/extrawurst/7cbbb5b1918b5876a93705b92d65e196

here is the entire log of the above example in 3d72e08:
https://gist.github.com/extrawurst/b91117297242d412091862db171e29ab

If you compare this to the 14.2 behaviour there are a few things very different:

1. we don't have timestamps anymore
2. instead of just the old friend processing non RedrawRequested event after the main event loop: AboutToWait we now seem to get this second log every frame: Monitor removed 4v3088#13262859010052
3. the startup produces an absolutely massive amount of additional logs if you compare both full logs

I wonder if this is all intended? The repeating Monotitor removed at the very least looks very wrong.

Additional Information

This additional activity seems to mirror also the huge additional CPU load:

Average CPU usage in the example goes up from ~90% to >200%. This is a regression in my books.

[alice-i-cecile]

This is important to me, but I don't see an imminent easy fix at this stage. We'll do our best to backport anything that's done though.

[extrawurst]

ok instrumentation reveals that we spent 15% in bevy_winit::system::create_monitors:

The reason for this is because we detect a new unseen monitor each frame and spawn it:

bevy/crates/bevy_winit/src/system.rs

Line 166 in 75c92fb

let entity = commands

just to delete the old one from last frame:

bevy/crates/bevy_winit/src/system.rs

Line 202 in 75c92fb

info!("Monitor removed {:?}", entity);

which triggers exactly the logging line that we see spamming: Monitor removed 4v3086#13254269075460

I am not sure yet why this is. Its almost as if we can't seem to rely on the MonitorHandle::eq check. @tychedelia did you run into this when adding this via 3360b45 ?

[tychedelia]

I am not sure yet why this is. Its almost as if we can't seem to rely on the MonitorHandle::eq check. @tychedelia did you run into this when adding this via 3360b45 ?

No, this is not the behavior that we see on desktop, and I don't have a way to test mobile. But this is a good call out, we should investigate on the winit side as the id for the monitor should be stable, it's possible this is a regression there.

[tychedelia]

I also imagine that there's a lot of cost to the info! log while it's spamming. Not that this is a "good" solution but compiling out that log may at least help the perf if we want a stop gap solution.

[extrawurst]

I also imagine that there's a lot of cost to the info! log while it's spamming. Not that this is a "good" solution but compiling out that log may at least help the perf if we want a stop gap solution.

60% of this is the span of info and 40% is the hotpath Vec::retain

[tychedelia]

UiKit:

impl PartialEq for MonitorHandle {
    fn eq(&self, other: &Self) -> bool {
        ptr::eq(self, other)
    }
}

AppKit:

impl PartialEq for MonitorHandle {
    fn eq(&self, other: &Self) -> bool {
        unsafe {
            ffi::CGDisplayCreateUUIDFromDisplayID(self.0)
                == ffi::CGDisplayCreateUUIDFromDisplayID(other.0)
        }
    }
}

[extrawurst]

@madsmtm would be great to have your opinion

[madsmtm]

Indeed, that's wrong, Winit is comparing the pointer address of MonitorHandle itself (not the pointer address of the inner UIScreen). I've put up rust-windowing/winit#4013, though don't have the time rn to test if that's actually enough.

[mockersf]

The monitor log spam actually makes the real issue visible: we're running about_to_wait as fast as possible. create_monitors eats 15% cpu because we're running it 5000 times per second on my simulator.

Fixing it is a good thing, but we should look again at how we handle the winit loop