200-250ms lag on 'mouse down' events on macOS

[chrishulbert]

Bevy version 0.8

Relevant system information

macOS Monterey

What you did

I found that mouse click events were delayed in my game.

Here is the example: https://github.com/bevyengine/bevy/blob/latest/examples/input/mouse_input.rs

What went wrong

To reproduce this, I ran the bare-bones bevy input example linked below, and get the same result. With some logging I found the delay for mouse down is consistently 200-250ms. However there is 0 delay for mouse up.

Additional information

Since delayed mouse input is a deal-breaker for the use of Bevy for me, I spent quite a white trying to reproduce this.

I created a bare-bones example using Winit (not bevy at all) and mouse down and mouse up are instant - no delay, so i do not think there is an issue there.

I replicated Bevy locally and started commenting things out to see if i could isolate the issue, and if i comment out the following, there is no delay, so i assume the culprit is in there somewhere:

https://github.com/bevyengine/bevy/blob/latest/crates/bevy_winit/src/lib.rs

Comment out the body of the event::Event::MainEventsCleared => { match case, eg:

        event::Event::MainEventsCleared => {
            handle_create_window_events(
                &mut app.world,
                event_loop,
                &mut create_window_event_reader,
            );
            let winit_config = app.world.resource::<WinitSettings>();
            let update = if winit_state.active {
                let windows = app.world.resource::<Windows>();
                let focused = windows.iter().any(|w| w.is_focused());
                match winit_config.update_mode(focused) {
                    UpdateMode::Continuous | UpdateMode::Reactive { .. } => true,
                    UpdateMode::ReactiveLowPower { .. } => {
                        winit_state.low_power_event
                            || winit_state.redraw_request_sent
                            || winit_state.timeout_reached
                    }
                }
            } else {
                false
            };
            if update {
                winit_state.last_update = Instant::now();
                app.update();
            }
        }

Thanks for reading and thanks for the lovely game engine, I hope to be able to use it :)

[alice-i-cecile]

What UpdateMode are you using here?

[chrishulbert]

Thanks for responding! :) Just the default, as per https://github.com/bevyengine/bevy/blob/latest/examples/input/mouse_input.rs

-edit-

I believe the default is as follows:

impl Default for WinitSettings {
    fn default() -> Self {
        WinitSettings {
            return_from_run: false,
            focused_mode: UpdateMode::Continuous,
            unfocused_mode: UpdateMode::Continuous,
        }
    }
}

[alice-i-cecile]

            handle_create_window_events(
                &mut app.world,
                event_loop,
                &mut create_window_event_reader,
            );

This looks like the only section of that code that could have non-trivial cost then; I would start further investigation there.

[chrishulbert]

Thanks, unfortunately if i comment only that handle_create_window_events part out, it still has the lag.
I've whittled it down to this line being the culprit, if i comment it out, the lag disappears: app.update();

[chrishulbert]

If i revert all my comments in bevy_winit/src/lib.rs, thus use vanilla bevy, and instead put the following in my main.rs, the lag goes away:

fn main() {
    App::new()
        .insert_resource(WinitSettings {
            focused_mode: UpdateMode::ReactiveLowPower { max_wait: Duration::from_millis(100) },
            ..default()
        })...

However i'm fairly sure ReactiveLowPower isn't what I want for an interactive game.

[chrishulbert]

I don't want to be presumptuous or crass... but is there a chance there's a bug bounty program? Could i get my company to chip in a bit to get someone with knowledge of the ECS to get this fixed? Is there some way the project coordinates requests like these, and how much should i offer? My apologies, but i tried following what was going on inside the ECS to find the culprit but it's amazingly complex code. Thanks as always, Bevy and the team are fantastic :)

[alice-i-cecile]

Ping @cart @mockersf @superdump for an answer on bug bounties :)

[mockersf]

I'm not sure I'm able to reproduce the issue, but then I may miss a 200ms difference I guess. Could you share the code you use to measure it?

[chrishulbert]

@mockersf I reproduce this by running the example here: https://github.com/bevyengine/bevy/blob/latest/examples/input/mouse_input.rs
To my eyes the delay between clicking and the 'pressed' appearing in logs is quite obvious.

To get the timings, I made a local copy of bevy, changed my cargo.toml to point to that, and added println's (with times) to the event loop in bevy_winit/src/lib.rs/event_handler. I found a consistent 200-240ms between a 'TouchpadPressure' event and 'MouseInput' events. It looks like this:

    let start = SystemTime::now();

    let event_handler = move |event: Event<()>,
                              event_loop: &EventLoopWindowTarget<()>,
                              control_flow: &mut ControlFlow| {
                                

        match event {
            event::Event::NewEvents(_) => {},
            event::Event::RedrawEventsCleared => {},
            event::Event::MainEventsCleared => {},
            event::Event::LoopDestroyed => {},
            // event::Event::WindowEvent(window_id, event: WindowEvent::CursorMoved} => {},
            _ => {
                let dur = SystemTime::now().duration_since(start).unwrap();
                println!("Time: {} ms", dur.as_millis());
                println!("  event: {:?}", event);
            },
        }

Thanks again for the great framework.

[mockersf]

I can't reproduce on my Mac... Do you have an intel or a m1/m2? I have a m1 max

It didn't seem to make a difference for me, but are you running in debug or release?

[chrishulbert]

Hi, I have a 2020 M1 air running Monterey (12.5.1)
I tried both debug and release
I'll try on my other mac and see what happens

[chrishulbert]

Just tried on my mac studio ultra and yes, have the same lag.

[zyxkad]

There is no problem on my platform:

• Rust: rustc 1.63.0 (4b91a6ea7 2022-08-08)
• OS:
  • Model Name: MacBook Pro
  • Model Identifier: MacBookPro18,3
  • Chip: Apple M1 Pro
  • Total Number of Cores: 8 (6 performance and 2 efficiency)
  • Memory: 16 GB
  • OS Loader Version: 7429.61.2
• Bevy: 0.8.1

[chrishulbert]

Thanks so much for attempting to reproduce this, i'm so grateful for your efforts :)
One thing that might be worth mentioning is that it doesn't occur if you lift your finger off the button immediately after pressing down, eg a 'quick click'.
It occurs if you press down and hold.
If it helps, here are my versions:
rustc 1.62.0 (a8314ef7d 2022-06-27)
cargo 1.62.0 (a748cf5a3 2022-06-08)
Thanks again :)

[chrishulbert]

Oh and i'm on bevy 0.8.1.

Here's a slo-mo video demonstrating the delay, using the vanilla examples/input/mouse_input.rs. In a blue terminal window you'll see the current time in seconds. By looking at it frame-by-frame I came to the following measurements:

Normal.with.lag.mp4

lag video at 2s mark:
tap down: 3.316
update: 3.642
delay: 326ms

lag video 31s mark:
tap down: 6.924
update: 7.196
delay: 272ms

[chrishulbert]

And for comparison, here it is with the ReactiveLowPower workaround.

You can see the delay is only 90ms in this case, which i'm happy to put down to delay in the terminal etc. So if you subtract the baseline 90ms, I believe the problem is causing between 182 and 236ms delay in the first example.

ReactiveLowPower.Workaround.mp4

workaround video around 11s mark:
tap down 7.591
update: 7.681
delay: 90ms (5 frames at 60fps)

workaround video around 32s mark:
tap: 0.419
update: 0.509
delay: 90ms (5 frames at 60fps)

Hope that helps :) Thanks again everyone on this lovely framework and all the herculean efforts towards it!

[chrishulbert]

Ok! I appear to have stumbled across the culprit: I run an app called 'magnet' on my macs that gives keyboard shortcuts for moving your windows around. For some reason, when this is running, i have the delay, and when it is not running, there is no delay. I'll see if the developers of that app can fix it.

Here's the app: https://apps.apple.com/au/app/magnet/id441258766?mt=12

I'm terribly sorry to have wasted your time!

[mockersf]

nice to hear you found the source of the delay!