How can I debug intermittent stutters on one client?

[tremby]

I used to have (to my ears) flawless playback through snapcast on this particular client.

No other clients have changed.

This client has changed in that I updated my OS, and I'm now using pipewire with pipewire-pulse rather than plain pulseaudio. I am not 100% sure, but there's a good chance I started noticing stutters in sound at the same time.

I start snapclient on this machine with snapclient --player pulse --host mysnapserver --mixer hardware

I started it just now with trace logging, and this is how things start:

2023-06-28 16-10-35.122 [Debug] (Snapclient) Trying to get PCM device for player: pulse, parameter: , card: default
2023-06-28 16-10-35.133 [Info] (Snapclient) Version 0.27.0, revision 54a3d862
2023-06-28 16-10-35.133 [Info] (Connection) Resolving host IP for: mysnapserver
2023-06-28 16-10-35.134 [Info] (Connection) Connecting
2023-06-28 16-10-35.135 [Notice] (Connection) Connected to 10.0.0.46
2023-06-28 16-10-35.135 [Info] (Connection) My MAC: "xx:xx:xx:xx:xx:xx", socket: 8
2023-06-28 16-10-35.167 [Debug] (Connection) outstanding async_write
2023-06-28 16-10-35.167 [Trace] (Connection) Wrote 232 bytes to socket
2023-06-28 16-10-35.167 [Trace] (Connection) Wrote 34 bytes to socket
2023-06-28 16-10-35.168 [Info] (Controller) ServerSettings - buffer: 1000, latency: 0, volume: 100, muted: 0
2023-06-28 16-10-35.168 [Warn] (Connection) Failed to deserialize message of type: Unknown
2023-06-28 16-10-35.168 [Info] (Controller) Codec: flac, sampleformat: 44100:16:2
2023-06-28 16-10-35.168 [Info] (Player) Player name: pulse, device: default, description: Let PulseAudio server choose the device, idx: 59, sharing mode: unspecified, parameters: <
none>
2023-06-28 16-10-35.168 [Info] (Player) Mixer mode: hardware, parameters: <none>
2023-06-28 16-10-35.168 [Info] (Player) Sampleformat: 44100:16:2, stream: 44100:16:2
2023-06-28 16-10-35.168 [Info] (PulsePlayer) Setting property "application.icon_name" to "snapcast"
2023-06-28 16-10-35.168 [Info] (PulsePlayer) Setting property "media.role" to "music"
2023-06-28 16-10-35.168 [Info] (PulsePlayer) Using buffer_time: 100 ms, server: default
2023-06-28 16-10-35.168 [Info] (PulsePlayer) Start
2023-06-28 16-10-35.168 [Info] (PulsePlayer) Connecting to pulse
2023-06-28 16-10-35.169 [Debug] (PulsePlayer) State changed 2: authorizing
2023-06-28 16-10-35.174 [Debug] (PulsePlayer) State changed 3: setting name
2023-06-28 16-10-35.178 [Debug] (PulsePlayer) State changed 4: ready
2023-06-28 16-10-35.179 [Trace] (Connection) Wrote 34 bytes to socket
2023-06-28 16-10-35.180 [Trace] (Connection) Wrote 34 bytes to socket
2023-06-28 16-10-35.180 [Trace] (PulsePlayer) subscribeCallback, event type: 2, idx: 16899
2023-06-28 16-10-35.180 [Debug] (PulsePlayer) event_type: 0, facility: 2
2023-06-28 16-10-35.180 [Trace] (Connection) Wrote 34 bytes to socket
2023-06-28 16-10-35.181 [Trace] (Connection) Wrote 34 bytes to socket
2023-06-28 16-10-35.181 [Trace] (Connection) Wrote 34 bytes to socket
2023-06-28 16-10-35.181 [Trace] (PulsePlayer) subscribeCallback, event type: 18, idx: 16899
2023-06-28 16-10-35.181 [Debug] (PulsePlayer) event_type: 16, facility: 2
2023-06-28 16-10-35.181 [Trace] (Connection) Wrote 34 bytes to socket
2023-06-28 16-10-35.182 [Trace] (Connection) Wrote 34 bytes to socket

Every once in a while I get a stutter. I've noticed that they coincide with messages like this in the log:

...
2023-06-28 16-11-23.242 [Trace] (Connection) Wrote 34 bytes to socket
2023-06-28 16-11-24.019 [Debug] (Stats) Chunk: -28      -28     18      -18     500     77      0
2023-06-28 16-11-24.243 [Trace] (Connection) Wrote 34 bytes to socket
2023-06-28 16-11-25.021 [Debug] (Stats) Chunk: -28      -27     -27     -19     500     78      0
2023-06-28 16-11-25.244 [Trace] (Connection) Wrote 34 bytes to socket
2023-06-28 16-11-26.024 [Debug] (Stats) Chunk: 13       -27     -28     -22     500     81      21
2023-06-28 16-11-26.045 [Info] (Stream) pBuffer->full() && (abs(median_) > 2): -2234
2023-06-28 16-11-26.066 [Debug] (Stream) age > 0: 1ms, dropping old chunks
2023-06-28 16-11-26.066 [Debug] (Stream) age: -19, requested chunk_duration: 21, duration: 26
2023-06-28 16-11-26.066 [Debug] (Stream) Silent frames: 844, frames: 941, age: -19.158
2023-06-28 16-11-26.244 [Trace] (Connection) Wrote 34 bytes to socket
2023-06-28 16-11-27.026 [Debug] (Stats) Chunk: 0        0       0       0       45      81      0
2023-06-28 16-11-27.245 [Trace] (Connection) Wrote 34 bytes to socket
2023-06-28 16-11-28.007 [Debug] (Stats) Chunk: -46      -46     0       0       91      77      0
2023-06-28 16-11-28.246 [Trace] (Connection) Wrote 34 bytes to socket
2023-06-28 16-11-29.010 [Debug] (Stats) Chunk: -50      -49     -46     -45     138     76      0
2023-06-28 16-11-29.247 [Trace] (Connection) Wrote 34 bytes to socket
2023-06-28 16-11-30.013 [Debug] (Stats) Chunk: -43      -44     -46     -44     185     76      22
...

I'm not really sure where to start on trying to figure out what the problem might be, short of going back to Pulseaudio. Figured I'd ask here first in case there are other things I should try first.

The other clients don't seem to stutter. Those are all single-purpose raspberry pis, using alsa directly.

The machine this client is running on is pretty powerful, with fast networking too. I'm on Ubuntu 22.04.

There's nothing that stands out to me in the server config other than the sample rate of 44100 (since almost all music I play is ripped from CD and so at 44100Hz). And I wouldn't have thought the server is the issue since the other clients seem fine.

Any ideas?