Add Audio Server profiling time to the profiler

8 files changed, 198 insertions, 84 deletions

diff --git a/drivers/alsa/audio_driver_alsa.cpp b/drivers/alsa/audio_driver_alsa.cpp
index 1e17e72532..ae85ee50d1 100644
--- a/drivers/alsa/audio_driver_alsa.cpp
+++ b/drivers/alsa/audio_driver_alsa.cpp
@@ -142,8 +142,6 @@ Error AudioDriverALSA::init_device() {
 	samples_in.resize(period_size * channels);
 	samples_out.resize(period_size * channels);
 
-	snd_pcm_nonblock(pcm_handle, 0);
-
 	return OK;
 }
 
@@ -168,54 +166,50 @@ void AudioDriverALSA::thread_func(void *p_udata) {
 	AudioDriverALSA *ad = (AudioDriverALSA *)p_udata;
 
 	while (!ad->exit_thread) {
+
+		ad->lock();
+		ad->start_counting_ticks();
+
 		if (!ad->active) {
 			for (unsigned int i = 0; i < ad->period_size * ad->channels; i++) {
 				ad->samples_out[i] = 0;
-			};
-		} else {
-			ad->lock();
+			}
 
+		} else {
 			ad->audio_server_process(ad->period_size, ad->samples_in.ptrw());
 
-			ad->unlock();
-
 			for (unsigned int i = 0; i < ad->period_size * ad->channels; i++) {
 				ad->samples_out[i] = ad->samples_in[i] >> 16;
 			}
-		};
+		}
 
 		int todo = ad->period_size;
 		int total = 0;
 
-		while (todo) {
-			if (ad->exit_thread)
-				break;
+		while (todo && !ad->exit_thread) {
 			uint8_t *src = (uint8_t *)ad->samples_out.ptr();
 			int wrote = snd_pcm_writei(ad->pcm_handle, (void *)(src + (total * ad->channels)), todo);
 
-			if (wrote < 0) {
-				if (ad->exit_thread)
-					break;
+			if (wrote > 0) {
+				total += wrote;
+				todo -= wrote;
+			} else if (wrote == -EAGAIN) {
+				ad->stop_counting_ticks();
+				ad->unlock();
 
-				if (wrote == -EAGAIN) {
-					//can't write yet (though this is blocking..)
-					usleep(1000);
-					continue;
-				}
+				OS::get_singleton()->delay_usec(1000);
+
+				ad->lock();
+				ad->start_counting_ticks();
+			} else {
 				wrote = snd_pcm_recover(ad->pcm_handle, wrote, 0);
 				if (wrote < 0) {
-					//absolute fail
-					fprintf(stderr, "ALSA failed and can't recover: %s\n", snd_strerror(wrote));
+					ERR_PRINTS("ALSA: Failed and can't recover: " + String(snd_strerror(wrote)));
 					ad->active = false;
 					ad->exit_thread = true;
-					break;
 				}
-				continue;
-			};
-
-			total += wrote;
-			todo -= wrote;
-		};
+			}
+		}
 
 		// User selected a new device, finish the current one so we'll init the new device
 		if (ad->device_name != ad->new_device) {
@@ -232,10 +226,12 @@ void AudioDriverALSA::thread_func(void *p_udata) {
 				if (err != OK) {
 					ad->active = false;
 					ad->exit_thread = true;
-					break;
 				}
 			}
 		}
+
+		ad->stop_counting_ticks();
+		ad->unlock();
 	};
 
 	ad->thread_exited = true;
@@ -296,7 +292,9 @@ String AudioDriverALSA::get_device() {
 
 void AudioDriverALSA::set_device(String device) {
 
+	lock();
 	new_device = device;
+	unlock();
 }
 
 void AudioDriverALSA::lock() {
@@ -323,21 +321,21 @@ void AudioDriverALSA::finish_device() {
 
 void AudioDriverALSA::finish() {
 
-	if (!thread)
-		return;
-
-	exit_thread = true;
-	Thread::wait_to_finish(thread);
+	if (thread) {
+		exit_thread = true;
+		Thread::wait_to_finish(thread);
 
-	finish_device();
+		memdelete(thread);
+		thread = NULL;
 
-	memdelete(thread);
-	if (mutex) {
-		memdelete(mutex);
-		mutex = NULL;
+		if (mutex) {
+			memdelete(mutex);
+			mutex = NULL;
+		}
 	}
-	thread = NULL;
-};
+
+	finish_device();
+}
 
 AudioDriverALSA::AudioDriverALSA() {
 
diff --git a/drivers/coreaudio/audio_driver_coreaudio.cpp b/drivers/coreaudio/audio_driver_coreaudio.cpp
index ef7858b4ca..63af4506f3 100644
--- a/drivers/coreaudio/audio_driver_coreaudio.cpp
+++ b/drivers/coreaudio/audio_driver_coreaudio.cpp
@@ -163,6 +163,8 @@ OSStatus AudioDriverCoreAudio::output_callback(void *inRefCon,
 		return 0;
 	};
 
+	ad->start_counting_ticks();
+
 	for (unsigned int i = 0; i < ioData->mNumberBuffers; i++) {
 
 		AudioBuffer *abuf = &ioData->mBuffers[i];
@@ -184,6 +186,7 @@ OSStatus AudioDriverCoreAudio::output_callback(void *inRefCon,
 		};
 	};
 
+	ad->stop_counting_ticks();
 	ad->unlock();
 
 	return 0;
diff --git a/drivers/pulseaudio/audio_driver_pulseaudio.cpp b/drivers/pulseaudio/audio_driver_pulseaudio.cpp
index 0f47949b4b..ed6af04b9d 100644
--- a/drivers/pulseaudio/audio_driver_pulseaudio.cpp
+++ b/drivers/pulseaudio/audio_driver_pulseaudio.cpp
@@ -289,18 +289,18 @@ void AudioDriverPulseAudio::thread_func(void *p_udata) {
 	AudioDriverPulseAudio *ad = (AudioDriverPulseAudio *)p_udata;
 
 	while (!ad->exit_thread) {
+
+		ad->lock();
+		ad->start_counting_ticks();
+
 		if (!ad->active) {
 			for (unsigned int i = 0; i < ad->pa_buffer_size; i++) {
 				ad->samples_out[i] = 0;
 			}
 
 		} else {
-			ad->lock();
-
 			ad->audio_server_process(ad->buffer_frames, ad->samples_in.ptrw());
 
-			ad->unlock();
-
 			if (ad->channels == ad->pa_map.channels) {
 				for (unsigned int i = 0; i < ad->pa_buffer_size; i++) {
 					ad->samples_out[i] = ad->samples_in[i] >> 16;
@@ -323,9 +323,6 @@ void AudioDriverPulseAudio::thread_func(void *p_udata) {
 
 		int error_code;
 		int byte_size = ad->pa_buffer_size * sizeof(int16_t);
-
-		ad->lock();
-
 		int ret;
 		do {
 			ret = pa_mainloop_iterate(ad->pa_ml, 0, NULL);
@@ -350,11 +347,13 @@ void AudioDriverPulseAudio::thread_func(void *p_udata) {
 					if (ret == 0) {
 						// If pa_mainloop_iterate returns 0 sleep for 1 msec to wait
 						// for the stream to be able to process more bytes
+						ad->stop_counting_ticks();
 						ad->unlock();
 
 						OS::get_singleton()->delay_usec(1000);
 
 						ad->lock();
+						ad->start_counting_ticks();
 					}
 				}
 			}
@@ -380,6 +379,7 @@ void AudioDriverPulseAudio::thread_func(void *p_udata) {
 			}
 		}
 
+		ad->stop_counting_ticks();
 		ad->unlock();
 	}
 
@@ -453,7 +453,9 @@ String AudioDriverPulseAudio::get_device() {
 
 void AudioDriverPulseAudio::set_device(String device) {
 
+	lock();
 	new_device = device;
+	unlock();
 }
 
 void AudioDriverPulseAudio::lock() {
diff --git a/drivers/wasapi/audio_driver_wasapi.cpp b/drivers/wasapi/audio_driver_wasapi.cpp
index e1680601ad..3c54c429d9 100644
--- a/drivers/wasapi/audio_driver_wasapi.cpp
+++ b/drivers/wasapi/audio_driver_wasapi.cpp
@@ -335,22 +335,6 @@ Error AudioDriverWASAPI::init() {
 	return OK;
 }
 
-Error AudioDriverWASAPI::reopen() {
-	Error err = finish_device();
-	if (err != OK) {
-		ERR_PRINT("WASAPI: finish_device error");
-	} else {
-		err = init_device();
-		if (err != OK) {
-			ERR_PRINT("WASAPI: init_device error");
-		} else {
-			start();
-		}
-	}
-
-	return err;
-}
-
 int AudioDriverWASAPI::get_mix_rate() const {
 
 	return mix_rate;
@@ -416,7 +400,9 @@ String AudioDriverWASAPI::get_device() {
 
 void AudioDriverWASAPI::set_device(String device) {
 
+	lock();
 	new_device = device;
+	unlock();
 }
 
 void AudioDriverWASAPI::write_sample(AudioDriverWASAPI *ad, BYTE *buffer, int i, int32_t sample) {
@@ -453,24 +439,31 @@ void AudioDriverWASAPI::thread_func(void *p_udata) {
 	AudioDriverWASAPI *ad = (AudioDriverWASAPI *)p_udata;
 
 	while (!ad->exit_thread) {
-		if (ad->active) {
-			ad->lock();
 
-			ad->audio_server_process(ad->buffer_frames, ad->samples_in.ptrw());
+		ad->lock();
+		ad->start_counting_ticks();
 
-			ad->unlock();
+		if (ad->active) {
+			ad->audio_server_process(ad->buffer_frames, ad->samples_in.ptrw());
 		} else {
 			for (unsigned int i = 0; i < ad->buffer_size; i++) {
 				ad->samples_in[i] = 0;
 			}
 		}
 
+		ad->stop_counting_ticks();
+		ad->unlock();
+
 		unsigned int left_frames = ad->buffer_frames;
 		unsigned int buffer_idx = 0;
 		while (left_frames > 0 && ad->audio_client) {
 			WaitForSingleObject(ad->event, 1000);
 
+			ad->lock();
+			ad->start_counting_ticks();
+
 			UINT32 cur_frames;
+			bool invalidated = false;
 			HRESULT hr = ad->audio_client->GetCurrentPadding(&cur_frames);
 			if (hr == S_OK) {
 				// Check how much frames are available on the WASAPI buffer
@@ -506,34 +499,34 @@ void AudioDriverWASAPI::thread_func(void *p_udata) {
 
 					left_frames -= write_frames;
 				} else if (hr == AUDCLNT_E_DEVICE_INVALIDATED) {
-					// Device is not valid anymore, reopen it
-
-					Error err = ad->finish_device();
-					if (err != OK) {
-						ERR_PRINT("WASAPI: finish_device error");
-					} else {
-						// We reopened the device and samples_in may have resized, so invalidate the current left_frames
-						left_frames = 0;
-					}
+					invalidated = true;
 				} else {
 					ERR_PRINT("WASAPI: Get buffer error");
 					ad->exit_thread = true;
 				}
 			} else if (hr == AUDCLNT_E_DEVICE_INVALIDATED) {
-				// Device is not valid anymore, reopen it
+				invalidated = true;
+			} else {
+				ERR_PRINT("WASAPI: GetCurrentPadding error");
+			}
+
+			if (invalidated) {
+				// Device is not valid anymore
+				WARN_PRINT("WASAPI: Current device invalidated, closing device");
 
 				Error err = ad->finish_device();
 				if (err != OK) {
 					ERR_PRINT("WASAPI: finish_device error");
-				} else {
-					// We reopened the device and samples_in may have resized, so invalidate the current left_frames
-					left_frames = 0;
 				}
-			} else {
-				ERR_PRINT("WASAPI: GetCurrentPadding error");
 			}
+
+			ad->stop_counting_ticks();
+			ad->unlock();
 		}
 
+		ad->lock();
+		ad->start_counting_ticks();
+
 		// If we're using the Default device and it changed finish it so we'll re-init the device
 		if (ad->device_name == "Default" && default_device_changed) {
 			Error err = ad->finish_device();
@@ -559,6 +552,9 @@ void AudioDriverWASAPI::thread_func(void *p_udata) {
 				ad->start();
 			}
 		}
+
+		ad->stop_counting_ticks();
+		ad->unlock();
 	}
 
 	ad->thread_exited = true;
diff --git a/drivers/wasapi/audio_driver_wasapi.h b/drivers/wasapi/audio_driver_wasapi.h
index c97f4c288c..f3ee5976eb 100644
--- a/drivers/wasapi/audio_driver_wasapi.h
+++ b/drivers/wasapi/audio_driver_wasapi.h
@@ -72,7 +72,6 @@ class AudioDriverWASAPI : public AudioDriver {
 
 	Error init_device(bool reinit = false);
 	Error finish_device();
-	Error reopen();
 
 public:
 	virtual const char *get_name() const {
diff --git a/main/main.cpp b/main/main.cpp
index 23acb60c89..23f2776737 100644
--- a/main/main.cpp
+++ b/main/main.cpp
@@ -1823,6 +1823,8 @@ bool Main::iteration() {
 		ScriptServer::get_language(i)->frame();
 	}
 
+	AudioServer::get_singleton()->update();
+
 	if (script_debugger) {
 		if (script_debugger->is_profiling()) {
 			script_debugger->profiling_set_frame_times(USEC_TO_SEC(frame_time), USEC_TO_SEC(idle_process_ticks), USEC_TO_SEC(physics_process_ticks), frame_slice);
diff --git a/servers/audio_server.cpp b/servers/audio_server.cpp
index 69c1318a48..ef794ac380 100644
--- a/servers/audio_server.cpp
+++ b/servers/audio_server.cpp
@@ -117,6 +117,10 @@ AudioDriver::AudioDriver() {
 
 	_last_mix_time = 0;
 	_mix_amount = 0;
+
+#ifdef DEBUG_ENABLED
+	prof_time = 0;
+#endif
 }
 
 AudioDriver *AudioDriverManager::drivers[MAX_DRIVERS];
@@ -184,6 +188,10 @@ void AudioServer::_driver_process(int p_frames, int32_t *p_buffer) {
 
 	int todo = p_frames;
 
+#ifdef DEBUG_ENABLED
+	uint64_t prof_ticks = OS::get_singleton()->get_ticks_usec();
+#endif
+
 	if (channel_count != get_channel_count()) {
 		// Amount of channels changed due to a device change
 		// reinitialize the buses channels and buffers
@@ -241,6 +249,10 @@ void AudioServer::_driver_process(int p_frames, int32_t *p_buffer) {
 		output_latency = (ticks - output_latency_ticks) / 1000000.f;
 		output_latency_ticks = ticks;
 	}
+
+#ifdef DEBUG_ENABLED
+	prof_time += OS::get_singleton()->get_ticks_usec() - prof_ticks;
+#endif
 }
 
 void AudioServer::_mix_step() {
@@ -314,6 +326,10 @@ void AudioServer::_mix_step() {
 				if (!bus->effects[j].enabled)
 					continue;
 
+#ifdef DEBUG_ENABLED
+				uint64_t ticks = OS::get_singleton()->get_ticks_usec();
+#endif
+
 				for (int k = 0; k < bus->channels.size(); k++) {
 
 					if (!bus->channels[k].active)
@@ -328,6 +344,10 @@ void AudioServer::_mix_step() {
 						continue;
 					SWAP(bus->channels[k].buffer, temp_buffer[k]);
 				}
+
+#ifdef DEBUG_ENABLED
+				bus->effects[j].prof_time += OS::get_singleton()->get_ticks_usec() - ticks;
+#endif
 			}
 		}
 
@@ -768,6 +788,9 @@ void AudioServer::add_bus_effect(int p_bus, const Ref<AudioEffect> &p_effect, in
 	fx.effect = p_effect;
 	//fx.instance=p_effect->instance();
 	fx.enabled = true;
+#ifdef DEBUG_ENABLED
+	fx.prof_time = 0;
+#endif
 
 	if (p_at_pos >= buses[p_bus]->effects.size() || p_at_pos < 0) {
 		buses[p_bus]->effects.push_back(fx);
@@ -900,6 +923,68 @@ void AudioServer::init() {
 	GLOBAL_DEF("audio/video_delay_compensation_ms", 0);
 }
 
+void AudioServer::update() {
+#ifdef DEBUG_ENABLED
+	if (ScriptDebugger::get_singleton() && ScriptDebugger::get_singleton()->is_profiling()) {
+
+		// Driver time includes server time + effects times
+		// Server time includes effects times
+		uint64_t driver_time = AudioDriver::get_singleton()->get_profiling_time();
+		uint64_t server_time = prof_time;
+
+		// Substract the server time from the driver time
+		if (driver_time > server_time)
+			driver_time -= server_time;
+
+		Array values;
+
+		for (int i = buses.size() - 1; i >= 0; i--) {
+			Bus *bus = buses[i];
+			if (bus->bypass)
+				continue;
+
+			for (int j = 0; j < bus->effects.size(); j++) {
+				if (!bus->effects[j].enabled)
+					continue;
+
+				values.push_back(String(bus->name) + bus->effects[j].effect->get_name());
+				values.push_back(USEC_TO_SEC(bus->effects[j].prof_time));
+
+				// Substract the effect time from the driver and server times
+				if (driver_time > bus->effects[j].prof_time)
+					driver_time -= bus->effects[j].prof_time;
+				if (server_time > bus->effects[j].prof_time)
+					server_time -= bus->effects[j].prof_time;
+			}
+		}
+
+		values.push_back("audio_server");
+		values.push_back(USEC_TO_SEC(server_time));
+		values.push_back("audio_driver");
+		values.push_back(USEC_TO_SEC(driver_time));
+
+		ScriptDebugger::get_singleton()->add_profiling_frame_data("audio_thread", values);
+	}
+
+	// Reset profiling times
+	for (int i = buses.size() - 1; i >= 0; i--) {
+		Bus *bus = buses[i];
+		if (bus->bypass)
+			continue;
+
+		for (int j = 0; j < bus->effects.size(); j++) {
+			if (!bus->effects[j].enabled)
+				continue;
+
+			bus->effects[j].prof_time = 0;
+		}
+	}
+
+	AudioDriver::get_singleton()->reset_profiling_time();
+	prof_time = 0;
+#endif
+}
+
 void AudioServer::load_default_bus_layout() {
 
 	if (FileAccess::exists("res://default_bus_layout.tres")) {
@@ -1187,6 +1272,9 @@ AudioServer::AudioServer() {
 	to_mix = 0;
 	output_latency = 0;
 	output_latency_ticks = 0;
+#ifdef DEBUG_ENABLED
+	prof_time = 0;
+#endif
 }
 
 AudioServer::~AudioServer() {
diff --git a/servers/audio_server.h b/servers/audio_server.h
index f928acc7b5..258fd1d9b0 100644
--- a/servers/audio_server.h
+++ b/servers/audio_server.h
@@ -33,6 +33,7 @@
 
 #include "audio_frame.h"
 #include "object.h"
+#include "os/os.h"
 #include "servers/audio/audio_effect.h"
 #include "variant.h"
 
@@ -44,10 +45,23 @@ class AudioDriver {
 	uint64_t _last_mix_time;
 	uint64_t _mix_amount;
 
+#ifdef DEBUG_ENABLED
+	uint64_t prof_ticks;
+	uint64_t prof_time;
+#endif
+
 protected:
 	void audio_server_process(int p_frames, int32_t *p_buffer, bool p_update_mix_time = true);
 	void update_mix_time(int p_frames);
 
+#ifdef DEBUG_ENABLED
+	_FORCE_INLINE_ void start_counting_ticks() { prof_ticks = OS::get_singleton()->get_ticks_usec(); }
+	_FORCE_INLINE_ void stop_counting_ticks() { prof_time += OS::get_singleton()->get_ticks_usec() - prof_ticks; }
+#else
+	_FORCE_INLINE_ void start_counting_ticks() {}
+	_FORCE_INLINE_ void stop_counting_ticks() {}
+#endif
+
 public:
 	double get_mix_time() const; //useful for video -> audio sync
 
@@ -82,6 +96,11 @@ public:
 	SpeakerMode get_speaker_mode_by_total_channels(int p_channels) const;
 	int get_total_channels_by_speaker_mode(SpeakerMode) const;
 
+#ifdef DEBUG_ENABLED
+	uint64_t get_profiling_time() const { return prof_time; }
+	void reset_profiling_time() { prof_time = 0; }
+#endif
+
 	AudioDriver();
 	virtual ~AudioDriver() {}
 };
@@ -129,6 +148,9 @@ private:
 	uint32_t buffer_size;
 	uint64_t mix_count;
 	uint64_t mix_frames;
+#ifdef DEBUG_ENABLED
+	uint64_t prof_time;
+#endif
 
 	float channel_disable_threshold_db;
 	uint32_t channel_disable_frames;
@@ -166,6 +188,9 @@ private:
 		struct Effect {
 			Ref<AudioEffect> effect;
 			bool enabled;
+#ifdef DEBUG_ENABLED
+			uint64_t prof_time;
+#endif
 		};
 
 		Vector<Effect> effects;
@@ -276,6 +301,7 @@ public:
 
 	virtual void init();
 	virtual void finish();
+	virtual void update();
 	virtual void load_default_bus_layout();
 
 	/* MISC config */