onResync dropouts with docker

[jaycemil]

I have mpd and snapserver (v0.25) running in docker containers. I'm getting onResync dropouts pretty consistently from all snapclients. I've tried adjusting buffer sizes, process nice values and various other things. Could someone explain what onResync coming from the snapserver indicates? Even better, does someone have any suggestions on where to look to debug this? Thanks.

Here's a log excerpt from the snapserver:
2021-10-08 01-15-16.282 [Info] (PosixStream) next read < 0 (default): -26.34 ms
2021-10-08 01-16-01.239 [Info] (PosixStream) next read < 0 (default): -43.726 ms
2021-10-08 01-16-16.345 [Info] (Server) onResync (default): 89.0416 ms
2021-10-08 01-18-31.279 [Info] (PosixStream) next read < 0 (default): -3.907 ms
2021-10-08 01-18-46.254 [Info] (Server) onResync (default): 99.0411 ms
2021-10-08 01-19-46.259 [Info] (PosixStream) next read < 0 (default): -14.421 ms
2021-10-08 01-21-06.262 [Info] (PosixStream) next read < 0 (default): -37.867 ms
2021-10-08 01-21-41.377 [Info] (Server) onResync (default): 52.8366 ms
2021-10-08 01-21-46.358 [Info] (Server) onResync (default): 131.043 ms
2021-10-08 01-21-51.274 [Info] (Server) onResync (default): 65.3169 ms
2021-10-08 01-21-56.324 [Info] (Server) onResync (default): 80.0499 ms
2021-10-08 01-22-01.312 [Info] (Server) onResync (default): 77.5323 ms
2021-10-08 01-22-21.874 [Info] (Server) onResync (default): 172.427 ms
2021-10-08 01-22-26.748 [Info] (PosixStream) next read < 0 (default): -23.595 ms
2021-10-08 01-22-31.903 [Info] (Server) onResync (default): 138.783 ms
2021-10-08 01-22-36.909 [Info] (Server) onResync (default): 155.693 ms
2021-10-08 01-23-51.255 [Info] (Server) onResync (default): 75.2173 ms
2021-10-08 01-24-51.215 [Info] (PosixStream) next read < 0 (default): -30.458 ms
2021-10-08 01-25-36.330 [Info] (PosixStream) next read < 0 (default): -24.771 ms
2021-10-08 01-26-46.359 [Info] (Server) onResync (default): 153.792 ms
2021-10-08 01-27-46.181 [Info] (PosixStream) next read < 0 (default): -11.592 ms
2021-10-08 01-29-52.187 [Info] (PosixStream) next read < 0 (default): -18.369 ms
2021-10-08 01-30-02.389 [Info] (Server) onResync (default): 140.471 ms
2021-10-08 01-30-07.299 [Info] (Server) onResync (default): 59.3572 ms
2021-10-08 01-30-17.391 [Info] (Server) onResync (default): 141.797 ms
2021-10-08 01-30-22.389 [Info] (Server) onResync (default): 87.6404 ms
2021-10-08 01-30-27.454 [Info] (Server) onResync (default): 155.466 ms
2021-10-08 01-30-32.656 [Info] (Server) onResync (default): 351.765 ms
2021-10-08 01-30-37.383 [Info] (Server) onResync (default): 56.7804 ms
2021-10-08 01-30-42.243 [Info] (PosixStream) next read < 0 (default): -9.334 ms
2021-10-08 01-30-47.261 [Info] (Server) onResync (default): 107.277 ms
2021-10-08 01-30-52.271 [Info] (Server) onResync (default): 99.6124 ms
2021-10-08 01-30-57.233 [Info] (Server) onResync (default): 52.1851 ms
2021-10-08 01-31-02.276 [Info] (Server) onResync (default): 72.4037 ms
2021-10-08 01-31-12.318 [Info] (PosixStream) next read < 0 (default): -31.83 ms
2021-10-08 01-31-17.415 [Info] (Server) onResync (default): 149.546 ms

[cuthulino]

I got the same problem here.
Aswell in a docker container but with some bigger values;

2022-01-30 01-32-18.806 [Info] (PcmStream) State changed: Mopidy1, state: idle => playing
2022-01-30 01-32-18.806 [Info] (Server) onStateChanged (Mopidy1): playing
2022-01-30 01-32-41.935 [Info] (Server) onResync (Mopidy1): 3443.59 ms
2022-01-30 01-33-09.699 [Info] (Server) onResync (Mopidy1): 2474.35 ms
2022-01-30 01-35-58.659 [Info] (Server) onResync (Mopidy1): 1749.91 ms
2022-01-30 01-36-34.499 [Info] (Server) onResync (Mopidy1): 309.604 ms

thats really annoying. i cant find sth to solve this.

[jaycemil]

My issue turned out to be a horribly underperforming nfs store I was streaming the music from. Once that was fixed snapcast works like a charm. Basically, the file system couldn't keep up with the stream no matter how much buffer I gave it.

[cuthulino]

Thanks for your reply.
I used a named volume for sharing the fifo file between snapcast and mopidy container.
I think this can be underperforming aswell.

I will give tcp a try.

[oliv3r]

a named pipe should in theory be much more performant, curious how you solved this in the end...

[gjdawson]

I'm also having this issue, in a microk8s cluster, with mopidy on a fifo over a shared volume (with a local music library, so no network issues getting in the way there) and librespot inside the same container as snapserver. Every client I've connected has suffered stuttering, with an onResync error and some small number of ms delay.

The browser client kept reporting age issues with chunks. "Chunk is too young" was one of them. The container, its host, and the client computer are all synced to the same ntp server.

Thing is, I had the exact same setup on bare metal - mopidy through a fifo, librespot, snapserver - and it showed no issues. No pause or stutter whatsoever, no matter the client. I can only assume it's something about the container environment that's bottlenecking snapserver somehow. I just can't work out what.

[squat]

There are lots of possible things that could be causing this issue. I wonder if it might have to do with the libc version that is buffering input / output. The containers I'm running are all based on Alpine and thus using musl libc. I'll try with some debian-based containers to see if there's any difference.

[gjdawson]

@squat an older intel celeron ultra-compact. 1.6GHz I think, 16MB ram, gigabit ethernet. It's running a K3s node with containers for mop mopidy and snapcast (with librespot in the same container), and a couple of other related utilities. The snapcast container builds librespot in a rust container based on debian bullseye, then uses ubuntu focal as a runner, so I think that should rule out the libc version being the issue.

To get a working setup, I moved snapserver and librespot back out onto the host and piped mopidy through a fifo that was mounted into its container. That works without issue.

What I've wanted to try next, but not had the time, is running both mopidy and snapserver inside a containers with them both communicating through a fifo mounted from the host, rather than on an volume claim. It strikes me that the issue might be related to the filesystem used in the mounted volumes/containers in some way.

[squat]

What I've wanted to try next, but not had the time, is running both mopidy and snapserver inside a containers with them both communicating through a fifo mounted from the host, rather than on an volume claim. It strikes me that the issue might be related to the filesystem used in the mounted volumes/containers in some way.

I just ran this example now. I used a hostPath volume and created all of the FIFOs in there. This results in the same consitent resyncs and dropouts.

[squat]

One distinct possibility right now is that the issue has to do with using FIFOs outside of the host namespaces. However, when re-running these experiments using FIFOs living in the host mount namespace, and using the host's PID and IPC namespaces for the whole pod, the issue persists. I'm going to try to run directly on the host like you are doing to see if it's not a fundamental issue with my host.

[squat]

Some more notes:

• I have a minimal reproducible setup with two Docker containers; this issue is not reproducible on my laptop, which is a nice sanity check that there isn't something fundamentally wrong with this whole setup
• resyncs occur even if no clients are connected; as long as a stream over a pipe is selected and is playing, the resyncs can be seen
• when not using pipes, e.g. directly reading from STDIO of librespot, the issue is not reproducible! This suggests something funny is happening related pipes, clocks, or scheduling in the kernel
• when using the exact same hardware but a different Linux distribution (Raspberry PI OS), the issue is not reproducible! Again, suggests something is likely going on with the kernel. This also indicates that the issue is not some fundamental issue with pipes / namespaces / cgroups or with the hardware.

I'm still trying to get to the bottom of the issue.

[ackstorm23]

I came strait to this issue looking for an answer to the same performance issue and errors but with mpd in docker

In this case I am running docker on my NAS server so it has direct access to the data without NFS.

I've even tried putting the fifo on /tmp/ shared between mpd and snapserver containers but the resyncs still regularly happen.

snapserver    | 2022-04-19 07-01-27.362 [Info] (PosixStream) next read < 0 (mpd): -1.85 ms
snapserver    | 2022-04-19 07-01-28.304 [Info] (Server) onResync (mpd): 64.3577 ms
snapserver    | 2022-04-19 07-01-29.783 [Info] (Server) onResync (mpd): 68.6646 ms
snapserver    | 2022-04-19 07-01-31.669 [Info] (Server) onResync (mpd): 55.1636 ms
snapserver    | 2022-04-19 07-01-33.881 [Info] (PosixStream) next read < 0 (mpd): -42.321 ms
snapserver    | 2022-04-19 07-01-33.881 [Info] (PosixStream) next read < 0 (mpd): -22.654 ms
snapserver    | 2022-04-19 07-01-33.882 [Info] (PosixStream) next read < 0 (mpd): -2.868 ms
snapserver    | 2022-04-19 07-01-36.081 [Info] (PosixStream) next read < 0 (mpd): -42.1 ms
snapserver    | 2022-04-19 07-01-36.081 [Info] (PosixStream) next read < 0 (mpd): -22.36 ms
snapserver    | 2022-04-19 07-01-36.081 [Info] (PosixStream) next read < 0 (mpd): -2.579 ms
snapserver    | 2022-04-19 07-01-38.934 [Info] (Server) onResync (mpd): 54.6702 ms
snapserver    | 2022-04-19 07-01-40.120 [Info] (Server) onResync (mpd): 56.5361 ms
snapserver    | 2022-04-19 07-01-40.885 [Info] (PosixStream) next read < 0 (mpd): -15.113 ms
snapserver    | 2022-04-19 07-01-48.568 [Info] (Server) onResync (mpd): 58.2704 ms

I only started having this problem after moving my mpd+snapcast setup to my docker container.

Before this I was running it on a raspberry pi-4 over wireless and nfs to the same NAS without any problems.

[squat]

:) niceness is indeed the traditional solution here. Unfortunately, Kubernetes doesn't expose configuration to nice the pods that get created. However, i think the offending process is actually the kubelet itself, which can be niced.

[LeoSum8]

@ackstorm23 I would like to try this approach, as I am currently also experiencing similar stuttering. Can you explain a bit, how you "reniced snapserver and mpd to -20"? Is this something within the docker file or the run command?

[ackstorm23]

I did it on the host OS. I also used ionice in addition to renice.

However this only reduced the stuttering, it did not resolve it. Under heavy I/O load it was impossible to avoid it until I moved Snapserver off if the NAS server.

When I moved it to a raspberry pi on the same network, accessing the same filesystem on the same host (but over NFS), it no longer stuttered. Even if the NFS host was under heavy I/O load!

[LeoSum8]

I also shifted to using a separate old raspy 3 now instead of my homeserver. Works without stuttering. Would have been nice to get rid of several devices but it needs to work.

[bitclick]

i had a similar problem.. resync-events on the server running in a VM on Freebsd. The fix: setting realtime priority for the vm on the host. resyncs are gone :-) (i am running rtprio via cron on the pid of the VM.. )

maybe this should be mentioned in the docs? Could snapserver detect scheduling-issues and emit warnings? This could reduce the debugging-hours spent by users greatly 😉