From 9f6536bd0af75ea1dad3a5cbfe1c7987e5557986 Mon Sep 17 00:00:00 2001 From: Marcelo Fernandez Date: Wed, 20 Jun 2018 21:02:02 -0300 Subject: [PATCH] Add Audio Server profiling time to the profiler --- drivers/alsa/audio_driver_alsa.cpp | 80 ++++++++--------- drivers/coreaudio/audio_driver_coreaudio.cpp | 3 + .../pulseaudio/audio_driver_pulseaudio.cpp | 16 ++-- drivers/wasapi/audio_driver_wasapi.cpp | 66 +++++++------- drivers/wasapi/audio_driver_wasapi.h | 1 - main/main.cpp | 2 + servers/audio_server.cpp | 88 +++++++++++++++++++ servers/audio_server.h | 26 ++++++ 8 files changed, 198 insertions(+), 84 deletions(-) diff --git a/drivers/alsa/audio_driver_alsa.cpp b/drivers/alsa/audio_driver_alsa.cpp index 1e17e725324a..ae85ee50d187 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(); - 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; + if (thread) { + exit_thread = true; + Thread::wait_to_finish(thread); - exit_thread = true; - Thread::wait_to_finish(thread); + memdelete(thread); + thread = NULL; + + if (mutex) { + memdelete(mutex); + mutex = NULL; + } + } finish_device(); - - memdelete(thread); - if (mutex) { - memdelete(mutex); - mutex = NULL; - } - thread = NULL; -}; +} AudioDriverALSA::AudioDriverALSA() { diff --git a/drivers/coreaudio/audio_driver_coreaudio.cpp b/drivers/coreaudio/audio_driver_coreaudio.cpp index ef7858b4cadb..63af4506f355 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 0f47949b4b42..ed6af04b9ded 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 e1680601ad06..3c54c429d9fe 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) { + + ad->lock(); + ad->start_counting_ticks(); + if (ad->active) { - ad->lock(); - ad->audio_server_process(ad->buffer_frames, ad->samples_in.ptrw()); - - ad->unlock(); } 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 c97f4c288ce4..f3ee5976eb24 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 23acb60c89e4..23f2776737f9 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 69c1318a488c..ef794ac3807c 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 &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 f928acc7b5fe..258fd1d9b0f7 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 effect; bool enabled; +#ifdef DEBUG_ENABLED + uint64_t prof_time; +#endif }; Vector effects; @@ -276,6 +301,7 @@ public: virtual void init(); virtual void finish(); + virtual void update(); virtual void load_default_bus_layout(); /* MISC config */