Strange delay with snapserver + ALSA loopback after some time

[elan]

Describe the bug

Running snapserver on a Raspberry Pi, using ALSA loopback like this:

source = alsa://?name=Loopback&device=hw:0,0,0

Generally speaking, latency is great and if I play something with aplay to the loopback device I see snapserver log State changed: Loopback, state: idle => playing immediately.

However, after some number of hours (mix of idle and non-idle), there is suddenly a large delay (~5 seconds) between playing to loopback and snapserver "seeing" the data and leaving idle.

I'm not sure it's a snapserver or ALSA issue, but I figured I'd post in case anyone else had seen it or knows and more.

Steps to Reproduce

1. Setup snapserver with loopback ALSA.
2. Go about your business.
3. Notice that after some number of hours, starting/stopping audio gets ~5 seconds of delay.

Environment details

• OS: Raspbian
• Snapcast version: master
• Self compiled

Attach logfile if applicable

Logs don't show anything obvious.

[badaix]

Even there is nothing obvious in the logs, they could help. You could have a message like this:

    if (rate != sampleFormat_.rate())
    {
        LOG(WARNING, LOG_TAG) << "Rate is not accurate (requested: " << sampleFormat_.rate() << ", got: " << rate << "), using: " << rate << "\n";
        sampleFormat_.setFormat(rate, sampleFormat_.bits(), sampleFormat_.channels());
    }

Please try to specify the sample rate explicitly, e.g.:

source = alsa:://?name=Loopback&device=hw:0,0,0&sampleformat=44100:16:2

Maybe your input is 48kHz and Snapcast reads with 44100Hz.

[elan]

Thanks, I will try that! I did not see any warnings about sample rate mismatches.

I did try one thing last night, a bit of a hack because I felt like the problem could be that the ASLA buffer was getting read too slowly during at least the idle period (along the lines of what you said above):

diff --git a/server/streamreader/alsa_stream.cpp b/server/streamreader/alsa_stream.cpp
index 5106411c..73e127e4 100644
--- a/server/streamreader/alsa_stream.cpp
+++ b/server/streamreader/alsa_stream.cpp
@@ -292,6 +292,8 @@ void AlsaStream::do_read()
         {
             // LOG(DEBUG, LOG_TAG) << "Next read: " << std::chrono::duration_cast<std::chrono::milliseconds>(next_read).count() << "\n";
             // synchronize reads to an interval of chunk_ms_
+            auto delay = state_ == ReaderState::kIdle && !send_silence_ ? (nextTick_ - currentTick - 5ms) : (nextTick_ - currentTick);
+
             wait(read_timer_, nextTick_ - currentTick, [this] { do_read(); });
             return;
         }

So far haven't had the issue overnight, will keep checking today.

[badaix]

Yep, it looks like the buffer is being read too slowly. If one read took longer than expected (longer than the configured "chunk size", e.g. 20 ms), an additional delay is introduced, assuming that the read took longer because of a buffer under run. In f2225c19592090bb2ed42a2716d34e5fcfac0528 this additional delay is removed and a check for available bytes has been added. If there are not enough bytes available, a delay is added before the next read and if there are too many bytes waiting, they get read and dropped, to avoid a raise of the audio delay.

[frafall]

I have an all ALSA loop based system, mpd, spotify, bluetooth ++ running on seperate loopback interfaces, mainly due to the idle detection, I had issues with bluetooth always sending so my meta stream didnt switch.

The latency on ALSA loopback has been an issue since day one, after adding this patch its gone to normal latency, ie second response on player commands (pause/play/stop/volume..).

So far no side effects detected, nice work :)

-frafall

[badaix]

Fixed in snapcast v0.27.0