When accessing AudioServer.get_time_since_last_mix() from multiple threads it sometimes (rarely) returns an insanely large number

[laplante-sean]

Godot version: v3.2.4.beta4.official

OS/device including version: Windows 10 Build 18363.1256

Issue description:

AudioServer.get_time_since_last_mix() sometimes returns a crazy huge result when using multiple threads. Here's some output:

DEBUG: Time since last mix: 18446744073709.551

I have two threads running analyzing a song as it plays to synchronize gameplay to audio. As part of this I have a function that both threads call fairly regularly:

func get_background_playback_position():
	playback_pos_mutex.lock()
	var pos = backAudioPlayer.get_playback_position()
	var time_since_last_mix = AudioServer.get_time_since_last_mix()
	playback_pos_mutex.unlock()

	if pos > 1000:
		print("DEBUG: pos: ", pos)
	if time_since_last_mix > 1.0:
		print("DEBUG: Time since last mix: ", time_since_last_mix)
	
	return pos + time_since_last_mix

Initially I was not using the playback_pos_mutex like I am now. Adding the mutex has not fixed the issue (I'm pretty sure the AudioServer is thread-safe anyway according to docs.

Steps to reproduce:

1. Create two threads that poll the time since last mix for the audio server
2. Log when time_since_last_mix is large

I found I can more reliably reproduce the behavior if I click out of the main game window. When it doesn't have focus it seems like the bug happens more often but otherwise it's seemingly random.

Minimal reproduction project: See attached zip below. You'll need the 3.2.4.beta4 for MP3 support. Run the game, select a song and then click out of the window so it no longer has focus. This is not required to reproduce the bug however it makes it happen more reliably.

bug_time_since_last_mix.zip

[laplante-sean]

Edited issue description with example project.

[laplante-sean]

Looked into this briefly. I haven't tested anything yet but I'm guessing the bug is here:

godot/platform/windows/os_windows.cpp

Lines 376 to 377 in 2abe996

	if (!QueryPerformanceCounter((LARGE_INTEGER *)&ticks))
	ticks = (UINT64)timeGetTime();

In os_windows.cpp get_ticks_usec - If the call to QueryPerformanceCounter fails (which I haven't tested - just a hunch b/c Windows...so it's probably failing), it falls back to timeGetTime which I don't think is a drop-in replacement for QueryPerformanceCounter.

According to the docs for QueryPerformanceCounter, it updates a 64-bit integer with the "performance-counter value, in counts." while the docs for timeGetTime indicate that it returns a 32-bit value in milliseconds.

Additionally, the MS Docs for timeGetTime warn that:

Note that the value returned by the timeGetTime function is a DWORD value. The return value wraps around to 0 every 2^32 milliseconds, which is about 49.71 days. This can cause problems in code that directly uses the timeGetTime return value in computations, particularly where the value is used to control code execution. You should always use the difference between two timeGetTime return values in computations.

[laplante-sean]

My prior comment is not the issue. Although I am curious what would happen if QueryPerformanceCounter ever failed.

The issue is that get_time_since_last_mix is being called by my thread at the same time as AudioDriver::update_mix_time and _last_mix_time is not protected by any sort of lock and it's not atomic.

I compiled from source on v3.2.4.beta.custom_build.ecf432abc and was able to reproduce. I added some error printing and found the issue is that _last_mix_time can actually be greater than ticks_usec in this multithreading edge case:

ERROR: IDK HOW TO GODOT tick_usec: 171990805 _last_mix_time: 171990808 result: 1.84467e+13
   At: servers\audio_server.cpp:82

Which, because both are uint64_t's, causes the unsinged values to wrap around resulting in a massive result when converted to a double.

So my proposed fix is as follows:

1. First, ensure the value of _last_mix_time is always retrieved prior to calling get_ticks_usec() so that it will never be bigger:

double AudioDriver::get_time_since_last_mix() const {
	uint64_t last_mix_time = _last_mix_time;
	return (OS::get_singleton()->get_ticks_usec() - last_mix_time) / 1000000.0;
}

2. Then, change the _last_mix_time instance variable to be an atomic unit64_t since technically, without making it atomic, there is still a chance that only part of the value has been written when we grab it to store locally (on 32-bit systems).