From 3ce9b380989dc136285e83b7b7b54f13e33289a0 Mon Sep 17 00:00:00 2001 From: chenjintao Date: Tue, 11 Aug 2026 15:17:37 +0800 Subject: [PATCH] fix(multimodal): stabilize downstream audio playback - add configurable prebuffer and adaptive rebuffer for packet jitter - mute stalled output, auto-clear I2S DMA, and abort inactive playback after 3 seconds - discard stale-generation packets and add optional downstream diagnostics --- .../platform/src/multimodal/audio_pipeline.c | 46 ++ .../audio_pipeline_codec_impl.c | 3 +- .../audio_pipeline_runtime_impl.c | 611 +++++++++++++++++- main/Kconfig.projbuild | 48 ++ sdkconfig.defaults | 5 + 5 files changed, 703 insertions(+), 10 deletions(-) diff --git a/components/platform/src/multimodal/audio_pipeline.c b/components/platform/src/multimodal/audio_pipeline.c index 83a7e3c..cdfed89 100644 --- a/components/platform/src/multimodal/audio_pipeline.c +++ b/components/platform/src/multimodal/audio_pipeline.c @@ -131,6 +131,26 @@ #define CONFIG_MULTIMODAL_AUDIO_DOWNSTREAM_IDLE_MUTE_MS 250 #endif +#ifndef CONFIG_MULTIMODAL_AUDIO_DOWNSTREAM_ACTIVE_STALL_MUTE_MS +#define CONFIG_MULTIMODAL_AUDIO_DOWNSTREAM_ACTIVE_STALL_MUTE_MS 3000 +#endif + +#ifndef CONFIG_MULTIMODAL_AUDIO_DOWNSTREAM_PREBUFFER_MS +#define CONFIG_MULTIMODAL_AUDIO_DOWNSTREAM_PREBUFFER_MS 160 +#endif + +#ifndef CONFIG_MULTIMODAL_AUDIO_DOWNSTREAM_REBUFFER_GAP_MS +#define CONFIG_MULTIMODAL_AUDIO_DOWNSTREAM_REBUFFER_GAP_MS 120 +#endif + +#ifndef CONFIG_MULTIMODAL_AUDIO_DOWNSTREAM_MAX_REBUFFER_MS +#define CONFIG_MULTIMODAL_AUDIO_DOWNSTREAM_MAX_REBUFFER_MS 640 +#endif + +#ifndef CONFIG_MULTIMODAL_AUDIO_DOWNSTREAM_DIAGNOSTICS_ENABLE +#define CONFIG_MULTIMODAL_AUDIO_DOWNSTREAM_DIAGNOSTICS_ENABLE 0 +#endif + #ifndef CONFIG_MULTIMODAL_AUDIO_DOWNSTREAM_PLAYBACK_TASK_STACK #define CONFIG_MULTIMODAL_AUDIO_DOWNSTREAM_PLAYBACK_TASK_STACK 12288 #endif @@ -304,6 +324,8 @@ typedef struct { bool downstream_output_primed; bool downstream_response_active; bool downstream_response_end_received; + TickType_t downstream_last_audio_tick; + TickType_t downstream_last_response_activity_tick; esp_timer_handle_t downstream_idle_mute_timer; QueueHandle_t downstream_playback_queue; bool downstream_playback_queue_with_caps; @@ -347,6 +369,29 @@ static uint32_t s_downstream_overflow_count; static TickType_t s_downstream_overflow_last_log_tick; static uint32_t s_downstream_queued_packet_total; static uint32_t s_downstream_played_packet_total; +#if CONFIG_MULTIMODAL_AUDIO_DOWNSTREAM_DIAGNOSTICS_ENABLE +typedef struct { + TickType_t response_begin_tick; + TickType_t arrival_last_tick; + TickType_t first_arrival_tick; + TickType_t first_playback_tick; + TickType_t last_playback_tick; + TickType_t queue_empty_since_tick; + uint32_t arrival_gap_min_ms; + uint32_t arrival_gap_max_ms; + uint64_t arrival_gap_total_ms; + uint32_t arrival_gap_samples; + UBaseType_t queue_depth_min; + UBaseType_t queue_depth_max; + uint32_t queue_empty_events; + uint32_t queue_empty_max_ms; + uint32_t enqueue_failures; + uint32_t playback_failures; + bool summary_logged; +} downstream_diagnostics_t; + +static downstream_diagnostics_t s_downstream_diagnostics; +#endif static SemaphoreHandle_t s_downstream_playback_queue_mutex; static bool s_downstream_playback_queue_mutex_initializing; #if ( configSUPPORT_STATIC_ALLOCATION == 1 ) @@ -360,6 +405,7 @@ typedef struct { typedef struct { size_t len; + uint32_t playback_generation; uint8_t *data; } downstream_packet_t; diff --git a/components/platform/src/multimodal/audio_pipeline/audio_pipeline_codec_impl.c b/components/platform/src/multimodal/audio_pipeline/audio_pipeline_codec_impl.c index 430f1f8..bd324fe 100644 --- a/components/platform/src/multimodal/audio_pipeline/audio_pipeline_codec_impl.c +++ b/components/platform/src/multimodal/audio_pipeline/audio_pipeline_codec_impl.c @@ -197,6 +197,7 @@ static esp_err_t init_i2s_bus(multimodal_audio_ctx_t *ctx) (i2s_port_t)CONFIG_MULTIMODAL_AUDIO_I2S_PORT, I2S_ROLE_MASTER); chan_cfg.dma_desc_num = CONFIG_MULTIMODAL_AUDIO_I2S_DMA_DESC_NUM; chan_cfg.dma_frame_num = CONFIG_MULTIMODAL_AUDIO_I2S_DMA_FRAME_NUM; + chan_cfg.auto_clear_after_cb = true; esp_err_t err = i2s_new_channel(&chan_cfg, &ctx->tx_handle, &ctx->rx_handle); if (err != ESP_OK) { ESP_LOGE(TAG, "Create I2S channels failed: %s", esp_err_to_name(err)); @@ -247,7 +248,7 @@ static esp_err_t init_i2s_bus(multimodal_audio_ctx_t *ctx) } ESP_LOGI(TAG, - "I2S ready: port=%d mclk=%d bclk=%d ws=%d dout=%d din=%d use_mclk=%d dma(desc=%d frame=%d)", + "I2S ready: port=%d mclk=%d bclk=%d ws=%d dout=%d din=%d use_mclk=%d dma(desc=%d frame=%d auto_clear=1)", CONFIG_MULTIMODAL_AUDIO_I2S_PORT, CONFIG_MULTIMODAL_AUDIO_I2S_MCLK_GPIO, CONFIG_MULTIMODAL_AUDIO_I2S_BCLK_GPIO, diff --git a/components/platform/src/multimodal/audio_pipeline/audio_pipeline_runtime_impl.c b/components/platform/src/multimodal/audio_pipeline/audio_pipeline_runtime_impl.c index 9282a44..c359902 100644 --- a/components/platform/src/multimodal/audio_pipeline/audio_pipeline_runtime_impl.c +++ b/components/platform/src/multimodal/audio_pipeline/audio_pipeline_runtime_impl.c @@ -425,6 +425,16 @@ static void drain_downstream_playback_queue(multimodal_audio_ctx_t *ctx) unlock_downstream_playback_queue(); } +static void drain_downstream_playback_queue_now(multimodal_audio_ctx_t *ctx) +{ + if (ctx == NULL || !lock_downstream_playback_queue(0)) { + return; + } + QueueHandle_t queue = ctx->downstream_playback_queue; + drain_downstream_playback_queue_handle(queue); + unlock_downstream_playback_queue(); +} + static void track_uplink_packet_queued(size_t len) { #if CONFIG_MULTIMODAL_AUDIO_LOG_UPLINK_LEVELS @@ -545,6 +555,270 @@ static esp_err_t stop_downstream_idle_mute_task(multimodal_audio_ctx_t *ctx, int #define MULTIMODAL_AUDIO_DOWNSTREAM_STATS_INTERVAL 200U #define MULTIMODAL_AUDIO_DOWNSTREAM_BACKLOG_WARN_MS 5000U +#define MULTIMODAL_AUDIO_DOWNSTREAM_DIAGNOSTICS_ACTIVE_INTERVAL_MS 1000U + +#if CONFIG_MULTIMODAL_AUDIO_DOWNSTREAM_DIAGNOSTICS_ENABLE +static void reset_downstream_diagnostics(void) +{ + TickType_t now = xTaskGetTickCount(); + + portENTER_CRITICAL(&s_audio_runtime_lock); + memset(&s_downstream_diagnostics, 0, sizeof(s_downstream_diagnostics)); + s_downstream_diagnostics.response_begin_tick = now; + s_downstream_diagnostics.arrival_gap_min_ms = UINT32_MAX; + s_downstream_diagnostics.queue_depth_min = UINT32_MAX; + portEXIT_CRITICAL(&s_audio_runtime_lock); +} + +static void note_downstream_arrival(UBaseType_t queue_depth) +{ + TickType_t now = xTaskGetTickCount(); + bool first_arrival = false; + uint32_t first_arrival_ms = 0U; + + portENTER_CRITICAL(&s_audio_runtime_lock); + TickType_t previous = s_downstream_diagnostics.arrival_last_tick; + if (s_downstream_diagnostics.first_arrival_tick == 0U) { + s_downstream_diagnostics.first_arrival_tick = now; + first_arrival = true; + first_arrival_ms = (uint32_t)pdTICKS_TO_MS( + now - s_downstream_diagnostics.response_begin_tick); + } + s_downstream_diagnostics.arrival_last_tick = now; + if (previous != 0U) { + uint32_t gap_ms = (uint32_t)pdTICKS_TO_MS(now - previous); + if (gap_ms < s_downstream_diagnostics.arrival_gap_min_ms) { + s_downstream_diagnostics.arrival_gap_min_ms = gap_ms; + } + if (gap_ms > s_downstream_diagnostics.arrival_gap_max_ms) { + s_downstream_diagnostics.arrival_gap_max_ms = gap_ms; + } + s_downstream_diagnostics.arrival_gap_total_ms += gap_ms; + s_downstream_diagnostics.arrival_gap_samples++; + } + if (queue_depth < s_downstream_diagnostics.queue_depth_min) { + s_downstream_diagnostics.queue_depth_min = queue_depth; + } + if (queue_depth > s_downstream_diagnostics.queue_depth_max) { + s_downstream_diagnostics.queue_depth_max = queue_depth; + } + portEXIT_CRITICAL(&s_audio_runtime_lock); + + if (first_arrival) { + ESP_LOGI(TAG, + "Downstream diagnostics first packet: wait_ms=%u queue_depth=%u", + (unsigned)first_arrival_ms, + (unsigned)queue_depth); + } +} + +static void note_downstream_playback(void) +{ + TickType_t now = xTaskGetTickCount(); + bool first_playback = false; + uint32_t first_playback_ms = 0U; + + portENTER_CRITICAL(&s_audio_runtime_lock); + if (s_downstream_diagnostics.first_playback_tick == 0U) { + s_downstream_diagnostics.first_playback_tick = now; + first_playback = true; + first_playback_ms = (uint32_t)pdTICKS_TO_MS( + now - s_downstream_diagnostics.response_begin_tick); + } + s_downstream_diagnostics.last_playback_tick = now; + portEXIT_CRITICAL(&s_audio_runtime_lock); + + if (first_playback) { + ESP_LOGI(TAG, + "Downstream diagnostics first playback: wait_ms=%u", + (unsigned)first_playback_ms); + } +} + +static void note_downstream_queue_empty(void) +{ + TickType_t now = xTaskGetTickCount(); + + portENTER_CRITICAL(&s_audio_runtime_lock); + if (s_downstream_diagnostics.queue_empty_since_tick == 0U) { + s_downstream_diagnostics.queue_empty_since_tick = now; + } + portEXIT_CRITICAL(&s_audio_runtime_lock); +} + +static void note_downstream_queue_recovered(void) +{ + TickType_t now = xTaskGetTickCount(); + uint32_t empty_ms = 0U; + + portENTER_CRITICAL(&s_audio_runtime_lock); + TickType_t empty_since = s_downstream_diagnostics.queue_empty_since_tick; + if (empty_since != 0U) { + empty_ms = (uint32_t)pdTICKS_TO_MS(now - empty_since); + s_downstream_diagnostics.queue_empty_since_tick = 0U; + s_downstream_diagnostics.queue_empty_events++; + if (empty_ms > s_downstream_diagnostics.queue_empty_max_ms) { + s_downstream_diagnostics.queue_empty_max_ms = empty_ms; + } + } + portEXIT_CRITICAL(&s_audio_runtime_lock); + + if (empty_ms >= s_audio.opus_frame_duration_ms) { + ESP_LOGW(TAG, + "Downstream diagnostics: queue recovered after %u ms empty", + (unsigned)empty_ms); + } +} + +static void note_downstream_enqueue_failure(void) +{ + portENTER_CRITICAL(&s_audio_runtime_lock); + s_downstream_diagnostics.enqueue_failures++; + portEXIT_CRITICAL(&s_audio_runtime_lock); +} + +static void note_downstream_playback_failure(void) +{ + portENTER_CRITICAL(&s_audio_runtime_lock); + s_downstream_diagnostics.playback_failures++; + portEXIT_CRITICAL(&s_audio_runtime_lock); +} + +static void log_downstream_diagnostics(const char *phase, bool final_summary) +{ + downstream_diagnostics_t snapshot = {0}; + TickType_t now = xTaskGetTickCount(); + + portENTER_CRITICAL(&s_audio_runtime_lock); + if (final_summary && s_downstream_diagnostics.summary_logged) { + portEXIT_CRITICAL(&s_audio_runtime_lock); + return; + } + if (final_summary) { + s_downstream_diagnostics.summary_logged = true; + } + snapshot = s_downstream_diagnostics; + portEXIT_CRITICAL(&s_audio_runtime_lock); + + uint32_t gap_min_ms = snapshot.arrival_gap_samples > 0U ? + snapshot.arrival_gap_min_ms : 0U; + uint32_t gap_avg_ms = snapshot.arrival_gap_samples > 0U ? + (uint32_t)(snapshot.arrival_gap_total_ms / snapshot.arrival_gap_samples) : 0U; + UBaseType_t depth_min = snapshot.queue_depth_min != UINT32_MAX ? + snapshot.queue_depth_min : 0U; + uint32_t response_age_ms = snapshot.response_begin_tick != 0U ? + (uint32_t)pdTICKS_TO_MS(now - snapshot.response_begin_tick) : 0U; + uint32_t first_arrival_ms = snapshot.first_arrival_tick != 0U ? + (uint32_t)pdTICKS_TO_MS(snapshot.first_arrival_tick - snapshot.response_begin_tick) : 0U; + uint32_t last_arrival_age_ms = snapshot.arrival_last_tick != 0U ? + (uint32_t)pdTICKS_TO_MS(now - snapshot.arrival_last_tick) : 0U; + uint32_t first_playback_ms = snapshot.first_playback_tick != 0U ? + (uint32_t)pdTICKS_TO_MS(snapshot.first_playback_tick - snapshot.response_begin_tick) : 0U; + uint32_t last_playback_age_ms = snapshot.last_playback_tick != 0U ? + (uint32_t)pdTICKS_TO_MS(now - snapshot.last_playback_tick) : 0U; + UBaseType_t current_depth = 0U; + if (lock_downstream_playback_queue(pdMS_TO_TICKS(20))) { + QueueHandle_t queue = s_audio.downstream_playback_queue; + if (queue != NULL) { + current_depth = uxQueueMessagesWaiting(queue); + } + unlock_downstream_playback_queue(); + } + + ESP_LOGI(TAG, + "Downstream diagnostics %s: response_age_ms=%u first_packet=%d first_packet_ms=%u last_packet_age_ms=%u first_playback=%d first_playback_ms=%u last_playback_age_ms=%u queued=%u played=%u current_depth=%u depth_min=%u depth_max=%u arrival_gap_ms(min/avg/max)=%u/%u/%u empty_events=%u empty_max_ms=%u enqueue_failures=%u playback_failures=%u", + phase != NULL ? phase : "snapshot", + (unsigned)response_age_ms, + snapshot.first_arrival_tick != 0U ? 1 : 0, + (unsigned)first_arrival_ms, + (unsigned)last_arrival_age_ms, + snapshot.first_playback_tick != 0U ? 1 : 0, + (unsigned)first_playback_ms, + (unsigned)last_playback_age_ms, + (unsigned)s_downstream_queued_packet_total, + (unsigned)s_downstream_played_packet_total, + (unsigned)current_depth, + (unsigned)depth_min, + (unsigned)snapshot.queue_depth_max, + (unsigned)gap_min_ms, + (unsigned)gap_avg_ms, + (unsigned)snapshot.arrival_gap_max_ms, + (unsigned)snapshot.queue_empty_events, + (unsigned)snapshot.queue_empty_max_ms, + (unsigned)snapshot.enqueue_failures, + (unsigned)snapshot.playback_failures); +} + +static void log_downstream_active_diagnostics(void) +{ + downstream_diagnostics_t snapshot = {0}; + TickType_t now = xTaskGetTickCount(); + + portENTER_CRITICAL(&s_audio_runtime_lock); + snapshot = s_downstream_diagnostics; + portEXIT_CRITICAL(&s_audio_runtime_lock); + + uint32_t response_age_ms = snapshot.response_begin_tick != 0U ? + (uint32_t)pdTICKS_TO_MS(now - snapshot.response_begin_tick) : 0U; + uint32_t last_packet_age_ms = snapshot.arrival_last_tick != 0U ? + (uint32_t)pdTICKS_TO_MS(now - snapshot.arrival_last_tick) : 0U; + uint32_t last_playback_age_ms = snapshot.last_playback_tick != 0U ? + (uint32_t)pdTICKS_TO_MS(now - snapshot.last_playback_tick) : 0U; + uint32_t queued = s_downstream_queued_packet_total; + uint32_t played = s_downstream_played_packet_total; + uint32_t pending_estimate = queued > played ? queued - played : 0U; + + ESP_LOGW(TAG, + "Downstream diagnostics active_wait: response_age_ms=%u first_packet=%d last_packet_age_ms=%u first_playback=%d last_playback_age_ms=%u queued=%u played=%u pending_estimate=%u enqueue_failures=%u playback_failures=%u", + (unsigned)response_age_ms, + snapshot.first_arrival_tick != 0U ? 1 : 0, + (unsigned)last_packet_age_ms, + snapshot.first_playback_tick != 0U ? 1 : 0, + (unsigned)last_playback_age_ms, + (unsigned)queued, + (unsigned)played, + (unsigned)pending_estimate, + (unsigned)snapshot.enqueue_failures, + (unsigned)snapshot.playback_failures); +} + +static void arm_downstream_active_diagnostics(multimodal_audio_ctx_t *ctx) +{ + esp_timer_handle_t timer = audio_get_downstream_idle_mute_timer(ctx); + if (timer == NULL) { + return; + } + (void)esp_timer_stop(timer); + (void)esp_timer_start_once( + timer, + (uint64_t)MULTIMODAL_AUDIO_DOWNSTREAM_DIAGNOSTICS_ACTIVE_INTERVAL_MS * 1000ULL); +} +#else +static inline void reset_downstream_diagnostics(void) {} +static inline void note_downstream_arrival(UBaseType_t queue_depth) { (void)queue_depth; } +static inline void note_downstream_playback(void) {} +static inline void note_downstream_queue_empty(void) {} +static inline void note_downstream_queue_recovered(void) {} +static inline void note_downstream_enqueue_failure(void) {} +static inline void note_downstream_playback_failure(void) {} +static inline void log_downstream_diagnostics(const char *phase, bool final_summary) +{ + (void)phase; + (void)final_summary; +} +static inline void log_downstream_active_diagnostics(void) {} +static inline void arm_downstream_active_diagnostics(multimodal_audio_ctx_t *ctx) +{ + esp_timer_handle_t timer = audio_get_downstream_idle_mute_timer(ctx); + if (timer == NULL) { + return; + } + (void)esp_timer_stop(timer); + (void)esp_timer_start_once( + timer, + (uint64_t)CONFIG_MULTIMODAL_AUDIO_DOWNSTREAM_ACTIVE_STALL_MUTE_MS * 1000ULL); +} +#endif static void log_downstream_pcm_stats(uint32_t played, size_t opus_len, @@ -1378,6 +1652,50 @@ static bool snapshot_downstream_response_active(void) return active; } +static TickType_t snapshot_downstream_last_audio_tick(const multimodal_audio_ctx_t *ctx) +{ + TickType_t tick = 0; + portENTER_CRITICAL(&s_audio_runtime_lock); + if (ctx != NULL) { + tick = ctx->downstream_last_audio_tick; + } + portEXIT_CRITICAL(&s_audio_runtime_lock); + return tick; +} + +static TickType_t snapshot_downstream_last_response_activity_tick( + const multimodal_audio_ctx_t *ctx) +{ + TickType_t tick = 0; + portENTER_CRITICAL(&s_audio_runtime_lock); + if (ctx != NULL) { + tick = ctx->downstream_last_response_activity_tick; + } + portEXIT_CRITICAL(&s_audio_runtime_lock); + return tick; +} + +static void update_downstream_last_audio_tick(multimodal_audio_ctx_t *ctx, + TickType_t tick) +{ + portENTER_CRITICAL(&s_audio_runtime_lock); + if (ctx != NULL) { + ctx->downstream_last_audio_tick = tick; + ctx->downstream_last_response_activity_tick = tick; + } + portEXIT_CRITICAL(&s_audio_runtime_lock); +} + +static void update_downstream_response_activity_tick(multimodal_audio_ctx_t *ctx, + TickType_t tick) +{ + portENTER_CRITICAL(&s_audio_runtime_lock); + if (ctx != NULL && ctx->downstream_response_active) { + ctx->downstream_last_response_activity_tick = tick; + } + portEXIT_CRITICAL(&s_audio_runtime_lock); +} + static void update_downstream_response_state(bool active, bool end_received) { portENTER_CRITICAL(&s_audio_runtime_lock); @@ -1391,6 +1709,24 @@ static void notify_downstream_playback_stopped(void) notify_downstream_playback_finished(MULTIMODAL_AUDIO_DOWNSTREAM_PLAYBACK_STOPPED); } +static void abort_downstream_response_after_active_stall(multimodal_audio_ctx_t *ctx, + uint32_t idle_ms) +{ + ESP_LOGW(TAG, + "Downstream protection watchdog: abort stalled response idle_ms=%u", + (unsigned)idle_ms); + (void)advance_downstream_playback_generation(); + notify_downstream_playback_stopped(); + update_downstream_response_state(false, false); + if (audio_get_downstream_playback_task(ctx) != NULL || + audio_get_downstream_playback_starting(ctx)) { + audio_set_downstream_playback_stopping(ctx, true); + audio_set_downstream_playback_keep_stopping_on_exit(ctx, false); + audio_set_downstream_playback_stop_requested(ctx, true); + } + drain_downstream_playback_queue_now(ctx); +} + static void maybe_notify_downstream_playback_completed_after_drain(const char *reason) { if (!snapshot_downstream_response_end_received()) { @@ -1413,6 +1749,7 @@ static void maybe_notify_downstream_playback_completed_after_drain(const char *r ESP_LOGI(TAG, "Downstream playback completed after response end (%s)", reason ? reason : "drained"); + log_downstream_diagnostics("playback_complete", true); notify_downstream_playback_completed(); update_downstream_response_state(false, false); } @@ -1456,10 +1793,111 @@ static uint32_t get_downstream_idle_mute_timeout_ms(void) return timeout_ms; } +static uint32_t get_downstream_active_stall_mute_timeout_ms(void) +{ + uint32_t timeout_ms = + (uint32_t)CONFIG_MULTIMODAL_AUDIO_DOWNSTREAM_ACTIVE_STALL_MUTE_MS; + uint32_t idle_timeout_ms = get_downstream_idle_mute_timeout_ms(); + return timeout_ms < idle_timeout_ms ? idle_timeout_ms : timeout_ms; +} + +static UBaseType_t get_downstream_prebuffer_packet_count( + const multimodal_audio_ctx_t *ctx) +{ + uint32_t frame_ms = ctx != NULL && ctx->opus_frame_duration_ms != 0U ? + ctx->opus_frame_duration_ms : 20U; + uint32_t packet_count = + ((uint32_t)CONFIG_MULTIMODAL_AUDIO_DOWNSTREAM_PREBUFFER_MS + frame_ms - 1U) / + frame_ms; + if (packet_count == 0U) { + packet_count = 1U; + } + UBaseType_t queue_len = get_downstream_playback_queue_len(); + return packet_count > (uint32_t)queue_len ? queue_len : (UBaseType_t)packet_count; +} + +static UBaseType_t get_downstream_recovery_packet_count( + const multimodal_audio_ctx_t *ctx, + uint32_t underrun_count) +{ + uint32_t frame_ms = ctx != NULL && ctx->opus_frame_duration_ms != 0U ? + ctx->opus_frame_duration_ms : 20U; + uint32_t base_ms = (uint32_t)CONFIG_MULTIMODAL_AUDIO_DOWNSTREAM_PREBUFFER_MS; + if (base_ms < frame_ms) { + base_ms = frame_ms; + } + uint32_t max_ms = (uint32_t)CONFIG_MULTIMODAL_AUDIO_DOWNSTREAM_MAX_REBUFFER_MS; + if (max_ms < base_ms) { + max_ms = base_ms; + } + uint64_t scaled_ms = (uint64_t)base_ms * ((uint64_t)underrun_count + 1ULL); + uint32_t recovery_ms = scaled_ms > max_ms ? max_ms : (uint32_t)scaled_ms; + uint32_t packet_count = (recovery_ms + frame_ms - 1U) / frame_ms; + UBaseType_t queue_len = get_downstream_playback_queue_len(); + return packet_count > (uint32_t)queue_len ? queue_len : (UBaseType_t)packet_count; +} + +static uint32_t get_downstream_rebuffer_gap_ms(const multimodal_audio_ctx_t *ctx) +{ + uint32_t frame_ms = ctx != NULL && ctx->opus_frame_duration_ms != 0U ? + ctx->opus_frame_duration_ms : 20U; + uint32_t gap_ms = (uint32_t)CONFIG_MULTIMODAL_AUDIO_DOWNSTREAM_REBUFFER_GAP_MS; + return gap_ms < frame_ms ? frame_ms : gap_ms; +} + +static void restart_downstream_idle_mute_timer(multimodal_audio_ctx_t *ctx, + uint32_t timeout_ms) +{ + esp_timer_handle_t timer = audio_get_downstream_idle_mute_timer(ctx); + if (timer == NULL) { + return; + } + (void)esp_timer_stop(timer); + (void)esp_timer_start_once(timer, (uint64_t)(timeout_ms == 0U ? 1U : timeout_ms) * 1000ULL); +} + static void downstream_idle_mute_timer_cb(void *arg) { multimodal_audio_ctx_t *ctx = (multimodal_audio_ctx_t *)arg; - if (ctx == NULL || snapshot_downstream_response_active()) { + if (ctx == NULL) { + return; + } + + const bool response_active = snapshot_downstream_response_active(); + if (response_active) { + log_downstream_active_diagnostics(); + TickType_t now = xTaskGetTickCount(); + TickType_t last_audio_tick = snapshot_downstream_last_audio_tick(ctx); + uint32_t idle_ms = last_audio_tick != 0U ? + (uint32_t)pdTICKS_TO_MS(now - last_audio_tick) : 0U; + uint32_t idle_timeout_ms = get_downstream_idle_mute_timeout_ms(); + uint32_t stall_timeout_ms = get_downstream_active_stall_mute_timeout_ms(); + if (idle_ms < idle_timeout_ms) { + restart_downstream_idle_mute_timer(ctx, idle_timeout_ms - idle_ms); + return; + } + if (ctx->initialized && ctx->codec_dev != NULL) { + (void)set_downstream_output_mute_if_needed(ctx, true, "Active response gap"); + } + if (idle_ms < stall_timeout_ms) { + uint32_t remaining_ms = stall_timeout_ms - idle_ms; +#if CONFIG_MULTIMODAL_AUDIO_DOWNSTREAM_DIAGNOSTICS_ENABLE + if (remaining_ms > MULTIMODAL_AUDIO_DOWNSTREAM_DIAGNOSTICS_ACTIVE_INTERVAL_MS) { + remaining_ms = MULTIMODAL_AUDIO_DOWNSTREAM_DIAGNOSTICS_ACTIVE_INTERVAL_MS; + } +#endif + restart_downstream_idle_mute_timer(ctx, remaining_ms); + return; + } + + TickType_t last_activity_tick = snapshot_downstream_last_response_activity_tick(ctx); + uint32_t response_idle_ms = last_activity_tick != 0U ? + (uint32_t)pdTICKS_TO_MS(now - last_activity_tick) : idle_ms; + if (response_idle_ms < stall_timeout_ms) { + restart_downstream_idle_mute_timer(ctx, stall_timeout_ms - response_idle_ms); + return; + } + abort_downstream_response_after_active_stall(ctx, idle_ms); return; } @@ -1504,13 +1942,11 @@ static esp_err_t ensure_downstream_idle_mute_task(multimodal_audio_ctx_t *ctx) static void notify_downstream_audio_active(multimodal_audio_ctx_t *ctx) { - esp_timer_handle_t timer = audio_get_downstream_idle_mute_timer(ctx); - if (ctx == NULL || timer == NULL) { + if (ctx == NULL) { return; } - - (void)esp_timer_stop(timer); - (void)esp_timer_start_once(timer, (uint64_t)get_downstream_idle_mute_timeout_ms() * 1000ULL); + update_downstream_last_audio_tick(ctx, xTaskGetTickCount()); + restart_downstream_idle_mute_timer(ctx, get_downstream_idle_mute_timeout_ms()); } static esp_err_t ensure_downstream_tx_bounce_buffer(multimodal_audio_ctx_t *ctx) @@ -1678,29 +2114,167 @@ static void downstream_playback_task(void *arg) (unsigned)get_downstream_playback_max_packet_bytes()); downstream_packet_t packet = {0}; + uint32_t buffered_generation = UINT32_MAX; + TickType_t buffer_wait_since = 0U; + TickType_t queue_empty_since = 0U; + TickType_t underrun_since = 0U; + TickType_t first_recovery_packet_tick = 0U; + bool playback_buffer_ready = false; + bool generation_started = false; + uint32_t recovery_underrun_count = 0U; while (!audio_get_downstream_playback_stop_requested(ctx)) { BaseType_t received = pdFALSE; + QueueHandle_t queue = NULL; if (lock_downstream_playback_queue(pdMS_TO_TICKS(20))) { - QueueHandle_t queue = ctx->downstream_playback_queue; + queue = ctx->downstream_playback_queue; unlock_downstream_playback_queue(); - if (queue != NULL) { - received = xQueueReceive(queue, &packet, pdMS_TO_TICKS(20)); + } + + uint32_t current_generation = snapshot_downstream_playback_generation(); + if (current_generation != buffered_generation) { + buffered_generation = current_generation; + buffer_wait_since = xTaskGetTickCount(); + queue_empty_since = 0U; + underrun_since = 0U; + first_recovery_packet_tick = 0U; + playback_buffer_ready = false; + generation_started = false; + recovery_underrun_count = 0U; + } + + if (queue != NULL && !playback_buffer_ready) { + UBaseType_t queued_packets = uxQueueMessagesWaiting(queue); + UBaseType_t target_packets = generation_started ? + get_downstream_recovery_packet_count(ctx, recovery_underrun_count) : + get_downstream_prebuffer_packet_count(ctx); + TickType_t now = xTaskGetTickCount(); + if (generation_started && queued_packets > 0U && first_recovery_packet_tick == 0U) { + first_recovery_packet_tick = now; + } + bool response_ended = snapshot_downstream_response_end_received(); + if (queued_packets >= target_packets || (response_ended && queued_packets > 0U)) { + playback_buffer_ready = true; + uint32_t buffered_ms = (uint32_t)queued_packets * ctx->opus_frame_duration_ms; + uint32_t waited_ms = buffer_wait_since != 0U ? + (uint32_t)pdTICKS_TO_MS(now - buffer_wait_since) : 0U; + if (generation_started) { + uint32_t outage_ms = underrun_since != 0U ? + (uint32_t)pdTICKS_TO_MS(now - underrun_since) : waited_ms; +#if CONFIG_MULTIMODAL_AUDIO_DOWNSTREAM_DIAGNOSTICS_ENABLE + uint32_t first_packet_wait_ms = + underrun_since != 0U && first_recovery_packet_tick != 0U ? + (uint32_t)pdTICKS_TO_MS( + first_recovery_packet_tick - underrun_since) : 0U; + uint32_t held_after_first_packet_ms = first_recovery_packet_tick != 0U ? + (uint32_t)pdTICKS_TO_MS(now - first_recovery_packet_tick) : 0U; +#endif + ESP_LOGI(TAG, + "Downstream recovery buffer ready: depth=%u target=%u buffered_ms=%u waited_ms=%u outage_ms=%u", + (unsigned)queued_packets, + (unsigned)target_packets, + (unsigned)buffered_ms, + (unsigned)waited_ms, + (unsigned)outage_ms); +#if CONFIG_MULTIMODAL_AUDIO_DOWNSTREAM_DIAGNOSTICS_ENABLE + ESP_LOGW(TAG, + "Downstream protection evidence: underrun=%u outage_ms=%u first_packet_wait_ms=%u held_after_first_packet_ms=%u buffered_ms=%u legacy_would_resume_at_first_packet=1", + (unsigned)recovery_underrun_count, + (unsigned)outage_ms, + (unsigned)first_packet_wait_ms, + (unsigned)held_after_first_packet_ms, + (unsigned)buffered_ms); +#endif + note_downstream_queue_recovered(); + } else { + ESP_LOGI(TAG, + "Downstream initial buffer ready: depth=%u target=%u buffered_ms=%u waited_ms=%u", + (unsigned)queued_packets, + (unsigned)target_packets, + (unsigned)buffered_ms, + (unsigned)waited_ms); +#if CONFIG_MULTIMODAL_AUDIO_DOWNSTREAM_DIAGNOSTICS_ENABLE + ESP_LOGI(TAG, + "Downstream protection evidence: initial_wait_ms=%u buffered_ms=%u first_audio_jitter_budget_ms=%u", + (unsigned)waited_ms, + (unsigned)buffered_ms, + (unsigned)buffered_ms); +#endif + } } } + + if (queue != NULL && playback_buffer_ready) { + received = xQueueReceive(queue, &packet, pdMS_TO_TICKS(20)); + } + + /* The response can change while xQueueReceive() is waiting. Do not let + * the previous generation's playback/empty state contaminate the new + * response diagnostics or completion handling. */ + if (snapshot_downstream_playback_generation() != buffered_generation) { + if (received == pdTRUE) { + free_downstream_packet(&packet); + } + continue; + } + if (received != pdTRUE || packet.data == NULL || packet.len == 0U) { if (snapshot_downstream_response_end_received()) { maybe_notify_downstream_playback_completed_after_drain("queue_empty"); + } else if (playback_buffer_ready && generation_started && + snapshot_downstream_response_active()) { + TickType_t now = xTaskGetTickCount(); + if (queue_empty_since == 0U) { + queue_empty_since = now; + note_downstream_queue_empty(); + } + uint32_t empty_ms = (uint32_t)pdTICKS_TO_MS(now - queue_empty_since); + if (empty_ms >= get_downstream_rebuffer_gap_ms(ctx)) { + if (recovery_underrun_count < UINT32_MAX) { + recovery_underrun_count++; + } + UBaseType_t recovery_target = get_downstream_recovery_packet_count( + ctx, + recovery_underrun_count); + (void)set_downstream_output_mute_if_needed( + ctx, + true, + "Playback underrun"); + playback_buffer_ready = false; + underrun_since = queue_empty_since; + buffer_wait_since = now; + first_recovery_packet_tick = 0U; + queue_empty_since = 0U; + ESP_LOGW(TAG, + "Downstream protection engaged: empty_ms=%u underrun=%u recovery_target=%u packets target_ms=%u output_muted=1", + (unsigned)empty_ms, + (unsigned)recovery_underrun_count, + (unsigned)recovery_target, + (unsigned)((uint32_t)recovery_target * + ctx->opus_frame_duration_ms)); + } } vTaskDelay(pdMS_TO_TICKS(10)); continue; } + if (queue_empty_since != 0U) { + note_downstream_queue_recovered(); + queue_empty_since = 0U; + } + + if (packet.playback_generation != snapshot_downstream_playback_generation()) { + free_downstream_packet(&packet); + continue; + } + if (!audio_get_downstream_playback_stop_requested(ctx)) { esp_err_t err = handle_downstream_opus_sync(packet.data, packet.len); if (err != ESP_OK && err != ESP_ERR_INVALID_STATE) { + note_downstream_playback_failure(); ESP_LOGW(TAG, "Downstream playback packet failed: %s", esp_err_to_name(err)); } } + generation_started = true; free_downstream_packet(&packet); } @@ -2079,6 +2653,7 @@ static esp_err_t handle_downstream_opus_sync(const uint8_t *data, size_t len) (unsigned)out_frame.decoded_size); return (esp_err_t)write_ret; } + note_downstream_playback(); notify_downstream_playback_started(playback_generation); notify_downstream_audio_active(ctx); if ((played % MULTIMODAL_AUDIO_DOWNSTREAM_STATS_INTERVAL) == 0U) { @@ -2150,6 +2725,7 @@ static esp_err_t handle_downstream_opus_sync(const uint8_t *data, size_t len) (unsigned)out_codec_bytes); return (esp_err_t)write_ret; } + note_downstream_playback(); notify_downstream_playback_started(playback_generation); notify_downstream_audio_active(ctx); if ((played % MULTIMODAL_AUDIO_DOWNSTREAM_STATS_INTERVAL) == 0U) { @@ -2199,20 +2775,24 @@ esp_err_t multimodal_audio_handle_downstream_opus(const uint8_t *data, size_t le esp_err_t task_err = ensure_downstream_playback_task(ctx); if (task_err != ESP_OK) { + note_downstream_enqueue_failure(); return task_err; } downstream_packet_t packet = { .len = len, + .playback_generation = snapshot_downstream_playback_generation(), .data = (uint8_t *)audio_psram_first_malloc(len), }; if (packet.data == NULL) { + note_downstream_enqueue_failure(); return ESP_ERR_NO_MEM; } memcpy(packet.data, data, len); esp_err_t queue_err = ESP_OK; if (!lock_downstream_playback_queue(pdMS_TO_TICKS(20))) { + note_downstream_enqueue_failure(); free_downstream_packet(&packet); return ESP_ERR_TIMEOUT; } @@ -2220,6 +2800,7 @@ esp_err_t multimodal_audio_handle_downstream_opus(const uint8_t *data, size_t le QueueHandle_t queue = ctx->downstream_playback_queue; if (ctx->downstream_playback_stopping || queue == NULL) { unlock_downstream_playback_queue(); + note_downstream_enqueue_failure(); free_downstream_packet(&packet); return ESP_ERR_INVALID_STATE; } @@ -2245,12 +2826,15 @@ esp_err_t multimodal_audio_handle_downstream_opus(const uint8_t *data, size_t le queue_err = ESP_ERR_TIMEOUT; } if (queue_err != ESP_OK) { + note_downstream_enqueue_failure(); free_downstream_packet(&packet); return queue_err; } if (queued) { + update_downstream_response_activity_tick(ctx, xTaskGetTickCount()); uint32_t total = ++s_downstream_queued_packet_total; + note_downstream_arrival(queued_depth); uint32_t queued_ms = (uint32_t)queued_depth * ctx->opus_frame_duration_ms; if ((total % MULTIMODAL_AUDIO_DOWNSTREAM_STATS_INTERVAL) == 0U) { ESP_LOGI(TAG, @@ -2267,6 +2851,9 @@ esp_err_t multimodal_audio_handle_downstream_opus(const uint8_t *data, size_t le (unsigned)queued_depth, (unsigned)queued_ms); } + if ((total % MULTIMODAL_AUDIO_DOWNSTREAM_STATS_INTERVAL) == 0U) { + log_downstream_diagnostics("periodic", false); + } } return ESP_OK; @@ -2281,15 +2868,19 @@ esp_err_t multimodal_audio_begin_downstream_response(void) uint32_t playback_generation = advance_downstream_playback_generation(); + TickType_t begin_tick = xTaskGetTickCount(); portENTER_CRITICAL(&s_audio_runtime_lock); ctx->downstream_response_active = true; ctx->downstream_response_end_received = false; ctx->downstream_output_primed = false; ctx->downstream_playback_in_progress = false; + ctx->downstream_last_audio_tick = begin_tick; + ctx->downstream_last_response_activity_tick = begin_tick; portEXIT_CRITICAL(&s_audio_runtime_lock); s_downstream_queued_packet_total = 0U; s_downstream_played_packet_total = 0U; + reset_downstream_diagnostics(); ESP_LOGI(TAG, "Downstream response begin: sample_rate=%u frame=%ums codec_channels=%u pa_gpio=%d out_volume=%d", (unsigned)ctx->opus_sample_rate, @@ -2321,6 +2912,8 @@ esp_err_t multimodal_audio_begin_downstream_response(void) esp_err_t idle_err = ensure_downstream_idle_mute_task(ctx); if (idle_err != ESP_OK) { ESP_LOGW(TAG, "Prepare downstream idle mute failed: %s", esp_err_to_name(idle_err)); + } else { + arm_downstream_active_diagnostics(ctx); } esp_err_t task_err = ensure_downstream_playback_task(ctx); diff --git a/main/Kconfig.projbuild b/main/Kconfig.projbuild index 917db02..f208574 100644 --- a/main/Kconfig.projbuild +++ b/main/Kconfig.projbuild @@ -1101,6 +1101,54 @@ menu "Example Configuration" the ES8311 output path. This keeps the PA control behavior unchanged while suppressing idle speaker noise. + config MULTIMODAL_AUDIO_DOWNSTREAM_ACTIVE_STALL_MUTE_MS + int "Downstream active response stall timeout (ms)" + default 3000 + range 500 10000 + help + Abort the current playback generation when neither audio + output nor downstream response packets advance for this + long. The output is muted first so a stalled response + cannot leave stale DMA audio audible indefinitely. + + config MULTIMODAL_AUDIO_DOWNSTREAM_PREBUFFER_MS + int "Downstream playback prebuffer (ms)" + default 160 + range 0 1000 + help + Audio accumulated before initial playback. This adds a + small first-audio delay in exchange for absorbing normal + Wi-Fi and server delivery jitter. + + config MULTIMODAL_AUDIO_DOWNSTREAM_REBUFFER_GAP_MS + int "Downstream underrun detection delay (ms)" + default 120 + range 20 500 + help + Continuous empty-queue interval that mutes the output and + returns playback to buffering instead of restarting on + every isolated packet. + + config MULTIMODAL_AUDIO_DOWNSTREAM_MAX_REBUFFER_MS + int "Maximum adaptive downstream recovery buffer (ms)" + default 640 + range 160 2000 + help + Maximum audio accumulated after repeated queue underruns. + The recovery target grows from twice the initial prebuffer + up to this limit for an unstable response. + + config MULTIMODAL_AUDIO_DOWNSTREAM_DIAGNOSTICS_ENABLE + bool "Enable downstream audio diagnostics" + default n + help + Collect and report low-rate downstream audio timing, queue + depth, queue starvation, enqueue failure, and playback + failure statistics. Active responses also report a + once-per-second wait snapshot when no audio advances. + Disabled by default to avoid diagnostic logging and + per-packet accounting in production builds. + config MULTIMODAL_AUDIO_DOWNSTREAM_PLAYBACK_TASK_STACK int "Downstream playback task stack (bytes)" default 12288 diff --git a/sdkconfig.defaults b/sdkconfig.defaults index 41e2dfb..5780c38 100644 --- a/sdkconfig.defaults +++ b/sdkconfig.defaults @@ -171,6 +171,11 @@ CONFIG_MULTIMODAL_AUDIO_AEC_REFERENCE_CHANNEL=1 CONFIG_MULTIMODAL_AUDIO_AEC_FILTER_LENGTH=4 CONFIG_MULTIMODAL_AUDIO_UPLINK_MAX_PACKET_BYTES=1024 CONFIG_MULTIMODAL_AUDIO_DOWNSTREAM_PLAYBACK_TASK_STACK=12288 +# CONFIG_MULTIMODAL_AUDIO_DOWNSTREAM_DIAGNOSTICS_ENABLE is not set +CONFIG_MULTIMODAL_AUDIO_DOWNSTREAM_ACTIVE_STALL_MUTE_MS=3000 +CONFIG_MULTIMODAL_AUDIO_DOWNSTREAM_PREBUFFER_MS=160 +CONFIG_MULTIMODAL_AUDIO_DOWNSTREAM_REBUFFER_GAP_MS=120 +CONFIG_MULTIMODAL_AUDIO_DOWNSTREAM_MAX_REBUFFER_MS=640 CONFIG_MULTIMODAL_AUDIO_DOWNSTREAM_PLAYBACK_QUEUE_LEN=1024 CONFIG_MULTIMODAL_AUDIO_DOWNSTREAM_PLAYBACK_MAX_PACKET_BYTES=2048 CONFIG_MULTIMODAL_AUDIO_I2S_DMA_DESC_NUM=4