time_step doesn't look like to be called every 50Hz

[shazz]

Hi,
I hope you'll see this issue this time :D (no worries)

In my game using pygase I had the feeling it was a little too fast compared to the local version. For example I have a counter which add 10 points every second and definitively it happens faster than every second.

So I added a check in time_step to see how much time was elapsed since the last call (which should be equal to dt meaning 0.02)
But as expected it looks to be around 0.016 in average.

So time_step is called 50x in 0.80s in average and not 1s so 20% faster

Here is the code I added in the chase example to check:

last_call = 0

# Define the game loop iteration function.
def time_step(game_state, dt):

    global last_call

    current_time = time.time()
    interval = current_time - last_call
    print(f"interval: {interval} vs {dt} => delta {dt-interval} => {interval*50}")
    last_call = time.time()

Results

interval: 0.02029275894165039 vs 0.02 => delta -0.0002927589416503902 => 1.0146379470825195
interval: 0.01049351692199707 vs 0.02 => delta 0.00950648307800293 => 0.5246758460998535
interval: 0.01621699333190918 vs 0.02 => delta 0.0037830066680908207 => 0.810849666595459
interval: 0.016791343688964844 vs 0.02 => delta 0.0032086563110351567 => 0.8395671844482422
interval: 0.01358938217163086 vs 0.02 => delta 0.006410617828369141 => 0.679469108581543
interval: 0.01653909683227539 vs 0.02 => delta 0.00346090316772461 => 0.8269548416137695
interval: 0.015427112579345703 vs 0.02 => delta 0.004572887420654297 => 0.7713556289672852
interval: 0.015175819396972656 vs 0.02 => delta 0.004824180603027344 => 0.7587909698486328
interval: 0.016242504119873047 vs 0.02 => delta 0.0037574958801269535 => 0.8121252059936523
interval: 0.014711618423461914 vs 0.02 => delta 0.005288381576538086 => 0.7355809211730957
interval: 0.016119003295898438 vs 0.02 => delta 0.003880996704101563 => 0.8059501647949219
interval: 0.015097618103027344 vs 0.02 => delta 0.004902381896972657 => 0.7548809051513672
interval: 0.016288280487060547 vs 0.02 => delta 0.0037117195129394535 => 0.8144140243530273

Did I misunderstand something ?

Moreover, could you add in the Backend run() method the interval (if not 0.02 by default) ?

Thanks !

[shazz]

I forked the code and tried a few modifications, looks to be better:

    @awaitable(run_game_loop)
    async def run_game_loop(self, interval: float = 0.02) -> None:  # pylint: disable=function-redefined
        # pylint: disable=missing-docstring
        if self._game_state_store.get_game_state().game_status == GameStatus.get("Paused"):
            self._game_state_store.push_update(
                GameStateUpdate(
                    self._game_state_store.get_game_state().time_order + 1, game_status=GameStatus.get("Active")
                )
            )
        game_state = self._game_state_store.get_game_state()
        dt = interval
        self._game_loop_is_running = True
        logger.info(f"State machine starting game loop with interval of {interval} seconds.")
        while game_state.game_status == GameStatus.get("Active"):
            t0 = time.perf_counter()

            update_dict = self.time_step(game_state, dt)
            while not self._event_queue.empty():
                event = await self._event_queue.get()
                event_update = await self._universal_event_handler.handle(event, game_state=game_state, dt=dt)
                update_dict.update(event_update)
                if time.perf_counter() - t0 > 0.95 * interval:
                    break

            self._game_state_store.push_update(GameStateUpdate(game_state.time_order + 1, **update_dict))
            game_state = self._game_state_store.get_game_state()

            # real elapsed time since the loop start
            real_elapsed_time = time.perf_counter() - t0

            # consume the  remaining time to reach the interval
            delta = interval - real_elapsed_time
            while delta > 0.0000001:
                delta = interval - (time.perf_counter() - t0)

            # adding the real spent time to the game time
            dt = interval - delta
            self.game_time += dt
            logger.info(f"loop time: {round(dt, 4)} vs expected {round(interval, 4)} => delta {round(dt - interval, 6)}")

        logger.info("Game loop stopped.")
        self._game_loop_is_running = False