Mouse events have latency on macos due to a change in accesskit crate

[artursapek]

Bevy version

0.11 (anything after #8655)

Relevant system information

macos 13.5 (22G74) on 2020 M1 Macbook Air

What you did

I'm running code that uses mouse events, such as the mouse_input example

What went wrong

There is a noticeable delay in mouse clicks being captured. See https://imgur.com/a/py58Zk4. On the left is bevy 0.11, and on the right is bevy 0.10. Watch with the sound on to hear when I click my mouse.

Additional information

I binary searched through the commit log until I was able to narrow it down to this specific change inside accesskit. https://github.com/AccessKit/accesskit/pull/231/files#r1287857891

If I revert that code change, the observed latency in bevy capturing mouse events disappears.

I don't know what to do here. I don't understand why that change was made to accesskit, or exactly why it's causing this latency. I am an end-user of bevy who got annoyed and jumped down this rabbit hole and am looking for an opinion from bevy core devs. It seems like accessibility features slowing down an example as simple as mouse_input indicate the accessibility code might need to be isolated better.

[mwcampbell]

Does this affect all users of Bevy-based games on macOS?

@artursapek I gather from the video that you're not using VoiceOver. Do you have any other macOS accessibility features enabled? AccessKit should have no effect on machines that aren't running any accessibility tools (a.k.a. assistive technologies).

[artursapek]

@mwcampbell I went through them all in system prefs and none appear to be enabled. is there a way for me to add a print into accesskit that will tell me the reason it's enabled?

[mwcampbell]

As far as I know, there's no way for AccessKit to know which accessibility client is calling it. Maybe someone who knows much more about macOS internals than I do could come up with some kind of hack to determine that. But I think it's much more important to find out how widespread the problem reported in this issue is.

[artursapek]

I agree. I don't know how widespread it is. I haven't tested it on a second Mac yet. hoping other people chime in here.

[jim-ec]

I definitely have the same problem here on macOS (13.4.1, 2020 M1 Macbook Air). Keyboard input is instant, but mouse input has a noticeable delay of a few frames.

[basilkohler]

Wanted to report the same issue: Left click has a noticeable delay.
M1 Macbook pro 16 on latest MacOS 13.5.
Right click works as expected.

[mwcampbell]

I think we still need an answer to the question of whether this is affecting all macOS users or only a minority. If the latter, that doesn't mean it's unimportant, of course. But in that case, it may help to figure out what the common factor is. This question also affects the urgency of the issue.

[artursapek]

I'm really not sure, but I would expect more people to be complaining if this affected all macos users.

regardless though, it's slow code and should be fixed

[aevyrie]

Just noticed this as well, only seems to impact LMB. VoiceOver is disabled.

[aevyrie]

It looks like Res<bevy::a11y::AccessibilityRequested> is being set to true as soon as I click on the window, even though I'm not using any assistive technologies. However, inputs shouldn't be hanging regardless.

This is the behavior I am noticing:

INFO mouse_input_events: Frame 602
INFO mouse_input_events: MouseMotion { delta: Vec2(-36.0, -2.0) }
INFO mouse_input_events: MouseMotion { delta: Vec2(-35.0, -2.0) }
INFO mouse_input_events: Frame 603
INFO mouse_input_events: MouseMotion { delta: Vec2(-20.0, -2.0) }
INFO mouse_input_events: Frame 604
INFO mouse_input_events: Frame 605
INFO mouse_input_events: Frame 606
INFO mouse_input_events: MouseMotion { delta: Vec2(-31.0, -1.0) }
INFO mouse_input_events: MouseMotion { delta: Vec2(-29.0, -1.0) }
INFO mouse_input_events: Frame 607
INFO mouse_input_events: Frame 608
INFO mouse_input_events: Frame 609
INFO mouse_input_events: Frame 610
INFO mouse_input_events: Frame 611
INFO mouse_input_events: Frame 612
INFO mouse_input_events: Frame 613
INFO mouse_input_events: Frame 614
INFO mouse_input_events: Frame 615
INFO mouse_input_events: Frame 616
INFO mouse_input_events: Frame 617
INFO mouse_input_events: Frame 618
INFO mouse_input_events: Frame 619
INFO mouse_input_events: Frame 620
INFO mouse_input_events: Frame 621
INFO mouse_input_events: Frame 622
INFO mouse_input_events: Frame 623
INFO mouse_input_events: Frame 624
INFO mouse_input_events: MouseButtonInput { button: Left, state: Pressed, window: 0v0 }
INFO mouse_input_events: Frame 625
INFO mouse_input_events: Frame 626
INFO mouse_input_events: Frame 627
INFO mouse_input_events: Frame 628
INFO mouse_input_events: MouseMotion { delta: Vec2(-38.0, 0.0) }
INFO mouse_input_events: Frame 629
INFO mouse_input_events: MouseButtonInput { button: Left, state: Pressed, window: 0v0 }
INFO mouse_input_events: MouseMotion { delta: Vec2(-390.0, -2.0) }
INFO mouse_input_events: MouseMotion { delta: Vec2(-194.0, -2.0) }
INFO mouse_input_events: Frame 630
INFO mouse_input_events: Frame 631
INFO mouse_input_events: Frame 632
INFO mouse_input_events: MouseMotion { delta: Vec2(-75.0, -1.0) }
INFO mouse_input_events: MouseMotion { delta: Vec2(-78.0, -3.0) }
INFO mouse_input_events: Frame 633
INFO mouse_input_events: MouseMotion { delta: Vec2(-68.0, -1.0) }
INFO mouse_input_events: Frame 634
INFO mouse_input_events: MouseMotion { delta: Vec2(-75.0, -1.0) }

Somewhere around frame 607 is where the LMB is being pressed, however instead we see a huge gap in events until frame 624, where the press is registered, then another 4 frames until a small delta is received, then the release event is received, and finally, on frame 629 we see two huge mouse deltas show up, about 10x larger than normal. This is where the inputs "catch up" after the hitch.

It's strange that we see the small delta show up on frame 629, even though we know we are still missing a few hundred pixels of mouse motion at that point. It's as if something is gumming up the winit events.

I've confirmed this is not the issue, as initially suspected:

bevy/crates/bevy_winit/src/lib.rs

Lines 508 to 512 in 22e39c4

	// Somewhat surprisingly, this call has meaningful side effects
	// See https://github.com/AccessKit/accesskit/issues/300
	// AccessKit might later need to filter events based on this, but we currently do not.
	// See https://github.com/bevyengine/bevy/pull/10239#issuecomment-1775572176
	let _ = adapter.on_event(window, &event);

[aevyrie]

Another observation - running with vsync off masks the issue, suggesting the delay isn't related to some call taking some amount of time, rather, it seems to be delayed by some number of frames.

After a significant amount of troubleshooting, I'm pretty sure the issue I'm seeing (input lag after left click) is unrelated to access kit, and is instead: rust-windowing/winit#1418 (comment)

[mwcampbell]

@aevyrie Thanks for investigating this. What does LMB mean in this context?

I think the fact that it only happens with vsync enabled is significant. It tells me that when vsync is enabled, the application's main thread is blocked for a significant amount of time for each frame. This is bad for any accessibility client on macOS, and it appears that some OS component is acting as an accessibility client even when you're not running VoiceOver or another visible accessibility tool. The main thread needs to remain responsive to events as much as possible in order for accessibility clients to work quickly, because accessibility clients often have to make several IPC round trips to complete a single action. This isn't as severe an issue on Windows, because UI Automation provides a way to handle most accessibility requests away from the main thread, and AccessKit takes advantage of that. And it's not an issue at all in Unix desktop environments using AT-SPI.

[aevyrie]

@mwcampbell after doing some more debugging, I've edited my posts and created a new issue. While there may indeed be an access kit issue, there also seems to be a winit issue, specifically when left clicking and moving. By LMB, I mean left mouse button.

[mwcampbell]

I remain convinced that vsync is the culprit. The big question is whether it's practical, with wgpu, to do proper frame pacing without wgpu's get_current_texture blocking the main thread.

[geirsagberg]

Do you have any window managers installed, like Magnet? I noticed a strange lag on mouse events, especially dragging the window. Disabling Magnet made it go away.

[samuelselleck]

Disabling magnet solved the issue for me! Thank you @geirsagberg. I do wonder why this happens, haven't noticed it in other games/apps.

[jmskov]

Can confirm that the suggestion by @geirsagberg to close Magnet removes the lag on M2 Macbook, 14.6.1.

Edit: Looks like other tools can cause this behavior, too. rust-windowing/winit#1737

[artursapek]

Just realized @geirsagberg posted an answer here. Nice. I'm going to close this.