OS.get_system_time_msecs output is wrong

[poperigby]

Godot version:

3.2.3

OS/device including version:

OS: Arch Linux

Issue description:

When running OS.get_system_time_msecs() in _physics_process(), it seems to be counting incorrectly. The last three numbers will stay the same for multiple lines before flipping even though they're supposed to be milliseconds. It's hard to describe, so here's a video of it happening:

recording.mp4

Also, I'm not positive, but I think this might be causing some serious network sync latency issues, because my solution uses this function to sync the world state.

Steps to reproduce:
Put print(OS.get_system_time_msecs()) in _physics_process()

Minimal reproduction project:

SystemTimeTest.zip

[Demindiro]

I'm unable to reproduce this on Debian 10.7 (Linux pc 4.19.0-12-amd64 #1 SMP Debian 4.19.152-1 (2020-10-18) x86_64 GNU/Linux). Milliseconds are counting up just fine.

Out of curiosity, what do you get if you run date +%s.%3N multiple times?

[poperigby]

Out of curiosity, what do you get if you run date +%s.%3N multiple times?

This:

recording.mp4

[qarmin]

I also can't reproduce but with Ubuntu 20.04
Are you sure, that you don't set physics fps in project settings to 1?

[poperigby]

Yes I'm sure. I didn't change any project settings, you can check in the project I uploaded.

[poperigby]

I ran a test on my laptop (also running Arch Linux) and got this result:

godot-screencast.mp4

Does this look right?

[Faless]

This is fixed by: #39189 . Also, don't use OS.get_*_time* functions for precision timing, use OS.get_ticks_* instead.

[poperigby]

How does that pull request fix it not updating correctly? Replacing the OS.get_system_time_msecs() with OS.get_ticks_msecs() in the above problem yields the same broken results.

[Faless]

How does that pull request fix it not updating correctly?

Oh, my bad I didn't read the description well, and thought you were on Windows (which had a broken get_system_time_msecs).

Replacing the OS.get_system_time_msecs() with OS.get_ticks_msecs() in the above problem yields the same broken results.

This is really weird, get_ticks_msec/get_ticks_usec use a completely different clock source (and that one is monotonic). What if you use get_ticks_usec? Even two consecutive calls to OS.get_ticks_usec() usually return different values.

[poperigby]

What if you use get_ticks_usec?

recording.mp4

[Demindiro]

So it just occurred to me that roughly the same output is printed exactly 8 times per iteration, which reminded me of this particular piece of code:

godot/main/main.cpp

Lines 2064 to 2068 in 31d0f8a

	static const int max_physics_steps = 8;
	if (fixed_fps == -1 && advance.physics_steps > max_physics_steps) {
	step -= (advance.physics_steps - max_physics_steps) * frame_slice;
	advance.physics_steps = max_physics_steps;
	}

I then managed to reproduce a similar output by executing the following snippet with godot --frame-delay 1000 -s main.gd

# main.gd
extends MainLoop


func _iteration(delta: float) -> bool:
	print(OS.get_system_time_msecs())
	return false

Output:

1608847883988
1608847883988
1608847883988
1608847883988
1608847883988
1608847883988
1608847883988
1608847883988
1608847884988
1608847884988
1608847884988
1608847884988
1608847884988
1608847884988
1608847884988
1608847884988
1608847885988
1608847885988
1608847885988
1608847885988
1608847885988
1608847885988
1608847885988
1608847885988

So the question now is: what is limiting the FPS?

[poperigby]

Interesting. Have any ideas of what I can test to figure it out?

[Faless]

why do you keep using get_system_time_msecs while I explicitly told you that's a bad idea.
It's useless to post the result of get_system_time_msecs instead of get_ticks_usec.

[poperigby]

What are you talking about? The last output I posted was from get_ticks_usec.

[Faless]

I was referring to @Demindiro 's last test.

Anyway, as @Demindiro mentioned, what you are seeing might be the side effect of the way _physics_process happens (see also #17353), i.e. the fact that the delta there does not directly represent the time passed since the last function call, but only the time this step should care about.
Although, this should only be relevant when your FPSs (Main::iteration) is lower than the physics FPS (which needs to be constant if you want the simulation to be stable).
@poperigby can you provide some info on your system (CPU/GPU/Monitor refresh rate)?
Can you check if you end up having a higher physics FPS then rendering FPS?
Engine.get_frames_per_second() should be 60 or greater/equal to the value you set in physics/common/physics_fps project settings.
float(Engine.get_idle_frames()) / max(1, float(Engine.get_physics_frames())) should stabilize to be >= 1.
That said, I don't see how the minimal reproduction project you provided could end up doing less then 60 FPS unless there's some (driver?) issue which you should notice anyway when running any project 😕 .

EDIT: The recording application might be causing the FPS drop I guess, but I assume you are seeing the issue even when not recording?

[poperigby]

@poperigby can you provide some info on your system (CPU/GPU/Monitor refresh rate)?

Sure.
CPU: Ryzen 5 3700X
GPU: RX 5700XT
Refresh Rate: 60Hz

Can you check if you end up having a higher physics FPS then rendering FPS?

I'm getting some really bizarre numbers if I print Engine.get_frames_per_second() within physics_process. It starts out at around 44, then it drops down to 13, and then finally it drops to 1 and stays there.

EDIT: The recording application might be causing the FPS drop I guess, but I assume you are seeing the issue even when not recording?

Yeah, I am.

[Faless]

I'm getting some really bizarre numbers if I print Engine.get_frames_per_second() within physics_process. It starts out at around 44, then it drops down to 13, and then finally it drops to 1 and stays there.

@poperigby this likely confirms you have some driver issues, with those specs, you definitively should not have problems reaching 60FPS in an empty scene.

One thing you can try is disabling vsync and see if that's an issue with your setup (OS.vsync_enabled = false), but you should also make sure that your drivers are working correctly and can run GL applications well (refer to Arch documentation for that).
In any case, I think you should open a new issue since this one has gone quite off-target, explaining the low FPS in an empty scene with your setup, detailing your hardware and software (OS version, kernel version, mesa version, etc) and reporting glxinfo and glxgears results.

[poperigby]

One thing you can try is disabling vsync and see if that's an issue with your setup (OS.vsync_enabled = false)

After disabling v-sync, my FPS starts out at one and climbs to 5 digits.

but you should also make sure that your drivers are working correctly and can run GL applications well

I can run GL applications well. I can even run Godot applications very well.

Also, in that game, unfocusing the game window made it drop down to 1, but refocusing it made it climb back up to 60. I'm starting to think that it has something to do with unfocusing the window. That's what my new issue will be about.

Edit: #44741 is the new issue

[Faless]

Closing, as the discussion will move over to #44741.