Snapcast: Audio distortion / clicks and pops - replace CLOCK_REALTIME with CLOCK_MONOTONIC

[christf]

snapcast uses the system clock of the server as a source for playback. This clock is not continous. Playing audio synchronized to a jumping clock likely causes pops.

On the client-side a monotonic clock should be used to determine when a chunk is to be played. An offset to the server should be maintained and adjusted periodically.

EDIT: I have found this not to be correct. We can play back synchronized when relying on NTP and CLOCK_REALTIME just fine.

[dmckminard]

Are you also having trouble about a certain latence ? I see that you're a lot implicated in snapcast and I'm having like 1,5 sec of latence.
I'm streaming via bluetooth from my phone (without latence) and when I'm using the snapcast multiroom system, I'm having latency

[christf]

latency is a different story altogether: Do you mean latency between different clients (snapcast should avoid that) or latency between the server and the client (snapcast is designed to induce some latency which is set as bufferMs value on the server to allow for caching).

That being said, I have realized that the behavior of my clients can be explained by the code in snapcast and not by my environment. Changing the Code of snapcast is massive work and touches on fundamental design choices. It might be easier to take the learning and start from scratch using:

• UDP
• resampling using libsoxr instead of dropping frames
• single-threaded application design
• Opus
• recycling the android app by using the same interface

[dmckminard]

I mean latency between the control of my music and when the server play it.
For example in my case : there is like 1,5 sec of latency when I change a music with my phone (by bluetooth) before I can hear my music (and same for changing volume, changing tracks etc).
So I think it's between server and client ?

Do you know that some of things like that have been performed ? I am a novice in this domain and I don't think I'll be able to setup something like that

[christf]

The latency you describe is to be expected and due to buffering audio which is done to avoid dropouts. The default buffersize is 1s. You can experiment with smaller values, setting -b for snapserver - depending on your network equipment this may or may not work well.

I am currently looking at scoping a project like described above.

[unimatrix27]

I did a small recording of what I am experiencing regularly every ~24 hours with a always on setup of snapserver on my Ubuntu server and snapclient on a Raspberry PI 2 (all updated to newest versions). Is this the dropouts this is about? Any way I can avoid them by changing system time settings? It seems they are not visible in the log, otherwise I would watch the log to automatically restart. A restart of either snapserver or snapclient resolves the problem for the time being.

I am not using WLAN, this is all through 1 Gbit Switches.

Distortion.zip

[christf]

You are hearing the effect of the server not correctly tagging the time for chunks it reads from the pipe. This symptom is more prominent, when the server is under high load. One of my PR is fixing that but revealing other issues.

That is one of the reasons I started snapcastc https://github.com/christf/snapcastc/ - essentially a rewrite of snapcast in C having the properties described above (opus, UDP, single-threaded).

I have implemented and discarded soxr as it changes pitch (also see https://github.com/mikebrady/shairport-sync/issues/797 including remediation.). Currently time stretching is accomplished with the very same naive algorithm as implemented here and elsewere - by dropping or inserting a single frame. This is subject to change though: synchronisation is rather slow that way when using big audio chunks like with 96Kbit opus at 60ms or 120ms chunks.

The implementation of the control socket is still missing. That being said, I already use it as a replacement for snapcast for playback of audio on two raspberryPi B over wifi.

I would be happy about help, be it packaging, implementation, documentation or ideas and issues.

[6i6i]

I did a small recording of what I am experiencing regularly every ~24 hours with a always on setup of snapserver on my Ubuntu server and snapclient on a Raspberry PI 2 (all updated to newest versions). Is this the dropouts this is about? Any way I can avoid them by changing system time settings? It seems they are not visible in the log, otherwise I would watch the log to automatically restart. A restart of either snapserver or snapclient resolves the problem for the time being.

I am not using WLAN, this is all through 1 Gbit Switches.

Distortion.zip

I have the exact same problem with SnapcastServer running on Ubuntu Server AMD64 (i3-3220T) and attached to that 4 clients (different RPI) and one local client directly on the server. They are all connected via LAN.
I do not have the problem on the local client. It does not appear on all clients at the same time. To fix it I have to mute the client and unmute it again. A restart is not required of either server or clients.
Sometimes it works for days. Sometimes the problem appears again just a hour after after the last occurence.

As the snapcast solution works perfectly despite of this fact i do not want to replace it.
Does someone has a solution for it?

[christf]

@unimatrix, there is actually one more problem that could lead to sound like this: when using mpd and the fifo plugin, this will silently drop data when the pipe is full. I have described this penomenon here: https://github.com/christf/snapcastc#configuring-mpd----use-the-pipe-plugin

I have spent quite some time analyzing this and was able to solve it in snapcastc.
fast sync is now implemented (again) using soxr for now. I already have zero dropouts on multiple clients over the course of many listening hours. There is a status socket now that already supports muting clients using the same API as snapcast (although snapdroid does not display the clients yet. Not sure what is wrong). I am currently working on adjusting the volume.

Support for multiple streams is next.

To the original point of the issue:
When working on snapcastc I have found that given NTP on clients and server, the Clock source is not all that important for resolving audio dropouts. If we were to implement synchronized playback without synchronized clocks, then this would be a major problem, however more for drift than for drops.

[6i6i]

I was able to do a workaround muting all Clients for 500ms each hour per cronjob. Now it works perfectly since weeks.
`#!/usr/bin/python

import telnetlib
import json
import time

requestId = 1
group="f67571df-ccc9-4f2c-45cc-fc0d2e416ffb"

def doRequest( j, requestId ):
#print("send: " + j)
try:
telnet.write(j + "\r\n")
except Exception:
telnet = telnetlib.Telnet("192.168.0.222", 1705)
telnet.write(j + "\r\n")
while (True):
response = telnet.read_until("\r\n", 2)
jResponse = json.loads(response)
if 'id' in jResponse:
if jResponse['id'] == requestId:
#print("recv: " + response)
return jResponse;
return;

def mute(mute):
global requestId
doRequest(json.dumps({'jsonrpc': '2.0', 'method': 'Group.SetMute', 'params': {'id': group, 'mute': mute}, 'id': requestId}), requestId)
requestId = requestId + 1

mute(True)
time.sleep(0.5)
mute(False)
`

[badaix]

Clock is changed in master, starting with release v0.19

[6i6i]

I upgraded to v0.19 yesterday for all clients and the server and now have the problem occuring again even my mute and unmute script is still running. So the problem got worse again.
I am feeding snapcast via mopidy from a web stream.

[badaix]

How is gstreamer connected? Via file or TCP? Please try TCP, as discussed in #511

[6i6i]

Hi,

OK. I was using pipe before as listed in the configuration readme of snapcast. Now I switched to Snapcast running in TCP server mode.
I'll now let it run and monitor it :-).

Thank you for your help!

[6i6i]

Hi,

unfortunatelly the change to TCP didn't help. The problem occurs every now and then and is recoverable by muting the whole group for about 1 sec like with v 0.15 before.
Do you have any further hints what I can try?

Thank you

[badaix]

Logs would be great. Please start the clients on command line with --debug and enable debug logging in the snapserver.conf.

[6i6i]

I activated logging now. So I am waiting for the issue to occur again and come back to you.

[6i6i]

Hi,

I have now the debug log of the client and server when the problem happened.
It was around 17:10 but I cannot get anything out of the debug logs rather than "2020-06-08 17-08-27.063 [Error] (Alsa) XRUN: Broken pipe" But this log entry is also there before the issue happend.
The log in the zip file is from one client. 5 other clients are connected too. 4 of them are having the same problem at different time. Only the local client that runs on the same machine as the snapserver does not have this problem.
All clients that have this problems are Raspberry Pi's.

Audio_distortion_log.zip

Thank you
BR Martin

[badaix]

Seems that the XRUNs are causing the problem. Are you using some special audio device? The 0.20 fixes a problem in alsa playback for dome DACs. Also you can raise your buffer, which you set to the minimum of 400ms.

[6i6i]

I am using different types of USB DAC's on the PI's. 0.20 is not released yet i think?
Where can i set the buffer value (client or server configuration)?

[badaix]

server, the "-b" parameter in the stream.
But I think it's rather the alsa player, DAC combination. Can you use the built-in DAC?
Please also try out the current develop branch (not yet released, mainly because it's only me doing QA)

[6i6i]

OK. I setup buffer to 1000ms in snapserver.conf. I'll monitor it again. It would not be easy to use the built-in DAC because the PI's are not easily reachable and the sound quality is really bad using the internal DAC.
OK. I'll try to get it compiled on the PI.

I had no problems before using MPD directly on the PI with this DAC's.

Thank you
BR
Martin

[badaix]

It would not be easy to use the built-in DAC because the PI's are not easily reachable and the sound quality is really bad using the internal DAC.

Well, it's worth the test (if you can still see XRUNs in the log to check if it's DAC related (don't use debug logging for this)) and it's just a matter of calling snapclient with a different -s parameter.
But please go for the v0.20 first.

[6i6i]

Ok I compiled the client for pi and I am now running v0.20 on one Pi. I'll monitor it and let you know.
Thank you

[6i6i]

The problem exists even when running on v0.20 :-( I'll let the client run again on debug mode to see if i get some output of it.
I checked syslog and dmesg too but there are no real hints what could cause the problem.

[6i6i]

I have now upgraded to v0.20 from the "release" site on all clients and the server. Regarding the DAC issue I have a question do you. What type of DAC are you using on what system? ( I remember you wrote something about Behringer USB DAC?)

[6i6i]

So far i have not found anything useful out of the logfiles. But what I can hear is, that when the problem happens it sound different than with version 0.15. In 0.15 it was a distortion. Now it sounds like an echo or if you play the same sound twice with a few ms difference.

[6i6i]

So far i made some progress. I updated all RPI Clients from Raspian Stretch to Buster. In addition I do my mute 500ms unmute every 15 Minutes. I had no distortions any more.

[xabolcs]

@6i6i at what time do your clients start distortions?
My clients can survive a few hours!

Would you mind sharing your mute-unmute script?

[6i6i]

@xabolcs it does not start at a specific time and not at the same time at every client. Sometimes it runs for hours and sometimes only for 40 minutes. As It was to annoying for me to mute and unmute manually every time I implemented a script that runs via cron task evey 15 minutes:

#!/usr/bin/python

import telnetlib
import json
import time

requestId = 1


def doRequest( j, requestId ):
        #print("send: " + j)
        try:
                telnet.write(j + "\r\n")
        except Exception:
                telnet = telnetlib.Telnet("localhost", 1705)
                telnet.write(j + "\r\n")
        while (True):
                response = telnet.read_until("\r\n", 2)
                jResponse = json.loads(response)
                if 'id' in jResponse:
                        if jResponse['id'] == requestId:
                                return jResponse;
        return;


def getGroupid(client):
    j = doRequest(json.dumps({'jsonrpc': '2.0', 'method': 'Server.GetStatus', 'id': 1}), 1)
    for group in j["result"]["server"]["groups"]:
        for client in group["clients"]:
            if client['id'] == '1':
                return str(group['id'])

group=getGroupid(1)

def mute(mute):
        global requestId
        doRequest(json.dumps({'jsonrpc': '2.0', 'method': 'Group.SetMute', 'params': {'id':  group, 'mute': mute}, 'id': requestId}), requestId)
        requestId = requestId + 1

mute(True)
time.sleep(0.5)
mute(False)