Time-keeping broken with `UpdateMode::Reactive` (X11 and WASM)

Azorlogh commented 1 month ago

Bevy version

Bevy 0.14.1 and main

X11 adapter: AdapterInfo { name: "NVIDIA GeForce RTX 2060", vendor: 4318, device: 7817, device_type: DiscreteGpu, driver: "NVIDIA", driver_info: "555.58.02", backend: Vulkan } WASM adapter:AdapterInfo { name: "NVIDIA GeForce GTX 980, or similar", vendor: 4318, device: 0, device_type: Other, driver: "WebGL", driver_info: "2.0", backend: Gl }

Happens on native X11, and WASM (Firefox and Chrome)

What you did

Run this example:

use std::time::Duration;

use bevy::{
    input::common_conditions::input_just_pressed,
    prelude::*,
    winit::{UpdateMode, WinitSettings},
};

fn main() {
    App::new()
        .add_plugins(DefaultPlugins.build())
        .add_systems(Startup, |mut cmds: Commands| {
            cmds.spawn(Camera2dBundle::default());
        })
        .add_systems(
            Update,
            (run, switch.run_if(input_just_pressed(KeyCode::KeyU))).chain(),
        )
        .run();
}

fn switch(mut settings: ResMut<WinitSettings>) {
    settings.focused_mode = match settings.focused_mode {
        UpdateMode::Continuous => {
            info!("Switching to continuous!");
            UpdateMode::reactive(Duration::from_secs(1))
        }
        UpdateMode::Reactive { .. } => {
            info!("Switching to reactive!");
            UpdateMode::Continuous
        }
    };
    settings.unfocused_mode = settings.focused_mode;
}

fn run(time: Res<Time>, settings: ResMut<WinitSettings>, mut gizmos: Gizmos) {
    info!("{} {:?}", time.delta_seconds(), settings.focused_mode);
    gizmos.circle_2d(
        Vec2::from_angle(time.elapsed_seconds() * std::f32::consts::TAU) * 128.0,
        32.0,
        Color::WHITE,
    );
}

What went wrong

Initially, delta_time is consistent
The circle revolves at 1 revolution per second.
Press U, to switch to reactive mode
Now the delta_time increases every frame, until it caps off at 0.25s
- As a result, the circle moves around instead of appearing roughly in the same place (what you would expect if the app updates ~every second)
Press U again, to switch back to continuous mode
- The next frame has a low delta_time, as expected BUT
- The following frame gets a strange lag spike at 0.25s, making the circle briefly appear in another position before going back to rotating normally.

Additional information

X11 logs

``` 2024-08-09T15:29:24.328881Z INFO update_mode_switch: 0.006974337 Continuous 2024-08-09T15:29:24.335733Z INFO update_mode_switch: 0.006931047 Continuous 2024-08-09T15:29:24.342786Z INFO update_mode_switch: 0.006965437 Continuous 2024-08-09T15:29:24.342826Z INFO update_mode_switch: Switching to reactive! 2024-08-09T15:29:24.349579Z INFO update_mode_switch: 0.006900987 Reactive { wait: 1s, react_to_device_events: true, react_to_user_events: true, react_to_window_events: true } 2024-08-09T15:29:24.422030Z INFO update_mode_switch: 0.006958497 Reactive { wait: 1s, react_to_device_events: true, react_to_user_events: true, react_to_window_events: true } 2024-08-09T15:29:25.342941Z INFO update_mode_switch: 0.006940747 Reactive { wait: 1s, react_to_device_events: true, react_to_user_events: true, react_to_window_events: true } 2024-08-09T15:29:26.343144Z INFO update_mode_switch: 0.05999414 Reactive { wait: 1s, react_to_device_events: true, react_to_user_events: true, react_to_window_events: true } 2024-08-09T15:29:27.343763Z INFO update_mode_switch: 0.25 Reactive { wait: 1s, react_to_device_events: true, react_to_user_events: true, react_to_window_events: true } 2024-08-09T15:29:28.343784Z INFO update_mode_switch: 0.25 Reactive { wait: 1s, react_to_device_events: true, react_to_user_events: true, react_to_window_events: true } 2024-08-09T15:29:29.343866Z INFO update_mode_switch: 0.25 Reactive { wait: 1s, react_to_device_events: true, react_to_user_events: true, react_to_window_events: true } 2024-08-09T15:29:29.812715Z INFO update_mode_switch: 0.25 Reactive { wait: 1s, react_to_device_events: true, react_to_user_events: true, react_to_window_events: true } 2024-08-09T15:29:29.812754Z INFO update_mode_switch: Switching to continuous! 2024-08-09T15:29:29.813895Z INFO update_mode_switch: 0.25 Continuous 2024-08-09T15:29:29.814938Z INFO update_mode_switch: 0.25 Continuous 2024-08-09T15:29:29.815371Z INFO update_mode_switch: 0.00067504 Continuous 2024-08-09T15:29:29.816060Z INFO update_mode_switch: 0.001055621 Continuous 2024-08-09T15:29:29.816653Z INFO update_mode_switch: 0.000581371 Continuous 2024-08-09T15:29:29.817327Z INFO update_mode_switch: 0.00066637 Continuous 2024-08-09T15:29:29.817929Z INFO update_mode_switch: 0.000625411 Continuous ```

X11 logs (different run showing a single normal continuous frame in between the freaky 0.25s frames)

``` 2024-08-09T15:37:07.687200Z INFO update_mode_switch: 0.006944937 Continuous 2024-08-09T15:37:07.694232Z INFO update_mode_switch: 0.006939317 Continuous 2024-08-09T15:37:07.701115Z INFO update_mode_switch: 0.006946427 Continuous 2024-08-09T15:37:07.701148Z INFO update_mode_switch: Switching to reactive! 2024-08-09T15:37:07.708097Z INFO update_mode_switch: 0.006948797 Reactive { wait: 1s, react_to_device_events: true, react_to_user_events: true, react_to_window_events: true } 2024-08-09T15:37:07.809416Z INFO update_mode_switch: 0.006945327 Reactive { wait: 1s, react_to_device_events: true, react_to_user_events: true, react_to_window_events: true } 2024-08-09T15:37:08.532579Z INFO update_mode_switch: 0.006942567 Reactive { wait: 1s, react_to_device_events: true, react_to_user_events: true, react_to_window_events: true } 2024-08-09T15:37:08.532621Z INFO update_mode_switch: Switching to continuous! 2024-08-09T15:37:08.533378Z INFO update_mode_switch: 0.08901965 Continuous 2024-08-09T15:37:08.534797Z INFO update_mode_switch: 0.25 Continuous 2024-08-09T15:37:08.535216Z INFO update_mode_switch: 0.000840611 Continuous 2024-08-09T15:37:08.535908Z INFO update_mode_switch: 0.00076325 Continuous 2024-08-09T15:37:08.536541Z INFO update_mode_switch: 0.000646981 Continuous 2024-08-09T15:37:08.537180Z INFO update_mode_switch: 0.000634641 Continuous ```

WASM logs

``` INFO examples/window/update_mode_switch.rs:27 Switching to reactive! wasm_example.js:435:21 INFO examples/window/update_mode_switch.rs:39 0.006 Reactive { wait: 1s, react_to_device_events: true, react_to_user_events: true, react_to_window_events: true } wasm_example.js:435:21 INFO examples/window/update_mode_switch.rs:39 0.008 Reactive { wait: 1s, react_to_device_events: true, react_to_user_events: true, react_to_window_events: true } wasm_example.js:435:21 INFO examples/window/update_mode_switch.rs:39 0.082 Reactive { wait: 1s, react_to_device_events: true, react_to_user_events: true, react_to_window_events: true } wasm_example.js:435:21 INFO examples/window/update_mode_switch.rs:39 0.25 Reactive { wait: 1s, react_to_device_events: true, react_to_user_events: true, react_to_window_events: true } 8 wasm_example.js:435:21 INFO examples/window/update_mode_switch.rs:31 Switching to continuous! wasm_example.js:435:21 INFO examples/window/update_mode_switch.rs:39 0.25 Continuous wasm_example.js:435:21 INFO examples/window/update_mode_switch.rs:39 0.002 Continuous wasm_example.js:435:21 INFO examples/window/update_mode_switch.rs:39 0.013 Continuous wasm_example.js:435:21 INFO examples/window/update_mode_switch.rs:39 0.008 Continuous wasm_example.js:435:21 INFO examples/window/update_mode_switch.rs:39 0.012 Continuous wasm_example.js:435:21 ```

tychedelia commented 1 month ago

The behavior that I'm seeing on macOS is that when I switch into reactive mode, the circle does not animate correct for the first few frames before the delta stabilizes. This seems to be the opposite of what's described in "what went wrong"?

Azorlogh commented 1 month ago

Update: It seems that Time<Virtual> has its delta-time capped at 0.25s, so this part is easily explained. I think this reduces the problem to being a delay in the reported delta-times. When switching to reactive mode, it reports the previous, smaller delta-times of continuous mode for a few frames, causing animations to slow down. When switching back to continuous mode, it reports the previous, larger delta-times of reactive mode for a few frames, causing animations to speed up.

I suspect it's actually unrelated to UpdateMode, and is just a quirk of bevy's timekeeping logic since frame times are reported from the render thread. The timings take a while to arrive so I guess we always read delta-times from a few frames back

bevyengine / bevy