From c9dfb183758b7220c800a2111f60d38c114ada48 Mon Sep 17 00:00:00 2001 From: mchughalex <25671999+mchughalex@users.noreply.github.com> Date: Sat, 11 Jul 2026 06:55:21 +0100 Subject: [PATCH] Audio: fix credit-pacing starvation on large device quanta (robotic/slowed audio) --- include/rex/audio/sdl/sdl_audio_driver.h | 20 ++++- src/audio/sdl/sdl_audio_driver.cpp | 104 +++++++++++++++++++++-- 2 files changed, 117 insertions(+), 7 deletions(-) diff --git a/include/rex/audio/sdl/sdl_audio_driver.h b/include/rex/audio/sdl/sdl_audio_driver.h index 2d54b44..67064f8 100644 --- a/include/rex/audio/sdl/sdl_audio_driver.h +++ b/include/rex/audio/sdl/sdl_audio_driver.h @@ -11,6 +11,7 @@ #pragma once +#include #include #include #include @@ -41,8 +42,9 @@ class SDLAudioDriver : public AudioDriver { // drains the stream faster than real time (e.g. a Bluetooth device in a // broken state) would otherwise release credits at an unbounded rate, // speeding up the guest's whole audio clock and anything paced by it (such - // as video playback). Called only from the SDL audio thread. - void ReleasePacedCredits(uint32_t new_credits); + // as video playback). Called only from the SDL audio thread. Returns the + // number of credits actually released to the guest. + uint64_t ReleasePacedCredits(uint32_t new_credits); rex::thread::Semaphore* semaphore_ = nullptr; @@ -58,6 +60,10 @@ class SDLAudioDriver : public AudioDriver { std::queue frames_queued_ = {}; std::stack frames_unused_ = {}; std::mutex frames_mutex_ = {}; + // Signaled by SubmitFrame; lets the device callback briefly wait for frames + // the guest is mixing right now instead of splicing silence when a large + // device quantum outruns the queue depth. + std::condition_variable frames_available_cv_ = {}; // Credit pacing state - only touched on the SDL audio thread. The allowance // accumulates with wall time (slightly above real time to tolerate device @@ -65,6 +71,16 @@ class SDLAudioDriver : public AudioDriver { double pace_allowance_frames_ = 4.0; uint64_t pace_last_ns_ = 0; uint64_t pace_deferred_credits_ = 0; + + // audio_stats window counters - only touched on the SDL audio thread. + uint64_t stats_window_start_ns_ = 0; + uint64_t stats_last_callback_ns_ = 0; + uint64_t stats_max_callback_gap_ns_ = 0; + uint32_t stats_callbacks_ = 0; + uint32_t stats_frames_ = 0; + uint32_t stats_silence_chunks_ = 0; + size_t stats_queue_min_ = SIZE_MAX; + size_t stats_queue_max_ = 0; }; } // namespace rex::audio::sdl diff --git a/src/audio/sdl/sdl_audio_driver.cpp b/src/audio/sdl/sdl_audio_driver.cpp index 72c32c4..bf462b8 100644 --- a/src/audio/sdl/sdl_audio_driver.cpp +++ b/src/audio/sdl/sdl_audio_driver.cpp @@ -35,6 +35,13 @@ REXCVAR_DEFINE_BOOL(audio_realtime_credit_pacing, true, "Audio", "times too fast.") .lifecycle(rex::cvar::Lifecycle::kHotReload); +REXCVAR_DEFINE_BOOL(audio_stats, false, "Audio", + "Log a 5-second audio pipeline stats line: device callback rate/gaps, " + "frames consumed vs real time, silence insertions (underruns), queue " + "depth and pacing state. Turn on when diagnosing robotic/slowed/" + "crackling audio reports.") + .lifecycle(rex::cvar::Lifecycle::kHotReload); + REXCVAR_DEFINE_INT32(audio_device_sample_frames, 0, "Audio", "Requested audio device buffer size in sample frames (0 = backend default). " "Larger values (e.g. 1024 or 2048) add latency but tolerate scheduling " @@ -161,6 +168,7 @@ void SDLAudioDriver::SubmitFrame(uint32_t frame_ptr) { frames_queued_.push(output_frame); PROFILE_BUFFER_QUEUE_DEPTH(static_cast(frames_queued_.size())); } + frames_available_cv_.notify_one(); } void SDLAudioDriver::Shutdown() { @@ -199,13 +207,52 @@ void SDLAudioDriver::SDLCallback(void* userdata, SDL_AudioStream* stream, int ad REXAPU_ERROR("SDLAudioDriver::SDLCallback failed to allocate {} samples", sample_count); return; } + const bool stats_enabled = REXCVAR_GET(audio_stats); + if (stats_enabled) { + const uint64_t now_ns = AudioNowNs(); + if (!driver->stats_window_start_ns_) { + driver->stats_window_start_ns_ = now_ns; + } + if (driver->stats_last_callback_ns_) { + driver->stats_max_callback_gap_ns_ = + std::max(driver->stats_max_callback_gap_ns_, now_ns - driver->stats_last_callback_ns_); + } + driver->stats_last_callback_ns_ = now_ns; + driver->stats_callbacks_++; + { + std::unique_lock guard(driver->frames_mutex_); + const size_t depth = driver->frames_queued_.size(); + driver->stats_queue_min_ = std::min(driver->stats_queue_min_, depth); + driver->stats_queue_max_ = std::max(driver->stats_queue_max_, depth); + } + } + // Bounded budget for waiting on frames the guest owes us: a large device + // quantum (PipeWire force-quantum / Bluetooth / HDMI sinks) can request more + // audio per callback than the credit pool depth, so the queue legitimately + // runs dry mid-request while the guest is mixing the frames we just + // credited. Waiting a few ms for those beats splicing silence. Scaled to + // half the request duration so small-buffer backends never risk their own + // deadline; only spent when credits were released this callback (an idle + // guest - loading screens, shutdown - never engages it). + const int64_t request_chunks = (int64_t(additional_amount) + len - 1) / len; + int64_t wait_budget_ns = + std::min(15000000, request_chunks * int64_t(channel_samples_) * 1000000000ll / + int64_t(frame_frequency_) / 2); // Grant credits deferred by the real-time pacer once enough time has passed. - driver->ReleasePacedCredits(0); + uint64_t credits_released = driver->ReleasePacedCredits(0); while (additional_amount > 0) { static uint32_t sdl_callback_count = 0; float* buffer = nullptr; { std::unique_lock guard(driver->frames_mutex_); + if (driver->frames_queued_.empty() && credits_released && wait_budget_ns > 0) { + const auto wait_start = std::chrono::steady_clock::now(); + driver->frames_available_cv_.wait_for(guard, std::chrono::nanoseconds(wait_budget_ns), + [&] { return !driver->frames_queued_.empty(); }); + wait_budget_ns -= std::chrono::duration_cast( + std::chrono::steady_clock::now() - wait_start) + .count(); + } if (!driver->frames_queued_.empty()) { buffer = driver->frames_queued_.front(); driver->frames_queued_.pop(); @@ -218,6 +265,9 @@ void SDLAudioDriver::SDLCallback(void* userdata, SDL_AudioStream* stream, int ad REXAPU_DEBUG("SDLCallback: no frames queued (silence)"); sdl_callback_count++; } + if (stats_enabled) { + driver->stats_silence_chunks_++; + } std::memset(data, 0, len); if (!SDL_PutAudioStreamData(stream, data, len)) { REXAPU_ERROR("SDL_PutAudioStreamData() failed while filling silence: {}", SDL_GetError()); @@ -250,18 +300,46 @@ void SDLAudioDriver::SDLCallback(void* userdata, SDL_AudioStream* stream, int ad break; } - driver->ReleasePacedCredits(1); + credits_released += driver->ReleasePacedCredits(1); + if (stats_enabled) { + driver->stats_frames_++; + } additional_amount -= len; } } + if (stats_enabled) { + const uint64_t now_ns = AudioNowNs(); + const uint64_t window_ns = now_ns - driver->stats_window_start_ns_; + if (window_ns >= 5000000000ull) { + const double window_s = double(window_ns) * 1e-9; + REXAPU_INFO( + "Audio stats ({:.1f}s): callbacks={} frames={} ({:.1f}/s, real-time={:.1f}/s) " + "silence_chunks={} queue_depth={}..{} deferred_credits={} allowance={:.1f} " + "max_callback_gap={}ms", + window_s, driver->stats_callbacks_, driver->stats_frames_, + double(driver->stats_frames_) / window_s, + double(frame_frequency_) / double(channel_samples_), driver->stats_silence_chunks_, + driver->stats_queue_min_ == SIZE_MAX ? 0 : driver->stats_queue_min_, + driver->stats_queue_max_, driver->pace_deferred_credits_, + driver->pace_allowance_frames_, driver->stats_max_callback_gap_ns_ / 1000000ull); + driver->stats_window_start_ns_ = now_ns; + driver->stats_callbacks_ = 0; + driver->stats_frames_ = 0; + driver->stats_silence_chunks_ = 0; + driver->stats_queue_min_ = SIZE_MAX; + driver->stats_queue_max_ = 0; + driver->stats_max_callback_gap_ns_ = 0; + } + } + SDL_stack_free(data); } -void SDLAudioDriver::ReleasePacedCredits(uint32_t new_credits) { +uint64_t SDLAudioDriver::ReleasePacedCredits(uint32_t new_credits) { pace_deferred_credits_ += new_credits; if (!pace_deferred_credits_) { - return; + return 0; } uint64_t releasable = pace_deferred_credits_; if (REXCVAR_GET(audio_realtime_credit_pacing)) { @@ -275,19 +353,35 @@ void SDLAudioDriver::ReleasePacedCredits(uint32_t new_credits) { (double(frame_frequency_) / double(channel_samples_)) * 1.01; } pace_last_ns_ = now_ns; - constexpr double kMaxBankedFrames = 8.0; + // The bank must cover the largest burst a HEALTHY device consumes in one + // callback cluster, or steady-state playback is throttled below real time + // (the guest audio clock slows down and the queue underruns into + // interleaved 5.3ms silence chunks - reported as "robotic"/"slowed down" + // audio). PipeWire fires the callback once per graph quantum, which + // force-quantum / Bluetooth / HDMI sinks can raise to 8192 device frames + // (~170ms = 32 guest frames); loaded low-spec machines can delay the + // audio thread similarly. 64 frames covers those with margin. Runaway + // devices are still bounded by the 1.01x real-time accrual above - the + // bank only sizes the transient catch-up burst after a stall (<=340ms of + // guest audio clock, and the release is further clamped by the credit + // pool depth). + constexpr double kMaxBankedFrames = 64.0; pace_allowance_frames_ = std::min(pace_allowance_frames_, kMaxBankedFrames); releasable = std::min(releasable, uint64_t(pace_allowance_frames_)); } if (releasable) { auto ret = semaphore_->Release(int(releasable), nullptr); assert_true(ret); + if (!ret) { + return 0; + } pace_deferred_credits_ -= releasable; pace_allowance_frames_ -= double(releasable); if (pace_allowance_frames_ < 0.0) { pace_allowance_frames_ = 0.0; } } + return releasable; } } // namespace rex::audio::sdl