From 126d3f4e04ebe8fa0de2c3bbaba2bf6804301ea6 Mon Sep 17 00:00:00 2001 From: philippe44 Date: Tue, 17 Mar 2020 19:01:44 -0700 Subject: [PATCH] airplay: fix some silly unsigned errors and handle network blackouts - release --- components/squeezelite/decode_external.c | 34 +++++++++++++----------- 1 file changed, 19 insertions(+), 15 deletions(-) diff --git a/components/squeezelite/decode_external.c b/components/squeezelite/decode_external.c index 6a5a25fc..7b0f73b5 100644 --- a/components/squeezelite/decode_external.c +++ b/components/squeezelite/decode_external.c @@ -52,7 +52,7 @@ static raop_event_t raop_state; static EXT_RAM_ATTR struct { bool enabled; int sum, count, win, errors[SYNC_WIN_RUN]; - u32_t len; + s32_t len; u32_t start_time, playtime; } raop_sync; @@ -209,20 +209,21 @@ static bool raop_sink_cmd_handler(raop_event_t event, va_list args) // how many ms have we really played ms = now - output.updated + ((u64_t) (output.frames_played_dmp - output.device_frames) * 1000) / RAOP_SAMPLE_RATE; error = ms - (now - raop_sync.start_time); + LOG_INFO("backend played %u, desired %u, (delta:%d)", ms, now - raop_sync.start_time, ms - (now - raop_sync.start_time)); } else { - // in how many ms will the most recent block play - ms = ((u64_t) ((_buf_used(outputbuf) - raop_sync.len) / BYTES_PER_FRAME + output.device_frames + output.frames_in_process) * 1000) / RAOP_SAMPLE_RATE - (now - output.updated); - error = (raop_sync.playtime - now) - ms; + u32_t level = _buf_used(outputbuf); - // make sure impact of erroneous point is limited, but taken into account - if (abs(error) > 1000) { - LOG_INFO("limiting erroneous sync point %d", error); - error = (error > 0) ? SYNC_WIN_RUN : -SYNC_WIN_RUN; - } - - LOG_DEBUG("head local:%u, remote:%u (delta:%d)", ms, raop_sync.playtime - now, error); - LOG_DEBUG("obuf:%u, sync_len:%u, devframes:%u, inproc:%u", _buf_used(outputbuf), raop_sync.len, output.device_frames, output.frames_in_process); + // in how many ms will the most recent block play + ms = (((s32_t)(level - raop_sync.len) / BYTES_PER_FRAME + output.device_frames + output.frames_in_process) * 10) / (RAOP_SAMPLE_RATE / 100) - (s32_t) (now - output.updated); + + // when outputbuf is empty, it means we have a network black-out or something + error = level ? (raop_sync.playtime - now) - ms : 0; + + if (loglevel == lDEBUG || !level) { + LOG_INFO("head local:%d, remote:%d (delta:%d)", ms, raop_sync.playtime - now, error); + LOG_INFO("obuf:%u, sync_len:%u, devframes:%u, inproc:%u", _buf_used(outputbuf), raop_sync.len, output.device_frames, output.frames_in_process); + } } // calculate sum, error and update sliding window @@ -231,7 +232,10 @@ static bool raop_sink_cmd_handler(raop_event_t event, va_list args) error = raop_sync.sum / min(raop_sync.count, raop_sync.win); // move to normal mode if possible - if (raop_sync.win == SYNC_WIN_START && raop_sync.count >= SYNC_WIN_START && abs(error) < 10) raop_sync.win = SYNC_WIN_RUN; + if (raop_sync.win == SYNC_WIN_START && raop_sync.count >= SYNC_WIN_START && abs(error) < 10) { + raop_sync.win = SYNC_WIN_RUN; + LOG_INFO("switching to slow sync mode %u", raop_sync.win); + } // wait till e have enough data or there is a strong deviation if ((raop_sync.count >= raop_sync.win && abs(error) > 10) || (raop_sync.count >= SYNC_WIN_CHECK && abs(error) > 100)) { @@ -240,11 +244,11 @@ static bool raop_sink_cmd_handler(raop_event_t event, va_list args) if (error < 0) { output.skip_frames = -(error * RAOP_SAMPLE_RATE) / 1000; output.state = OUTPUT_SKIP_FRAMES; - LOG_INFO("skipping %u frames", output.skip_frames); + LOG_INFO("skipping %u frames (count:%d)", output.skip_frames, raop_sync.count); } else { output.pause_frames = (error * RAOP_SAMPLE_RATE) / 1000; output.state = OUTPUT_PAUSE_FRAMES; - LOG_INFO("pausing for %u frames", output.pause_frames); + LOG_INFO("pausing for %u frames (count: %d)", output.pause_frames, raop_sync.count); } // reset sliding window