Variable frametime during user input

[aevyrie]

Bevy version

0.7

Operating system & version

Win11

What you did

Use the tracing features to observe frame timings.

What you expected to happen

Frametime should be consistent with an empty app.

What actually happened

Extreme variability in the un-instrumented time between runs of the system graph while moving the mouse.

Additional information

Using immediate mode (vsync off). I started moving my mouse in the second half of the capture:

A closer look at the time in question:

[tim-blackbird]

Figured this was caused by the winit event loop in so I added some trace spans to bevy_winit.

Manjaro, X11 Empty Bevy app with DefaultPlugins added. Presentmode set to immediate. running at around 330 fps.

with the cursor still, the event loop takes around 0.015 ms between frames.

While moving the cursor around it can usually takes anywhere from 0.03 to 0.15 ms.

Here are a bunch of strange outliers that happened while moving the cursor around.

Here you can see certain event handling randomly taking 0.1 ms.

The handler for DeviceEvent::MouseMotion is just this:

let mut mouse_motion_events = app.world.resource_mut::<Events<MouseMotion>>();
 mouse_motion_events.send(MouseMotion {
     delta: Vec2::new(delta.0 as f32, delta.1 as f32),
 });

Presumably this calling resource_mut on world can randomly block for 0.1 ms

This one is with v-sync. fps should be 60, so more events per frame. Here are a bunch of CursorMoved events taking a whole 0.75 ms. (Added more spans within CursorMoved here)

Even with some optimization of the code for CursorMoved it can still take 0.5 ms.

The span I placed covers our entire event handler so I believe this pause(0.25 ms) must come from within winit.

Conclusion

The winit event loop has some issues and is just not very fast. I think there are some bad hiccups on world access. No idea why since the runner has exclusive access to World.

[mockersf]

Could you check if https://github.com/mockersf/bevy/tree/reduce-mouse-lag reduces the lag? Does it happens for other input or is it just the mouse?

[tim-blackbird]

Sorry @mockersf I should have specified that that is the optimization I tried. It does help a bit, but the events can still take up to .5 ms.

It's mostly the CursorMoved events eating up time by sheer number of them. Even if a frame takes only 3 ms total, there can still be a number of these events each frame. With each of these events taking 15 us at best to process...

[mockersf]

Do you have a branch with the added spans up somewhere? It could be useful to check on a few different platforms as winit code for that can change.

[tim-blackbird]

Here it is: https://github.com/devil-ira/bevy/tree/bevy-winit-tracing. Added spans for the event handler and every event within.