Add Audio Server profiling time to the profiler

This commit is contained in:
Marcelo Fernandez 2018-06-20 21:02:02 -03:00
parent b64bf118f1
commit 9f6536bd0a
8 changed files with 198 additions and 84 deletions

View file

@ -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() {

View file

@ -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;

View file

@ -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() {

View file

@ -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;

View file

@ -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 {

View file

@ -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);

View file

@ -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() {

View file

@ -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 */