From 91933ce05ba157dc549d52ed6c00c71c457fca05 Mon Sep 17 00:00:00 2001 From: skal Date: Wed, 4 Feb 2026 19:40:40 +0100 Subject: feat: Audio playback stability, NOTE_ parsing fix, sample caching, and debug logging infrastructure MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit MILESTONE: Audio System Robustness & Debugging Core Audio Backend Optimization: - Fixed stop-and-go audio glitches caused by timing mismatch - Core Audio optimized for 44.1kHz (10ms periods), but 32kHz expected ~13.78ms - Added allowNominalSampleRateChange=TRUE to force OS-level 32kHz native - Added performanceProfile=conservative for 4096-frame buffers (128ms) - Result: Stable ~128ms callbacks, <1ms jitter, zero underruns Ring Buffer Improvements: - Increased capacity from 200ms to 400ms for tempo scaling headroom - Added comprehensive bounds checking with abort() on violations - Fixed tempo-scaled buffer fill: dt * g_tempo_scale - Buffer maintains 400ms fullness during 2.0x acceleration NOTE_ Parsing Fix & Sample Caching: - Fixed is_note_name() checking only first letter (A-G) - ASSET_KICK_1 was misidentified as A0 (27.5 Hz) - Required "NOTE_" prefix to distinguish notes from assets - Updated music.track to use NOTE_E2, NOTE_G4 format - Discovered resource exhaustion: 14 unique samples → 228 registrations - Implemented comprehensive caching in tracker_init() - Assets: loaded once from AssetManager, cached synth_id - Generated notes: created once, stored in persistent pool - Result: MAX_SPECTROGRAMS 256 → 32 (88% memory reduction) Debug Logging Infrastructure: - Created src/util/debug.h with 7 category macros (AUDIO, RING_BUFFER, TRACKER, SYNTH, 3D, ASSETS, GPU) - Added DEMO_ENABLE_DEBUG_LOGS CMake option (defines DEBUG_LOG_ALL) - Converted all diagnostic code to use category macros - Default build: macros compile to ((void)0) for zero runtime cost - Debug build: comprehensive logging for troubleshooting - Updated CONTRIBUTING.md with pre-commit policy Resource Analysis Tool: - Enhanced tracker_compiler to report pool sizes and cache potential - Analysis: 152/228 spectrograms without caching, 14 with caching - Tool generates optimization recommendations during compilation Files Changed: - CMakeLists.txt: Add DEBUG_LOG option - src/util/debug.h: New debug logging header (7 categories) - src/audio/miniaudio_backend.cc: Use DEBUG_AUDIO/DEBUG_RING_BUFFER - src/audio/ring_buffer.cc: Use DEBUG_RING_BUFFER for underruns - src/audio/tracker.cc: Implement sample caching, use DEBUG_TRACKER - src/audio/synth.cc: Use DEBUG_SYNTH for validation - src/audio/synth.h: Update MAX_SPECTROGRAMS (256→32), document caching - tools/tracker_compiler.cc: Fix is_note_name(), add resource analysis - assets/music.track: Update to use NOTE_ prefix format - doc/CONTRIBUTING.md: Add debug logging pre-commit policy - PROJECT_CONTEXT.md: Document milestone - TODO.md: Mark tasks completed Verification: - Default build: No debug output, audio plays correctly - Debug build: Comprehensive logging, audio plays correctly - Caching working: 14 unique samples cached at init - All tests passing (17/17) handoff(Claude): Audio system now stable with robust diagnostic infrastructure. Co-Authored-By: Claude Sonnet 4.5 --- src/audio/miniaudio_backend.cc | 164 ++++++++++++++++++++++++++++++++++++++++- 1 file changed, 162 insertions(+), 2 deletions(-) (limited to 'src/audio/miniaudio_backend.cc') diff --git a/src/audio/miniaudio_backend.cc b/src/audio/miniaudio_backend.cc index 9dd2b50..c2db268 100644 --- a/src/audio/miniaudio_backend.cc +++ b/src/audio/miniaudio_backend.cc @@ -5,22 +5,140 @@ #include "miniaudio_backend.h" #include "audio.h" #include "ring_buffer.h" +#include "util/debug.h" #include +#include // for abort() // Static callback for miniaudio (C API requirement) void MiniaudioBackend::audio_callback(ma_device* pDevice, void* pOutput, const void* pInput, ma_uint32 frameCount) { - (void)pDevice; (void)pInput; + +#if defined(DEBUG_LOG_AUDIO) + // Validate callback parameters + static ma_uint32 last_frameCount = 0; + static int callback_reentry = 0; + static double last_time = 0.0; + static int timing_initialized = 0; + static uint64_t total_frames_requested = 0; + static uint64_t callback_number = 0; + + callback_number++; + total_frames_requested += frameCount; + + // Track timing + struct timespec ts; + clock_gettime(CLOCK_MONOTONIC, &ts); + double now = ts.tv_sec + ts.tv_nsec / 1000000000.0; + + if (timing_initialized) { + double delta = (now - last_time) * 1000.0; // ms + double expected = ((double)frameCount / pDevice->sampleRate) * 1000.0; + double jitter = delta - expected; + + // Enhanced logging: Log first 20 callbacks in detail, then periodic summary + if (callback_number <= 20 || callback_number % 50 == 0) { + const double elapsed_by_frames = (double)total_frames_requested / pDevice->sampleRate * 1000.0; + const double elapsed_by_time = now * 1000.0; // Convert to ms + DEBUG_AUDIO("[CB#%llu] frameCount=%u, Delta=%.2fms, Expected=%.2fms, Jitter=%.2fms, " + "TotalFrames=%llu (%.1fms), TotalTime=%.1fms, Drift=%.2fms\n", + callback_number, frameCount, delta, expected, jitter, + total_frames_requested, elapsed_by_frames, elapsed_by_time, + elapsed_by_time - elapsed_by_frames); + } + + // Detect large timing anomalies (>5ms off from expected) + if (fabs(jitter) > 5.0) { + DEBUG_AUDIO("[TIMING ANOMALY] CB#%llu Delta=%.2fms, Expected=%.2fms, Jitter=%.2fms\n", + callback_number, delta, expected, jitter); + } + } + last_time = now; + timing_initialized = 1; + + // Check for re-entrant calls + if (callback_reentry > 0) { + DEBUG_AUDIO("FATAL: Callback re-entered! depth=%d\n", callback_reentry); + abort(); + } + callback_reentry++; + + // Check if frameCount changed unexpectedly + if (last_frameCount != 0 && frameCount != last_frameCount) { + DEBUG_AUDIO("WARNING: frameCount changed! was=%u, now=%u\n", + last_frameCount, frameCount); + } + last_frameCount = frameCount; + + // Validate device state + if (!pDevice || pDevice->sampleRate == 0) { + DEBUG_AUDIO("FATAL: Invalid device in callback!\n"); + abort(); + } + + // Check actual sample rate matches our expectation + if (pDevice->sampleRate != 32000) { + static int rate_warning = 0; + if (rate_warning++ == 0) { + DEBUG_AUDIO("WARNING: Device sample rate is %u, not 32000! Resampling may occur.\n", + pDevice->sampleRate); + } + } +#endif /* defined(DEBUG_LOG_AUDIO) */ + float* fOutput = (float*)pOutput; + // BOUNDS CHECK: Sanity check on frameCount + if (frameCount > 8192 || frameCount == 0) { + fprintf(stderr, "AUDIO CALLBACK ERROR: frameCount=%u (unreasonable!)\n", frameCount); + abort(); + } + // Read from ring buffer instead of calling synth directly AudioRingBuffer* ring_buffer = audio_get_ring_buffer(); if (ring_buffer != nullptr) { const int samples_to_read = (int)frameCount * 2; // Stereo - ring_buffer->read(fOutput, samples_to_read); + +#if defined(DEBUG_LOG_RING_BUFFER) + // Track buffer level and detect drops + static int min_available = 99999; + const int available = ring_buffer->available_read(); + + if (available < min_available) { + min_available = available; + DEBUG_RING_BUFFER("[BUFFER] CB#%llu NEW MIN: available=%d (%.1fms)\n", + callback_number, available, (float)available / (32000.0f * 2.0f) * 1000.0f); + } + + // Log buffer state for first 20 callbacks and periodically + if (callback_number <= 20 || callback_number % 50 == 0) { + DEBUG_RING_BUFFER("[BUFFER] CB#%llu requested=%d, available=%d (%.1fms), min=%d\n", + callback_number, samples_to_read, available, + (float)available / (32000.0f * 2.0f) * 1000.0f, min_available); + } + + // CRITICAL: Verify we have enough samples + if (available < samples_to_read) { + DEBUG_RING_BUFFER("[BUFFER UNDERRUN] CB#%llu requested=%d, available=%d, SHORT=%d\n", + callback_number, samples_to_read, available, samples_to_read - available); + } +#endif /* defined(DEBUG_LOG_RING_BUFFER) */ + + const int actually_read = ring_buffer->read(fOutput, samples_to_read); + +#if defined(DEBUG_LOG_RING_BUFFER) + if (actually_read < samples_to_read) { + DEBUG_RING_BUFFER("[PARTIAL READ] CB#%llu requested=%d, got=%d, padded=%d with silence\n", + callback_number, samples_to_read, actually_read, samples_to_read - actually_read); + } +#endif /* defined(DEBUG_LOG_RING_BUFFER) */ } + +#if defined(DEBUG_LOG_AUDIO) + // Clear reentry flag + callback_reentry--; +#endif /* defined(DEBUG_LOG_AUDIO) */ } MiniaudioBackend::MiniaudioBackend() : initialized_(false) { @@ -41,6 +159,21 @@ void MiniaudioBackend::init() { config.playback.format = ma_format_f32; config.playback.channels = 2; config.sampleRate = 32000; + + // Core Audio Backend-Specific Configuration + // Problem: Core Audio uses 10ms periods optimized for 44.1kHz, causing + // uneven callback timing (10ms/10ms/20ms) when resampling to 32kHz + // + // Solution 1: Force OS-level sample rate to 32kHz to avoid resampling + config.coreaudio.allowNominalSampleRateChange = MA_TRUE; + + // Solution 2: Use conservative performance profile for larger buffers + config.performanceProfile = ma_performance_profile_conservative; + + // Let Core Audio choose the period size based on conservative profile + config.periodSizeInFrames = 0; // 0 = let backend decide + config.periods = 0; // 0 = let backend decide based on performance profile + config.dataCallback = MiniaudioBackend::audio_callback; config.pUserData = this; @@ -49,6 +182,33 @@ void MiniaudioBackend::init() { return; } +#if defined(DEBUG_LOG_AUDIO) + // Log actual device configuration (to stderr for visibility) + DEBUG_AUDIO("\n=== MINIAUDIO DEVICE CONFIGURATION ===\n"); + DEBUG_AUDIO(" Sample rate: %u (requested: 32000)\n", device_.sampleRate); + DEBUG_AUDIO(" Channels: %u (requested: 2)\n", device_.playback.channels); + DEBUG_AUDIO(" Format: %d (requested: %d, f32=%d)\n", + device_.playback.format, config.playback.format, ma_format_f32); + DEBUG_AUDIO(" Period size: %u frames (%.1fms at %uHz)\n", + device_.playback.internalPeriodSizeInFrames, + (float)device_.playback.internalPeriodSizeInFrames / device_.sampleRate * 1000.0f, + device_.sampleRate); + DEBUG_AUDIO(" Periods: %u (buffer multiplier)\n", device_.playback.internalPeriods); + DEBUG_AUDIO(" Backend: %s\n", ma_get_backend_name(device_.pContext->backend)); + DEBUG_AUDIO(" Total buffer size: %u frames (%.2fms) [period * periods]\n", + device_.playback.internalPeriodSizeInFrames * device_.playback.internalPeriods, + (float)(device_.playback.internalPeriodSizeInFrames * device_.playback.internalPeriods) / device_.sampleRate * 1000.0f); + + // Calculate expected callback interval + if (device_.playback.internalPeriodSizeInFrames > 0) { + const float expected_callback_ms = (float)device_.playback.internalPeriodSizeInFrames / device_.sampleRate * 1000.0f; + DEBUG_AUDIO(" Expected callback interval: %.2fms (based on period size)\n", expected_callback_ms); + DEBUG_AUDIO(" WARNING: If actual callback interval differs, audio corruption may occur!\n"); + } + DEBUG_AUDIO("======================================\n\n"); + fflush(stderr); +#endif /* defined(DEBUG_LOG_AUDIO) */ + initialized_ = true; } -- cgit v1.2.3