Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Dropouts with snapclient v0.23 and ALSA backend #774

Closed
mrdago opened this issue Jan 18, 2021 · 63 comments
Closed

Dropouts with snapclient v0.23 and ALSA backend #774

mrdago opened this issue Jan 18, 2021 · 63 comments
Labels
bug next release fixed in develop branch and will be part of the next release

Comments

@mrdago
Copy link

mrdago commented Jan 18, 2021

I'm running snapserver on a small Intel server and snapclient on various Raspberry PI (2,3,4). Last weekend I started to upgrade the server and clients from snapcast v.0.19. to snapcast v.0.23. On the server I'm using pulse audio with the following snapserver configuration: **source = pipe:///tmp/snapfifo?name=snapcast&mode=read
The linux clients use the alsa audio interface and don't have pulse installed. I can't remember any problem with snapclient v.0.19, but with snapclient v.0.23 I was faced with terrible dropouts (see logs).
Downgrading the client to v.0.19 fixed the issue. Unfortunately I'm not deep enough in technical details to provide more information. Here is my OS configuration:

Server: Linux cms 4.9.0-9-amd64 #1 SMP Debian 4.9.168-1+deb9u2 (2019-05-13) x86_64 GNU/Linux
--- snapserver & snapclient v.0.23 => no issues
Client: Linux amadeus 5.4.83-v7+ #1379 SMP Mon Dec 14 13:08:57 GMT 2020 armv7l GNU/Linux
--- snapclient v.0.23 (alsa, no pulse installed) => dropouts, downgrade to snapclient v.0.19 fixed the problem

snapclient v0.23.0: DROPOUTS

Jan 18 15:23:32 amadeus systemd[1]: Started Snapcast client.
Jan 18 15:23:32 amadeus snapclient[929]: Resolving host IP for: cms
Jan 18 15:23:32 amadeus snapclient[929]: Connecting
Jan 18 15:23:32 amadeus snapclient[929]: Connected to 192.168.1.37
Jan 18 15:23:32 amadeus snapclient[929]: My MAC: "b8:27:eb:4c:0b:d0", socket: 9
Jan 18 15:23:33 amadeus snapclient[929]: ServerSettings - buffer: 1000, latency: 0, volume: 0, muted: 1
Jan 18 15:23:33 amadeus snapclient[929]: metadata:{"STREAM":"snapcast"}
Jan 18 15:23:33 amadeus snapclient[929]: Codec: flac, sampleformat: 48000:16:2
Jan 18 15:23:33 amadeus snapclient[929]: Player name: alsa, device: default, description: <none>, idx: 3, sharing mode: unspecified, parameters: <non
Jan 18 15:23:33 amadeus snapclient[929]: Mixer mode: software, parameters: <none>
Jan 18 15:23:33 amadeus snapclient[929]: Sampleformat: 48000:16:2, stream: 48000:16:2
Jan 18 15:23:33 amadeus snapclient[929]: Using buffer_time: 80 ms, fragments: 4
Jan 18 15:23:33 amadeus snapclient[929]: PCM name: default, sample rate: 48000 Hz, channels: 2, buffer time: 250020 us, periods: 2, period time: 1250
Jan 18 15:23:33 amadeus snapclient[929]: No chunks available
Jan 18 15:23:33 amadeus snapclient[929]: Failed to get chunk
Jan 18 15:23:33 amadeus snapclient[929]: diff to server [ms]: 5.73622e+07
Jan 18 15:23:38 amadeus snapclient[929]: No chunk received for 5000ms. Closing ALSA.
Jan 18 15:24:12 amadeus snapclient[929]: ServerSettings - buffer: 1000, latency: 0, volume: 100, muted: 0
Jan 18 15:24:12 amadeus snapclient[929]: PCM name: default, sample rate: 48000 Hz, channels: 2, buffer time: 250020 us, periods: 2, period time: 1250
Jan 18 15:24:17 amadeus snapclient[929]: snd_pcm_avail_delay failed: Broken pipe (-32), avail: 5981, delay: 6020, using snd_pcm_avail amd snd_pcm_del
Jan 18 15:24:17 amadeus snapclient[929]: snd_pcm_delay failed: Broken pipe (-32), avail: -32, delay: 6020
Jan 18 15:24:18 amadeus snapclient[929]: XRUN while writing to PCM: Broken pipe
Jan 18 15:24:18 amadeus snapclient[929]: snd_pcm_avail_delay failed: Broken pipe (-32), avail: 5906, delay: 6095, using snd_pcm_avail amd snd_pcm_del
Jan 18 15:24:18 amadeus snapclient[929]: snd_pcm_delay failed: Broken pipe (-32), avail: -32, delay: 6095
Jan 18 15:24:19 amadeus snapclient[929]: pMiniBuffer->full() && (abs(pMiniBuffer->mean()) > 50): -102804
Jan 18 15:24:20 amadeus snapclient[929]: snd_pcm_avail_delay failed: Broken pipe (-32), avail: 5955, delay: 6037, using snd_pcm_avail amd snd_pcm_del
Jan 18 15:24:20 amadeus snapclient[929]: snd_pcm_delay failed: Broken pipe (-32), avail: -32, delay: 6037
Jan 18 15:24:22 amadeus snapclient[929]: pMiniBuffer->full() && (abs(pMiniBuffer->mean()) > 50): -100639
Jan 18 15:24:22 amadeus snapclient[929]: XRUN while writing to PCM: Broken pipe
Jan 18 15:24:25 amadeus snapclient[929]: XRUN while writing to PCM: Broken pipe
Jan 18 15:24:26 amadeus snapclient[929]: pMiniBuffer->full() && (abs(pMiniBuffer->mean()) > 50): -242589
Jan 18 15:24:27 amadeus snapclient[929]: XRUN while writing to PCM: Broken pipe
Jan 18 15:24:29 amadeus snapclient[929]: pMiniBuffer->full() && (abs(pMiniBuffer->mean()) > 50): -243876
Jan 18 15:24:30 amadeus snapclient[929]: XRUN while writing to PCM: Broken pipe
Jan 18 15:24:32 amadeus snapclient[929]: pMiniBuffer->full() && (abs(pMiniBuffer->mean()) > 50): -243456

snapclient v0.19.0

2021-01-18 15-31-21 [Info] (browse_callback) (Browser) CACHE_EXHAUSTED
2021-01-18 15-31-21 [Info] (resolve_callback) Service 'Snapcast' of type '_snapcast._tcp' in domain 'local':
2021-01-18 15-31-21 [Info] (resolve_callback)   cms.local:1704 (192.168.1.37)
2021-01-18 15-31-21 [Info] (main) Found server 192.168.1.37:1704
2021-01-18 15-31-21 [Info] (main) Latency: 0
2021-01-18 15-31-21 [Notice] (start) Connected to 192.168.1.37
2021-01-18 15-31-21 [Info] (getMacAddress) My MAC: "b8:27:eb:4c:0b:d0", socket: 6
2021-01-18 15-31-21 [Info] (onMessageReceived) ServerSettings - buffer: 1000, latency: 0, volume: 100, muted: 0
metadata:{"STREAM":"snapcast"}
2021-01-18 15-31-21 [Info] (onMessageReceived) Codec: flac
2021-01-18 15-31-21 [Notice] (state) sampleformat: 48000:16:2
2021-01-18 15-31-21 [Info] (Alsa) frames: 6000
2021-01-18 15-31-21 [Info] (Alsa) Resizing buffer from 0 to 48004
2021-01-18 15-31-21 [Info] (Stream) no chunks available
2021-01-18 15-31-21 [Info] (Alsa) Failed to get chunk
2021-01-18 15-31-22 [Info] (worker) diff to server [ms]: 5.73622e+07
2021-01-18 15-31-22 [Info] (Stream) Chunk: -1   -1      -1      -1      1       124     0
2021-01-18 15-31-23 [Info] (Stream) Chunk: -1   -1      -1      -1      4       124     0
2021-01-18 15-31-24 [Info] (Stream) Chunk: 0    0       0       0       12      125     0
2021-01-18 15-31-25 [Info] (Stream) Chunk: 0    0       0       0       20      125     0
2021-01-18 15-31-26 [Info] (Stream) Chunk: -1   0       0       0       28      124     0
2021-01-18 15-31-27 [Info] (Stream) Chunk: 3    0       0       0       36      125     0
2021-01-18 15-31-28 [Info] (Stream) Chunk: 3    2       0       0       44      125     0
2021-01-18 15-31-29 [Info] (Stream) Chunk: 4    3       0       0       52      124     0
2021-01-18 15-31-30 [Info] (Stream) Chunk: 4    3       1       1       60      125     0
@mrdago mrdago added the bug label Jan 18, 2021
@badaix
Copy link
Owner

badaix commented Jan 18, 2021

From which device are the 0.23 logs? Raspberry Pi 1, 2, 3? What audio device was used? Onboard sound? What OS? (is Linux amadeus an OS?)
Can you try the 0.22? There are some changes in 0.23, trying to fix #727 and #722. I was never able to reproduce it and the original issue reporters stopped responding.

You can also try to change the player parameters (buffer_time and fragments):

snapclient --logfilter *:debug --player alsa:?
Options are a comma separated list of:
 "buffer_time=<total buffer size [ms]>" - default 80, min 10
 "fragments=<number of buffers>" - default 4, min 2

E.g. snapclient --logfilter *:debug --player alsa:buffer_time=50,fragments=2

@mrdago
Copy link
Author

mrdago commented Jan 19, 2021

Hi badaix, thanks for your fast reply! First the answers to your questions:

amadeus is the hostname of the player running snapclient. It's a
Raspberry Pi 3 Model B, 1 GB RAM (a02082)
No LSB modules are available.
Distributor ID: Raspbian
Description: Raspbian GNU/Linux 10 (buster)
Release: 10
Codename: buster

All reported logs were created on that Raspberry Pi 3. My audio device is a HifiBerry DAC.
aplay -l
**** List of PLAYBACK Hardware Devices ****
card 0: sndrpihifiberry [snd_rpi_hifiberry_dac], device 0: HifiBerry DAC HiFi pcm5102a-hifi-0 [HifiBerry DAC HiFi pcm5102a-hifi-0]
Subdevices: 1/1
Subdevice #0: subdevice #0

Trying snapclient v.0.23 or v.0.22 with a smaller 'buffer_time' still produce dropouts:

snapclient --logfilter *:debug --player alsa:buffer_time=50,fragments=2 -h cms

pi@amadeus:~/downloads $ snapclient --logfilter *:debug --player alsa:buffer_time=50,fragments=2 -h cms
2021-01-19 13-36-11.797 [Info] (Connection) Resolving host IP for: cms
2021-01-19 13-36-11.861 [Info] (Connection) Connecting
2021-01-19 13-36-11.865 [Notice] (Connection) Connected to 192.168.1.37
2021-01-19 13-36-11.865 [Info] (Connection) My MAC: "b8:27:eb:4c:0b:d0", socket: 8
2021-01-19 13-36-12.073 [Debug] (Connection) outstanding async_write
2021-01-19 13-36-12.078 [Info] (Controller) ServerSettings - buffer: 1000, latency: 0, volume: 100, muted: 0
metadata:{"STREAM":"snapcast"}
2021-01-19 13-36-12.079 [Info] (Controller) Codec: flac, sampleformat: 44100:16:2
2021-01-19 13-36-12.079 [Info] (Player) Player name: alsa, device: default, description: <none>, idx: 3, sharing mode: unspecified, parameters: buffer_time=50,fragments=2
2021-01-19 13-36-12.079 [Info] (Player) Mixer mode: software, parameters: <none>
2021-01-19 13-36-12.079 [Info] (Player) Sampleformat: 44100:16:2, stream: 44100:16:2
2021-01-19 13-36-12.083 [Debug] (Alsa) PCM name: default
2021-01-19 13-36-12.083 [Debug] (Alsa) PCM state: PREPARED
2021-01-19 13-36-12.083 [Debug] (Alsa) channels: 2
2021-01-19 13-36-12.083 [Debug] (Alsa) rate: 44100 bps
2021-01-19 13-36-12.083 [Debug] (Alsa) frames: 5512
2021-01-19 13-36-12.083 [Debug] (Alsa) period time: 125000
2021-01-19 13-36-12.083 [Debug] (Alsa) setVolume exp with base 10: 1 => 1
2021-01-19 13-36-12.083 [Debug] (Alsa) Resizing buffer from 0 to 44100
2021-01-19 13-36-12.084 [Info] (Stream) no chunks available
2021-01-19 13-36-12.084 [Info] (Alsa) Failed to get chunk
2021-01-19 13-36-12.343 [Info] (Controller) diff to server [ms]: 6.789e+07
2021-01-19 13-36-12.888 [Debug] (Stream) Silent frames: 3003, frames: 5512, age: -68.114
2021-01-19 13-36-13.013 [Debug] (Stats) Chunk: 0        0       0       0       1       124     0
2021-01-19 13-36-14.013 [Debug] (Stats) Chunk: 0        0       0       0       9       125     0
2021-01-19 13-36-15.013 [Debug] (Stats) Chunk: 1        0       0       0       17      125     0
2021-01-19 13-36-16.013 [Debug] (Stats) Chunk: 2        1       1       1       25      125     0
2021-01-19 13-36-17.013 [Debug] (Stats) Chunk: 3        2       1       1       33      125     0
2021-01-19 13-36-18.013 [Debug] (Stats) Chunk: 4        3       2       2       41      125     0
2021-01-19 13-36-19.013 [Debug] (Stats) Chunk: 4        4       2       2       49      124     0
2021-01-19 13-36-20.023 [Debug] (Stats) Chunk: 5        4       2       2       57      124     0
2021-01-19 13-36-21.044 [Debug] (Stats) Chunk: 5        5       3       3       65      124     0
2021-01-19 13-36-22.064 [Debug] (Stats) Chunk: 8        6       3       3       73      125     0
2021-01-19 13-36-23.095 [Debug] (Stats) Chunk: 7        7       4       4       81      124     0
2021-01-19 13-36-23.869 [Error] (Alsa) XRUN: Broken pipe
2021-01-19 13-36-24.013 [Debug] (Stats) Chunk: -2427    8       4       4       89      111     0
2021-01-19 13-36-25.014 [Debug] (Stats) Chunk: -2426    7       4       4       97      124     0
2021-01-19 13-36-25.273 [Info] (Stream) pMiniBuffer->full() && (abs(pMiniBuffer->mean()) > 50): -242576
2021-01-19 13-36-25.523 [Debug] (Stream) Silent frames: 5183, frames: 5512, age: -117.55
2021-01-19 13-36-26.023 [Debug] (Stats) Chunk: 0        0       0       0       4       125     0
2021-01-19 13-36-27.034 [Debug] (Stats) Chunk: 0        0       0       0       12      124     0
2021-01-19 13-36-28.054 [Debug] (Stats) Chunk: 0        0       0       0       20      124     0
2021-01-19 13-36-29.094 [Debug] (Stats) Chunk: 1        0       0       0       28      115     0
2021-01-19 13-36-29.875 [Warn] (Alsa) snd_pcm_avail_delay failed: Broken pipe, avail: 5504, delay: 5513, retrying.
2021-01-19 13-36-29.885 [Warn] (Alsa) snd_pcm_avail_delay failed again: Broken pipe, avail: 5504, delay: 5513, using snd_pcm_avail and snd_pcm_delay.
2021-01-19 13-36-29.885 [Warn] (Alsa) snd_pcm_avail and snd_pcm_delay failed: Broken pipe, avail: -32, delay: 5513
2021-01-19 13-36-30.138 [Debug] (Stats) Chunk: -895     1       0       0       35      12      0
2021-01-19 13-36-31.013 [Debug] (Stats) Chunk: -894     0       0       0       42      125     0
2021-01-19 13-36-31.388 [Info] (Stream) pMiniBuffer->full() && (abs(pMiniBuffer->mean()) > 50): -89439
2021-01-19 13-36-31.513 [Debug] (Stream) Silent frames: 3943, frames: 5512, age: -89.427
2021-01-19 13-36-32.013 [Debug] (Stats) Chunk: 0        0       0       0       4       125     0

I tested also snapclient v.0.21. This version is running fine, witout any dropouts.
So, it seem´s that the cause is related to a change in Version v.0.22.

@mrdago mrdago closed this as completed Jan 19, 2021
@badaix badaix reopened this Jan 19, 2021
@badaix
Copy link
Owner

badaix commented Jan 19, 2021

thanks, but I don't think that sticking to an older version is a solution to this problem.

There are three parameters involved for alsa:

  1. fragment time
  2. fragments
  3. buffer time

where

  • buffer time is the total audio buffer "size" (= time from passing audio to the PCM device, until it's audible).
  • the buffer time is split into fragments * fragment time

There is always one fragment rendered, while another fragment is filled with new data that will be rendered later. For smooth playback without dropouts you will need at least two fragments, which actually seems not enough, so 3 or 4 are recommended.
I can reproduce dropouts if I configure two fragments, but I cannot reproduce your problem with my HiFiBerry DAC+ devices, nor with the integrated RPi PCM devices.

Your issue seems to be that Snapclient requests 4 fragments and 80ms buffer time (and expects to get 20ms fragments, but that's left to alsa and the hardware):

Jan 18 15:23:33 amadeus snapclient[929]: Using buffer_time: 80 ms, fragments: 4
Jan 18 15:23:33 amadeus snapclient[929]: PCM name: default, sample rate: 48000 Hz, channels: 2, buffer time: 250020 us, periods: 2, period time: 1250

What you get is 250ms buffer and 2 fragments (= periods), 125ms each.

The differences between Snapclient versions are:

  • 0.21: Requested 4 fragments with a fragment size of 30ms => buffer time = 120ms
  • 0.22: Requested 4 fragments with a fragment size of 15ms => buffer time = 60ms
  • 0.23: Requests X fragments (default 4) and buffer time Y (default 80) => fragment size 20ms

A request is just a request and alsa will try to apply them or use values close to the configured ones.
Can you test the 0.23 with buffer_time=120,fragments=4? This should result in 30ms fragments as they were used in 0.21

@mrdago
Copy link
Author

mrdago commented Jan 20, 2021

Using buffer_time=120,fragments=4 leads to a reduction of dropouts, but there are still scattered dropouts.

snapclient --logfilter *:debug --player alsa:buffer_time=120,fragments=4 -h cms

pi@amadeus:~/downloads $ snapclient --logfilter *:debug --player alsa:buffer_time=120,fragments=4 -h cms
2021-01-20 07-30-48.556 [Info] (Connection) Resolving host IP for: cms
2021-01-20 07-30-48.584 [Info] (Connection) Connecting
2021-01-20 07-30-48.588 [Notice] (Connection) Connected to 192.168.1.37
2021-01-20 07-30-48.588 [Info] (Connection) My MAC: "b8:27:eb:4c:0b:d0", socket: 8
2021-01-20 07-30-48.802 [Debug] (Connection) outstanding async_write
2021-01-20 07-30-48.806 [Info] (Controller) ServerSettings - buffer: 1000, latency: 0, volume: 100, muted: 0
metadata:{"STREAM":"snapcast"}
2021-01-20 07-30-48.808 [Info] (Controller) Codec: flac, sampleformat: 44100:16:2
2021-01-20 07-30-48.808 [Info] (Player) Player name: alsa, device: default, description: <none>, idx: 3, sharing mode: unspecified, parameters: buffer_time=120,fragments=4
2021-01-20 07-30-48.808 [Info] (Player) Mixer mode: software, parameters: <none>
2021-01-20 07-30-48.808 [Info] (Player) Sampleformat: 44100:16:2, stream: 44100:16:2
2021-01-20 07-30-48.808 [Info] (Alsa) Using buffer_time: 120 ms, fragments: 4
2021-01-20 07-30-48.812 [Info] (Alsa) PCM name: default, sample rate: 44100 Hz, channels: 2, buffer time: 250000 us, periods: 2, period time: 125000 us, period frames: 5512
2021-01-20 07-30-48.813 [Debug] (Alsa) setVolume exp with base 10: 1 => 1
2021-01-20 07-30-48.813 [Debug] (Alsa) Resizing buffer from 0 to 44100
2021-01-20 07-30-48.813 [Info] (Stream) No chunks available
2021-01-20 07-30-48.813 [Info] (Alsa) Failed to get chunk
2021-01-20 07-30-48.966 [Info] (Controller) diff to server [ms]: 1.32083e+08
2021-01-20 07-30-49.559 [Debug] (Stream) Silent frames: 4128, frames: 5512, age: -93.626
2021-01-20 07-30-49.685 [Debug] (Stats) Chunk: 0        0       0       0       1       125     0
2021-01-20 07-30-50.060 [Debug] (Stats) Chunk: 0        0       0       0       4       125     0
2021-01-20 07-30-51.060 [Debug] (Stats) Chunk: 0        0       0       0       12      125     0
2021-01-20 07-30-52.060 [Debug] (Stats) Chunk: 1        0       0       0       20      125     0
2021-01-20 07-30-53.060 [Debug] (Stats) Chunk: 2        1       1       1       28      125     0
2021-01-20 07-30-54.060 [Debug] (Stats) Chunk: 3        2       1       1       36      125     0
2021-01-20 07-30-55.060 [Debug] (Stats) Chunk: 4        3       2       2       44      125     0
2021-01-20 07-30-56.060 [Debug] (Stats) Chunk: 5        4       2       2       52      125     0
2021-01-20 07-30-57.059 [Debug] (Stats) Chunk: 5        4       2       2       60      125     0
2021-01-20 07-30-58.060 [Debug] (Stats) Chunk: 6        5       3       3       68      125     0
2021-01-20 07-30-59.059 [Debug] (Stats) Chunk: 7        6       3       3       76      125     0
2021-01-20 07-31-00.059 [Debug] (Stats) Chunk: 8        7       4       4       84      125     0
2021-01-20 07-31-01.060 [Debug] (Stats) Chunk: 9        8       4       4       92      125     0
2021-01-20 07-31-02.059 [Debug] (Stats) Chunk: 10       9       4       4       100     125     0
2021-01-20 07-31-03.059 [Debug] (Stats) Chunk: 9        9       5       5       108     125     -7
2021-01-20 07-31-04.059 [Debug] (Stats) Chunk: 7        9       6       5       116     125     -11
2021-01-20 07-31-05.059 [Debug] (Stats) Chunk: 5        8       6       5       124     125     -13
2021-01-20 07-31-06.059 [Debug] (Stats) Chunk: 3        6       6       5       132     125     -13
2021-01-20 07-31-07.059 [Debug] (Stats) Chunk: 1        4       6       5       140     125     -14
2021-01-20 07-31-08.059 [Debug] (Stats) Chunk: 0        2       6       5       148     125     -8
2021-01-20 07-31-09.059 [Debug] (Stats) Chunk: 0        0       6       4       156     125     -2
2021-01-20 07-31-10.059 [Debug] (Stats) Chunk: 0        0       6       4       164     125     -3
2021-01-20 07-31-11.059 [Debug] (Stats) Chunk: 1        0       6       4       172     125     -1
2021-01-20 07-31-12.059 [Debug] (Stats) Chunk: 0        0       4       4       180     125     -7
2021-01-20 07-31-13.059 [Debug] (Stats) Chunk: 0        0       2       3       188     125     -4
2021-01-20 07-31-14.059 [Debug] (Stats) Chunk: 0        0       1       3       196     125     -2
2021-01-20 07-31-15.059 [Debug] (Stats) Chunk: 1        0       1       3       204     125     -1
2021-01-20 07-31-16.059 [Debug] (Stats) Chunk: 1        1       1       2       212     125     -2
2021-01-20 07-31-17.059 [Debug] (Stats) Chunk: 2        1       1       2       220     125     -3
2021-01-20 07-31-18.059 [Debug] (Stats) Chunk: 2        2       1       2       228     125     -2
2021-01-20 07-31-19.059 [Debug] (Stats) Chunk: 2        2       1       2       236     125     -2
2021-01-20 07-31-20.059 [Debug] (Stats) Chunk: 2        2       1       2       244     125     -2
2021-01-20 07-31-21.059 [Debug] (Stats) Chunk: 3        2       1       2       252     125     -2
2021-01-20 07-31-22.059 [Debug] (Stats) Chunk: 3        3       1       2       260     125     -3
2021-01-20 07-31-23.059 [Debug] (Stats) Chunk: 3        3       2       2       268     125     -2
2021-01-20 07-31-24.059 [Debug] (Stats) Chunk: 3        3       2       2       276     125     -4
2021-01-20 07-31-25.059 [Debug] (Stats) Chunk: 3        3       2       3       284     125     -5
2021-01-20 07-31-26.059 [Debug] (Stats) Chunk: 3        3       2       3       292     125     -4
2021-01-20 07-31-26.941 [Error] (Alsa) XRUN while writing to PCM: Broken pipe
2021-01-20 07-31-27.184 [Debug] (Stats) Chunk: -2424    3       3       3       301     12      -5
2021-01-20 07-31-28.059 [Debug] (Stats) Chunk: -2424    2       3       3       308     125     0
2021-01-20 07-31-28.434 [Info] (Stream) pMiniBuffer->full() && (abs(pMiniBuffer->mean()) > 50): -242389
2021-01-20 07-31-28.684 [Debug] (Stream) Silent frames: 5175, frames: 5512, age: -117.357
2021-01-20 07-31-29.059 [Debug] (Stats) Chunk: 0        0       0       0       3       125     0
2021-01-20 07-31-30.059 [Debug] (Stats) Chunk: 0        0       0       0       11      125     0
2021-01-20 07-31-31.059 [Debug] (Stats) Chunk: 1        0       0       0       19      125     0
2021-01-20 07-31-32.059 [Debug] (Stats) Chunk: 2        1       0       0       27      125     0
2021-01-20 07-31-33.059 [Debug] (Stats) Chunk: 3        2       1       1       35      125     0
2021-01-20 07-31-34.064 [Debug] (Stats) Chunk: 3        2       1       1       43      125     0
2021-01-20 07-31-35.064 [Debug] (Stats) Chunk: 4        3       2       2       51      125     0
2021-01-20 07-31-36.064 [Debug] (Stats) Chunk: 5        4       2       2       59      125     0
2021-01-20 07-31-37.064 [Debug] (Stats) Chunk: 6        5       2       2       67      125     0
2021-01-20 07-31-38.064 [Debug] (Stats) Chunk: 7        6       3       3       75      125     0
2021-01-20 07-31-39.064 [Debug] (Stats) Chunk: 8        7       3       3       83      125     0
2021-01-20 07-31-39.449 [Warn] (Alsa) snd_pcm_avail_delay failed: Broken pipe (-32), avail: 5482, delay: 5543, using snd_pcm_avail amd snd_pcm_delay.
2021-01-20 07-31-39.450 [Warn] (Alsa) snd_pcm_delay failed: Broken pipe (-32), avail: -32, delay: 5543
2021-01-20 07-31-40.059 [Debug] (Stats) Chunk: -1036    7       3       3       90      125     0
2021-01-20 07-31-40.934 [Info] (Stream) pMiniBuffer->full() && (abs(pMiniBuffer->mean()) > 50): -103546
2021-01-20 07-31-41.059 [Debug] (Stream) Silent frames: 4566, frames: 5512, age: -103.55
2021-01-20 07-31-41.184 [Debug] (Stats) Chunk: 0        0       0       0       1       125     0
2021-01-20 07-31-42.059 [Debug] (Stats) Chunk: 0        0       0       0       8       125     0
2021-01-20 07-31-43.059 [Debug] (Stats) Chunk: 1        0       0       0       16      125     0
2021-01-20 07-31-44.059 [Debug] (Stats) Chunk: 2        1       1       1       24      125     0

@badaix
Copy link
Owner

badaix commented Jan 20, 2021

Thanks for testing this. It seems that alsa is still applying the same settings, especially 2 fragments (periods):

2021-01-20 07-30-48.812 [Info] (Alsa) PCM name: default, sample rate: 44100 Hz, channels: 2, buffer time: 250000 us, periods: 2, period time: 125000 us, period frames: 5512

I've now changed d03a9ea the alsa player to set the period time instead of the buffer time, as it was done in v0.21, you can find a snapshot debian package in actions

@mrdago
Copy link
Author

mrdago commented Jan 21, 2021

Dear Johannes,

GREAT WORK!

Running the pached version, I can't hear anymore dropouts and the log also don't show any hicups.
Thanks a lot!
For the case that you are looking for support in testing, feel free to send me a request. I'm willing to spend time for support as far as possible.

pi@amadeus:~/downloads $ snapclient -v
snapclient v0.23.0
Copyright (C) 2014-2020 BadAix (snapcast@badaix.de).
License GPLv3+: GNU GPL version 3 or later http://gnu.org/licenses/gpl.html.
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.

Written by Johannes M. Pohl.

pi@amadeus:~ $ snapclient --logfilter *:debug -h cms --latency=3 --player=alsa

2021-01-21 10-51-49.481 [Info] (Connection) Resolving host IP for: cms
2021-01-21 10-51-49.508 [Info] (Connection) Connecting
2021-01-21 10-51-49.514 [Notice] (Connection) Connected to 192.168.1.37
2021-01-21 10-51-49.514 [Info] (Connection) My MAC: "b8:27:eb:4c:0b:d0", socket: 8
2021-01-21 10-51-49.724 [Debug] (Connection) outstanding async_write
2021-01-21 10-51-50.034 [Info] (Controller) ServerSettings - buffer: 1000, latency: 0, volume: 100, muted: 0
metadata:{"STREAM":"snapcast"}
2021-01-21 10-51-50.034 [Info] (Controller) Codec: flac, sampleformat: 44100:16:2
2021-01-21 10-51-50.035 [Info] (Player) Player name: alsa, device: default, description: <none>, idx: 3, sharing mode: unspecified, parameters: <none>
2021-01-21 10-51-50.035 [Info] (Player) Mixer mode: software, parameters: <none>
2021-01-21 10-51-50.035 [Info] (Player) Sampleformat: 44100:16:2, stream: 44100:16:2
2021-01-21 10-51-50.035 [Info] (Alsa) Using buffer_time: 80 ms, fragments: 4
2021-01-21 10-51-50.038 [Info] (Alsa) Period time too small, changing from 20000 to 125000
2021-01-21 10-51-50.039 [Info] (Alsa) PCM name: default, sample rate: 44100 Hz, channels: 2, buffer time: 374988 us, periods: 3, period time: 125000 us, period frames: 5512
2021-01-21 10-51-50.040 [Debug] (Alsa) setVolume exp with base 10: 1 => 1
2021-01-21 10-51-50.040 [Debug] (Alsa) Resizing buffer from 0 to 66148
2021-01-21 10-51-50.040 [Info] (Stream) No chunks available
2021-01-21 10-51-50.040 [Info] (Alsa) Failed to get chunk
2021-01-21 10-51-50.536 [Debug] (Stream) Silent frames: 1684, frames: 5512, age: -38.189
2021-01-21 10-51-51.037 [Debug] (Stats) Chunk: 16       16      16      16      4       249     0
2021-01-21 10-51-51.604 [Info] (Controller) diff to server [ms]: 2.31431e+08
2021-01-21 10-51-52.036 [Debug] (Stats) Chunk: 1        1       1       1       11      250     0
2021-01-21 10-51-53.036 [Debug] (Stats) Chunk: 2        2       2       2       19      249     0
2021-01-21 10-51-54.036 [Debug] (Stats) Chunk: 3        2       2       2       27      249     0
2021-01-21 10-51-55.036 [Debug] (Stats) Chunk: 4        3       3       3       34      250     0
2021-01-21 10-51-56.036 [Debug] (Stats) Chunk: -10      4       3       3       42      249     0
2021-01-21 10-51-57.161 [Debug] (Stats) Chunk: -8       4       2       2       50      133     0
2021-01-21 10-51-58.036 [Debug] (Stats) Chunk: -7       -8      2       2       57      250     0
2021-01-21 10-51-59.036 [Debug] (Stats) Chunk: -6       -7      1       1       64      250     0
2021-01-21 10-52-00.036 [Debug] (Stats) Chunk: 9        -6      2       2       71      135     0
2021-01-21 10-52-01.036 [Debug] (Stats) Chunk: 9        8       2       2       79      250     0
2021-01-21 10-52-02.036 [Debug] (Stats) Chunk: 10       9       3       3       86      249     0
2021-01-21 10-52-03.036 [Debug] (Stats) Chunk: 11       10      3       3       94      249     0
2021-01-21 10-52-04.036 [Debug] (Stats) Chunk: 12       11      4       4       101     250     0
2021-01-21 10-52-05.036 [Debug] (Stats) Chunk: 12       12      4       4       109     250     -8
2021-01-21 10-52-06.036 [Debug] (Stats) Chunk: 11       12      8       4       117     250     -9
2021-01-21 10-52-07.037 [Debug] (Stats) Chunk: 8        11      9       8       125     249     -17
2021-01-21 10-52-08.036 [Debug] (Stats) Chunk: 20       10      9       8       132     250     -20
2021-01-21 10-52-09.036 [Debug] (Stats) Chunk: 16       16      10      8       140     250     -20
2021-01-21 10-52-10.036 [Debug] (Stats) Chunk: 12       16      11      9       148     250     -22
2021-01-21 10-52-11.036 [Debug] (Stats) Chunk: 8        14      11      9       155     250     -22
2021-01-21 10-52-12.036 [Debug] (Stats) Chunk: 4        9       11      9       163     250     -22
2021-01-21 10-52-13.036 [Debug] (Stats) Chunk: 32       8       11      9       171     250     -22
2021-01-21 10-52-14.036 [Debug] (Stats) Chunk: 28       30      12      9       179     250     -22
2021-01-21 10-52-15.036 [Debug] (Stats) Chunk: 27       29      12      9       187     250     -22
2021-01-21 10-52-16.036 [Debug] (Stats) Chunk: 23       27      13      10      195     250     -22
2021-01-21 10-52-17.036 [Debug] (Stats) Chunk: 21       24      16      10      203     250     -22
2021-01-21 10-52-18.036 [Debug] (Stats) Chunk: 17       21      18      10      211     250     -22
2021-01-21 10-52-19.036 [Debug] (Stats) Chunk: 18       18      18      11      219     250     -22
2021-01-21 10-52-20.036 [Debug] (Stats) Chunk: 14       16      18      11      227     250     -22
2021-01-21 10-52-21.036 [Debug] (Stats) Chunk: 10       14      17      11      235     250     -22
2021-01-21 10-52-22.036 [Debug] (Stats) Chunk: 7        11      17      11      243     250     -22
2021-01-21 10-52-23.036 [Debug] (Stats) Chunk: 3        9       17      11      251     250     -22
2021-01-21 10-52-24.036 [Debug] (Stats) Chunk: 0        5       17      10      258     250     -20
2021-01-21 10-52-25.036 [Debug] (Stats) Chunk: 0        0       16      10      266     250     0
2021-01-21 10-52-26.036 [Debug] (Stats) Chunk: 0        0       14      10      274     250     -5
2021-01-21 10-52-27.036 [Debug] (Stats) Chunk: 0        0       12      10      282     250     0
2021-01-21 10-52-28.036 [Debug] (Stats) Chunk: 1        0       9       9       290     250     0
2021-01-21 10-52-29.036 [Debug] (Stats) Chunk: 1        0       5       9       298     250     -8
2021-01-21 10-52-30.036 [Debug] (Stats) Chunk: 1        1       1       9       306     250     -5
2021-01-21 10-52-31.036 [Debug] (Stats) Chunk: 0        0       1       9       314     250     -2
2021-01-21 10-52-32.036 [Debug] (Stats) Chunk: 2        0       1       8       322     250     -1
2021-01-21 10-52-33.036 [Debug] (Stats) Chunk: 2        2       1       8       330     250     0
2021-01-21 10-52-34.036 [Debug] (Stats) Chunk: 6        2       1       8       338     250     0
2021-01-21 10-52-35.036 [Debug] (Stats) Chunk: 7        3       1       7       346     250     0
2021-01-21 10-52-36.036 [Debug] (Stats) Chunk: 7        6       1       7       354     250     0
2021-01-21 10-52-37.036 [Debug] (Stats) Chunk: 9        7       1       7       362     250     0
2021-01-21 10-52-38.036 [Debug] (Stats) Chunk: 9        9       2       8       370     250     -2
2021-01-21 10-52-39.036 [Debug] (Stats) Chunk: 9        9       2       8       378     250     -4
2021-01-21 10-52-40.036 [Debug] (Stats) Chunk: 9        9       3       8       386     250     -5
2021-01-21 10-52-41.036 [Debug] (Stats) Chunk: 8        9       6       8       394     250     -6

@badaix
Copy link
Owner

badaix commented Jan 21, 2021

Sounds good (literally) :)

There is still a difference between v0.19 and v0.23.dev: the number next to the end is 125 vs 250. This number is the playout time [ms] for the currently requested audio chunk, which will be a multiple of the fragment size (in your case the fragment size seems to be fixed to 125ms (period time: 125000). So it seems that the v0.19 uses one fragment less than the 0.23:

v0.19:

2021-01-18 15-31-27 [Info] (Stream) Chunk: 3    0       0       0       36      125     0

v0.23.dev:

2021-01-21 10-52-34.036 [Debug] (Stats) Chunk: 6        2       1       8       338     250     0

I want to accept your offer to test one more development version (in actions with the commit message Set buffer time instead of periods). This version dumps the raw parameters of the audio device to the debug log (such as min and max fragment size) and will work like the 0.19 (requesting fragment size and buffer size, instead of fragment size and number of fragments from alsa). I will probably revert this change, but would like to see the debug log output of this version with the default settings buffer_time=80,fragments=4 and with the v0.19 settings buffer_time=120,fragments=4

Thanks in advance

PS: the version number of this snapshot is set to 0.23.100

@mrdago
Copy link
Author

mrdago commented Jan 22, 2021

Ok, here we are ...

pi@amadeus:~/downloads $ snapclient -v
snapclient v0.23.100, built Jan 9 2021

 
pi@amadeus:~/downloads $ snapclient --user snapclient:snapclient --logfilter *:debug -h cms --player alsa
2021-01-22 06-50-45.650 [Info] (Connection) Resolving host IP for: cms
2021-01-22 06-50-45.656 [Info] (Connection) Connecting
2021-01-22 06-50-45.674 [Notice] (Connection) Connected to 192.168.1.37
2021-01-22 06-50-45.675 [Info] (Connection) My MAC: "80:1f:02:8a:4f:26", socket: 8
2021-01-22 06-50-45.880 [Debug] (Connection) outstanding async_write
2021-01-22 06-50-45.885 [Info] (Controller) ServerSettings - buffer: 1000, latency: 0, volume: 100, muted: 0
metadata:{"STREAM":"snapcast"}
2021-01-22 06-50-45.885 [Info] (Controller) Codec: flac, sampleformat: 44100:16:2
2021-01-22 06-50-45.885 [Info] (Player) Player name: alsa, device: default, description: <none>, idx: 3, sharing mode: unspecified, parameters: <none>
2021-01-22 06-50-45.885 [Info] (Player) Mixer mode: software, parameters: <none>
2021-01-22 06-50-45.885 [Info] (Player) Sampleformat: 44100:16:2, stream: 44100:16:2
2021-01-22 06-50-45.885 [Info] (Alsa) Using buffer_time: 80 ms, fragments: 4
2021-01-22 06-50-45.888 [Debug] (Alsa) ACCESS:  MMAP_INTERLEAVED MMAP_NONINTERLEAVED MMAP_COMPLEX RW_INTERLEAVED RW_NONINTERLEAVED
2021-01-22 06-50-45.888 [Debug] (Alsa) FORMAT:  S8 U8 S16_LE S16_BE U16_LE U16_BE S24_LE S24_BE U24_LE U24_BE S32_LE S32_BE U32_LE U32_BE FLOAT_LE FLOAT_BE FLOAT64_LE FLOAT64_BE MU_LAW A_LAW IMA_ADPCM S20_LE S20_BE U20_LE U20_BE S24_3LE S24_3BE U24_3LE U24_3BE S20_3LE S20_3BE U20_3LE U20_3BE S18_3LE S18_3BE U18_3LE U18_3BE
2021-01-22 06-50-45.888 [Debug] (Alsa) SUBFORMAT:  STD
2021-01-22 06-50-45.888 [Debug] (Alsa) SAMPLE_BITS: [4 64]
2021-01-22 06-50-45.888 [Debug] (Alsa) FRAME_BITS: [4 640000]
2021-01-22 06-50-45.888 [Debug] (Alsa) CHANNELS: [1 10000]
2021-01-22 06-50-45.888 [Debug] (Alsa) RATE: [4000 4294967295)
2021-01-22 06-50-45.888 [Debug] (Alsa) PERIOD_TIME: 125000
2021-01-22 06-50-45.888 [Debug] (Alsa) PERIOD_SIZE: [500 536870912)
2021-01-22 06-50-45.888 [Debug] (Alsa) PERIOD_BYTES: [250 4294967295)
2021-01-22 06-50-45.888 [Debug] (Alsa) PERIODS: (0 3221226)
2021-01-22 06-50-45.888 [Debug] (Alsa) BUFFER_TIME: [1 4294967295]
2021-01-22 06-50-45.888 [Debug] (Alsa) BUFFER_SIZE: [1000 1610612735]
2021-01-22 06-50-45.888 [Debug] (Alsa) BUFFER_BYTES: [500 4294967295]
2021-01-22 06-50-45.888 [Debug] (Alsa) TICK_TIME: ALL
2021-01-22 06-50-45.891 [Info] (Alsa) PCM name: default, sample rate: 44100 Hz, channels: 2, buffer time: 250000 us, periods: 2, period time: 125000 us, period frames: 5512
2021-01-22 06-50-45.891 [Debug] (Alsa) setVolume exp with base 10: 1 => 1
2021-01-22 06-50-45.891 [Debug] (Alsa) Resizing buffer from 0 to 44100
2021-01-22 06-50-45.892 [Info] (Stream) No chunks available
2021-01-22 06-50-45.892 [Info] (Alsa) Failed to get chunk
2021-01-22 06-50-46.637 [Debug] (Stream) Silent frames: 3713, frames: 5512, age: -84.204
2021-01-22 06-50-46.645 [Info] (Controller) diff to server [ms]: 3.02419e+08
2021-01-22 06-50-46.762 [Debug] (Stats) Chunk: -3       -3      -3      -3      1       125     0
2021-01-22 06-50-47.012 [Debug] (Stats) Chunk: -2       -2      -2      -2      3       125     0
2021-01-22 06-50-48.012 [Debug] (Stats) Chunk: -1       -2      -2      -2      11      125     0
2021-01-22 06-50-49.012 [Debug] (Stats) Chunk: 0        -1      -1      -1      19      125     0
2021-01-22 06-50-50.012 [Debug] (Stats) Chunk: 0        0       -1      -1      27      125     0
2021-01-22 06-50-51.012 [Debug] (Stats) Chunk: 0        0       0       0       35      125     0
2021-01-22 06-50-52.012 [Debug] (Stats) Chunk: 1        0       0       0       43      125     0
2021-01-22 06-50-53.012 [Debug] (Stats) Chunk: -1       1       0       0       51      125     0
2021-01-22 06-50-54.012 [Debug] (Stats) Chunk: -1       0       0       0       59      125     0
2021-01-22 06-50-55.012 [Debug] (Stats) Chunk: -2       -1      0       0       67      125     0
2021-01-22 06-50-56.012 [Debug] (Stats) Chunk: 0        -1      0       0       75      125     0
2021-01-22 06-50-57.012 [Debug] (Stats) Chunk: -1       0       0       0       83      125     0
2021-01-22 06-50-58.012 [Debug] (Stats) Chunk: 0        0       0       0       91      125     0
2021-01-22 06-50-59.012 [Debug] (Stats) Chunk: -1       0       0       0       99      125     0
2021-01-22 06-51-00.012 [Debug] (Stats) Chunk: 1        0       0       0       107     125     0
2021-01-22 06-51-01.012 [Debug] (Stats) Chunk: 2        0       0       0       115     125     0
2021-01-22 06-51-01.519 [Error] (Alsa) XRUN while writing to PCM: Broken pipe
2021-01-22 06-51-02.012 [Debug] (Stats) Chunk: -2426    1       0       0       123     125     0
2021-01-22 06-51-03.012 [Info] (Stream) pMiniBuffer->full() && (abs(pMiniBuffer->mean()) > 50): -242579
2021-01-22 06-51-03.012 [Debug] (Stats) Chunk: -2426    -2426   0       0       131     125     0
2021-01-22 06-51-03.262 [Debug] (Stream) Silent frames: 5185, frames: 5512, age: -117.59
2021-01-22 06-51-04.012 [Debug] (Stats) Chunk: 0        0       0       0       6       125     0
2021-01-22 06-51-05.012 [Debug] (Stats) Chunk: 1        0       0       0       14      125     0
2021-01-22 06-51-06.012 [Debug] (Stats) Chunk: 0        0       0       0       22      125     0
2021-01-22 06-51-07.012 [Debug] (Stats) Chunk: 3        1       0       0       30      125     0
2021-01-22 06-51-08.012 [Debug] (Stats) Chunk: 1        1       0       0       38      125     0
2021-01-22 06-51-09.012 [Debug] (Stats) Chunk: 2        1       1       1       46      125     0
2021-01-22 06-51-10.012 [Debug] (Stats) Chunk: 1        1       1       1       54      125     0
2021-01-22 06-51-11.012 [Debug] (Stats) Chunk: 2        2       1       1       62      125     0
2021-01-22 06-51-12.012 [Debug] (Stats) Chunk: 3        2       1       1       70      125     0
2021-01-22 06-51-13.012 [Debug] (Stats) Chunk: 4        3       1       1       78      125     0
2021-01-22 06-51-14.012 [Debug] (Stats) Chunk: 4        3       2       2       86      125     0
2021-01-22 06-51-15.012 [Debug] (Stats) Chunk: 5        4       2       2       94      125     0
2021-01-22 06-51-16.012 [Debug] (Stats) Chunk: 6        5       2       2       102     125     0
2021-01-22 06-51-17.012 [Debug] (Stats) Chunk: 5        5       2       2       110     125     -4
2021-01-22 06-51-18.017 [Debug] (Stats) Chunk: 5        5       3       2       118     125     -5
2021-01-22 06-51-18.651 [Warn] (Alsa) snd_pcm_avail_delay failed: Broken pipe (-32), avail: 5453, delay: 5564, using snd_pcm_avail amd snd_pcm_delay.
2021-01-22 06-51-18.652 [Warn] (Alsa) snd_pcm_delay failed: Broken pipe (-32), avail: -32, delay: 5564
2021-01-22 06-51-19.012 [Debug] (Stats) Chunk: -1044    5       3       2       125     125     -5
2021-01-22 06-51-20.022 [Debug] (Stats) Chunk: -1043    -1043   3       2       133     120     0
2021-01-22 06-51-20.147 [Info] (Stream) pMiniBuffer->full() && (abs(pMiniBuffer->mean()) > 50): -104389
2021-01-22 06-51-20.272 [Debug] (Stream) Silent frames: 4602, frames: 5512, age: -104.376
2021-01-22 06-51-21.032 [Debug] (Stats) Chunk: 0        0       0       0       6       120     0

pi@amadeus:~/downloads $ snapclient -v
snapclient v0.19.0

pi@amadeus:~/downloads $ snapclient --user snapclient:snapclient --logfilter *:debug -h cms
2021-01-22 06-59-38 [Info] (main) Latency: 0
2021-01-22 06-59-38 [Notice] (start) Connected to 192.168.1.37
2021-01-22 06-59-38 [Info] (getMacAddress) My MAC: "80:1f:02:8a:4f:26", socket: 6
2021-01-22 06-59-38 [Info] (onMessageReceived) ServerSettings - buffer: 1000, latency: 0, volume: 100, muted: 0
metadata:{"STREAM":"snapcast"}
2021-01-22 06-59-38 [Info] (onMessageReceived) Codec: flac
2021-01-22 06-59-38 [Notice] (state) sampleformat: 44100:16:2
2021-01-22 06-59-38 [Info] (Alsa) frames: 5512
2021-01-22 06-59-38 [Info] (Alsa) Resizing buffer from 0 to 44100
2021-01-22 06-59-38 [Info] (Stream) no chunks available
2021-01-22 06-59-38 [Info] (Alsa) Failed to get chunk
2021-01-22 06-59-39 [Info] (Stream) Chunk: 0    0       0       0       1       125     0
2021-01-22 06-59-39 [Info] (worker) diff to server [ms]: 3.02419e+08
2021-01-22 06-59-40 [Info] (Stream) Chunk: 0    0       0       0       5       125     0
2021-01-22 06-59-41 [Info] (Stream) Chunk: 0    0       0       0       13      125     0
2021-01-22 06-59-42 [Info] (Stream) Chunk: 1    0       0       0       21      125     0
2021-01-22 06-59-43 [Info] (Stream) Chunk: 2    1       0       0       29      125     0
2021-01-22 06-59-44 [Info] (Stream) Chunk: 3    2       1       1       37      125     0
2021-01-22 06-59-45 [Info] (Stream) Chunk: 4    3       1       1       45      125     0
2021-01-22 06-59-46 [Info] (Stream) Chunk: 5    4       2       2       53      125     0
2021-01-22 06-59-47 [Info] (Stream) Chunk: 6    5       2       2       61      125     0
2021-01-22 06-59-48 [Info] (Stream) Chunk: 7    6       3       3       69      125     0
2021-01-22 06-59-49 [Info] (Stream) Chunk: 8    7       3       3       77      125     0
2021-01-22 06-59-50 [Info] (Stream) Chunk: 9    8       3       3       85      125     0
2021-01-22 06-59-51 [Info] (Stream) Chunk: 10   9       4       4       93      125     0
2021-01-22 06-59-52 [Info] (Stream) Chunk: 11   10      5       5       101     125     0
2021-01-22 06-59-53 [Info] (Stream) Chunk: 10   10      6       5       109     125     -10
2021-01-22 06-59-54 [Info] (Stream) Chunk: 7    10      7       6       117     125     -13
2021-01-22 06-59-55 [Info] (Stream) Chunk: 5    8       7       6       125     125     -15
2021-01-22 06-59-56 [Info] (Stream) Chunk: 2    5       7       5       133     125     -16
2021-01-22 06-59-57 [Info] (Stream) Chunk: 0    3       7       5       141     125     -13
2021-01-22 06-59-58 [Info] (Stream) Chunk: 0    0       7       5       149     125     -4
2021-01-22 06-59-59 [Info] (Stream) Chunk: 1    0       7       4       157     125     0
2021-01-22 07-00-00 [Info] (Stream) Chunk: 1    0       7       4       165     125     -6
2021-01-22 07-00-01 [Info] (Stream) Chunk: 0    0       5       3       173     125     -6
2021-01-22 07-00-02 [Info] (Stream) Chunk: 0    0       3       3       181     125     -4

@badaix
Copy link
Owner

badaix commented Jan 22, 2021

Thanks :)

with the v0.19 settings buffer_time=120,fragments=4

Sorry, what I meant is to run the 0.23.100 with --player alsa:buffer_time=120,fragments=4, which reflects the defaults that were used in 0.19

Edit: the 0.23.100 log looks already as expected, the default is to use buffer_time 80 with 4 fragments, so Snapclient requests a fragment time of 20 (= 80 / 4) and gets 125 (the only fragment time supported by your DAC (or driver)), then Snapclient requests a buffer time "near to 80" and gets 250, because alsa decides to use at least two fragments (which is perfectly reasonable, one fragment will not work without audible drops).

Now I'm still curious what you will get with buffer_time=120,fragments=4, I would expect the same.

FYI: The 0.23.100 heuristic is the same that the alsa tool aplay applies: It chooses a default buffer_time of 500ms with 4 fragments. It first requests the fragment_time (125ms), followed by the buffer time. Because Snapclient is interested in lowering the latency, I think it makes more sense to configure the desired latency (i.e. buffer_time) and request a fragment_time the device is capable of and then configure the number of fragments to lower the risk of getting dropouts.

@mrdago
Copy link
Author

mrdago commented Jan 22, 2021

First the good news, version 0.23.100 with parameter buffer_time=120,fragments=4 is running without any errors on player amadeus.
The bad news, and that is really strange, I tested v0.23.100 on a another client a Rapberry Pi Zero. This client has no issues with snapclient v.0.19, but with version v.0.23.100 this client shows up with dropouts (see attached log).

Here are the logs from client amadeus (Raspberry Pi 3 with audio device driver sndrpihifiberry ) and client ludwig a Raspberry Pi Zero with the same audio device driver as client amadeus.

pi@amadeus:~/downloads $ snapclient --user snapclient:snapclient --logfilter *:debug -h cms --player alsa:buffer_time=120,fragments=4

2021-01-22 16-00-26.249 [Info] (Connection) Resolving host IP for: cms
2021-01-22 16-00-26.254 [Info] (Connection) Connecting
2021-01-22 16-00-26.274 [Notice] (Connection) Connected to 192.168.1.37
2021-01-22 16-00-26.275 [Info] (Connection) My MAC: "80:1f:02:8a:4f:26", socket: 8
2021-01-22 16-00-26.478 [Debug] (Connection) outstanding async_write
2021-01-22 16-00-26.482 [Info] (Controller) ServerSettings - buffer: 1000, latency: 0, volume: 100, muted: 0
metadata:{"STREAM":"snapcast"}
2021-01-22 16-00-26.483 [Info] (Controller) Codec: flac, sampleformat: 44100:16:2
2021-01-22 16-00-26.483 [Info] (Player) Player name: alsa, device: default, description: <none>, idx: 3, sharing mode: unspecified, parameters: buffer_time=120,fragments=4
2021-01-22 16-00-26.483 [Info] (Player) Mixer mode: software, parameters: <none>
2021-01-22 16-00-26.483 [Info] (Player) Sampleformat: 44100:16:2, stream: 44100:16:2
2021-01-22 16-00-26.483 [Info] (Alsa) Using buffer_time: 120 ms, fragments: 4
2021-01-22 16-00-26.487 [Info] (Alsa) Period time too small, changing from 30000 to 125000
2021-01-22 16-00-26.488 [Info] (Alsa) PCM name: default, sample rate: 44100 Hz, channels: 2, buffer time: 374988 us, periods: 3, period time: 125000 us, period frames: 5512
2021-01-22 16-00-26.488 [Debug] (Alsa) setVolume exp with base 10: 1 => 1
2021-01-22 16-00-26.488 [Debug] (Alsa) Resizing buffer from 0 to 66148
2021-01-22 16-00-26.488 [Info] (Stream) No chunks available
2021-01-22 16-00-26.488 [Info] (Alsa) Failed to get chunk
2021-01-22 16-00-27.109 [Debug] (Stream) Silent frames: 4841, frames: 5512, age: -109.783
2021-01-22 16-00-27.144 [Info] (Controller) diff to server [ms]: 3.34453e+08
2021-01-22 16-00-27.234 [Debug] (Stats) Chunk: -3       -3      -3      -3      1       250     0
2021-01-22 16-00-28.109 [Debug] (Stats) Chunk: -2       -2      -2      -2      8       250     0
2021-01-22 16-00-29.109 [Debug] (Stats) Chunk: -1       -2      -2      -2      16      250     0
2021-01-22 16-00-30.109 [Debug] (Stats) Chunk: -1       -2      -2      -2      24      250     0
2021-01-22 16-00-31.109 [Debug] (Stats) Chunk: 0        -1      -2      -2      32      250     0
2021-01-22 16-00-32.109 [Debug] (Stats) Chunk: 0        0       -1      -1      39      250     0
2021-01-22 16-00-33.109 [Debug] (Stats) Chunk: 1        0       -1      -1      47      250     0
2021-01-22 16-00-34.109 [Debug] (Stats) Chunk: 2        1       0       0       55      250     0
2021-01-22 16-00-35.109 [Debug] (Stats) Chunk: 3        1       0       0       62      250     0
2021-01-22 16-00-36.109 [Debug] (Stats) Chunk: 3        2       0       0       70      250     0
2021-01-22 16-00-37.109 [Debug] (Stats) Chunk: 4        3       0       0       78      250     0
2021-01-22 16-00-38.109 [Debug] (Stats) Chunk: 4        3       0       0       85      250     0
2021-01-22 16-00-39.109 [Debug] (Stats) Chunk: 5        4       1       1       93      250     0
2021-01-22 16-00-40.109 [Debug] (Stats) Chunk: 4        4       1       1       101     250     0
2021-01-22 16-00-41.109 [Debug] (Stats) Chunk: 6        5       2       2       108     250     -2
2021-01-22 16-00-42.109 [Debug] (Stats) Chunk: 4        4       3       2       116     250     -4
2021-01-22 16-00-43.109 [Debug] (Stats) Chunk: 5        6       3       2       124     250     -7
2021-01-22 16-00-44.109 [Debug] (Stats) Chunk: 5        5       3       3       131     250     -6
2021-01-22 16-00-45.109 [Debug] (Stats) Chunk: 4        5       4       3       139     250     -7
2021-01-22 16-00-46.109 [Debug] (Stats) Chunk: 1        4       4       3       147     250     -9
2021-01-22 16-00-47.109 [Debug] (Stats) Chunk: 0        2       4       2       154     250     -9
2021-01-22 16-00-48.109 [Debug] (Stats) Chunk: 0        0       4       2       162     250     -1
2021-01-22 16-00-49.109 [Debug] (Stats) Chunk: 0        0       4       2       170     250     0
2021-01-22 16-00-50.109 [Debug] (Stats) Chunk: 0        0       4       2       177     250     0
2021-01-22 16-00-51.109 [Debug] (Stats) Chunk: 1        0       4       1       185     250     -6
2021-01-22 16-00-52.109 [Debug] (Stats) Chunk: 0        1       2       1       193     250     -5
2021-01-22 16-00-53.109 [Debug] (Stats) Chunk: 1        1       1       1       200     250     -2
2021-01-22 16-00-54.109 [Debug] (Stats) Chunk: 1        1       1       1       208     250     -2
2021-01-22 16-00-55.109 [Debug] (Stats) Chunk: 2        1       1       1       216     250     -2
2021-01-22 16-00-56.109 [Debug] (Stats) Chunk: 3        2       1       1       223     250     -2
2021-01-22 16-00-57.109 [Debug] (Stats) Chunk: 5        3       1       1       231     250     -2
2021-01-22 16-00-58.109 [Debug] (Stats) Chunk: 3        3       1       2       239     250     -3
2021-01-22 16-00-59.109 [Debug] (Stats) Chunk: 4        4       1       2       246     250     -2
2021-01-22 16-01-00.109 [Debug] (Stats) Chunk: 3        4       1       2       254     250     -2
2021-01-22 16-01-01.109 [Debug] (Stats) Chunk: 4        4       2       2       262     250     -2

Now, the test on the Raspberry Pi Zero
pi@ludwig:~/install $ cat /sys/firmware/devicetree/base/model
Rapberry Pi Zero W Rev 1.1

pi@ludwig:~ $ aplay -l
**** Liste der Hardware-Geräte (PLAYBACK) ****
Karte 0: sndrpihifiberry [snd_rpi_hifiberry_dac], Gerät 0: HifiBerry DAC HiFi pcm5102a-hifi-0 [HifiBerry DAC HiFi pcm5102a-hifi-0]

pi@ludwig:~/downloads $ snapclient --logfilter *:debug -h cms --player alsa
2021-01-22 19-36-00.972 [Info] (Connection) Resolving host IP for: cms
2021-01-22 19-36-00.988 [Info] (Connection) Connecting
2021-01-22 19-36-00.992 [Notice] (Connection) Connected to 192.168.1.37
2021-01-22 19-36-00.995 [Info] (Connection) My MAC: "80:1f:02:b3:46:c1", socket: 8
2021-01-22 19-36-02.360 [Debug] (Connection) outstanding async_write
2021-01-22 19-36-02.410 [Info] (Controller) ServerSettings - buffer: 1000, latency: 0, volume: 100, muted: 0
metadata:{"STREAM":"snapcast"}
2021-01-22 19-36-02.416 [Info] (Controller) Codec: flac, sampleformat: 44100:16:2
2021-01-22 19-36-02.418 [Info] (Player) Player name: alsa, device: default, description: <none>, idx: 3, sharing mode: unspecified, parameters: <none>
2021-01-22 19-36-02.421 [Info] (Player) Mixer mode: software, parameters: <none>
2021-01-22 19-36-02.422 [Info] (Player) Sampleformat: 44100:16:2, stream: 44100:16:2
2021-01-22 19-36-02.427 [Info] (Alsa) Using buffer_time: 80 ms, fragments: 4
2021-01-22 19-36-02.435 [Debug] (Alsa) ACCESS:  MMAP_INTERLEAVED MMAP_NONINTERLEAVED MMAP_COMPLEX RW_INTERLEAVED RW_NONINTERLEAVED
2021-01-22 19-36-02.435 [Debug] (Alsa) FORMAT:  S8 U8 S16_LE S16_BE U16_LE U16_BE S24_LE S24_BE U24_LE U24_BE S32_LE S32_BE U32_LE U32_BE FLOAT_LE FLOAT_BE FLOAT64_LE FLOAT64_BE MU_LAW A_LAW IMA_ADPCM S20_LE S20_BE U20_LE U20_BE S24_3LE S24_3BE U24_3LE U24_3BE S20_3LE S20_3BE U20_3LE U20_3BE S18_3LE S18_3BE U18_3LE U18_3BE
2021-01-22 19-36-02.435 [Debug] (Alsa) SUBFORMAT:  STD
2021-01-22 19-36-02.435 [Debug] (Alsa) SAMPLE_BITS: [4 64]
2021-01-22 19-36-02.435 [Debug] (Alsa) FRAME_BITS: [4 640000]
2021-01-22 19-36-02.435 [Debug] (Alsa) CHANNELS: [1 10000]
2021-01-22 19-36-02.435 [Debug] (Alsa) RATE: [4000 4294967295)
2021-01-22 19-36-02.435 [Debug] (Alsa) PERIOD_TIME: 125000
2021-01-22 19-36-02.435 [Debug] (Alsa) PERIOD_SIZE: [500 536870912)
2021-01-22 19-36-02.435 [Debug] (Alsa) PERIOD_BYTES: [250 4294967295)
2021-01-22 19-36-02.435 [Debug] (Alsa) PERIODS: (0 3221226)
2021-01-22 19-36-02.435 [Debug] (Alsa) BUFFER_TIME: [1 4294967295]
2021-01-22 19-36-02.435 [Debug] (Alsa) BUFFER_SIZE: [1000 1610612735]
2021-01-22 19-36-02.435 [Debug] (Alsa) BUFFER_BYTES: [500 4294967295]
2021-01-22 19-36-02.435 [Debug] (Alsa) TICK_TIME: ALL
2021-01-22 19-36-02.457 [Info] (Alsa) PCM name: default, sample rate: 44100 Hz, channels: 2, buffer time: 250000 us, periods: 2, period time: 125000 us, period frames: 5512
2021-01-22 19-36-02.460 [Debug] (Player) setVolume exp with base 10: 1 => 1
2021-01-22 19-36-02.469 [Debug] (Alsa) Resizing buffer from 0 to 44100
2021-01-22 19-36-02.668 [Info] (Controller) diff to server [ms]: -1.62166e+07
2021-01-22 19-36-03.120 [Debug] (Stream) Silent frames: 5036, frames: 5527, age: -114.197
2021-01-22 19-36-03.250 [Debug] (Stats) Chunk: 0        0       0       0       1       119     0
2021-01-22 19-36-04.020 [Debug] (Stats) Chunk: 0        0       0       0       7       120     0
2021-01-22 19-36-05.041 [Debug] (Stats) Chunk: 1        0       0       0       15      124     0
2021-01-22 19-36-06.073 [Debug] (Stats) Chunk: 2        1       1       1       23      123     0
2021-01-22 19-36-07.088 [Debug] (Stats) Chunk: 3        2       1       1       31      120     0
2021-01-22 19-36-07.475 [Error] (Alsa) XRUN while writing to PCM: Broken pipe
2021-01-22 19-36-08.126 [Debug] (Stats) Chunk: -2398    2       1       1       40      120     0
2021-01-22 19-36-08.892 [Info] (Stream) pMiniBuffer->full() && (abs(pMiniBuffer->mean()) > 50): -239807
2021-01-22 19-36-09.148 [Debug] (Stream) Silent frames: 5031, frames: 5726, age: -114.099
2021-01-22 19-36-09.273 [Debug] (Stats) Chunk: 1        1       1       1       1       124     0
2021-01-22 19-36-10.035 [Debug] (Stats) Chunk: 0        0       0       0       7       123     0
2021-01-22 19-36-11.066 [Debug] (Stats) Chunk: 2        1       1       1       15      117     0
2021-01-22 19-36-12.087 [Debug] (Stats) Chunk: 3        2       2       2       23      122     0
2021-01-22 19-36-13.107 [Debug] (Stats) Chunk: 3        3       2       2       31      117     0
2021-01-22 19-36-13.113 [Error] (Alsa) XRUN while writing to PCM: Broken pipe
2021-01-22 19-36-13.621 [Warn] (Alsa) snd_pcm_avail_delay failed: Broken pipe (-32), avail: 5703, delay: 5315, using snd_pcm_avail amd snd_pcm_delay.
2021-01-22 19-36-13.629 [Warn] (Alsa) snd_pcm_delay failed: Broken pipe (-32), avail: -32, delay: 5315
2021-01-22 19-36-14.110 [Debug] (Stats) Chunk: -3264    3       2       2       38      124     0
2021-01-22 19-36-14.746 [Info] (Stream) pMiniBuffer->full() && (abs(pMiniBuffer->mean()) > 50): -234543
2021-01-22 19-36-15.130 [Debug] (Stream) Silent frames: 3141, frames: 5688, age: -71.234
2021-01-22 19-36-15.256 [Debug] (Stats) Chunk: 0        0       0       0       1       124     0
2021-01-22 19-36-15.898 [Error] (Alsa) XRUN while writing to PCM: Broken pipe
2021-01-22 19-36-16.110 [Debug] (Stats) Chunk: -2331    0       0       0       8       51      0
2021-01-22 19-36-17.120 [Debug] (Stats) Chunk: -2330    -2330   -2330   -2330   16      124     0

If I switch back to snapclient v.0.19, everything is ok:

pi@ludwig:~/downloads $ snapclient --logfilter *:debug -h cms
2021-01-22 20-04-44 [Info] (main) Latency: 0
2021-01-22 20-04-44 [Notice] (start) Connected to 192.168.1.37
2021-01-22 20-04-44 [Info] (getMacAddress) My MAC: "80:1f:02:b3:46:c1", socket: 6
2021-01-22 20-04-45 [Info] (onMessageReceived) ServerSettings - buffer: 1000, latency: 0, volume: 100, muted: 0
metadata:{"STREAM":"snapcast"}
2021-01-22 20-04-45 [Info] (onMessageReceived) Codec: flac
2021-01-22 20-04-45 [Notice] (state) sampleformat: 44100:16:2
2021-01-22 20-04-45 [Info] (Alsa) frames: 5512
2021-01-22 20-04-45 [Info] (Alsa) Resizing buffer from 0 to 44100
2021-01-22 20-04-45 [Info] (worker) diff to server [ms]: -1.62166e+07
2021-01-22 20-04-46 [Info] (Stream) Chunk: 0    0       0       0       1       129     0
2021-01-22 20-04-47 [Info] (Stream) Chunk: 0    0       0       0       7       123     0
2021-01-22 20-04-48 [Info] (Stream) Chunk: 1    0       0       0       15      123     0
2021-01-22 20-04-49 [Info] (Stream) Chunk: 1    0       0       0       23      124     0
2021-01-22 20-04-50 [Info] (Stream) Chunk: 2    1       1       1       31      127     0
2021-01-22 20-04-51 [Info] (Stream) Chunk: 2    2       1       1       39      129     0
2021-01-22 20-04-52 [Info] (Stream) Chunk: 4    2       1       1       47      124     0
2021-01-22 20-04-53 [Info] (Stream) Chunk: 4    4       2       2       55      124     0
2021-01-22 20-04-54 [Info] (Stream) Chunk: 6    4       2       2       63      127     0
2021-01-22 20-04-55 [Info] (Stream) Chunk: 7    6       2       2       71      120     0
2021-01-22 20-04-56 [Info] (Stream) Chunk: 8    6       3       3       79      127     0
2021-01-22 20-04-57 [Info] (Stream) Chunk: 7    7       3       3       87      123     0
2021-01-22 20-04-58 [Info] (Stream) Chunk: 9    8       4       4       95      124     0
2021-01-22 20-04-59 [Info] (Stream) Chunk: 10   9       4       4       103     124     -2
2021-01-22 20-05-00 [Info] (Stream) Chunk: 9    9       6       5       111     124     -9
2021-01-22 20-05-01 [Info] (Stream) Chunk: 7    9       6       5       119     125     -12
2021-01-22 20-05-02 [Info] (Stream) Chunk: 5    7       6       5       127     124     -13
2021-01-22 20-05-03 [Info] (Stream) Chunk: 2    5       6       5       135     124     -14
2021-01-22 20-05-04 [Info] (Stream) Chunk: 1    3       6       5       143     124     -11
2021-01-22 20-05-05 [Info] (Stream) Chunk: 0    1       6       4       151     125     -7
2021-01-22 20-05-06 [Info] (Stream) Chunk: 0    0       6       4       159     124     -3
2021-01-22 20-05-07 [Info] (Stream) Chunk: 0    0       6       4       167     124     0
2021-01-22 20-05-08 [Info] (Stream) Chunk: 0    0       5       3       175     124     -7
2021-01-22 20-05-09 [Info] (Stream) Chunk: 0    0       3       3       183     123     -4

@badaix
Copy link
Owner

badaix commented Jan 22, 2021

Thanks again for testing. I think the problem with the pi zero is that you didn't configure alsa:buffer_time=120,fragments=4 (on amadeus you did).
I'm still wondering about the 250 in 0.23.100 vs 125 in 0.19:

2021-01-22 16-00-36.109 [Debug] (Stats) Chunk: 3        2       0       0       70      250     0
2021-01-22 20-04-47 [Info] (Stream) Chunk: 0    0       0       0       7       123     0

One last favor: I've built the 0.23.101 Backport alsa_player from v0.19 that uses the alsa_player class from 0.19 with additional logging of the alsa parameters. Can you please post a debug log from this 0.23.101 version? It is using fixed settings and cannot be configured (regarding buffer time and fragments), because it is the original 0.19 player code.

@mrdago
Copy link
Author

mrdago commented Jan 23, 2021

Ok, I tested snapclient v.0.23.101 on player amadeus (RPI 3) as well as on player ludwig (RPI Zero). Using this version , both clients are playing fine, without any dropouts.

pi@amadeus:~/downloads $ snapclient -v
snapclient v0.23.101, built Jan 9 2021

pi@amadeus:~/downloads $ snapclient --user snapclient:snapclient -h cms --logfilter *:debug
2021-01-23 06-38-03.249 [Info] (Connection) Resolving host IP for: cms
2021-01-23 06-38-03.253 [Info] (Connection) Connecting
2021-01-23 06-38-03.271 [Notice] (Connection) Connected to 192.168.1.37
2021-01-23 06-38-03.271 [Info] (Connection) My MAC: "80:1f:02:8a:4f:26", socket: 8
2021-01-23 06-38-03.487 [Debug] (Connection) outstanding async_write
2021-01-23 06-38-03.495 [Info] (Controller) ServerSettings - buffer: 1000, latency: 0, volume: 100, muted: 0
metadata:{"STREAM":"snapcast"}
2021-01-23 06-38-03.495 [Info] (Controller) Codec: flac, sampleformat: 44100:16:2
2021-01-23 06-38-03.495 [Info] (Player) Player name: alsa, device: default, description: <none>, idx: 3, sharing mode: unspecified, parameters: <none>
2021-01-23 06-38-03.495 [Info] (Player) Mixer mode: software, parameters: <none>
2021-01-23 06-38-03.496 [Info] (Player) Sampleformat: 44100:16:2, stream: 44100:16:2
2021-01-23 06-38-03.498 [Debug] (Alsa) ACCESS:  MMAP_INTERLEAVED MMAP_NONINTERLEAVED MMAP_COMPLEX RW_INTERLEAVED RW_NONINTERLEAVED
2021-01-23 06-38-03.498 [Debug] (Alsa) FORMAT:  S8 U8 S16_LE S16_BE U16_LE U16_BE S24_LE S24_BE U24_LE U24_BE S32_LE S32_BE U32_LE U32_BE FLOAT_LE FLOAT_BE FLOAT64_LE FLOAT64_BE MU_LAW A_LAW IMA_ADPCM S20_LE S20_BE U20_LE U20_BE S24_3LE S24_3BE U24_3LE U24_3BE S20_3LE S20_3BE U20_3LE U20_3BE S18_3LE S18_3BE U18_3LE U18_3BE
2021-01-23 06-38-03.498 [Debug] (Alsa) SUBFORMAT:  STD
2021-01-23 06-38-03.498 [Debug] (Alsa) SAMPLE_BITS: [4 64]
2021-01-23 06-38-03.498 [Debug] (Alsa) FRAME_BITS: [4 640000]
2021-01-23 06-38-03.498 [Debug] (Alsa) CHANNELS: [1 10000]
2021-01-23 06-38-03.498 [Debug] (Alsa) RATE: [4000 4294967295)
2021-01-23 06-38-03.498 [Debug] (Alsa) PERIOD_TIME: 125000
2021-01-23 06-38-03.498 [Debug] (Alsa) PERIOD_SIZE: [500 536870912)
2021-01-23 06-38-03.498 [Debug] (Alsa) PERIOD_BYTES: [250 4294967295)
2021-01-23 06-38-03.498 [Debug] (Alsa) PERIODS: (0 3221226)
2021-01-23 06-38-03.498 [Debug] (Alsa) BUFFER_TIME: [1 4294967295]
2021-01-23 06-38-03.498 [Debug] (Alsa) BUFFER_SIZE: [1000 1610612735]
2021-01-23 06-38-03.498 [Debug] (Alsa) BUFFER_BYTES: [500 4294967295]
2021-01-23 06-38-03.498 [Debug] (Alsa) TICK_TIME: ALL
2021-01-23 06-38-03.500 [Info] (Alsa) PCM name: default, sample rate: 44100 Hz, channels: 2, buffer time: 250000 us, periods: 2, period time: 125000 us, period frames: 5512
2021-01-23 06-38-03.501 [Debug] (Alsa) PCM name: default
2021-01-23 06-38-03.501 [Debug] (Alsa) PCM state: PREPARED
2021-01-23 06-38-03.501 [Debug] (Alsa) channels: 2
2021-01-23 06-38-03.501 [Debug] (Alsa) rate: 44100 bps
2021-01-23 06-38-03.501 [Info] (Alsa) frames: 5512
2021-01-23 06-38-03.501 [Debug] (Alsa) period time: 125000
2021-01-23 06-38-03.501 [Info] (Alsa) Resizing buffer from 0 to 44100
2021-01-23 06-38-03.501 [Info] (Alsa) setVolume exp with base 10: 1 => 1
2021-01-23 06-38-03.501 [Info] (Stream) No chunks available
2021-01-23 06-38-03.501 [Info] (Alsa) Failed to get chunk
2021-01-23 06-38-04.061 [Info] (Controller) diff to server [ms]: 4.84784e+07
2021-01-23 06-38-04.247 [Debug] (Stream) Silent frames: 3866, frames: 5512, age: -87.679
2021-01-23 06-38-04.372 [Debug] (Stats) Chunk: 0        0       0       0       1       125     0
2021-01-23 06-38-05.122 [Debug] (Stats) Chunk: 0        0       0       0       7       125     0
2021-01-23 06-38-06.122 [Debug] (Stats) Chunk: 1        0       0       0       15      125     0
2021-01-23 06-38-07.122 [Debug] (Stats) Chunk: 2        1       1       1       23      125     0
2021-01-23 06-38-08.122 [Debug] (Stats) Chunk: 3        2       1       1       31      125     0
2021-01-23 06-38-09.122 [Debug] (Stats) Chunk: 3        2       1       1       39      125     0
2021-01-23 06-38-10.122 [Debug] (Stats) Chunk: 4        3       2       2       47      125     0
2021-01-23 06-38-11.122 [Debug] (Stats) Chunk: 5        4       2       2       55      125     0
2021-01-23 06-38-12.122 [Debug] (Stats) Chunk: 5        4       2       2       63      125     0
2021-01-23 06-38-13.122 [Debug] (Stats) Chunk: 6        5       3       3       71      125     0
2021-01-23 06-38-14.122 [Debug] (Stats) Chunk: 7        6       3       3       79      125     0
2021-01-23 06-38-15.122 [Debug] (Stats) Chunk: 8        7       3       3       87      125     0
2021-01-23 06-38-16.122 [Debug] (Stats) Chunk: 9        8       4       4       95      125     0
2021-01-23 06-38-17.122 [Debug] (Stats) Chunk: 9        9       4       4       103     125     -2
2021-01-23 06-38-18.122 [Debug] (Stats) Chunk: 8        9       5       5       111     125     -9
2021-01-23 06-38-19.122 [Debug] (Stats) Chunk: 6        9       6       5       119     125     -10
2021-01-23 06-38-20.122 [Debug] (Stats) Chunk: 4        7       6       5       127     125     -13
2021-01-23 06-38-21.122 [Debug] (Stats) Chunk: 2        5       6       5       135     125     -14
2021-01-23 06-38-22.122 [Debug] (Stats) Chunk: 0        2       6       4       143     125     -11
2021-01-23 06-38-23.122 [Debug] (Stats) Chunk: 0        0       6       4       151     125     -3
2021-01-23 06-38-24.122 [Debug] (Stats) Chunk: 0        0       6       4       159     125     -2
2021-01-23 06-38-25.122 [Debug] (Stats) Chunk: 0        0       6       3       167     125     -3
2021-01-23 06-38-26.122 [Debug] (Stats) Chunk: 0        0       5       3       175     125     -4
2021-01-23 06-38-27.122 [Debug] (Stats) Chunk: 0        0       2       3       183     125     -1
2021-01-23 06-38-28.122 [Debug] (Stats) Chunk: 1        0       1       3       191     125     0
2021-01-23 06-38-29.122 [Debug] (Stats) Chunk: 1        1       1       2       199     125     -1
2021-01-23 06-38-30.122 [Debug] (Stats) Chunk: 1        1       1       2       207     125     -2
2021-01-23 06-38-31.122 [Debug] (Stats) Chunk: 2        1       1       2       215     125     -3

pi@ludwig:~/downloads $ snapclient -v
snapclient v0.23.101, built Jan 9 2021

pi@ludwig:~/downloads $ snapclient  -h cms --logfilter *:debug
2021-01-23 06-56-18.263 [Info] (Connection) Resolving host IP for: cms
2021-01-23 06-56-18.279 [Info] (Connection) Connecting
2021-01-23 06-56-18.284 [Notice] (Connection) Connected to 192.168.1.37
2021-01-23 06-56-18.287 [Info] (Connection) My MAC: "80:1f:02:b3:46:c1", socket: 8
2021-01-23 06-56-19.487 [Debug] (Connection) outstanding async_write
2021-01-23 06-56-19.520 [Info] (Controller) ServerSettings - buffer: 1000, latency: 0, volume: 100, muted: 0
metadata:{"STREAM":"snapcast"}
2021-01-23 06-56-19.527 [Info] (Controller) Codec: flac, sampleformat: 44100:16:2
2021-01-23 06-56-19.529 [Info] (Player) Player name: alsa, device: default, description: <none>, idx: 3, sharing mode: unspecified, parameters: <none>
2021-01-23 06-56-19.530 [Info] (Player) Mixer mode: software, parameters: <none>
2021-01-23 06-56-19.531 [Info] (Player) Sampleformat: 44100:16:2, stream: 44100:16:2
2021-01-23 06-56-19.544 [Debug] (Alsa) ACCESS:  MMAP_INTERLEAVED MMAP_NONINTERLEAVED MMAP_COMPLEX RW_INTERLEAVED RW_NONINTERLEAVED
2021-01-23 06-56-19.544 [Debug] (Alsa) FORMAT:  S8 U8 S16_LE S16_BE U16_LE U16_BE S24_LE S24_BE U24_LE U24_BE S32_LE S32_BE U32_LE U32_BE FLOAT_LE FLOAT_BE FLOAT64_LE FLOAT64_BE MU_LAW A_LAW IMA_ADPCM S20_LE S20_BE U20_LE U20_BE S24_3LE S24_3BE U24_3LE U24_3BE S20_3LE S20_3BE U20_3LE U20_3BE S18_3LE S18_3BE U18_3LE U18_3BE
2021-01-23 06-56-19.544 [Debug] (Alsa) SUBFORMAT:  STD
2021-01-23 06-56-19.544 [Debug] (Alsa) SAMPLE_BITS: [4 64]
2021-01-23 06-56-19.544 [Debug] (Alsa) FRAME_BITS: [4 640000]
2021-01-23 06-56-19.544 [Debug] (Alsa) CHANNELS: [1 10000]
2021-01-23 06-56-19.544 [Debug] (Alsa) RATE: [4000 4294967295)
2021-01-23 06-56-19.544 [Debug] (Alsa) PERIOD_TIME: 125000
2021-01-23 06-56-19.544 [Debug] (Alsa) PERIOD_SIZE: [500 536870912)
2021-01-23 06-56-19.544 [Debug] (Alsa) PERIOD_BYTES: [250 4294967295)
2021-01-23 06-56-19.544 [Debug] (Alsa) PERIODS: (0 3221226)
2021-01-23 06-56-19.544 [Debug] (Alsa) BUFFER_TIME: [1 4294967295]
2021-01-23 06-56-19.544 [Debug] (Alsa) BUFFER_SIZE: [1000 1610612735]
2021-01-23 06-56-19.544 [Debug] (Alsa) BUFFER_BYTES: [500 4294967295]
2021-01-23 06-56-19.544 [Debug] (Alsa) TICK_TIME: ALL
2021-01-23 06-56-19.562 [Info] (Alsa) PCM name: default, sample rate: 44100 Hz, channels: 2, buffer time: 250000 us, periods: 2, period time: 125000 us, period frames: 5512
2021-01-23 06-56-19.564 [Debug] (Alsa) PCM name: default
2021-01-23 06-56-19.567 [Debug] (Alsa) PCM state: PREPARED
2021-01-23 06-56-19.569 [Debug] (Alsa) channels: 2
2021-01-23 06-56-19.570 [Debug] (Alsa) rate: 44100 bps
2021-01-23 06-56-19.571 [Info] (Alsa) frames: 5512
2021-01-23 06-56-19.571 [Debug] (Alsa) period time: 125000
2021-01-23 06-56-19.572 [Debug] (Player) setVolume exp with base 10: 1 => 1
2021-01-23 06-56-19.580 [Info] (Alsa) Resizing buffer from 0 to 44100
2021-01-23 06-56-19.747 [Info] (Controller) diff to server [ms]: 4.92051e+07
2021-01-23 06-56-20.289 [Debug] (Stream) Silent frames: 2841, frames: 5519, age: -64.44
2021-01-23 06-56-20.414 [Debug] (Stats) Chunk: 0        0       0       0       1       125     0
2021-01-23 06-56-21.039 [Debug] (Stats) Chunk: 0        0       0       0       6       124     0
2021-01-23 06-56-22.039 [Debug] (Stats) Chunk: 1        1       1       1       14      125     0
2021-01-23 06-56-23.039 [Debug] (Stats) Chunk: 2        1       1       1       22      125     0
2021-01-23 06-56-24.039 [Debug] (Stats) Chunk: 3        2       1       1       30      125     0
2021-01-23 06-56-25.039 [Debug] (Stats) Chunk: 3        2       2       2       38      124     0
2021-01-23 06-56-26.039 [Debug] (Stats) Chunk: 5        4       2       2       46      125     0
2021-01-23 06-56-27.039 [Debug] (Stats) Chunk: 6        4       2       2       54      125     0
2021-01-23 06-56-28.039 [Debug] (Stats) Chunk: 6        5       3       3       62      125     0
2021-01-23 06-56-29.039 [Debug] (Stats) Chunk: 7        6       3       3       70      125     0
2021-01-23 06-56-30.039 [Debug] (Stats) Chunk: 8        7       4       4       78      125     0
2021-01-23 06-56-31.039 [Debug] (Stats) Chunk: 9        7       4       4       86      125     0
2021-01-23 06-56-32.039 [Debug] (Stats) Chunk: 8        8       4       4       94      124     0
2021-01-23 06-56-33.039 [Debug] (Stats) Chunk: 9        9       5       5       102     124     -1
2021-01-23 06-56-34.039 [Debug] (Stats) Chunk: 8        9       6       6       110     125     -10

To complete the test results. here is the log from testing ludwig with the previous patch v.0.23.100 and buffer_time=120,fragments=4

pi@ludwig:~/downloads $ snapclient -v
snapclient v0.23.100, built Jan 9 2021

pi@ludwig:~/downloads $ snapclient  -h cms --logfilter *:debug --player alsa:buffer_time=120,fragments=4
2021-01-23 06-53-50.314 [Info] (Connection) Resolving host IP for: cms
2021-01-23 06-53-50.328 [Info] (Connection) Connecting
2021-01-23 06-53-50.332 [Notice] (Connection) Connected to 192.168.1.37
2021-01-23 06-53-50.334 [Info] (Connection) My MAC: "80:1f:02:b3:46:c1", socket: 8
2021-01-23 06-53-51.465 [Debug] (Connection) outstanding async_write
2021-01-23 06-53-51.500 [Info] (Controller) ServerSettings - buffer: 1000, latency: 0, volume: 100, muted: 0
metadata:{"STREAM":"snapcast"}
2021-01-23 06-53-51.509 [Info] (Controller) Codec: flac, sampleformat: 44100:16:2
2021-01-23 06-53-51.512 [Info] (Player) Player name: alsa, device: default, description: <none>, idx: 3, sharing mode: unspecified, parameters: buffer_time=120,fragments=4
2021-01-23 06-53-51.515 [Info] (Player) Mixer mode: software, parameters: <none>
2021-01-23 06-53-51.518 [Info] (Player) Sampleformat: 44100:16:2, stream: 44100:16:2
2021-01-23 06-53-51.520 [Info] (Alsa) Using buffer_time: 120 ms, fragments: 4
2021-01-23 06-53-51.536 [Debug] (Alsa) ACCESS:  MMAP_INTERLEAVED MMAP_NONINTERLEAVED MMAP_COMPLEX RW_INTERLEAVED RW_NONINTERLEAVED
2021-01-23 06-53-51.536 [Debug] (Alsa) FORMAT:  S8 U8 S16_LE S16_BE U16_LE U16_BE S24_LE S24_BE U24_LE U24_BE S32_LE S32_BE U32_LE U32_BE FLOAT_LE FLOAT_BE FLOAT64_LE FLOAT64_BE MU_LAW A_LAW IMA_ADPCM S20_LE S20_BE U20_LE U20_BE S24_3LE S24_3BE U24_3LE U24_3BE S20_3LE S20_3BE U20_3LE U20_3BE S18_3LE S18_3BE U18_3LE U18_3BE
2021-01-23 06-53-51.536 [Debug] (Alsa) SUBFORMAT:  STD
2021-01-23 06-53-51.536 [Debug] (Alsa) SAMPLE_BITS: [4 64]
2021-01-23 06-53-51.536 [Debug] (Alsa) FRAME_BITS: [4 640000]
2021-01-23 06-53-51.536 [Debug] (Alsa) CHANNELS: [1 10000]
2021-01-23 06-53-51.536 [Debug] (Alsa) RATE: [4000 4294967295)
2021-01-23 06-53-51.536 [Debug] (Alsa) PERIOD_TIME: 125000
2021-01-23 06-53-51.536 [Debug] (Alsa) PERIOD_SIZE: [500 536870912)
2021-01-23 06-53-51.536 [Debug] (Alsa) PERIOD_BYTES: [250 4294967295)
2021-01-23 06-53-51.536 [Debug] (Alsa) PERIODS: (0 3221226)
2021-01-23 06-53-51.536 [Debug] (Alsa) BUFFER_TIME: [1 4294967295]
2021-01-23 06-53-51.536 [Debug] (Alsa) BUFFER_SIZE: [1000 1610612735]
2021-01-23 06-53-51.536 [Debug] (Alsa) BUFFER_BYTES: [500 4294967295]
2021-01-23 06-53-51.536 [Debug] (Alsa) TICK_TIME: ALL
2021-01-23 06-53-51.557 [Info] (Alsa) PCM name: default, sample rate: 44100 Hz, channels: 2, buffer time: 250000 us, periods: 2, period time: 125000 us, period frames: 5512
2021-01-23 06-53-51.563 [Debug] (Player) setVolume exp with base 10: 1 => 1
2021-01-23 06-53-51.571 [Debug] (Alsa) Resizing buffer from 0 to 44100
2021-01-23 06-53-51.770 [Info] (Controller) diff to server [ms]: 4.92051e+07
2021-01-23 06-53-52.292 [Debug] (Stream) Silent frames: 1319, frames: 5740, age: -29.919
2021-01-23 06-53-52.422 [Debug] (Stats) Chunk: 0        0       0       0       1       120     0
2021-01-23 06-53-53.053 [Debug] (Stats) Chunk: 1        0       0       0       6       125     0
2021-01-23 06-53-54.079 [Warn] (Alsa) snd_pcm_avail_delay failed: Broken pipe (-32), avail: 5497, delay: 5520, using snd_pcm_avail amd snd_pcm_delay.
2021-01-23 06-53-54.086 [Warn] (Alsa) snd_pcm_delay failed: Broken pipe (-32), avail: -32, delay: 5520
2021-01-23 06-53-54.099 [Debug] (Stats) Chunk: -996     1       1       1       14      0       0
2021-01-23 06-53-55.042 [Debug] (Stats) Chunk: -916     0       0       0       21      125     0
2021-01-23 06-53-55.553 [Info] (Stream) pMiniBuffer->full() && (abs(pMiniBuffer->mean()) > 50): -91447
2021-01-23 06-53-55.677 [Debug] (Stream) Silent frames: 4039, frames: 5512, age: -91.603
2021-01-23 06-53-56.058 [Debug] (Stats) Chunk: 0        0       0       0       3       124     0
2021-01-23 06-53-57.075 [Debug] (Stats) Chunk: 0        0       0       0       11      123     0
2021-01-23 06-53-58.094 [Debug] (Stats) Chunk: 1        0       0       0       19      123     0
2021-01-23 06-53-58.733 [Error] (Alsa) XRUN while writing to PCM: Broken pipe
2021-01-23 06-53-59.031 [Debug] (Stats) Chunk: -2397    0       0       0       27      124     0
2021-01-23 06-54-00.042 [Debug] (Stats) Chunk: -2398    -2397   0       0       35      119     0
2021-01-23 06-54-00.167 [Info] (Stream) pMiniBuffer->full() && (abs(pMiniBuffer->mean()) > 50): -239712
2021-01-23 06-54-00.416 [Debug] (Stream) Silent frames: 5063, frames: 5512, age: -114.818
2021-01-23 06-54-01.053 [Debug] (Stats) Chunk: 1        1       1       1       5       124     0
2021-01-23 06-54-02.079 [Debug] (Stats) Chunk: 1        1       1       1       13      120     0

@badaix
Copy link
Owner

badaix commented Jan 23, 2021

Thanks :)
This is really interesting, using the exact same alsa configuration, the 0.19 (0.23.101) does not have any dropouts, while the 0.23.100 has dropouts, both using only 2 fragments. I have to investigate the difference in the player logic.

@badaix
Copy link
Owner

badaix commented Jan 23, 2021

Might be solved now with the commit Don't sleep if frames avail < period size.
Since v0.20 Snapclient only feeds complete fragments to the PCM device. If there is not enough space free in the device's buffer, Snapclient waits for the buffer to have enough free space, this will cause a buffer under run in case of two fragments. There was no explanation in the commit message or comment in the source code, so I removed this constraint, and hope that the develop branch will now work as reliable as the 0.19 did.

@mrdago
Copy link
Author

mrdago commented Jan 24, 2021

Yes, it seems that the problem is solved now!
I've tested v.23.100 - latest patch on RPI 3 and RPI Zero (player amadeus and ludwig) without any noticeable problem.
Test was executed with different buffer_times (multiples of 20ms) and different fragments (4,6) .

Thanks a lot for the effort you put into the development and maintenance of snapcast.

@badaix
Copy link
Owner

badaix commented Jan 24, 2021

Great, thanks again for testing!
Can you please once more paste the logs of latest version, just for me to double check that everything looks as expected?

@TotalSpaceshipguy
Copy link

Hi Guys

I've been watching this thread keenly, as I've been having the same dropout issues on a Pi Zero with ALSA and an adafruit voice bonnet. The hardware works as expected playing local mp3's using the mpg123 client.

This is my first exposure to snapcast so I've been using the latest 0.23 release of the server and client. The win32 client worked out of the box, but I had audio dropouts with the armhf client.

I've just tested with the .102 armhf client from the "Disable ccache in CI for debian packages" build, and if I run the client on its own without any command line parameters, then I sill get regular dropouts, but if I use the command line parameter "--player alsa:buffer_time=360,fragments=2" then everything seems fine. Using buffer_time of 120 and 240 still gives dropouts so I kept increasing until I got a successful outcome.

So, a couple of questions if I may...

  1. Is the client supposed to work out the buffer_time and fragments itself, or do we have to tune this manually
  2. I've tried setting SNAPCLIENT_OPTS="--player alsa:buffer_time=360,fragments=2" in the /etc/defaults/snapclient file, but this isn't picked up by the snapclient when running without any command line parameters. Have I done something wrong here?

Kind regards
Dom

@badaix
Copy link
Owner

badaix commented Jan 25, 2021

@TotalSpaceshipguy

  1. Yes, this would be the desired behavior. It's also the actual behavior on my test hardware, but unfortunately it seems that there are DACs out there where it doesn't work out. As you were following the thread, you might have read that it's recommended to use more than 2 fragments (i.e. 3 or 4). If you send logs, I can try to figure out what happened and to fix it. You can also try out the versions with these commit messages and send logs: Backport alsa_player from v0.19, Set buffer time instead of periods, Configure period time instead of buffer time.
    Without logs I can't do anything but guessing.
  2. The SNAPCLIENT_OPTS will be uses as command line arguments when started by systemd through the snapclient unit file:
[Service]
EnvironmentFile=-/etc/default/snapclient
ExecStart=/usr/bin/snapclient --logsink=system $SNAPCLIENT_OPTS

@TotalSpaceshipguy
Copy link

Hi @badaix

Thanks for the clarification on how the SNAPCLIENT_OPTS works. I'll download those other builds, do some more testing upload the logs for you

@badaix
Copy link
Owner

badaix commented Jan 25, 2021

The log output of the most recent release might be enough to get an idea of what's happening

@TotalSpaceshipguy
Copy link

TotalSpaceshipguy commented Jan 25, 2021

Hi @badaix

Thanks for looking into this. Attached is the output from the "Disable ccache in CI for debian packages" build without passing any command line parameters

Kind regards
Dom

Disable ccache in CI for debian packages-output.txt

@jeffhentschel
Copy link

I think I may be having a similar problem when running on my pi0. I've tried restarting the client with --player alsa:buffer_time=120,fragments=4 and so far that hasn't had any dropouts but will report back here if I notice any.

Here are the logs I was noticing from before if they can be any help:

$ cat /proc/cpuinfo
processor	: 0
model name	: ARMv6-compatible processor rev 7 (v6l)
BogoMIPS	: 997.08
Features	: half thumb fastmult vfp edsp java tls 
CPU implementer	: 0x41
CPU architecture: 7
CPU variant	: 0x0
CPU part	: 0xb76
CPU revision	: 7

Hardware	: BCM2835
Revision	: 9000c1
Model		: Raspberry Pi Zero W Rev 1.1
$ uname -a
Linux snapclient-pi0 5.4.83+ #1379 Mon Dec 14 13:06:05 GMT 2020 armv6l GNU/Linux
$ snapclient -v
snapclient v0.23.0
$ snapclient -l
0: null
Discard all samples (playback) or generate zero samples (capture)

1: raspiaudio


2: default


3: sysdefault:CARD=sndrpihifiberry
snd_rpi_hifiberry_dac, HifiBerry DAC HiFi pcm5102a-hifi-0
Default Audio Device

4: dmix:CARD=sndrpihifiberry,DEV=0
snd_rpi_hifiberry_dac, HifiBerry DAC HiFi pcm5102a-hifi-0
Direct sample mixing device

5: dsnoop:CARD=sndrpihifiberry,DEV=0
snd_rpi_hifiberry_dac, HifiBerry DAC HiFi pcm5102a-hifi-0
Direct sample snooping device

6: hw:CARD=sndrpihifiberry,DEV=0
snd_rpi_hifiberry_dac, HifiBerry DAC HiFi pcm5102a-hifi-0
Direct hardware device without any conversions

7: plughw:CARD=sndrpihifiberry,DEV=0
snd_rpi_hifiberry_dac, HifiBerry DAC HiFi pcm5102a-hifi-0
Hardware device with all software conversions
34:48: Failed to get chunk
34:48: Failed to get chunk
34:48: Failed to get chunk
34:48: Time sync request failed: Connection timed out
34:48: Error reading message body of length 1535: Operation canceled
34:49: Resolving host IP for: IP
34:49: Connecting
34:49: Connected to IP
34:49: My MAC: "MAC", socket: 9
34:49: ServerSettings - buffer: 1000, latency: 0, volume: 100, muted: 0
34:49: metadata:{"STREAM":"MyStream"}
34:50: Codec: flac, sampleformat: 44100:16:2
34:50: Player name: alsa, device: default, description: <none>, idx: 2, sharing mode: unspecified, parameters: <none>
34:50: Mixer mode: software, parameters: <none>
34:50: Sampleformat: 44100:16:2, stream: 44100:16:2
34:50: Using buffer_time: 80 ms, fragments: 4
34:50: PCM name: default, sample rate: 44100 Hz, channels: 2, buffer time: 80000 us, periods: 4, period time: 20000 us, period frames: 882
34:51: Exception: Not enough frames available, requested frames: 1760, available: 1498
34:51: Failed to get chunk
34:51: XRUN while waiting for PCM: Broken pipe
34:51: Failed to get chunk
[repeated]
34:51: Failed to get chunk
34:51: Exception: Not enough frames available, requested frames: 3528, available: 133
34:51: Failed to get chunk
34:51: Exception: Not enough frames available, requested frames: 3528, available: 992
34:51: Failed to get chunk
34:51: Exception: Not enough frames available, requested frames: 3076, available: 1152
34:51: Failed to get chunk
34:51: Exception: Not enough frames available, requested frames: 2815, available: 1152
34:51: Failed to get chunk
34:51: Exception: Not enough frames available, requested frames: 2070, available: 1152
34:51: Failed to get chunk
34:51: Exception: Not enough frames available, requested frames: 1216, available: 1152
34:51: Failed to get chunk

@mrdago
Copy link
Author

mrdago commented Jan 26, 2021

Here are the missing logs from my testing of v.0.23.102 ...

Raspberry PI 3

pi@amadeus:~ $ snapclient -v
snapclient v0.23.102, built Jan 9 2021

pi@amadeus:~ $ snapclient --user snapclient:snapclient -h cms --logfilter *:debug

2021-01-26 06-23-39.820 [Info] (Connection) Resolving host IP for: cms
2021-01-26 06-23-39.826 [Info] (Connection) Connecting
2021-01-26 06-23-39.839 [Notice] (Connection) Connected to 192.168.1.37
2021-01-26 06-23-39.839 [Info] (Connection) My MAC: "80:1f:02:8a:4f:26", socket: 8
2021-01-26 06-23-40.053 [Debug] (Connection) outstanding async_write
2021-01-26 06-23-40.057 [Info] (Controller) ServerSettings - buffer: 1000, latency: 0, volume: 100, muted: 0
metadata:{"STREAM":"snapcast"}
2021-01-26 06-23-40.058 [Info] (Controller) Codec: flac, sampleformat: 44100:16:2
2021-01-26 06-23-40.058 [Info] (Player) Player name: alsa, device: default, description: <none>, idx: 3, sharing mode: unspecified, parameters: <none>
2021-01-26 06-23-40.058 [Info] (Player) Mixer mode: software, parameters: <none>
2021-01-26 06-23-40.058 [Info] (Player) Sampleformat: 44100:16:2, stream: 44100:16:2
2021-01-26 06-23-40.058 [Info] (Alsa) Using buffer_time: 80 ms, fragments: 4
2021-01-26 06-23-40.061 [Debug] (Alsa) ACCESS:  MMAP_INTERLEAVED MMAP_NONINTERLEAVED MMAP_COMPLEX RW_INTERLEAVED RW_NONINTERLEAVED
2021-01-26 06-23-40.061 [Debug] (Alsa) FORMAT:  S8 U8 S16_LE S16_BE U16_LE U16_BE S24_LE S24_BE U24_LE U24_BE S32_LE S32_BE U32_LE U32_BE FLOAT_LE FLOAT_BE FLOAT64_LE FLOAT64_BE MU_LAW A_LAW IMA_ADPCM S20_LE S20_BE U20_LE U20_BE S24_3LE S24_3BE U24_3LE U24_3BE S20_3LE S20_3BE U20_3LE U20_3BE S18_3LE S18_3BE U18_3LE U18_3BE
2021-01-26 06-23-40.061 [Debug] (Alsa) SUBFORMAT:  STD
2021-01-26 06-23-40.061 [Debug] (Alsa) SAMPLE_BITS: [4 64]
2021-01-26 06-23-40.061 [Debug] (Alsa) FRAME_BITS: [4 640000]
2021-01-26 06-23-40.061 [Debug] (Alsa) CHANNELS: [1 10000]
2021-01-26 06-23-40.061 [Debug] (Alsa) RATE: [4000 4294967295)
2021-01-26 06-23-40.061 [Debug] (Alsa) PERIOD_TIME: 125000
2021-01-26 06-23-40.061 [Debug] (Alsa) PERIOD_SIZE: [500 536870912)
2021-01-26 06-23-40.061 [Debug] (Alsa) PERIOD_BYTES: [250 4294967295)
2021-01-26 06-23-40.061 [Debug] (Alsa) PERIODS: (0 3221226)
2021-01-26 06-23-40.061 [Debug] (Alsa) BUFFER_TIME: [1 4294967295]
2021-01-26 06-23-40.061 [Debug] (Alsa) BUFFER_SIZE: [1000 1610612735]
2021-01-26 06-23-40.061 [Debug] (Alsa) BUFFER_BYTES: [500 4294967295]
2021-01-26 06-23-40.061 [Debug] (Alsa) TICK_TIME: ALL
2021-01-26 06-23-40.062 [Info] (Alsa) Period time too small, changing from 20000 to 125000
2021-01-26 06-23-40.063 [Info] (Alsa) PCM name: default, sample rate: 44100 Hz, channels: 2, buffer time: 250000 us, periods: 2, period time: 125000 us, period frames: 5512
2021-01-26 06-23-40.064 [Debug] (Alsa) setVolume exp with base 10: 1 => 1
2021-01-26 06-23-40.064 [Debug] (Alsa) Resizing buffer from 0 to 44100
2021-01-26 06-23-40.064 [Info] (Stream) No chunks available
2021-01-26 06-23-40.064 [Info] (Alsa) Failed to get chunk
2021-01-26 06-23-40.935 [Debug] (Stream) Silent frames: 696, frames: 5512, age: -15.787
2021-01-26 06-23-41.009 [Info] (Controller) diff to server [ms]: 3.0678e+08
2021-01-26 06-23-41.060 [Debug] (Stats) Chunk: 0        0       0       0       1       125     0
2021-01-26 06-23-42.060 [Debug] (Stats) Chunk: 0        0       0       0       9       125     0
2021-01-26 06-23-43.060 [Debug] (Stats) Chunk: 1        0       0       0       17      125     0
2021-01-26 06-23-44.060 [Debug] (Stats) Chunk: 2        1       1       1       25      125     0
2021-01-26 06-23-45.060 [Debug] (Stats) Chunk: 4        2       1       1       33      125     0
2021-01-26 06-23-46.060 [Debug] (Stats) Chunk: 5        4       2       2       41      125     0
2021-01-26 06-23-47.060 [Debug] (Stats) Chunk: 6        5       2       2       49      125     0
2021-01-26 06-23-48.060 [Debug] (Stats) Chunk: 7        6       3       3       57      125     0
2021-01-26 06-23-49.060 [Debug] (Stats) Chunk: 9        7       4       4       65      125     0
2021-01-26 06-23-50.060 [Debug] (Stats) Chunk: 9        8       4       4       73      125     0
2021-01-26 06-23-51.060 [Debug] (Stats) Chunk: 10       9       5       5       81      125     0
2021-01-26 06-23-52.060 [Debug] (Stats) Chunk: 11       10      6       6       89      125     0
2021-01-26 06-23-53.060 [Debug] (Stats) Chunk: 12       11      6       6       97      125     0
2021-01-26 06-23-54.060 [Debug] (Stats) Chunk: 12       12      7       7       105     125     -6
2021-01-26 06-23-55.060 [Debug] (Stats) Chunk: 10       12      8       7       113     125     -15
2021-01-26 06-23-56.060 [Debug] (Stats) Chunk: 6        11      9       8       121     125     -18
2021-01-26 06-23-57.060 [Debug] (Stats) Chunk: 3        7       9       7       129     125     -19
2021-01-26 06-23-58.060 [Debug] (Stats) Chunk: 0        4       9       6       137     125     -20
2021-01-26 06-23-59.060 [Debug] (Stats) Chunk: 0        1       9       6       145     125     -5
2021-01-26 06-24-00.060 [Debug] (Stats) Chunk: 0        0       9       6       153     125     0
2021-01-26 06-24-01.060 [Debug] (Stats) Chunk: 1        0       9       5       161     125     -8
2021-01-26 06-24-02.060 [Debug] (Stats) Chunk: 0        0       7       5       169     125     -5
2021-01-26 06-24-03.060 [Debug] (Stats) Chunk: 0        0       4       4       177     125     -2
2021-01-26 06-24-04.060 [Debug] (Stats) Chunk: 1        0       1       4       185     125     -2
2021-01-26 06-24-05.060 [Debug] (Stats) Chunk: 1        1       1       4       193     125     -3
2021-01-26 06-24-06.060 [Debug] (Stats) Chunk: 2        1       1       3       201     125     -2

pi@amadeus:~ $ snapclient --user snapclient:snapclient -h cms --logfilter *:debug --player alsa:buffer_time=120,fragments=6

2021-01-26 06-26-19.231 [Info] (Connection) Resolving host IP for: cms
2021-01-26 06-26-19.236 [Info] (Connection) Connecting
2021-01-26 06-26-19.253 [Notice] (Connection) Connected to 192.168.1.37
2021-01-26 06-26-19.253 [Info] (Connection) My MAC: "80:1f:02:8a:4f:26", socket: 8
2021-01-26 06-26-19.494 [Debug] (Connection) outstanding async_write
2021-01-26 06-26-19.498 [Info] (Controller) ServerSettings - buffer: 1000, latency: 0, volume: 100, muted: 0
metadata:{"STREAM":"snapcast"}
2021-01-26 06-26-19.500 [Info] (Controller) Codec: flac, sampleformat: 44100:16:2
2021-01-26 06-26-19.500 [Info] (Player) Player name: alsa, device: default, description: <none>, idx: 3, sharing mode: unspecified, parameters: buffer_time=120,fragments=6
2021-01-26 06-26-19.501 [Info] (Player) Mixer mode: software, parameters: <none>
2021-01-26 06-26-19.501 [Info] (Player) Sampleformat: 44100:16:2, stream: 44100:16:2
2021-01-26 06-26-19.501 [Info] (Alsa) Using buffer_time: 120 ms, fragments: 6
2021-01-26 06-26-19.505 [Debug] (Alsa) ACCESS:  MMAP_INTERLEAVED MMAP_NONINTERLEAVED MMAP_COMPLEX RW_INTERLEAVED RW_NONINTERLEAVED
2021-01-26 06-26-19.505 [Debug] (Alsa) FORMAT:  S8 U8 S16_LE S16_BE U16_LE U16_BE S24_LE S24_BE U24_LE U24_BE S32_LE S32_BE U32_LE U32_BE FLOAT_LE FLOAT_BE FLOAT64_LE FLOAT64_BE MU_LAW A_LAW IMA_ADPCM S20_LE S20_BE U20_LE U20_BE S24_3LE S24_3BE U24_3LE U24_3BE S20_3LE S20_3BE U20_3LE U20_3BE S18_3LE S18_3BE U18_3LE U18_3BE
2021-01-26 06-26-19.505 [Debug] (Alsa) SUBFORMAT:  STD
2021-01-26 06-26-19.505 [Debug] (Alsa) SAMPLE_BITS: [4 64]
2021-01-26 06-26-19.505 [Debug] (Alsa) FRAME_BITS: [4 640000]
2021-01-26 06-26-19.505 [Debug] (Alsa) CHANNELS: [1 10000]
2021-01-26 06-26-19.505 [Debug] (Alsa) RATE: [4000 4294967295)
2021-01-26 06-26-19.505 [Debug] (Alsa) PERIOD_TIME: 125000
2021-01-26 06-26-19.505 [Debug] (Alsa) PERIOD_SIZE: [500 536870912)
2021-01-26 06-26-19.505 [Debug] (Alsa) PERIOD_BYTES: [250 4294967295)
2021-01-26 06-26-19.505 [Debug] (Alsa) PERIODS: (0 3221226)
2021-01-26 06-26-19.505 [Debug] (Alsa) BUFFER_TIME: [1 4294967295]
2021-01-26 06-26-19.505 [Debug] (Alsa) BUFFER_SIZE: [1000 1610612735]
2021-01-26 06-26-19.505 [Debug] (Alsa) BUFFER_BYTES: [500 4294967295]
2021-01-26 06-26-19.505 [Debug] (Alsa) TICK_TIME: ALL
2021-01-26 06-26-19.509 [Info] (Alsa) Period time too small, changing from 20000 to 125000
2021-01-26 06-26-19.511 [Info] (Alsa) PCM name: default, sample rate: 44100 Hz, channels: 2, buffer time: 250000 us, periods: 2, period time: 125000 us, period frames: 5512
2021-01-26 06-26-19.511 [Debug] (Alsa) setVolume exp with base 10: 1 => 1
2021-01-26 06-26-19.511 [Debug] (Alsa) Resizing buffer from 0 to 44100
2021-01-26 06-26-19.512 [Info] (Stream) No chunks available
2021-01-26 06-26-19.512 [Info] (Alsa) Failed to get chunk
2021-01-26 06-26-20.073 [Info] (Controller) diff to server [ms]: 3.0678e+08
2021-01-26 06-26-20.253 [Debug] (Stream) Silent frames: 4944, frames: 5512, age: -112.116
2021-01-26 06-26-20.378 [Debug] (Stats) Chunk: 0        0       0       0       1       125     0
2021-01-26 06-26-21.003 [Debug] (Stats) Chunk: 0        0       0       0       6       125     0
2021-01-26 06-26-22.003 [Debug] (Stats) Chunk: 0        0       0       0       14      125     0
2021-01-26 06-26-23.003 [Debug] (Stats) Chunk: 1        0       0       0       22      125     0
2021-01-26 06-26-24.003 [Debug] (Stats) Chunk: 1        1       1       1       30      125     0
2021-01-26 06-26-25.003 [Debug] (Stats) Chunk: 2        1       1       1       38      125     0
2021-01-26 06-26-26.003 [Debug] (Stats) Chunk: 2        2       1       1       46      125     0
2021-01-26 06-26-27.003 [Debug] (Stats) Chunk: 2        2       1       1       54      125     0
2021-01-26 06-26-28.003 [Debug] (Stats) Chunk: 3        2       2       2       62      125     0
2021-01-26 06-26-29.003 [Debug] (Stats) Chunk: 3        3       2       2       70      125     0
2021-01-26 06-26-30.003 [Debug] (Stats) Chunk: 4        3       2       2       78      125     0
2021-01-26 06-26-31.003 [Debug] (Stats) Chunk: 4        4       2       2       86      125     0
2021-01-26 06-26-32.003 [Debug] (Stats) Chunk: 5        4       2       2       94      125     0
2021-01-26 06-26-33.003 [Debug] (Stats) Chunk: 6        5       2       2       102     125     0
2021-01-26 06-26-34.003 [Debug] (Stats) Chunk: 4        5       3       2       110     125     -4
2021-01-26 06-26-35.003 [Debug] (Stats) Chunk: 3        5       3       3       118     125     -7
2021-01-26 06-26-36.002 [Debug] (Stats) Chunk: 2        3       3       3       126     125     -7
2021-01-26 06-26-37.002 [Debug] (Stats) Chunk: 1        2       3       2       134     125     -6
2021-01-26 06-26-38.002 [Debug] (Stats) Chunk: 0        1       3       2       142     125     -6
2021-01-26 06-26-39.002 [Debug] (Stats) Chunk: 0        0       3       2       150     125     -1
2021-01-26 06-26-40.002 [Debug] (Stats) Chunk: 1        0       3       2       158     125     -2
2021-01-26 06-26-41.002 [Debug] (Stats) Chunk: 0        0       3       2       166     125     -3
2021-01-26 06-26-42.002 [Debug] (Stats) Chunk: 0        0       2       2       174     125     -2
2021-01-26 06-26-43.002 [Debug] (Stats) Chunk: 0        0       1       2       182     125     -2
2021-01-26 06-26-44.002 [Debug] (Stats) Chunk: 0        0       0       2       190     125     0
2021-01-26 06-26-45.002 [Debug] (Stats) Chunk: 0        0       0       1       198     125     0
2021-01-26 06-26-46.002 [Debug] (Stats) Chunk: 0        0       0       1       206     125     0
2021-01-26 06-26-47.002 [Debug] (Stats) Chunk: 0        0       0       1       214     125     0

Raspberry PI Zero

pi@ludwig:~ $ snapclient -v
snapclient v0.23.102, built Jan 9 2021

pi@ludwig:~ $ snapclient --user snapclient:snapclient -h cms --logfilter *:debug

2021-01-26 06-30-28.216 [Info] (Connection) Resolving host IP for: cms
2021-01-26 06-30-28.231 [Info] (Connection) Connecting
2021-01-26 06-30-28.236 [Notice] (Connection) Connected to 192.168.1.37
2021-01-26 06-30-28.238 [Info] (Connection) My MAC: "80:1f:02:b3:46:c1", socket: 8
2021-01-26 06-30-29.573 [Debug] (Connection) outstanding async_write
2021-01-26 06-30-29.604 [Info] (Controller) ServerSettings - buffer: 1000, latency: 0, volume: 100, muted: 0
metadata:{"STREAM":"snapcast"}
2021-01-26 06-30-29.614 [Info] (Controller) Codec: flac, sampleformat: 44100:16:2
2021-01-26 06-30-29.617 [Info] (Player) Player name: alsa, device: default, description: <none>, idx: 3, sharing mode: unspecified, parameters: <none>
2021-01-26 06-30-29.618 [Info] (Player) Mixer mode: software, parameters: <none>
2021-01-26 06-30-29.619 [Info] (Player) Sampleformat: 44100:16:2, stream: 44100:16:2
2021-01-26 06-30-29.621 [Info] (Alsa) Using buffer_time: 80 ms, fragments: 4
2021-01-26 06-30-29.630 [Debug] (Alsa) ACCESS:  MMAP_INTERLEAVED MMAP_NONINTERLEAVED MMAP_COMPLEX RW_INTERLEAVED RW_NONINTERLEAVED
2021-01-26 06-30-29.630 [Debug] (Alsa) FORMAT:  S8 U8 S16_LE S16_BE U16_LE U16_BE S24_LE S24_BE U24_LE U24_BE S32_LE S32_BE U32_LE U32_BE FLOAT_LE FLOAT_BE FLOAT64_LE FLOAT64_BE MU_LAW A_LAW IMA_ADPCM S20_LE S20_BE U20_LE U20_BE S24_3LE S24_3BE U24_3LE U24_3BE S20_3LE S20_3BE U20_3LE U20_3BE S18_3LE S18_3BE U18_3LE U18_3BE
2021-01-26 06-30-29.630 [Debug] (Alsa) SUBFORMAT:  STD
2021-01-26 06-30-29.630 [Debug] (Alsa) SAMPLE_BITS: [4 64]
2021-01-26 06-30-29.630 [Debug] (Alsa) FRAME_BITS: [4 640000]
2021-01-26 06-30-29.630 [Debug] (Alsa) CHANNELS: [1 10000]
2021-01-26 06-30-29.630 [Debug] (Alsa) RATE: [4000 4294967295)
2021-01-26 06-30-29.630 [Debug] (Alsa) PERIOD_TIME: 125000
2021-01-26 06-30-29.630 [Debug] (Alsa) PERIOD_SIZE: [500 536870912)
2021-01-26 06-30-29.630 [Debug] (Alsa) PERIOD_BYTES: [250 4294967295)
2021-01-26 06-30-29.630 [Debug] (Alsa) PERIODS: (0 3221226)
2021-01-26 06-30-29.630 [Debug] (Alsa) BUFFER_TIME: [1 4294967295]
2021-01-26 06-30-29.630 [Debug] (Alsa) BUFFER_SIZE: [1000 1610612735]
2021-01-26 06-30-29.630 [Debug] (Alsa) BUFFER_BYTES: [500 4294967295]
2021-01-26 06-30-29.630 [Debug] (Alsa) TICK_TIME: ALL
2021-01-26 06-30-29.654 [Info] (Alsa) Period time too small, changing from 20000 to 125000
2021-01-26 06-30-29.659 [Info] (Alsa) PCM name: default, sample rate: 44100 Hz, channels: 2, buffer time: 250000 us, periods: 2, period time: 125000 us, period frames: 5512
2021-01-26 06-30-29.662 [Debug] (Player) setVolume exp with base 10: 1 => 1
2021-01-26 06-30-29.669 [Debug] (Alsa) Resizing buffer from 0 to 44100
2021-01-26 06-30-30.204 [Info] (Controller) diff to server [ms]: 1.33229e+08
2021-01-26 06-30-30.386 [Debug] (Stream) Silent frames: 2943, frames: 5527, age: -66.755
2021-01-26 06-30-30.510 [Debug] (Stats) Chunk: 0        0       0       0       1       126     0
2021-01-26 06-30-31.009 [Debug] (Stats) Chunk: 1        0       0       0       5       123     0
2021-01-26 06-30-32.007 [Debug] (Stats) Chunk: 1        1       1       1       13      124     0
2021-01-26 06-30-33.007 [Debug] (Stats) Chunk: 3        1       1       1       21      125     0
2021-01-26 06-30-34.007 [Debug] (Stats) Chunk: 4        2       1       1       29      125     0
2021-01-26 06-30-35.007 [Debug] (Stats) Chunk: 3        3       2       2       37      124     0
2021-01-26 06-30-36.007 [Debug] (Stats) Chunk: 5        4       3       3       45      125     0
2021-01-26 06-30-37.011 [Debug] (Stats) Chunk: 6        5       3       3       53      126     0
2021-01-26 06-30-38.007 [Debug] (Stats) Chunk: 7        5       3       3       61      125     0
2021-01-26 06-30-39.007 [Debug] (Stats) Chunk: 7        6       4       4       69      124     0
2021-01-26 06-30-40.007 [Debug] (Stats) Chunk: 8        7       4       4       77      125     0
2021-01-26 06-30-41.007 [Debug] (Stats) Chunk: 8        8       5       5       85      124     0
2021-01-26 06-30-42.007 [Debug] (Stats) Chunk: 10       9       5       5       93      125     0
2021-01-26 06-30-43.012 [Debug] (Stats) Chunk: 11       10      5       5       101     119     0
2021-01-26 06-30-44.007 [Debug] (Stats) Chunk: 10       10      7       6       109     125     -10
2021-01-26 06-30-45.007 [Debug] (Stats) Chunk: 6        10      7       6       117     125     -15
2021-01-26 06-30-46.007 [Debug] (Stats) Chunk: 5        7       7       6       125     125     -16
2021-01-26 06-30-47.007 [Debug] (Stats) Chunk: 2        5       7       6       133     125     -15
2021-01-26 06-30-48.007 [Debug] (Stats) Chunk: 0        3       7       5       141     125     -10

pi@ludwig:~ $ snapclient --user snapclient:snapclient -h cms --logfilter *:debug --player alsa:buffer_time=120,fragments=6

2021-01-26 06-33-03.848 [Info] (Connection) Resolving host IP for: cms
2021-01-26 06-33-03.864 [Info] (Connection) Connecting
2021-01-26 06-33-03.872 [Notice] (Connection) Connected to 192.168.1.37
2021-01-26 06-33-03.874 [Info] (Connection) My MAC: "80:1f:02:b3:46:c1", socket: 8
2021-01-26 06-33-05.224 [Debug] (Connection) outstanding async_write
2021-01-26 06-33-05.272 [Info] (Controller) ServerSettings - buffer: 1000, latency: 0, volume: 100, muted: 0
metadata:{"STREAM":"snapcast"}
2021-01-26 06-33-05.280 [Info] (Controller) Codec: flac, sampleformat: 44100:16:2
2021-01-26 06-33-05.283 [Info] (Player) Player name: alsa, device: default, description: <none>, idx: 3, sharing mode: unspecified, parameters: buffer_time=120,fragments=6
2021-01-26 06-33-05.285 [Info] (Player) Mixer mode: software, parameters: <none>
2021-01-26 06-33-05.287 [Info] (Player) Sampleformat: 44100:16:2, stream: 44100:16:2
2021-01-26 06-33-05.289 [Info] (Alsa) Using buffer_time: 120 ms, fragments: 6
2021-01-26 06-33-05.301 [Debug] (Alsa) ACCESS:  MMAP_INTERLEAVED MMAP_NONINTERLEAVED MMAP_COMPLEX RW_INTERLEAVED RW_NONINTERLEAVED
2021-01-26 06-33-05.301 [Debug] (Alsa) FORMAT:  S8 U8 S16_LE S16_BE U16_LE U16_BE S24_LE S24_BE U24_LE U24_BE S32_LE S32_BE U32_LE U32_BE FLOAT_LE FLOAT_BE FLOAT64_LE FLOAT64_BE MU_LAW A_LAW IMA_ADPCM S20_LE S20_BE U20_LE U20_BE S24_3LE S24_3BE U24_3LE U24_3BE S20_3LE S20_3BE U20_3LE U20_3BE S18_3LE S18_3BE U18_3LE U18_3BE
2021-01-26 06-33-05.301 [Debug] (Alsa) SUBFORMAT:  STD
2021-01-26 06-33-05.301 [Debug] (Alsa) SAMPLE_BITS: [4 64]
2021-01-26 06-33-05.301 [Debug] (Alsa) FRAME_BITS: [4 640000]
2021-01-26 06-33-05.301 [Debug] (Alsa) CHANNELS: [1 10000]
2021-01-26 06-33-05.301 [Debug] (Alsa) RATE: [4000 4294967295)
2021-01-26 06-33-05.301 [Debug] (Alsa) PERIOD_TIME: 125000
2021-01-26 06-33-05.301 [Debug] (Alsa) PERIOD_SIZE: [500 536870912)
2021-01-26 06-33-05.301 [Debug] (Alsa) PERIOD_BYTES: [250 4294967295)
2021-01-26 06-33-05.301 [Debug] (Alsa) PERIODS: (0 3221226)
2021-01-26 06-33-05.301 [Debug] (Alsa) BUFFER_TIME: [1 4294967295]
2021-01-26 06-33-05.301 [Debug] (Alsa) BUFFER_SIZE: [1000 1610612735]
2021-01-26 06-33-05.301 [Debug] (Alsa) BUFFER_BYTES: [500 4294967295]
2021-01-26 06-33-05.301 [Debug] (Alsa) TICK_TIME: ALL
2021-01-26 06-33-05.320 [Info] (Alsa) Period time too small, changing from 20000 to 125000
2021-01-26 06-33-05.324 [Info] (Alsa) PCM name: default, sample rate: 44100 Hz, channels: 2, buffer time: 250000 us, periods: 2, period time: 125000 us, period frames: 5512
2021-01-26 06-33-05.327 [Debug] (Player) setVolume exp with base 10: 1 => 1
2021-01-26 06-33-05.339 [Debug] (Alsa) Resizing buffer from 0 to 44100
2021-01-26 06-33-05.528 [Info] (Controller) diff to server [ms]: 1.33229e+08
2021-01-26 06-33-06.006 [Debug] (Stream) Silent frames: 3508, frames: 5335, age: -79.566
2021-01-26 06-33-06.131 [Debug] (Stats) Chunk: 0        0       0       0       1       125     0
2021-01-26 06-33-07.006 [Debug] (Stats) Chunk: 1        0       0       0       8       125     0
2021-01-26 06-33-08.006 [Debug] (Stats) Chunk: 1        1       1       1       16      125     0
2021-01-26 06-33-09.006 [Debug] (Stats) Chunk: 3        1       1       1       24      125     0
2021-01-26 06-33-10.006 [Debug] (Stats) Chunk: 3        2       1       1       32      125     0
2021-01-26 06-33-11.006 [Debug] (Stats) Chunk: 3        3       2       2       40      124     0
2021-01-26 06-33-12.006 [Debug] (Stats) Chunk: 4        4       2       2       48      125     0
2021-01-26 06-33-13.006 [Debug] (Stats) Chunk: 5        5       3       3       56      124     0
2021-01-26 06-33-14.011 [Debug] (Stats) Chunk: 7        5       3       3       64      124     0
2021-01-26 06-33-15.008 [Debug] (Stats) Chunk: 6        6       4       4       72      126     0
2021-01-26 06-33-16.012 [Debug] (Stats) Chunk: 8        7       4       4       80      124     0
2021-01-26 06-33-17.011 [Debug] (Stats) Chunk: 10       8       4       4       88      126     0
2021-01-26 06-33-18.011 [Debug] (Stats) Chunk: 9        9       5       5       96      124     0
2021-01-26 06-33-19.011 [Debug] (Stats) Chunk: 10       10      5       5       104     126     -4
2021-01-26 06-33-20.011 [Debug] (Stats) Chunk: 9        10      6       6       112     124     -11
2021-01-26 06-33-21.006 [Debug] (Stats) Chunk: 7        9       7       6       120     125     -13
2021-01-26 06-33-22.011 [Debug] (Stats) Chunk: 3        7       7       6       128     125     -15
2021-01-26 06-33-23.006 [Debug] (Stats) Chunk: 2        4       7       5       136     125     -15
2021-01-26 06-33-24.006 [Debug] (Stats) Chunk: 0        2       7       5       144     125     -8
2021-01-26 06-33-25.006 [Debug] (Stats) Chunk: 0        0       7       5       152     125     -8
2021-01-26 06-33-26.006 [Debug] (Stats) Chunk: 0        0       7       4       160     125     0
2021-01-26 06-33-27.006 [Debug] (Stats) Chunk: 1        0       7       4       168     129     0

@badaix
Copy link
Owner

badaix commented Jan 26, 2021

@mrdago thanks, the "125" is back (which used to be 250 in interim versions), that's good 😃 :

2021-01-26 06-26-45.002 [Debug] (Stats) Chunk: 0        0       0       1       198     125     0

@badaix
Copy link
Owner

badaix commented Jan 26, 2021

@TotalSpaceshipguy Your logs are looking similar to mrdrago's logs. Snapclient requests a total buffer of 120ms, splitted into four fragments, but your device/driver can only handle buffer fragments of 125ms. Trying to get close to the requested buffer time, Alsa decides to use two fragments, summing up to a total buffer of 250ms (I guess Alsa would not use less fragments, because one is not enough for smooth playback (there is always one fragment played out, while other's are being filled with new "to-be-played" data)).
Snapclient is setting such values using the snd_pcm_hw_params_set_XXX_near interface, leaving some room for alsa to use them just as a hint and to tweak the actual values to fit the demands of device/driver.
Alsa will not hinder Snapclient to use more buffer fragments. So I'm thinking about a solution to configure everything as before, and in case Alsa decides to use two fragments, to raise the fragment count to three if it is unconfigured. So that mrdrago could configure the fragment count to two, because his device can play drop-less with only two fragments.
Side note: the more buffer time and/or fragments, the higher is your latency, which Snapclient tries to keep low, to leave a buffer for network related latencies. Using a buffer_time of 500ms and a four fragments would most probably work fine on all devices out there (these are the aplay defaults), but many devices are ok with 50ms and less.

So, make your self prepared for some test version(s) 😉

@badaix
Copy link
Owner

badaix commented Jan 26, 2021

@TotalSpaceshipguy Please try the version in actions with the commit message Use at least 3 fragments by default and paste logs with default settings and with --player alsa:buffer_time=120,fragments=2.

@efung1232
Copy link

I have been using v0.22 without problem since December until now. I have seen v0.23 earlier today. So, I built it from new in Raspbian Linux moode 5.4.77-v7+ #1371. My Raspberry Pi model 3B+ 1GB RAM. I have modified moOde Player's codes to add GUI to enable Snapserver, Snapclient, Airplay, and Spotify. I have left the amplifier in idle for a few hours. Then, I played music again without experiencing "drop out". Here is the version I am using now: snapserver v0.23.0. I have both snapserver and snapclient running on the same machine: /usr/bin/snapclient --logsink=system -s sndrpihifiberry , /usr/bin/snapserver --logging.sink=system --server.datadir=/var/lib/snapserver , /usr/local/bin/librespot --name Spotify Library --bitrate 320 --backend pipe --initial-volume 100 --verbose , /usr/local/bin/shairport-sync --name="Airplay Library" --output=stdout --use-stderr --get-coverart --metadata-pipename=/tmp/shairme . I have not tried separate client server yet. But, I will try tomorrow. Product used is Soundberry Audio's Raspberry Pi + headphone amplifier HPA02A. I will try client-server tomorrow with PA90A which has class-D output.

@cmelbye
Copy link

cmelbye commented Feb 3, 2021

Thanks @badaix for this incredible project and the fix -- I believe I was seeing the same exact issue, and with the latest develop build it's now working perfectly. 👍

@dikt1338
Copy link

dikt1338 commented Feb 9, 2021

Thank you so much @badaix for your awesome project and the fix!
I am using snapserver and snapclient on the same raspberry pi zero. I had the same issues as described above. i patched to v0.23.103 (server and client). the broken pipe messages are gone completely. But sometimes (every 2mins) i have hiccups. As far as I can see in the log everything should be fine. Does anybody have an idea where to dig now?

log extract with default config

2021-02-09 21-49-36.114 [Debug] (Stats) Chunk: 0 0 1 0 179 250 0
2021-02-09 21-49-37.114 [Debug] (Stats) Chunk: 0 0 1 0 186 250 0
2021-02-09 21-49-38.239 [Debug] (Stats) Chunk: 0 0 1 0 194 126 0
2021-02-09 21-49-39.114 [Debug] (Stats) Chunk: 0 0 0 0 201 250 -1
2021-02-09 21-49-40.114 [Debug] (Stats) Chunk: 0 0 0 0 209 249 0
2021-02-09 21-49-41.114 [Debug] (Stats) Chunk: 0 0 0 0 216 250 0
2021-02-09 21-49-42.114 [Debug] (Stats) Chunk: 0 0 0 0 224 249 0
2021-02-09 21-49-43.114 [Debug] (Stats) Chunk: 0 0 0 0 230 250 0
2021-02-09 21-49-44.114 [Debug] (Stats) Chunk: 1 0 0 0 238 250 0
2021-02-09 21-49-45.114 [Debug] (Stats) Chunk: 0 0 0 0 246 250 0
2021-02-09 21-49-46.116 [Debug] (Stats) Chunk: 0 0 0 0 254 247 0 <-hiccup somewhere here
2021-02-09 21-49-47.114 [Debug] (Stats) Chunk: 0 0 0 0 261 249 0 <-hiccup somewhere here
2021-02-09 21-49-48.114 [Debug] (Stats) Chunk: 1 1 0 0 267 250 0 <-hiccup somewhere here

@badaix
Copy link
Owner

badaix commented Feb 9, 2021

Client log looks good. Maybe you have resync events on the server

@sebirdman
Copy link

sebirdman commented Feb 12, 2021

I'm seeing similar issues, but my debug output is kinda different

This is running on a rpi4 with a arm64 build that i did myself. I've built off of the develop branch at commit 2a1fde8

server is an rpi4 running 0.23 tag on arm64
i've got two other rpi4's that are runing different audio outputs, on the regular armhf build. These two work just fine.

i should also note that, this DID work at one point. i recently moved my audio server and that's when i noticed the problem.

snapclient -s default:CARD=audioinjectorpi --logfilter *:debug

2021-02-12 21-34-26.995 [Info] (Avahi) (Browser) NEW: service 'Snapcast' of type '_snapcast._tcp' in domain 'local'
2021-02-12 21-34-26.996 [Info] (Avahi) (Browser) CACHE_EXHAUSTED
2021-02-12 21-34-26.997 [Info] (Avahi) Service 'Snapcast' of type '_snapcast._tcp' in domain 'local':
2021-02-12 21-34-26.997 [Info] (Avahi) 	audio.local:1704 (192.168.1.3)
2021-02-12 21-34-26.997 [Debug] (Avahi) 	TXT=
2021-02-12 21-34-26.997 [Debug] (Avahi) 	Proto=0
2021-02-12 21-34-26.997 [Debug] (Avahi) 	cookie is 0
2021-02-12 21-34-26.997 [Debug] (Avahi) 	is_local: 0
2021-02-12 21-34-26.997 [Debug] (Avahi) 	our_own: 0
2021-02-12 21-34-26.997 [Debug] (Avahi) 	wide_area: 0
2021-02-12 21-34-26.997 [Debug] (Avahi) 	multicast: 1
2021-02-12 21-34-26.997 [Debug] (Avahi) 	cached: 1
2021-02-12 21-34-26.998 [Info] (Controller) Found server 192.168.1.3:1704
2021-02-12 21-34-26.998 [Info] (Connection) Resolving host IP for: 192.168.1.3
2021-02-12 21-34-26.998 [Info] (Connection) Connecting
2021-02-12 21-34-27.037 [Notice] (Connection) Connected to 192.168.1.3
2021-02-12 21-34-27.037 [Info] (Connection) My MAC: "dc:a6:32:c3:ab:99", socket: 8
2021-02-12 21-34-27.184 [Debug] (Connection) outstanding async_write
2021-02-12 21-34-27.186 [Info] (Controller) ServerSettings - buffer: 1000, latency: 0, volume: 100, muted: 0
metadata:{"STREAM":"Spotify"}
2021-02-12 21-34-27.187 [Info] (Controller) Codec: flac, sampleformat: 44100:16:2
2021-02-12 21-34-27.187 [Info] (Player) Player name: alsa, device: default:CARD=audioinjectorpi, description: audioinjector-pi-soundcard, AudioInjector audio wm8731-hifi-0
2021-02-12 21-34-27.187 [Info] (Player) Default Audio Device, idx: 15, sharing mode: unspecified, parameters: <none>
2021-02-12 21-34-27.187 [Info] (Player) Mixer mode: software, parameters: <none>
2021-02-12 21-34-27.187 [Info] (Player) Sampleformat: 44100:16:2, stream: 44100:16:2
2021-02-12 21-34-27.187 [Info] (Alsa) Using default buffer_time: 80 ms, default fragments: 4
2021-02-12 21-34-27.191 [Debug] (Alsa) ACCESS:  MMAP_INTERLEAVED MMAP_NONINTERLEAVED MMAP_COMPLEX RW_INTERLEAVED RW_NONINTERLEAVED
2021-02-12 21-34-27.191 [Debug] (Alsa) FORMAT:  S8 U8 S16_LE S16_BE U16_LE U16_BE S24_LE S24_BE U24_LE U24_BE S32_LE S32_BE U32_LE U32_BE FLOAT_LE FLOAT_BE FLOAT64_LE FLOAT64_BE MU_LAW A_LAW IMA_ADPCM S20_LE S20_BE U20_LE U20_BE S24_3LE S24_3BE U24_3LE U24_3BE S20_3LE S20_3BE U20_3LE U20_3BE S18_3LE S18_3BE U18_3LE U18_3BE
2021-02-12 21-34-27.191 [Debug] (Alsa) SUBFORMAT:  STD
2021-02-12 21-34-27.191 [Debug] (Alsa) SAMPLE_BITS: [4 64]
2021-02-12 21-34-27.191 [Debug] (Alsa) FRAME_BITS: [4 640000]
2021-02-12 21-34-27.191 [Debug] (Alsa) CHANNELS: [1 10000]
2021-02-12 21-34-27.191 [Debug] (Alsa) RATE: [4000 4294967295)
2021-02-12 21-34-27.191 [Debug] (Alsa) PERIOD_TIME: (333 8192000]
2021-02-12 21-34-27.191 [Debug] (Alsa) PERIOD_SIZE: (1 4294967295)
2021-02-12 21-34-27.191 [Debug] (Alsa) PERIOD_BYTES: (0 4294967295)
2021-02-12 21-34-27.191 [Debug] (Alsa) PERIODS: (0 4294967294)
2021-02-12 21-34-27.191 [Debug] (Alsa) BUFFER_TIME: [1 4294967295]
2021-02-12 21-34-27.191 [Debug] (Alsa) BUFFER_SIZE: [2 4294967294]
2021-02-12 21-34-27.191 [Debug] (Alsa) BUFFER_BYTES: [1 4294967295]
2021-02-12 21-34-27.191 [Debug] (Alsa) TICK_TIME: ALL
2021-02-12 21-34-27.201 [Info] (Alsa) PCM name: default:CARD=audioinjectorpi, sample rate: 44100 Hz, channels: 2, buffer time: 80000 us, periods: 4, period time: 20000 us, period frames: 882
2021-02-12 21-34-27.201 [Debug] (Alsa) Failed to start PCM: Broken pipe
2021-02-12 21-34-27.202 [Debug] (Alsa) setVolume exp with base 10: 1 => 1
2021-02-12 21-34-27.202 [Debug] (Alsa) Resizing buffer from 0 to 14112
2021-02-12 21-34-27.202 [Info] (Stream) No chunks available
2021-02-12 21-34-27.202 [Info] (Alsa) Failed to get chunk
2021-02-12 21-34-27.309 [Info] (Controller) diff to server [ms]: 9.57988e+07
2021-02-12 21-34-28.281 [Debug] (Stream) age > 0: 152ms, dropping old chunks
2021-02-12 21-34-28.281 [Debug] (Stream) age: 126, requested chunk_duration: 40, duration: 26
2021-02-12 21-34-28.281 [Debug] (Stream) age: 100, requested chunk_duration: 40, duration: 26
2021-02-12 21-34-28.281 [Debug] (Stream) age: 74, requested chunk_duration: 40, duration: 26
2021-02-12 21-34-28.282 [Debug] (Stream) age: 48, requested chunk_duration: 40, duration: 26
2021-02-12 21-34-28.282 [Debug] (Stream) age: 22, requested chunk_duration: 40, duration: 26
2021-02-12 21-34-29.920 [Info] (Stream) abs(age > 500): 1598867
2021-02-12 21-34-29.921 [Debug] (Stats) Chunk: 15988	15988	15988	15988	1	40	0
2021-02-12 21-34-29.921 [Info] (Alsa) Failed to get chunk
2021-02-12 21-34-29.921 [Debug] (Stream) age > 0: 1558ms, dropping old chunks
2021-02-12 21-34-29.921 [Debug] (Stream) age: 1556, requested chunk_duration: 40, duration: 26
2021-02-12 21-34-29.921 [Debug] (Stream) age: 1530, requested chunk_duration: 40, duration: 26
2021-02-12 21-34-29.921 [Debug] (Stream) age: 1504, requested chunk_duration: 40, duration: 26
2021-02-12 21-34-29.921 [Debug] (Stream) age: 1478, requested chunk_duration: 40, duration: 26
2021-02-12 21-34-29.921 [Debug] (Stream) age: 1452, requested chunk_duration: 40, duration: 26
2021-02-12 21-34-29.922 [Debug] (Stream) age: 1426, requested chunk_duration: 40, duration: 26
2021-02-12 21-34-29.922 [Debug] (Stream) age: 1400, requested chunk_duration: 40, duration: 26
2021-02-12 21-34-29.922 [Debug] (Stream) age: 1374, requested chunk_duration: 40, duration: 26
2021-02-12 21-34-29.922 [Debug] (Stream) age: 1348, requested chunk_duration: 40, duration: 26
2021-02-12 21-34-29.922 [Debug] (Stream) age: 1322, requested chunk_duration: 40, duration: 26
2021-02-12 21-34-29.922 [Debug] (Stream) age: 1296, requested chunk_duration: 40, duration: 26
2021-02-12 21-34-29.922 [Debug] (Stream) age: 1270, requested chunk_duration: 40, duration: 26
2021-02-12 21-34-29.922 [Debug] (Stream) age: 1244, requested chunk_duration: 40, duration: 26
2021-02-12 21-34-29.922 [Debug] (Stream) age: 1218, requested chunk_duration: 40, duration: 26
2021-02-12 21-34-29.922 [Debug] (Stream) age: 1192, requested chunk_duration: 40, duration: 26
2021-02-12 21-34-29.922 [Debug] (Stream) age: 1166, requested chunk_duration: 40, duration: 26
2021-02-12 21-34-29.923 [Debug] (Stream) age: 1140, requested chunk_duration: 40, duration: 26
2021-02-12 21-34-29.923 [Debug] (Stream) age: 1114, requested chunk_duration: 40, duration: 26
2021-02-12 21-34-29.923 [Debug] (Stream) age: 1088, requested chunk_duration: 40, duration: 26
2021-02-12 21-34-29.923 [Debug] (Stream) age: 1062, requested chunk_duration: 40, duration: 26
2021-02-12 21-34-29.923 [Debug] (Stream) age: 1036, requested chunk_duration: 40, duration: 26
2021-02-12 21-34-29.923 [Debug] (Stream) age: 1010, requested chunk_duration: 40, duration: 26
2021-02-12 21-34-29.923 [Debug] (Stream) age: 983, requested chunk_duration: 40, duration: 26
2021-02-12 21-34-29.923 [Debug] (Stream) age: 957, requested chunk_duration: 40, duration: 26
2021-02-12 21-34-29.923 [Debug] (Stream) age: 931, requested chunk_duration: 40, duration: 26
2021-02-12 21-34-29.923 [Debug] (Stream) age: 905, requested chunk_duration: 40, duration: 26
2021-02-12 21-34-29.923 [Debug] (Stream) age: 879, requested chunk_duration: 40, duration: 26
2021-02-12 21-34-29.923 [Debug] (Stream) age: 853, requested chunk_duration: 40, duration: 26
2021-02-12 21-34-29.923 [Debug] (Stream) age: 827, requested chunk_duration: 40, duration: 26
2021-02-12 21-34-29.923 [Debug] (Stream) age: 801, requested chunk_duration: 40, duration: 26
2021-02-12 21-34-29.924 [Debug] (Stream) age: 775, requested chunk_duration: 40, duration: 26
2021-02-12 21-34-29.924 [Debug] (Stream) age: 749, requested chunk_duration: 40, duration: 26
2021-02-12 21-34-29.924 [Debug] (Stream) age: 723, requested chunk_duration: 40, duration: 26
2021-02-12 21-34-29.924 [Debug] (Stream) age: 697, requested chunk_duration: 40, duration: 26
2021-02-12 21-34-29.924 [Debug] (Stream) age: 671, requested chunk_duration: 40, duration: 26
2021-02-12 21-34-29.924 [Debug] (Stream) age: 645, requested chunk_duration: 40, duration: 26
2021-02-12 21-34-29.924 [Debug] (Stream) age: 619, requested chunk_duration: 40, duration: 26
2021-02-12 21-34-29.924 [Debug] (Stream) age: 593, requested chunk_duration: 40, duration: 26
2021-02-12 21-34-29.924 [Debug] (Stream) age: 567, requested chunk_duration: 40, duration: 26
2021-02-12 21-34-29.924 [Debug] (Stream) age: 541, requested chunk_duration: 40, duration: 26
2021-02-12 21-34-29.924 [Debug] (Stream) age: 515, requested chunk_duration: 40, duration: 26
2021-02-12 21-34-29.924 [Debug] (Stream) age: 489, requested chunk_duration: 40, duration: 26
2021-02-12 21-34-29.924 [Debug] (Stream) age: 462, requested chunk_duration: 40, duration: 26
2021-02-12 21-34-29.924 [Debug] (Stream) age: 436, requested chunk_duration: 40, duration: 26
2021-02-12 21-34-29.925 [Debug] (Stream) age: 410, requested chunk_duration: 40, duration: 26
2021-02-12 21-34-29.925 [Debug] (Stream) age: 384, requested chunk_duration: 40, duration: 26
2021-02-12 21-34-29.925 [Debug] (Stream) age: 358, requested chunk_duration: 40, duration: 26
2021-02-12 21-34-29.925 [Debug] (Stream) age: 332, requested chunk_duration: 40, duration: 26
2021-02-12 21-34-29.925 [Debug] (Stream) age: 306, requested chunk_duration: 40, duration: 26
2021-02-12 21-34-29.925 [Debug] (Stream) age: 280, requested chunk_duration: 40, duration: 26
2021-02-12 21-34-29.925 [Debug] (Stream) age: 254, requested chunk_duration: 40, duration: 26
2021-02-12 21-34-29.925 [Debug] (Stream) age: 228, requested chunk_duration: 40, duration: 26
2021-02-12 21-34-29.925 [Debug] (Stream) age: 202, requested chunk_duration: 40, duration: 26
2021-02-12 21-34-29.925 [Debug] (Stream) age: 176, requested chunk_duration: 40, duration: 26
2021-02-12 21-34-29.925 [Debug] (Stream) age: 150, requested chunk_duration: 40, duration: 26
2021-02-12 21-34-29.925 [Debug] (Stream) age: 124, requested chunk_duration: 40, duration: 26
2021-02-12 21-34-29.925 [Debug] (Stream) age: 98, requested chunk_duration: 40, duration: 26
2021-02-12 21-34-29.925 [Debug] (Stream) age: 72, requested chunk_duration: 40, duration: 26
2021-02-12 21-34-29.926 [Debug] (Stream) age: 46, requested chunk_duration: 40, duration: 26
2021-02-12 21-34-29.926 [Debug] (Stream) age: 20, requested chunk_duration: 40, duration: 26
2021-02-12 21-34-34.138 [Info] (Stream) abs(age > 500): 4153241
2021-02-12 21-34-34.139 [Debug] (Stats) Chunk: 41532	41532	41532	41532	1	20	0
2021-02-12 21-34-34.139 [Info] (Alsa) Failed to get chunk
2021-02-12 21-34-34.139 [Debug] (Stream) age > 0: 4093ms, dropping old chunks
2021-02-12 21-34-34.139 [Debug] (Stream) age: 4083, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.139 [Debug] (Stream) age: 4057, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.139 [Debug] (Stream) age: 4031, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.139 [Debug] (Stream) age: 4005, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.139 [Debug] (Stream) age: 3979, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.140 [Debug] (Stream) age: 3953, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.140 [Debug] (Stream) age: 3927, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.140 [Debug] (Stream) age: 3901, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.140 [Debug] (Stream) age: 3875, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.140 [Debug] (Stream) age: 3849, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.140 [Debug] (Stream) age: 3823, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.140 [Debug] (Stream) age: 3797, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.140 [Debug] (Stream) age: 3771, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.140 [Debug] (Stream) age: 3745, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.140 [Debug] (Stream) age: 3718, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.140 [Debug] (Stream) age: 3692, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.141 [Debug] (Stream) age: 3666, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.141 [Debug] (Stream) age: 3640, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.141 [Debug] (Stream) age: 3614, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.141 [Debug] (Stream) age: 3588, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.141 [Debug] (Stream) age: 3562, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.141 [Debug] (Stream) age: 3536, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.141 [Debug] (Stream) age: 3510, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.141 [Debug] (Stream) age: 3484, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.141 [Debug] (Stream) age: 3458, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.141 [Debug] (Stream) age: 3432, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.141 [Debug] (Stream) age: 3406, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.141 [Debug] (Stream) age: 3380, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.141 [Debug] (Stream) age: 3354, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.141 [Debug] (Stream) age: 3328, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.142 [Debug] (Stream) age: 3302, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.142 [Debug] (Stream) age: 3276, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.142 [Debug] (Stream) age: 3250, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.142 [Debug] (Stream) age: 3224, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.142 [Debug] (Stream) age: 3197, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.142 [Debug] (Stream) age: 3171, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.142 [Debug] (Stream) age: 3145, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.142 [Debug] (Stream) age: 3119, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.142 [Debug] (Stream) age: 3093, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.142 [Debug] (Stream) age: 3067, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.142 [Debug] (Stream) age: 3041, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.142 [Debug] (Stream) age: 3015, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.142 [Debug] (Stream) age: 2989, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.142 [Debug] (Stream) age: 2963, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.143 [Debug] (Stream) age: 2937, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.143 [Debug] (Stream) age: 2911, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.143 [Debug] (Stream) age: 2885, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.143 [Debug] (Stream) age: 2859, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.143 [Debug] (Stream) age: 2833, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.143 [Debug] (Stream) age: 2807, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.143 [Debug] (Stream) age: 2781, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.143 [Debug] (Stream) age: 2755, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.143 [Debug] (Stream) age: 2729, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.143 [Debug] (Stream) age: 2703, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.143 [Debug] (Stream) age: 2677, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.143 [Debug] (Stream) age: 2650, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.143 [Debug] (Stream) age: 2624, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.144 [Debug] (Stream) age: 2598, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.144 [Debug] (Stream) age: 2572, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.144 [Debug] (Stream) age: 2546, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.144 [Debug] (Stream) age: 2520, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.144 [Debug] (Stream) age: 2494, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.144 [Debug] (Stream) age: 2468, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.144 [Debug] (Stream) age: 2442, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.144 [Debug] (Stream) age: 2416, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.144 [Debug] (Stream) age: 2390, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.144 [Debug] (Stream) age: 2364, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.145 [Debug] (Stream) age: 2338, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.145 [Debug] (Stream) age: 2312, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.145 [Debug] (Stream) age: 2286, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.145 [Debug] (Stream) age: 2260, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.145 [Debug] (Stream) age: 2234, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.145 [Debug] (Stream) age: 2208, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.145 [Debug] (Stream) age: 2182, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.145 [Debug] (Stream) age: 2156, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.145 [Debug] (Stream) age: 2130, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.145 [Debug] (Stream) age: 2103, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.145 [Debug] (Stream) age: 2077, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.145 [Debug] (Stream) age: 2051, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.145 [Debug] (Stream) age: 2025, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.145 [Debug] (Stream) age: 1999, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.145 [Debug] (Stream) age: 1973, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.145 [Debug] (Stream) age: 1947, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.145 [Debug] (Stream) age: 1921, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.145 [Debug] (Stream) age: 1895, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.145 [Debug] (Stream) age: 1869, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.145 [Debug] (Stream) age: 1843, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.146 [Debug] (Stream) age: 1817, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.146 [Debug] (Stream) age: 1791, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.146 [Debug] (Stream) age: 1765, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.146 [Debug] (Stream) age: 1739, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.146 [Debug] (Stream) age: 1712, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.146 [Debug] (Stream) age: 1686, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.146 [Debug] (Stream) age: 1660, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.146 [Debug] (Stream) age: 1634, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.146 [Debug] (Stream) age: 1608, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.146 [Debug] (Stream) age: 1582, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.146 [Debug] (Stream) age: 1556, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.146 [Debug] (Stream) age: 1530, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.146 [Debug] (Stream) age: 1504, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.146 [Debug] (Stream) age: 1478, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.146 [Debug] (Stream) age: 1452, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.146 [Debug] (Stream) age: 1426, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.147 [Debug] (Stream) age: 1400, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.147 [Debug] (Stream) age: 1374, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.147 [Debug] (Stream) age: 1348, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.147 [Debug] (Stream) age: 1322, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.147 [Debug] (Stream) age: 1295, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.147 [Debug] (Stream) age: 1269, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.147 [Debug] (Stream) age: 1243, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.147 [Debug] (Stream) age: 1217, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.147 [Debug] (Stream) age: 1191, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.147 [Debug] (Stream) age: 1165, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.147 [Debug] (Stream) age: 1139, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.147 [Debug] (Stream) age: 1113, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.147 [Debug] (Stream) age: 1087, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.147 [Debug] (Stream) age: 1061, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.147 [Debug] (Stream) age: 1035, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.147 [Debug] (Stream) age: 1009, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.147 [Debug] (Stream) age: 983, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.147 [Debug] (Stream) age: 957, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.147 [Debug] (Stream) age: 930, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.147 [Debug] (Stream) age: 904, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.148 [Debug] (Stream) age: 878, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.148 [Debug] (Stream) age: 852, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.148 [Debug] (Stream) age: 826, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.148 [Debug] (Stream) age: 800, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.148 [Debug] (Stream) age: 774, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.148 [Debug] (Stream) age: 748, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.148 [Debug] (Stream) age: 722, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.148 [Debug] (Stream) age: 696, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.148 [Debug] (Stream) age: 670, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.148 [Debug] (Stream) age: 644, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.148 [Debug] (Stream) age: 617, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.148 [Debug] (Stream) age: 591, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.148 [Debug] (Stream) age: 565, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.148 [Debug] (Stream) age: 539, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.148 [Debug] (Stream) age: 513, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.148 [Debug] (Stream) age: 487, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.148 [Debug] (Stream) age: 461, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.148 [Debug] (Stream) age: 435, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.148 [Debug] (Stream) age: 409, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.148 [Debug] (Stream) age: 383, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.148 [Debug] (Stream) age: 357, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.148 [Debug] (Stream) age: 331, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.148 [Debug] (Stream) age: 305, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.149 [Debug] (Stream) age: 278, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.149 [Debug] (Stream) age: 252, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.149 [Debug] (Stream) age: 226, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.149 [Debug] (Stream) age: 200, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.149 [Debug] (Stream) age: 174, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.149 [Debug] (Stream) age: 148, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.149 [Debug] (Stream) age: 122, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.149 [Debug] (Stream) age: 96, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.149 [Debug] (Stream) age: 70, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.149 [Debug] (Stream) age: 44, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-34.149 [Debug] (Stream) age: 18, requested chunk_duration: 60, duration: 26
2021-02-12 21-34-36.717 [Error] (Alsa) XRUN while waiting for PCM: Broken pipe
2021-02-12 21-34-36.718 [Info] (Stream) abs(age > 500): 2488768
2021-02-12 21-34-36.718 [Debug] (Stats) Chunk: 24887	24887	24887	24887	1	0	0
2021-02-12 21-34-36.718 [Info] (Alsa) Failed to get chunk

@sebirdman
Copy link

sebirdman commented Feb 12, 2021

I've managed to get it to play "audio" with a very very high fragment:

--player alsa:buffer_time=180,fragments=300

anything lower than this, and it's a mess.

Reading through this issue more closely, i think this means my output device is really bad. I've always had trouble with keeping this device in sync with the others, and i think this is just time to replace it.

ubuntu@ubuntu:~/snapcast/client$ snapclient -s default:CARD=audioinjectorpi --logfilter *:debug --player alsa:buffer_time=80,fragments=300
2021-02-12 23-38-01.728 [Info] (Avahi) (Browser) NEW: service 'Snapcast' of type '_snapcast._tcp' in domain 'local'
2021-02-12 23-38-01.729 [Info] (Avahi) (Browser) CACHE_EXHAUSTED
2021-02-12 23-38-02.139 [Info] (Avahi) Service 'Snapcast' of type '_snapcast._tcp' in domain 'local':
2021-02-12 23-38-02.139 [Info] (Avahi) 	audio.local:1704 (192.168.1.3)
2021-02-12 23-38-02.139 [Debug] (Avahi) 	TXT=
2021-02-12 23-38-02.139 [Debug] (Avahi) 	Proto=0
2021-02-12 23-38-02.139 [Debug] (Avahi) 	cookie is 0
2021-02-12 23-38-02.140 [Debug] (Avahi) 	is_local: 0
2021-02-12 23-38-02.140 [Debug] (Avahi) 	our_own: 0
2021-02-12 23-38-02.140 [Debug] (Avahi) 	wide_area: 0
2021-02-12 23-38-02.140 [Debug] (Avahi) 	multicast: 1
2021-02-12 23-38-02.140 [Debug] (Avahi) 	cached: 1
2021-02-12 23-38-02.142 [Info] (Controller) Found server 192.168.1.3:1704
2021-02-12 23-38-02.142 [Info] (Connection) Resolving host IP for: 192.168.1.3
2021-02-12 23-38-02.143 [Info] (Connection) Connecting
2021-02-12 23-38-02.146 [Notice] (Connection) Connected to 192.168.1.3
2021-02-12 23-38-02.146 [Info] (Connection) My MAC: "dc:a6:32:c3:ab:99", socket: 8
2021-02-12 23-38-02.289 [Debug] (Connection) outstanding async_write
2021-02-12 23-38-02.293 [Info] (Controller) ServerSettings - buffer: 1000, latency: 0, volume: 100, muted: 0
metadata:{"STREAM":"Spotify"}
2021-02-12 23-38-02.293 [Info] (Controller) Codec: flac, sampleformat: 44100:16:2
2021-02-12 23-38-02.293 [Info] (Player) Player name: alsa, device: default:CARD=audioinjectorpi, description: audioinjector-pi-soundcard, AudioInjector audio wm8731-hifi-0
2021-02-12 23-38-02.293 [Info] (Player) Default Audio Device, idx: 15, sharing mode: unspecified, parameters: buffer_time=80,fragments=300
2021-02-12 23-38-02.293 [Info] (Player) Mixer mode: software, parameters: <none>
2021-02-12 23-38-02.293 [Info] (Player) Sampleformat: 44100:16:2, stream: 44100:16:2
2021-02-12 23-38-02.293 [Info] (Alsa) Using configured buffer_time: 80 ms, configured fragments: 300
2021-02-12 23-38-02.297 [Debug] (Alsa) ACCESS:  MMAP_INTERLEAVED MMAP_NONINTERLEAVED MMAP_COMPLEX RW_INTERLEAVED RW_NONINTERLEAVED
2021-02-12 23-38-02.297 [Debug] (Alsa) FORMAT:  S8 U8 S16_LE S16_BE U16_LE U16_BE S24_LE S24_BE U24_LE U24_BE S32_LE S32_BE U32_LE U32_BE FLOAT_LE FLOAT_BE FLOAT64_LE FLOAT64_BE MU_LAW A_LAW IMA_ADPCM S20_LE S20_BE U20_LE U20_BE S24_3LE S24_3BE U24_3LE U24_3BE S20_3LE S20_3BE U20_3LE U20_3BE S18_3LE S18_3BE U18_3LE U18_3BE
2021-02-12 23-38-02.297 [Debug] (Alsa) SUBFORMAT:  STD
2021-02-12 23-38-02.297 [Debug] (Alsa) SAMPLE_BITS: [4 64]
2021-02-12 23-38-02.297 [Debug] (Alsa) FRAME_BITS: [4 640000]
2021-02-12 23-38-02.297 [Debug] (Alsa) CHANNELS: [1 10000]
2021-02-12 23-38-02.297 [Debug] (Alsa) RATE: [4000 4294967295)
2021-02-12 23-38-02.297 [Debug] (Alsa) PERIOD_TIME: (333 8192000]
2021-02-12 23-38-02.297 [Debug] (Alsa) PERIOD_SIZE: (1 4294967295)
2021-02-12 23-38-02.297 [Debug] (Alsa) PERIOD_BYTES: (0 4294967295)
2021-02-12 23-38-02.297 [Debug] (Alsa) PERIODS: (0 4294967294)
2021-02-12 23-38-02.297 [Debug] (Alsa) BUFFER_TIME: [1 4294967295]
2021-02-12 23-38-02.297 [Debug] (Alsa) BUFFER_SIZE: [2 4294967294]
2021-02-12 23-38-02.297 [Debug] (Alsa) BUFFER_BYTES: [1 4294967295]
2021-02-12 23-38-02.297 [Debug] (Alsa) TICK_TIME: ALL
2021-02-12 23-38-02.298 [Info] (Alsa) Period time too small, changing from 266 to 1451
2021-02-12 23-38-02.298 [Info] (Alsa) Buffer time smaller than 300 * periods: 80000 us < 435300 us, raising buffer time
2021-02-12 23-38-02.299 [Info] (Alsa) PCM name: default:CARD=audioinjectorpi, sample rate: 44100 Hz, channels: 2, buffer time: 435374 us, periods: 300, period time: 1451 us, period frames: 64
2021-02-12 23-38-02.300 [Debug] (Alsa) Failed to start PCM: Broken pipe
2021-02-12 23-38-02.300 [Debug] (Player) setVolume exp with base 10: 1 => 1
2021-02-12 23-38-02.300 [Debug] (Alsa) Resizing buffer from 0 to 76800
2021-02-12 23-38-02.300 [Info] (Stream) No chunks available
2021-02-12 23-38-02.300 [Info] (Alsa) Failed to get chunk
2021-02-12 23-38-02.413 [Info] (Controller) diff to server [ms]: 9.57988e+07
2021-02-12 23-38-02.849 [Debug] (Stream) Silent frames: 101, frames: 320, age: -2.308
2021-02-12 23-38-03.209 [Debug] (Stats) Chunk: -1	0	0	0	2	107	0
2021-02-12 23-38-04.310 [Debug] (Stats) Chunk: -8	-3	-3	-3	9	107	0
2021-02-12 23-38-05.083 [Debug] (Stats) Chunk: -11	-6	-6	-6	15	107	0
2021-02-12 23-38-06.067 [Debug] (Stats) Chunk: -14	-8	-8	-8	21	224	0
2021-02-12 23-38-07.324 [Debug] (Stats) Chunk: -22	-14	-10	-10	30	107	0
2021-02-12 23-38-08.058 [Debug] (Stats) Chunk: -25	-17	-12	-12	34	107	0
2021-02-12 23-38-09.199 [Debug] (Stats) Chunk: -29	-23	-17	-17	43	107	0
2021-02-12 23-38-10.300 [Debug] (Stats) Chunk: -36	-28	-18	-18	52	107	0
2021-02-12 23-38-11.034 [Debug] (Stats) Chunk: -39	-32	-20	-20	59	146	0
2021-02-12 23-38-12.174 [Debug] (Stats) Chunk: -44	-36	-23	-23	66	107	0
2021-02-12 23-38-13.314 [Debug] (Stats) Chunk: -48	-41	-27	-27	75	107	0
2021-02-12 23-38-14.048 [Debug] (Stats) Chunk: -53	-46	-27	-27	80	107	0
2021-02-12 23-38-15.149 [Debug] (Stats) Chunk: -58	-51	-30	-30	89	146	0
2021-02-12 23-38-16.289 [Debug] (Stats) Chunk: -62	-56	-32	-32	97	107	0
2021-02-12 23-38-17.023 [Debug] (Stats) Chunk: -67	-59	-34	-34	103	146	7
2021-02-12 23-38-18.163 [Debug] (Stats) Chunk: -67	-64	-39	-36	112	107	25
2021-02-12 23-38-19.148 [Debug] (Stats) Chunk: -66	-65	-46	-38	120	262	22
2021-02-12 23-38-20.037 [Debug] (Stats) Chunk: -66	-65	-48	-39	125	107	19
2021-02-12 23-38-21.138 [Debug] (Stats) Chunk: -66	-64	-55	-44	134	107	25
2021-02-12 23-38-21.177 [Info] (Stream) pShortBuffer->full() && (abs(shortMedian_) > 5): -5527
2021-02-12 23-38-21.216 [Debug] (Stream) Silent frames: 278, frames: 1728, age: -6.323
2021-02-12 23-38-22.185 [Debug] (Stats) Chunk: -4	-3	-3	-3	6	200	0
2021-02-12 23-38-23.012 [Debug] (Stats) Chunk: -10	-4	-4	-4	12	107	0
2021-02-12 23-38-24.152 [Debug] (Stats) Chunk: -15	-6	-6	-6	19	107	0
2021-02-12 23-38-25.253 [Debug] (Stats) Chunk: -20	-10	-8	-8	26	146	0
2021-02-12 23-38-26.027 [Debug] (Stats) Chunk: -22	-17	-12	-12	33	396	0
2021-02-12 23-38-27.068 [Debug] (Stats) Chunk: -27	-22	-17	-17	41	206	0
2021-02-12 23-38-28.268 [Debug] (Stats) Chunk: -32	-27	-19	-19	51	107	0
2021-02-12 23-38-29.002 [Debug] (Stats) Chunk: -37	-29	-19	-19	56	107	0
2021-02-12 23-38-30.142 [Debug] (Stats) Chunk: -43	-34	-22	-22	64	107	0
2021-02-12 23-38-31.243 [Debug] (Stats) Chunk: -48	-39	-24	-24	71	146	0
2021-02-12 23-38-32.016 [Debug] (Stats) Chunk: -51	-43	-26	-26	76	107	0
2021-02-12 23-38-33.117 [Debug] (Stats) Chunk: -57	-48	-27	-27	82	107	0
2021-02-12 23-38-34.257 [Debug] (Stats) Chunk: -62	-53	-29	-29	90	107	0
2021-02-12 23-38-35.030 [Debug] (Stats) Chunk: -64	-57	-30	-30	95	396	0
2021-02-12 23-38-36.092 [Debug] (Stats) Chunk: -68	-64	-34	-33	104	146	14
2021-02-12 23-38-37.232 [Debug] (Stats) Chunk: -69	-66	-39	-36	111	107	25
2021-02-12 23-38-38.006 [Debug] (Stats) Chunk: -68	-66	-44	-38	117	107	17
2021-02-12 23-38-39.107 [Debug] (Stats) Chunk: -68	-66	-48	-40	124	107	24

@badaix
Copy link
Owner

badaix commented Feb 12, 2021

try with --sampleformat 48000:16:*

@sebirdman
Copy link

@badaix With sample format i'm still needing to have a lot of fragments to get anything passable. here's the output of that with only sample format:

2021-02-13 15-42-16.586 [Info] (Player) Player name: alsa, device: default:CARD=audioinjectorpi, description: audioinjector-pi-soundcard, AudioInjector audio wm8731-hifi-0
2021-02-13 15-42-16.586 [Info] (Player) Default Audio Device, idx: 15, sharing mode: unspecified, parameters: <none>
2021-02-13 15-42-16.586 [Info] (Player) Mixer mode: software, parameters: <none>
2021-02-13 15-42-16.586 [Info] (Player) Sampleformat: 48000:16:0, stream: 48000:16:2
2021-02-13 15-42-16.586 [Info] (Alsa) Using default buffer_time: 80 ms, default fragments: 4
2021-02-13 15-42-16.591 [Debug] (Alsa) ACCESS:  MMAP_INTERLEAVED MMAP_NONINTERLEAVED MMAP_COMPLEX RW_INTERLEAVED RW_NONINTERLEAVED
2021-02-13 15-42-16.591 [Debug] (Alsa) FORMAT:  S8 U8 S16_LE S16_BE U16_LE U16_BE S24_LE S24_BE U24_LE U24_BE S32_LE S32_BE U32_LE U32_BE FLOAT_LE FLOAT_BE FLOAT64_LE FLOAT64_BE MU_LAW A_LAW IMA_ADPCM S20_LE S20_BE U20_LE U20_BE S24_3LE S24_3BE U24_3LE U24_3BE S20_3LE S20_3BE U20_3LE U20_3BE S18_3LE S18_3BE U18_3LE U18_3BE
2021-02-13 15-42-16.591 [Debug] (Alsa) SUBFORMAT:  STD
2021-02-13 15-42-16.591 [Debug] (Alsa) SAMPLE_BITS: [4 64]
2021-02-13 15-42-16.591 [Debug] (Alsa) FRAME_BITS: [4 640000]
2021-02-13 15-42-16.591 [Debug] (Alsa) CHANNELS: [1 10000]
2021-02-13 15-42-16.591 [Debug] (Alsa) RATE: [4000 4294967295)
2021-02-13 15-42-16.591 [Debug] (Alsa) PERIOD_TIME: (333 8192000]
2021-02-13 15-42-16.591 [Debug] (Alsa) PERIOD_SIZE: (1 4294967295)
2021-02-13 15-42-16.591 [Debug] (Alsa) PERIOD_BYTES: (0 4294967295)
2021-02-13 15-42-16.591 [Debug] (Alsa) PERIODS: (0 4294967294)
2021-02-13 15-42-16.591 [Debug] (Alsa) BUFFER_TIME: [1 4294967295]
2021-02-13 15-42-16.591 [Debug] (Alsa) BUFFER_SIZE: [2 4294967294]
2021-02-13 15-42-16.591 [Debug] (Alsa) BUFFER_BYTES: [1 4294967295]
2021-02-13 15-42-16.591 [Debug] (Alsa) TICK_TIME: ALL
2021-02-13 15-42-16.601 [Info] (Alsa) PCM name: default:CARD=audioinjectorpi, sample rate: 48000 Hz, channels: 2, buffer time: 80000 us, periods: 4, period time: 20000 us, period frames: 960
2021-02-13 15-42-16.601 [Debug] (Alsa) Failed to start PCM: Broken pipe
2021-02-13 15-42-16.602 [Debug] (Player) setVolume exp with base 10: 1 => 1
2021-02-13 15-42-16.602 [Debug] (Alsa) Resizing buffer from 0 to 15360
2021-02-13 15-42-16.602 [Info] (Stream) No chunks available
2021-02-13 15-42-16.602 [Info] (Alsa) Failed to get chunk
2021-02-13 15-42-16.634 [Debug] (Resampler) Resample buffer completely filled, adding space for 5ms; new buffer size: 4800 bytes
2021-02-13 15-42-16.655 [Debug] (Resampler) Resample buffer completely filled, adding space for 5ms; new buffer size: 5760 bytes
2021-02-13 15-42-16.694 [Debug] (Resampler) Resample buffer completely filled, adding space for 5ms; new buffer size: 6720 bytes
2021-02-13 15-42-16.745 [Info] (Controller) diff to server [ms]: 9.57988e+07
2021-02-13 15-42-16.774 [Debug] (Resampler) Resample buffer completely filled, adding space for 5ms; new buffer size: 7680 bytes
2021-02-13 15-42-21.754 [Error] (Alsa) XRUN while waiting for PCM: Broken pipe
2021-02-13 15-42-21.754 [Debug] (Stream) age > 0: 4161ms, dropping old chunks
2021-02-13 15-42-21.754 [Debug] (Stream) age: 4140, requested chunk_duration: 80, duration: 25
2021-02-13 15-42-21.754 [Debug] (Stream) age: 4115, requested chunk_duration: 80, duration: 29
2021-02-13 15-42-21.755 [Debug] (Stream) age: 4086, requested chunk_duration: 80, duration: 30
2021-02-13 15-42-21.755 [Debug] (Stream) age: 4056, requested chunk_duration: 80, duration: 25
2021-02-13 15-42-21.755 [Debug] (Stream) age: 4030, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.755 [Debug] (Stream) age: 4012, requested chunk_duration: 80, duration: 35
2021-02-13 15-42-21.755 [Debug] (Stream) age: 3977, requested chunk_duration: 80, duration: 20
2021-02-13 15-42-21.755 [Debug] (Stream) age: 3956, requested chunk_duration: 80, duration: 37
2021-02-13 15-42-21.755 [Debug] (Stream) age: 3919, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.755 [Debug] (Stream) age: 3901, requested chunk_duration: 80, duration: 37
2021-02-13 15-42-21.755 [Debug] (Stream) age: 3864, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.755 [Debug] (Stream) age: 3845, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.755 [Debug] (Stream) age: 3826, requested chunk_duration: 80, duration: 37
2021-02-13 15-42-21.755 [Debug] (Stream) age: 3789, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.755 [Debug] (Stream) age: 3771, requested chunk_duration: 80, duration: 37
2021-02-13 15-42-21.756 [Debug] (Stream) age: 3734, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.756 [Debug] (Stream) age: 3715, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.756 [Debug] (Stream) age: 3697, requested chunk_duration: 80, duration: 37
2021-02-13 15-42-21.756 [Debug] (Stream) age: 3660, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.756 [Debug] (Stream) age: 3641, requested chunk_duration: 80, duration: 37
2021-02-13 15-42-21.756 [Debug] (Stream) age: 3604, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.756 [Debug] (Stream) age: 3585, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.756 [Debug] (Stream) age: 3567, requested chunk_duration: 80, duration: 37
2021-02-13 15-42-21.756 [Debug] (Stream) age: 3530, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.756 [Debug] (Stream) age: 3511, requested chunk_duration: 80, duration: 37
2021-02-13 15-42-21.756 [Debug] (Stream) age: 3474, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.756 [Debug] (Stream) age: 3455, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.756 [Debug] (Stream) age: 3437, requested chunk_duration: 80, duration: 37
2021-02-13 15-42-21.756 [Debug] (Stream) age: 3400, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.756 [Debug] (Stream) age: 3381, requested chunk_duration: 80, duration: 37
2021-02-13 15-42-21.756 [Debug] (Stream) age: 3344, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.756 [Debug] (Stream) age: 3326, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.757 [Debug] (Stream) age: 3307, requested chunk_duration: 80, duration: 37
2021-02-13 15-42-21.757 [Debug] (Stream) age: 3270, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.757 [Debug] (Stream) age: 3251, requested chunk_duration: 80, duration: 37
2021-02-13 15-42-21.757 [Debug] (Stream) age: 3214, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.757 [Debug] (Stream) age: 3196, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.757 [Debug] (Stream) age: 3177, requested chunk_duration: 80, duration: 37
2021-02-13 15-42-21.757 [Debug] (Stream) age: 3140, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.757 [Debug] (Stream) age: 3122, requested chunk_duration: 80, duration: 37
2021-02-13 15-42-21.757 [Debug] (Stream) age: 3084, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.757 [Debug] (Stream) age: 3066, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.757 [Debug] (Stream) age: 3047, requested chunk_duration: 80, duration: 37
2021-02-13 15-42-21.757 [Debug] (Stream) age: 3010, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.757 [Debug] (Stream) age: 2992, requested chunk_duration: 80, duration: 37
2021-02-13 15-42-21.757 [Debug] (Stream) age: 2955, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.757 [Debug] (Stream) age: 2936, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.757 [Debug] (Stream) age: 2917, requested chunk_duration: 80, duration: 37
2021-02-13 15-42-21.757 [Debug] (Stream) age: 2880, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.758 [Debug] (Stream) age: 2862, requested chunk_duration: 80, duration: 37
2021-02-13 15-42-21.758 [Debug] (Stream) age: 2825, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.758 [Debug] (Stream) age: 2806, requested chunk_duration: 80, duration: 37
2021-02-13 15-42-21.758 [Debug] (Stream) age: 2769, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.758 [Debug] (Stream) age: 2750, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.758 [Debug] (Stream) age: 2695, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.758 [Debug] (Stream) age: 2676, requested chunk_duration: 80, duration: 37
2021-02-13 15-42-21.758 [Debug] (Stream) age: 2639, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.758 [Debug] (Stream) age: 2621, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.758 [Debug] (Stream) age: 2602, requested chunk_duration: 80, duration: 37
2021-02-13 15-42-21.758 [Debug] (Stream) age: 2565, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.759 [Debug] (Stream) Wrote 34 bytes to socket
2021-02-13 15-42-21.759 [Debug] (Stream) age: 2547, requested chunk_duration: 80, duration: 37
2021-02-13 15-42-21.759 [Debug] (Stream) age: 2510, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.759 [Debug] (Stream) age: 2491, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.759 [Debug] (Stream) age: 2473, requested chunk_duration: 80, duration: 37
2021-02-13 15-42-21.759 [Debug] (Stream) age: 2436, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.759 [Debug] (Stream) age: 2417, requested chunk_duration: 80, duration: 37
2021-02-13 15-42-21.759 [Debug] (Stream) age: 2380, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.759 [Debug] (Stream) age: 2361, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.759 [Debug] (Stream) age: 2343, requested chunk_duration: 80, duration: 37
2021-02-13 15-42-21.759 [Debug] (Stream) age: 2306, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.759 [Debug] (Stream) age: 2287, requested chunk_duration: 80, duration: 37
2021-02-13 15-42-21.759 [Debug] (Stream) age: 2250, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.759 [Debug] (Stream) age: 2232, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.759 [Debug] (Stream) age: 2213, requested chunk_duration: 80, duration: 37
2021-02-13 15-42-21.760 [Debug] (Stream) age: 2176, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.760 [Debug] (Stream) age: 2157, requested chunk_duration: 80, duration: 37
2021-02-13 15-42-21.760 [Debug] (Stream) age: 2120, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.760 [Debug] (Stream) age: 2102, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.760 [Debug] (Stream) age: 2083, requested chunk_duration: 80, duration: 37
2021-02-13 15-42-21.760 [Debug] (Stream) age: 2046, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.760 [Debug] (Stream) age: 2027, requested chunk_duration: 80, duration: 37
2021-02-13 15-42-21.760 [Debug] (Stream) age: 1990, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.760 [Debug] (Stream) age: 1972, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.760 [Debug] (Stream) age: 1953, requested chunk_duration: 80, duration: 37
2021-02-13 15-42-21.760 [Debug] (Stream) age: 1916, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.760 [Debug] (Stream) age: 1898, requested chunk_duration: 80, duration: 37
2021-02-13 15-42-21.760 [Debug] (Stream) age: 1860, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.760 [Debug] (Stream) age: 1842, requested chunk_duration: 80, duration: 37
2021-02-13 15-42-21.760 [Debug] (Stream) age: 1805, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.760 [Debug] (Stream) age: 1786, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.761 [Debug] (Stream) age: 1768, requested chunk_duration: 80, duration: 37
2021-02-13 15-42-21.761 [Debug] (Stream) age: 1731, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.761 [Debug] (Stream) age: 1712, requested chunk_duration: 80, duration: 37
2021-02-13 15-42-21.761 [Debug] (Stream) age: 1675, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.761 [Debug] (Stream) age: 1656, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.761 [Debug] (Stream) age: 1638, requested chunk_duration: 80, duration: 37
2021-02-13 15-42-21.761 [Debug] (Stream) age: 1601, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.761 [Debug] (Stream) age: 1582, requested chunk_duration: 80, duration: 37
2021-02-13 15-42-21.761 [Debug] (Stream) age: 1545, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.761 [Debug] (Stream) age: 1527, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.761 [Debug] (Stream) age: 1508, requested chunk_duration: 80, duration: 37
2021-02-13 15-42-21.761 [Debug] (Stream) age: 1471, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.761 [Debug] (Stream) age: 1452, requested chunk_duration: 80, duration: 37
2021-02-13 15-42-21.761 [Debug] (Stream) age: 1415, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.761 [Debug] (Stream) age: 1397, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.761 [Debug] (Stream) age: 1378, requested chunk_duration: 80, duration: 37
2021-02-13 15-42-21.761 [Debug] (Stream) age: 1341, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.761 [Debug] (Stream) age: 1322, requested chunk_duration: 80, duration: 37
2021-02-13 15-42-21.762 [Debug] (Stream) age: 1285, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.762 [Debug] (Stream) age: 1267, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.762 [Debug] (Stream) age: 1248, requested chunk_duration: 80, duration: 37
2021-02-13 15-42-21.762 [Debug] (Stream) age: 1211, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.762 [Debug] (Stream) age: 1193, requested chunk_duration: 80, duration: 37
2021-02-13 15-42-21.762 [Debug] (Stream) age: 1155, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.762 [Debug] (Stream) age: 1137, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.762 [Debug] (Stream) age: 1118, requested chunk_duration: 80, duration: 37
2021-02-13 15-42-21.762 [Debug] (Stream) age: 1081, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.762 [Debug] (Stream) age: 1063, requested chunk_duration: 80, duration: 37
2021-02-13 15-42-21.762 [Debug] (Stream) age: 1026, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.762 [Debug] (Stream) age: 1007, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.762 [Debug] (Stream) age: 989, requested chunk_duration: 80, duration: 37
2021-02-13 15-42-21.762 [Debug] (Stream) age: 951, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.762 [Debug] (Stream) age: 933, requested chunk_duration: 80, duration: 37
2021-02-13 15-42-21.762 [Debug] (Stream) age: 896, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.763 [Debug] (Stream) age: 877, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.763 [Debug] (Stream) age: 859, requested chunk_duration: 80, duration: 37
2021-02-13 15-42-21.763 [Debug] (Stream) age: 822, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.763 [Debug] (Stream) age: 803, requested chunk_duration: 80, duration: 37
2021-02-13 15-42-21.763 [Debug] (Stream) age: 766, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.763 [Debug] (Stream) age: 747, requested chunk_duration: 80, duration: 37
2021-02-13 15-42-21.763 [Debug] (Stream) age: 710, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.763 [Debug] (Stream) age: 692, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.763 [Debug] (Stream) age: 673, requested chunk_duration: 80, duration: 37
2021-02-13 15-42-21.763 [Debug] (Stream) age: 636, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.763 [Debug] (Stream) age: 617, requested chunk_duration: 80, duration: 37
2021-02-13 15-42-21.763 [Debug] (Stream) age: 580, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.763 [Debug] (Stream) age: 562, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.763 [Debug] (Stream) age: 543, requested chunk_duration: 80, duration: 37
2021-02-13 15-42-21.763 [Debug] (Stream) age: 506, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.763 [Debug] (Stream) age: 488, requested chunk_duration: 80, duration: 37
2021-02-13 15-42-21.764 [Debug] (Stream) age: 451, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.764 [Debug] (Stream) age: 432, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.764 [Debug] (Stream) age: 414, requested chunk_duration: 80, duration: 37
2021-02-13 15-42-21.764 [Debug] (Stream) age: 376, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.764 [Debug] (Stream) age: 358, requested chunk_duration: 80, duration: 37
2021-02-13 15-42-21.764 [Debug] (Stream) age: 321, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.764 [Debug] (Stream) age: 302, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.764 [Debug] (Stream) age: 284, requested chunk_duration: 80, duration: 37
2021-02-13 15-42-21.764 [Debug] (Stream) age: 246, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.764 [Debug] (Stream) age: 228, requested chunk_duration: 80, duration: 37
2021-02-13 15-42-21.764 [Debug] (Stream) age: 191, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.764 [Debug] (Stream) age: 172, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.764 [Debug] (Stream) age: 154, requested chunk_duration: 80, duration: 37
2021-02-13 15-42-21.764 [Debug] (Stream) age: 117, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.764 [Debug] (Stream) age: 98, requested chunk_duration: 80, duration: 37
2021-02-13 15-42-21.764 [Debug] (Stream) age: 61, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.764 [Debug] (Stream) age: 42, requested chunk_duration: 80, duration: 18
2021-02-13 15-42-21.765 [Debug] (Stream) age: 24, requested chunk_duration: 80, duration: 37

@sebirdman
Copy link

after moving one of my "working" setups to arm64 and recompiling at the 0.23 tag or the current tip of develop, i've got the same issues on it as well. i have to use a very high fragment in both cases. i wonder if it's an arm64 issue?

@badaix
Copy link
Owner

badaix commented Feb 14, 2021

@sebirdman what OS are you running one? What is an audioinjectorpi? Can you try if it's working with a physical audio device? Is aplay capable of using this device?
Also 300 fragments or more than 10 fragments is not sane (no setup should need more than 4 fragments).
Your setup will use 300 buffers of 1.5ms each, the DACs in this thread are using 125ms buffers. Snapcast and your device will be highly busy filling these small buffers. I would rather recommend to raise the buffer, e.g. --player alsa:buffer_time=200,fragments=4.

@sebirdman
Copy link

sebirdman commented Feb 14, 2021

@badaix I'm running ubuntu 20.04 and audioinjectorpi is this device: http://www.audioinjector.net/rpi-hat

I may be able to try with the headphones plug on the rpi later today, will try to get that for you

Edit:

Linux recordplayer 5.4.0-1028-raspi #31-Ubuntu SMP PREEMPT Wed Jan 20 11:30:45 UTC 2021 aarch64 aarch64 aarch64 GNU/Linux

without specifying the device, the log output looks correct.

ubuntu@recordplayer:~$ snapclient --logfilter *:debug
2021-02-14 18-19-55.446 [Info] (Avahi) (Browser) NEW: service 'Snapcast' of type '_snapcast._tcp' in domain 'local'
2021-02-14 18-19-55.447 [Info] (Avahi) (Browser) CACHE_EXHAUSTED
2021-02-14 18-19-55.448 [Info] (Avahi) Service 'Snapcast' of type '_snapcast._tcp' in domain 'local':
2021-02-14 18-19-55.448 [Info] (Avahi) 	audio.local:1704 (192.168.1.3)
2021-02-14 18-19-55.448 [Debug] (Avahi) 	TXT=
2021-02-14 18-19-55.448 [Debug] (Avahi) 	Proto=0
2021-02-14 18-19-55.448 [Debug] (Avahi) 	cookie is 0
2021-02-14 18-19-55.448 [Debug] (Avahi) 	is_local: 0
2021-02-14 18-19-55.448 [Debug] (Avahi) 	our_own: 0
2021-02-14 18-19-55.448 [Debug] (Avahi) 	wide_area: 0
2021-02-14 18-19-55.448 [Debug] (Avahi) 	multicast: 1
2021-02-14 18-19-55.448 [Debug] (Avahi) 	cached: 1
2021-02-14 18-19-55.449 [Info] (Controller) Found server 192.168.1.3:1704
2021-02-14 18-19-55.449 [Info] (Connection) Resolving host IP for: 192.168.1.3
2021-02-14 18-19-55.449 [Info] (Connection) Connecting
2021-02-14 18-19-55.451 [Notice] (Connection) Connected to 192.168.1.3
2021-02-14 18-19-55.451 [Info] (Connection) My MAC: "dc:a6:32:c3:ab:99", socket: 8
2021-02-14 18-19-55.593 [Debug] (Connection) outstanding async_write
2021-02-14 18-19-55.596 [Info] (Controller) ServerSettings - buffer: 1000, latency: 0, volume: 100, muted: 0
metadata:{"STREAM":"Spotify"}
2021-02-14 18-19-55.598 [Info] (Controller) Codec: flac, sampleformat: 44100:16:2
2021-02-14 18-19-55.598 [Info] (Player) Player name: alsa, device: default:CARD=Headphones, description: bcm2835 Headphones, bcm2835 Headphones
2021-02-14 18-19-55.598 [Info] (Player) Default Audio Device, idx: 8, sharing mode: unspecified, parameters: <none>
2021-02-14 18-19-55.598 [Info] (Player) Mixer mode: software, parameters: <none>
2021-02-14 18-19-55.598 [Info] (Player) Sampleformat: 44100:16:2, stream: 44100:16:2
2021-02-14 18-19-55.598 [Info] (Alsa) Using default buffer_time: 80 ms, default fragments: 4
2021-02-14 18-19-55.605 [Debug] (Alsa) ACCESS:  MMAP_INTERLEAVED MMAP_NONINTERLEAVED MMAP_COMPLEX RW_INTERLEAVED RW_NONINTERLEAVED
2021-02-14 18-19-55.605 [Debug] (Alsa) FORMAT:  S8 U8 S16_LE S16_BE U16_LE U16_BE S24_LE S24_BE U24_LE U24_BE S32_LE S32_BE U32_LE U32_BE FLOAT_LE FLOAT_BE FLOAT64_LE FLOAT64_BE MU_LAW A_LAW IMA_ADPCM S20_LE S20_BE U20_LE U20_BE S24_3LE S24_3BE U24_3LE U24_3BE S20_3LE S20_3BE U20_3LE U20_3BE S18_3LE S18_3BE U18_3LE U18_3BE
2021-02-14 18-19-55.605 [Debug] (Alsa) SUBFORMAT:  STD
2021-02-14 18-19-55.605 [Debug] (Alsa) SAMPLE_BITS: [4 64]
2021-02-14 18-19-55.605 [Debug] (Alsa) FRAME_BITS: [4 640000]
2021-02-14 18-19-55.605 [Debug] (Alsa) CHANNELS: [1 10000]
2021-02-14 18-19-55.605 [Debug] (Alsa) RATE: [4000 4294967295]
2021-02-14 18-19-55.605 [Debug] (Alsa) PERIOD_TIME: [10000 16384000]
2021-02-14 18-19-55.605 [Debug] (Alsa) PERIOD_SIZE: [40 4294967295]
2021-02-14 18-19-55.605 [Debug] (Alsa) PERIOD_BYTES: [20 4294967295]
2021-02-14 18-19-55.605 [Debug] (Alsa) PERIODS: (0 107374183)
2021-02-14 18-19-55.605 [Debug] (Alsa) BUFFER_TIME: [1 4294967295]
2021-02-14 18-19-55.605 [Debug] (Alsa) BUFFER_SIZE: [1 4294967294]
2021-02-14 18-19-55.605 [Debug] (Alsa) BUFFER_BYTES: [1 4294967295]
2021-02-14 18-19-55.605 [Debug] (Alsa) TICK_TIME: ALL
2021-02-14 18-19-55.607 [Info] (Alsa) PCM name: default:CARD=Headphones, sample rate: 44100 Hz, channels: 2, buffer time: 80000 us, periods: 3, period time: 20045 us, period frames: 884
2021-02-14 18-19-55.607 [Debug] (Alsa) Failed to start PCM: Broken pipe
2021-02-14 18-19-55.607 [Debug] (Player) setVolume exp with base 10: 1 => 1
2021-02-14 18-19-55.607 [Debug] (Alsa) Resizing buffer from 0 to 14112
2021-02-14 18-19-55.608 [Info] (Stream) No chunks available
2021-02-14 18-19-55.608 [Info] (Alsa) Failed to get chunk
2021-02-14 18-19-55.708 [Info] (Controller) diff to server [ms]: 1.65319e+08
2021-02-14 18-19-56.502 [Debug] (Stream) Silent frames: 1285, frames: 1753, age: -29.147
2021-02-14 18-19-56.523 [Debug] (Stats) Chunk: 0	0	0	0	1	59	0
2021-02-14 18-19-57.022 [Debug] (Stats) Chunk: 0	0	0	0	14	40	0
2021-02-14 18-19-58.022 [Debug] (Stats) Chunk: 0	0	0	0	43	40	0
2021-02-14 18-19-59.003 [Debug] (Stats) Chunk: 0	0	0	0	77	59	0
2021-02-14 18-20-00.022 [Debug] (Stats) Chunk: 0	0	0	0	106	40	0
2021-02-14 18-20-01.012 [Debug] (Stats) Chunk: 0	0	0	0	134	39	0

if i just try to raise the buffer time, i just get messages like:

buntu@recordplayer:~$ snapclient -s default:CARD=audioinjectorpi --logfilter *:debug --player alsa:buffer_time=500,fragments=4
2021-02-14 18-23-47.672 [Info] (Avahi) (Browser) NEW: service 'Snapcast' of type '_snapcast._tcp' in domain 'local'
2021-02-14 18-23-47.673 [Info] (Avahi) (Browser) CACHE_EXHAUSTED
2021-02-14 18-23-48.152 [Info] (Avahi) Service 'Snapcast' of type '_snapcast._tcp' in domain 'local':
2021-02-14 18-23-48.152 [Info] (Avahi) 	audio.local:1704 (192.168.1.3)
2021-02-14 18-23-48.152 [Debug] (Avahi) 	TXT=
2021-02-14 18-23-48.152 [Debug] (Avahi) 	Proto=0
2021-02-14 18-23-48.152 [Debug] (Avahi) 	cookie is 0
2021-02-14 18-23-48.152 [Debug] (Avahi) 	is_local: 0
2021-02-14 18-23-48.152 [Debug] (Avahi) 	our_own: 0
2021-02-14 18-23-48.153 [Debug] (Avahi) 	wide_area: 0
2021-02-14 18-23-48.153 [Debug] (Avahi) 	multicast: 1
2021-02-14 18-23-48.153 [Debug] (Avahi) 	cached: 1
2021-02-14 18-23-48.156 [Info] (Controller) Found server 192.168.1.3:1704
2021-02-14 18-23-48.156 [Info] (Connection) Resolving host IP for: 192.168.1.3
2021-02-14 18-23-48.156 [Info] (Connection) Connecting
2021-02-14 18-23-48.161 [Notice] (Connection) Connected to 192.168.1.3
2021-02-14 18-23-48.161 [Info] (Connection) My MAC: "dc:a6:32:c3:ab:99", socket: 8
2021-02-14 18-23-48.308 [Debug] (Connection) outstanding async_write
2021-02-14 18-23-48.311 [Info] (Controller) ServerSettings - buffer: 1000, latency: 0, volume: 100, muted: 0
metadata:{"STREAM":"Spotify"}
2021-02-14 18-23-48.311 [Info] (Controller) Codec: flac, sampleformat: 44100:16:2
2021-02-14 18-23-48.312 [Info] (Player) Player name: alsa, device: default:CARD=audioinjectorpi, description: audioinjector-pi-soundcard, AudioInjector audio wm8731-hifi-0
2021-02-14 18-23-48.312 [Info] (Player) Default Audio Device, idx: 15, sharing mode: unspecified, parameters: buffer_time=500,fragments=4
2021-02-14 18-23-48.312 [Info] (Player) Mixer mode: software, parameters: <none>
2021-02-14 18-23-48.312 [Info] (Player) Sampleformat: 44100:16:2, stream: 44100:16:2
2021-02-14 18-23-48.312 [Info] (Alsa) Using configured buffer_time: 500 ms, configured fragments: 4
2021-02-14 18-23-48.318 [Debug] (Alsa) ACCESS:  MMAP_INTERLEAVED MMAP_NONINTERLEAVED MMAP_COMPLEX RW_INTERLEAVED RW_NONINTERLEAVED
2021-02-14 18-23-48.318 [Debug] (Alsa) FORMAT:  S8 U8 S16_LE S16_BE U16_LE U16_BE S24_LE S24_BE U24_LE U24_BE S32_LE S32_BE U32_LE U32_BE FLOAT_LE FLOAT_BE FLOAT64_LE FLOAT64_BE MU_LAW A_LAW IMA_ADPCM S20_LE S20_BE U20_LE U20_BE S24_3LE S24_3BE U24_3LE U24_3BE S20_3LE S20_3BE U20_3LE U20_3BE S18_3LE S18_3BE U18_3LE U18_3BE
2021-02-14 18-23-48.318 [Debug] (Alsa) SUBFORMAT:  STD
2021-02-14 18-23-48.318 [Debug] (Alsa) SAMPLE_BITS: [4 64]
2021-02-14 18-23-48.318 [Debug] (Alsa) FRAME_BITS: [4 640000]
2021-02-14 18-23-48.318 [Debug] (Alsa) CHANNELS: [1 10000]
2021-02-14 18-23-48.318 [Debug] (Alsa) RATE: [4000 4294967295)
2021-02-14 18-23-48.318 [Debug] (Alsa) PERIOD_TIME: (333 8192000]
2021-02-14 18-23-48.318 [Debug] (Alsa) PERIOD_SIZE: (1 4294967295)
2021-02-14 18-23-48.318 [Debug] (Alsa) PERIOD_BYTES: (0 4294967295)
2021-02-14 18-23-48.318 [Debug] (Alsa) PERIODS: (0 4294967294)
2021-02-14 18-23-48.318 [Debug] (Alsa) BUFFER_TIME: [1 4294967295]
2021-02-14 18-23-48.318 [Debug] (Alsa) BUFFER_SIZE: [2 4294967294]
2021-02-14 18-23-48.318 [Debug] (Alsa) BUFFER_BYTES: [1 4294967295]
2021-02-14 18-23-48.318 [Debug] (Alsa) TICK_TIME: ALL
2021-02-14 18-23-48.320 [Info] (Alsa) Buffer time smaller than 4 * periods: 500000 us < 500044 us, raising buffer time
2021-02-14 18-23-48.329 [Info] (Alsa) PCM name: default:CARD=audioinjectorpi, sample rate: 44100 Hz, channels: 2, buffer time: 500045 us, periods: 4, period time: 125011 us, period frames: 5513
2021-02-14 18-23-48.329 [Debug] (Alsa) Failed to start PCM: Broken pipe
2021-02-14 18-23-48.329 [Debug] (Alsa) setVolume exp with base 10: 1 => 1
2021-02-14 18-23-48.329 [Debug] (Alsa) Resizing buffer from 0 to 88208
2021-02-14 18-23-48.330 [Info] (Stream) No chunks available
2021-02-14 18-23-48.330 [Info] (Alsa) Failed to get chunk
2021-02-14 18-23-48.432 [Info] (Controller) diff to server [ms]: 1.65319e+08
2021-02-14 18-23-48.954 [Debug] (Stream) age > 0: 32ms, dropping old chunks
2021-02-14 18-23-48.954 [Debug] (Stream) age: 6, requested chunk_duration: 125, duration: 26
2021-02-14 18-23-55.952 [Error] (Alsa) XRUN while waiting for PCM: Broken pipe
2021-02-14 18-23-55.952 [Info] (Stream) abs(age > 500): 6497798
2021-02-14 18-23-55.952 [Debug] (Stats) Chunk: 64977	64977	64977	64977	1	0	0
2021-02-14 18-23-55.953 [Info] (Alsa) Failed to get chunk
2021-02-14 18-23-55.953 [Debug] (Stream) age > 0: 4535ms, dropping old chunks
2021-02-14 18-23-55.953 [Debug] (Stream) age: 4513, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.953 [Debug] (Stream) age: 4487, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.953 [Debug] (Stream) age: 4461, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.953 [Debug] (Stream) age: 4435, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.953 [Debug] (Stream) age: 4409, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.953 [Debug] (Stream) age: 4383, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.953 [Debug] (Stream) age: 4357, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.953 [Debug] (Stream) age: 4331, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.953 [Debug] (Stream) age: 4305, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.953 [Debug] (Stream) age: 4279, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.954 [Debug] (Stream) age: 4253, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.954 [Debug] (Stream) age: 4227, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.954 [Debug] (Stream) age: 4201, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.954 [Debug] (Stream) age: 4175, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.954 [Debug] (Stream) age: 4149, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.954 [Debug] (Stream) age: 4123, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.954 [Debug] (Stream) age: 4097, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.954 [Debug] (Stream) age: 4071, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.954 [Debug] (Stream) age: 4045, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.954 [Debug] (Stream) age: 4019, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.954 [Debug] (Stream) age: 3993, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.954 [Debug] (Stream) age: 3966, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.954 [Debug] (Stream) age: 3940, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.955 [Debug] (Stream) age: 3914, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.955 [Debug] (Stream) age: 3888, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.955 [Debug] (Stream) age: 3862, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.955 [Debug] (Stream) age: 3836, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.955 [Debug] (Stream) age: 3810, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.955 [Debug] (Stream) age: 3784, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.955 [Debug] (Stream) age: 3758, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.955 [Debug] (Stream) age: 3732, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.955 [Debug] (Stream) age: 3706, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.955 [Debug] (Stream) age: 3680, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.955 [Debug] (Stream) age: 3654, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.955 [Debug] (Stream) age: 3628, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.955 [Debug] (Stream) age: 3602, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.955 [Debug] (Stream) age: 3576, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.956 [Debug] (Stream) age: 3550, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.956 [Debug] (Stream) age: 3524, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.956 [Debug] (Stream) age: 3498, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.956 [Debug] (Stream) age: 3472, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.956 [Debug] (Stream) age: 3445, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.956 [Debug] (Stream) age: 3419, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.956 [Debug] (Stream) age: 3393, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.956 [Debug] (Stream) age: 3367, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.956 [Debug] (Stream) age: 3341, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.956 [Debug] (Stream) age: 3315, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.956 [Debug] (Stream) age: 3289, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.956 [Debug] (Stream) age: 3263, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.956 [Debug] (Stream) age: 3237, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.957 [Debug] (Stream) age: 3211, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.957 [Debug] (Stream) age: 3185, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.957 [Debug] (Stream) age: 3159, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.957 [Debug] (Stream) age: 3133, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.957 [Debug] (Stream) age: 3107, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.957 [Debug] (Stream) age: 3081, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.957 [Debug] (Stream) age: 3055, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.957 [Debug] (Stream) age: 3029, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.957 [Debug] (Stream) age: 3003, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.957 [Debug] (Stream) age: 2977, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.957 [Debug] (Stream) age: 2951, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.957 [Debug] (Stream) age: 2925, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.957 [Debug] (Stream) age: 2898, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.958 [Debug] (Stream) age: 2872, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.958 [Debug] (Stream) age: 2846, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.958 [Debug] (Stream) age: 2820, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.958 [Debug] (Stream) age: 2794, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.958 [Debug] (Stream) age: 2768, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.958 [Debug] (Stream) age: 2742, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.958 [Debug] (Stream) age: 2716, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.958 [Debug] (Stream) age: 2690, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.958 [Debug] (Stream) age: 2664, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.958 [Debug] (Stream) age: 2638, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.958 [Debug] (Stream) age: 2612, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.958 [Debug] (Stream) age: 2586, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.958 [Debug] (Stream) age: 2560, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.959 [Debug] (Stream) age: 2534, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.959 [Debug] (Stream) age: 2508, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.959 [Debug] (Stream) age: 2482, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.959 [Debug] (Stream) age: 2456, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.959 [Debug] (Stream) age: 2430, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.959 [Debug] (Stream) age: 2404, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.959 [Debug] (Stream) age: 2378, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.959 [Debug] (Stream) age: 2352, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.959 [Debug] (Stream) age: 2325, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.959 [Debug] (Stream) age: 2299, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.959 [Debug] (Stream) age: 2273, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.959 [Debug] (Stream) age: 2247, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.959 [Debug] (Stream) age: 2221, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.959 [Debug] (Stream) age: 2195, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.960 [Debug] (Stream) age: 2169, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.960 [Debug] (Stream) age: 2143, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.960 [Debug] (Stream) age: 2117, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.960 [Debug] (Stream) age: 2091, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.960 [Debug] (Stream) age: 2065, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.960 [Debug] (Stream) age: 2039, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.960 [Debug] (Stream) age: 2013, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.960 [Debug] (Stream) age: 1987, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.960 [Debug] (Stream) age: 1961, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.960 [Debug] (Stream) age: 1935, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.960 [Debug] (Stream) age: 1909, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.960 [Debug] (Stream) age: 1883, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.960 [Debug] (Stream) age: 1857, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.960 [Debug] (Stream) age: 1831, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.961 [Debug] (Stream) age: 1804, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.961 [Debug] (Stream) age: 1778, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.961 [Debug] (Stream) age: 1752, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.961 [Debug] (Stream) age: 1726, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.961 [Debug] (Stream) age: 1700, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.961 [Debug] (Stream) age: 1674, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.961 [Debug] (Stream) age: 1648, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.961 [Debug] (Stream) age: 1622, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.961 [Debug] (Stream) age: 1596, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.961 [Debug] (Stream) age: 1570, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.961 [Debug] (Stream) age: 1544, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.961 [Debug] (Stream) age: 1518, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.961 [Debug] (Stream) age: 1492, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.961 [Debug] (Stream) age: 1466, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.962 [Debug] (Stream) age: 1440, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.962 [Debug] (Stream) age: 1414, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.962 [Debug] (Stream) age: 1388, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.962 [Debug] (Stream) age: 1361, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.962 [Debug] (Stream) age: 1335, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.962 [Debug] (Stream) age: 1309, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.962 [Debug] (Stream) age: 1283, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.962 [Debug] (Stream) age: 1257, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.962 [Debug] (Stream) age: 1231, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.962 [Debug] (Stream) age: 1205, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.962 [Debug] (Stream) age: 1179, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.962 [Debug] (Stream) age: 1153, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.962 [Debug] (Stream) age: 1127, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.962 [Debug] (Stream) age: 1101, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.962 [Debug] (Stream) age: 1074, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.962 [Debug] (Stream) age: 1048, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.962 [Debug] (Stream) age: 1022, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.962 [Debug] (Stream) age: 996, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.962 [Debug] (Stream) age: 970, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.962 [Debug] (Stream) age: 944, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.962 [Debug] (Stream) age: 918, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.962 [Debug] (Stream) age: 892, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.962 [Debug] (Stream) age: 866, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.962 [Debug] (Stream) age: 840, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.962 [Debug] (Stream) age: 813, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.962 [Debug] (Stream) age: 787, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.962 [Debug] (Stream) age: 761, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.962 [Debug] (Stream) age: 735, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.962 [Debug] (Stream) age: 709, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.962 [Debug] (Stream) age: 683, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.962 [Debug] (Stream) age: 657, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.962 [Debug] (Stream) age: 631, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.962 [Debug] (Stream) age: 605, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.962 [Debug] (Stream) age: 579, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.962 [Debug] (Stream) age: 553, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.963 [Debug] (Stream) age: 526, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.963 [Debug] (Stream) age: 500, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.963 [Debug] (Stream) age: 474, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.963 [Debug] (Stream) age: 448, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.963 [Debug] (Stream) age: 422, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.963 [Debug] (Stream) age: 396, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.963 [Debug] (Stream) age: 370, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.963 [Debug] (Stream) age: 344, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.963 [Debug] (Stream) age: 318, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.963 [Debug] (Stream) age: 292, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.963 [Debug] (Stream) age: 266, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.963 [Debug] (Stream) age: 239, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.963 [Debug] (Stream) age: 213, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.963 [Debug] (Stream) age: 187, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.963 [Debug] (Stream) age: 161, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.963 [Debug] (Stream) age: 135, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.963 [Debug] (Stream) age: 109, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.963 [Debug] (Stream) age: 83, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.963 [Debug] (Stream) age: 57, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.963 [Debug] (Stream) age: 31, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-55.963 [Debug] (Stream) age: 5, requested chunk_duration: 500, duration: 26
2021-02-14 18-23-56.338 [Debug] (Stats) Chunk: -6	-6	-6	-6	1	124	0

@badaix
Copy link
Owner

badaix commented Feb 14, 2021

The "requested chunk duration" should be some multiple of the fragment time (125ms), but in least cases the full buffer time (500ms). Maybe the audioinjectorpi driver doesn't reliably work on 64 bit arm.

@sebirdman
Copy link

sebirdman commented Feb 14, 2021

Maybe the audioinjectorpi driver doesn't reliably work on 64 bit arm.

very well could be, this audio hat doesn't seem to have much support now and honestly it's amazing that it works at all

I've swapped to the pulse backend, and amazingly its all working quite well so far. even with the default buffer settings.

@mattmofr
Copy link

mattmofr commented Feb 16, 2021

Hi Badaix, Hi everyone,

First of all thank you so much for snapcast which is running 24/7 ! My whole family gives you a huge hug, specially my 3 year old son who wants to listen to his lullabies all the time in the kitchen and livingroom with perfect sync of course !

I'm following this discussion with great interest as I'm experiencing also some hiccups/stuttering with a new system I'm trying to setup for my kids in their room.
I recently bought RPI0W and while waiting for some Hifiberry miniamps I used a spare Hifiberry Amp2 to test mopidy (my current kitchen/livingroom system is on Volumio).

Everything went flawless. Amazing ! 🥇

However, when using Hifiberry miniamp, everything works well until I used snapcast (snapserver and snapclient on the same rpi0), meaning that there was no hiccups/stutter when audio output of Mopidy was directed to the Hifiberry miniamp.

However when using snapclient, hiccups are appearing and quite a lot actually.

I first though the issue was the SD card. But using other ones led to the same symptoms.
Then I though it was the rpi0 which might be too slow for mopidy + snapserver + snapclient. But using a spare rpi3B+ led to the same symptoms.
I started to believe that the issue could come from the Hifiberry miniamp. But still I thought the issue was me and my Mopidy/snapserver/snapclient config or maybe the Wifi, so I decided to go back to Volumio and try out snapcast through the Saiyato plugin package with my rpi0 + Hifiberry miniamp.

Everything went flawless (with custom parameters of snapclient to select the correct device) ! 🥇

What ?!?! 😮

I'm kind of lost here now. Unfortunatly I'm not competent enough to understand how snapcast is configured through Volumio (besides the usual snapclient and server parameters). But I guess Volumio layer is doing something in the audio treatment that makes the hifiberry miniamp works with snapcast.

I didn't save the logs of the system I'm trying to setup, but I will try to send them in the coming days. I just wanted to share my thoughts about this issue and the fact that it is properly working under Volumio. Which I find weird. 😲

PS: I could also stick to Volumio but Volumio is under Python 2.7 and based on Jessie. I'd rather at least start this new project with the latest release i.e. Buster, python 3.7, Pillow 8.1.0 etc.

Cheers

@badaix
Copy link
Owner

badaix commented Feb 16, 2021

The volumio plugin seems to contain the ancient v0.15.0 Snapcast.
You should at least mention the version you've installed and provide logs. You can also install older versions to get an idea when it stopped working.

@mattmofr
Copy link

The volumio plugin seems to contain the ancient v0.15.0 Snapcast.
You should at least mention the version you've installed and provide logs. You can also install older versions to get an idea when it stopped working.

I will post my logs, config and setup. I probably should have wait to get them before posting. Sorry about that.

@mattmofr
Copy link

Good evening @badaix ,

As promised here are all the infos about my setup.
RPI 0 W v1.3 on Raspbian GNU/Linux 10 (buster) release 5.10.11+

/boot/config.txt

#dtparam=i2c_arm=on
#dtparam=i2s=on
dtparam=spi=on
#Enable audio (loads snd_bcm2835)
#dtparam=audio=on
dtoverlay=hifiberry-dac

aplay -l

**** Liste des Périphériques Matériels PLAYBACK ****
carte 0: sndrpihifiberry [snd_rpi_hifiberry_dac], périphérique 0: HifiBerry DAC HiFi pcm5102a-hifi-0 [HifiBerry DAC HiFi pcm5102a-hifi-0]
  Sous-périphériques: 1/1
  Sous-périphérique #0: subdevice #0

/etc/asound.conf

pcm.!default {
    type            plug
    slave.pcm       "softvol"   #make use of softvol
}

pcm.softvol {
    type            softvol
    slave {
        pcm         "hw:0,0"
    }
    control {
        name        "miniAmp"
        card        0
    }
}

snapclient --version
snapclient v0.23.0

snapserver --version
snapserver v0.23.0

snapclient -l

0: null
Discard all samples (playback) or generate zero samples (capture)

1: default


2: softvol


3: sysdefault:CARD=sndrpihifiberry
snd_rpi_hifiberry_dac, HifiBerry DAC HiFi pcm5102a-hifi-0
Default Audio Device

4: dmix:CARD=sndrpihifiberry,DEV=0
snd_rpi_hifiberry_dac, HifiBerry DAC HiFi pcm5102a-hifi-0
Direct sample mixing device

5: dsnoop:CARD=sndrpihifiberry,DEV=0
snd_rpi_hifiberry_dac, HifiBerry DAC HiFi pcm5102a-hifi-0
Direct sample snooping device

6: hw:CARD=sndrpihifiberry,DEV=0
snd_rpi_hifiberry_dac, HifiBerry DAC HiFi pcm5102a-hifi-0
Direct hardware device without any conversions

7: plughw:CARD=sndrpihifiberry,DEV=0
snd_rpi_hifiberry_dac, HifiBerry DAC HiFi pcm5102a-hifi-0
Hardware device with all software conversions

/etc/default/snapserver

START_SNAPSERVER=true
USER_OPTS="--user snapserver:snapserver -s pipe:///tmp/snapfifo?name=default&sampleformat=48000:16:2"
SNAPSERVER_OPTS=""

/etc/default/snapclient

START_SNAPCLIENT=true
USER_OPTS="--user snapclient:audio"
SNAPCLIENT_OPTS="-h 127.0.0.1 -s 2 --logfilter *:debug"

/etc/mopidy.mopidy.conf

[http]
hostname = ::

[audio]
output = audioconvert ! audio/x-raw,rate=48000,channels=2,format=S16LE ! wavenc ! filesink location=/tmp/snapfifo
mixer = alsamixer

[alsamixer]
control = miniAmp

[iris]
country = FR
locale = fr_FR

[spotify]
username = xxxx
password = xxxx
client_id = xxxx
client_secret = xxxx
bitrate = 320

[spotify_web]
client_id = xxxx
client_secret = xxxx

Snapserver log

févr. 16 23:08:55 paul systemd[1]: Started Snapcast server.
févr. 16 23:08:55 paul snapserver[1877]: Adding source: pipe:///tmp/snapfifo?name=default
févr. 16 23:08:55 paul snapserver[1877]: Settings file: "/var/lib/snapserver/server.json"
févr. 16 23:08:55 paul snapserver[1877]: Adding service 'Snapcast'
févr. 16 23:08:55 paul snapserver[1877]: PcmStream: default, sampleFormat: 48000:16:2
févr. 16 23:08:55 paul snapserver[1877]: Stream: default, metadata={
févr. 16 23:08:55 paul snapserver[1877]:     "STREAM": "default"
févr. 16 23:08:55 paul snapserver[1877]: }
févr. 16 23:08:55 paul snapserver[1877]: onMetaChanged (default)
févr. 16 23:08:55 paul snapserver[1877]: PipeStream mode: create
févr. 16 23:08:55 paul snapserver[1877]: Stream: {"fragment":"","host":"","path":"/tmp/snapfifo","query":{"chunk_ms":"20","codec":"flac","name":"default","sampleformat":"48000:16:2"},"raw":"pipe:////tmp/snapfifo?chunk_ms=20&codec=flac&name=default&sampleformat=48000:16:2","scheme":"pipe"}
févr. 16 23:08:55 paul snapserver[1877]: Creating TCP acceptor for address: 0.0.0.0, port: 1705
févr. 16 23:08:55 paul snapserver[1877]: Creating HTTP acceptor for address: 0.0.0.0, port: 1780
févr. 16 23:08:55 paul snapserver[1877]: Creating stream acceptor for address: 0.0.0.0, port: 1704
févr. 16 23:08:55 paul snapserver[1877]: number of threads: 2, hw threads: 1
févr. 16 23:08:56 paul snapserver[1877]: Service 'Snapcast' successfully established.
févr. 16 23:09:01 paul snapserver[1877]: StreamServer::NewConnection: 127.0.0.1
févr. 16 23:09:02 paul snapserver[1877]: Hello from b8:27:eb:d5:d1:dc, host: paul, v0.23.0, ClientName: Snapclient, OS: Raspbian GNU/Linux 10 (buster), Arch: armv6l, Protocol version: 2
févr. 16 23:09:45 paul snapserver[1877]: State changed: default, state: 1 => 2
févr. 16 23:09:45 paul snapserver[1877]: onStateChanged (default): 2
févr. 16 23:10:23 paul snapserver[1877]: State changed: default, state: 2 => 1
févr. 16 23:10:23 paul snapserver[1877]: onStateChanged (default): 1
févr. 16 23:10:25 paul snapserver[1877]: State changed: default, state: 1 => 2
févr. 16 23:10:25 paul snapserver[1877]: onStateChanged (default): 2
févr. 16 23:10:35 paul snapserver[1877]: next read < 0 (default): -1.27 ms
févr. 16 23:10:38 paul snapserver[1877]: State changed: default, state: 2 => 1
févr. 16 23:10:38 paul snapserver[1877]: onStateChanged (default): 1
févr. 16 23:10:38 paul snapserver[1877]: State changed: default, state: 1 => 2
févr. 16 23:10:38 paul snapserver[1877]: onStateChanged (default): 2
févr. 16 23:10:58 paul snapserver[1877]: State changed: default, state: 2 => 1
févr. 16 23:10:58 paul snapserver[1877]: onStateChanged (default): 1
févr. 16 23:11:01 paul snapserver[1877]: State changed: default, state: 1 => 2
févr. 16 23:11:01 paul snapserver[1877]: onStateChanged (default): 2
févr. 16 23:11:12 paul snapserver[1877]: State changed: default, state: 2 => 1
févr. 16 23:11:12 paul snapserver[1877]: onStateChanged (default): 1

Snapclient log

févr. 16 23:08:47 paul systemd[1]: Stopped Snapcast client.
févr. 16 23:09:01 paul systemd[1]: Started Snapcast client.
févr. 16 23:09:01 paul snapclient[1900]: Resolving host IP for: 127.0.0.1
févr. 16 23:09:01 paul snapclient[1900]: Connecting
févr. 16 23:09:01 paul snapclient[1900]: Connected to 127.0.0.1
févr. 16 23:09:01 paul snapclient[1900]: My MAC: "b8:27:eb:d5:d1:dc", socket: 9
févr. 16 23:09:02 paul snapclient[1900]: outstanding async_write
févr. 16 23:09:02 paul snapclient[1900]: ServerSettings - buffer: 1000, latency: 0, volume: 100, muted: 0
févr. 16 23:09:02 paul snapclient[1900]: metadata:{"STREAM":"default"}
févr. 16 23:09:02 paul snapclient[1900]: Codec: flac, sampleformat: 48000:16:2
févr. 16 23:09:02 paul snapclient[1900]: Player name: alsa, device: softvol, description: <none>, idx: 2, sharing mode: unspecified, parameters: <none>
févr. 16 23:09:02 paul snapclient[1900]: Mixer mode: software, parameters: <none>
févr. 16 23:09:02 paul snapclient[1900]: Sampleformat: 48000:16:2, stream: 48000:16:2
févr. 16 23:09:02 paul snapclient[1900]: Using buffer_time: 80 ms, fragments: 4
févr. 16 23:09:02 paul snapclient[1900]: PCM name: softvol, sample rate: 48000 Hz, channels: 2, buffer time: 80000 us, periods: 4, period time: 20000 us, period frames: 960
févr. 16 23:09:02 paul snapclient[1900]: Failed to start PCM: Broken pipe
févr. 16 23:09:02 paul snapclient[1900]: setVolume exp with base 10: 1 => 1
févr. 16 23:09:02 paul snapclient[1900]: Resizing buffer from 0 to 15360
févr. 16 23:09:02 paul snapclient[1900]: No chunks available
févr. 16 23:09:02 paul snapclient[1900]: Failed to get chunk
févr. 16 23:09:02 paul snapclient[1900]: Waiting for chunk
févr. 16 23:09:02 paul snapclient[1900]: diff to server [ms]: 0.126
févr. 16 23:09:03 paul snapclient[1900]: Waiting for chunk

[...]

févr. 16 23:09:45 paul snapclient[1900]: Waiting for chunk
févr. 16 23:09:45 paul snapclient[1900]: PCM name: softvol, sample rate: 48000 Hz, channels: 2, buffer time: 80000 us, periods: 4, period time: 20000 us, period frames: 960
févr. 16 23:09:45 paul snapclient[1900]: Failed to start PCM: Broken pipe
févr. 16 23:09:46 paul snapclient[1900]: Silent frames: 760, frames: 1920, age: -15.838
févr. 16 23:09:46 paul snapclient[1900]: Chunk: 0        0        0        0        1        40        0
févr. 16 23:09:47 paul snapclient[1900]: Chunk: 0        0        0        0        16        39        0
févr. 16 23:09:48 paul snapclient[1900]: Chunk: 0        0        0        0        41        39        0
févr. 16 23:09:49 paul snapclient[1900]: Chunk: 0        0        0        0        66        39        0
févr. 16 23:09:50 paul snapclient[1900]: Chunk: 0        0        0        0        91        39        0
févr. 16 23:09:51 paul snapclient[1900]: Chunk: 0        0        0        0        116        39        0
févr. 16 23:09:52 paul snapclient[1900]: Chunk: 0        0        0        0        141        39        0
févr. 16 23:09:53 paul snapclient[1900]: Chunk: 0        0        0        0        166        39        0
févr. 16 23:09:54 paul snapclient[1900]: Chunk: 0        0        0        0        192        39        0
févr. 16 23:09:55 paul snapclient[1900]: Chunk: 0        0        0        0        217        40        0
févr. 16 23:09:56 paul snapclient[1900]: Chunk: 0        0        0        0        242        39        0
févr. 16 23:09:57 paul snapclient[1900]: Chunk: 0        0        0        0        267        40        0
févr. 16 23:09:58 paul snapclient[1900]: Chunk: 0        0        0        0        292        40        0
févr. 16 23:09:59 paul snapclient[1900]: Chunk: -1        -1        0        0        317        39        0
févr. 16 23:10:00 paul snapclient[1900]: Chunk: -1        -1        0        0        342        39        0
févr. 16 23:10:01 paul snapclient[1900]: Chunk: 0        0        0        0        367        40        0
févr. 16 23:10:02 paul snapclient[1900]: Chunk: 0        0        0        0        392        40        0
févr. 16 23:10:03 paul snapclient[1900]: Chunk: -1        -1        0        0        417        40        0
févr. 16 23:10:04 paul snapclient[1900]: Chunk: -1        -1        0        0        442        40        0
févr. 16 23:10:05 paul snapclient[1900]: Chunk: -1        -1        -1        0        467        40        0
févr. 16 23:10:06 paul snapclient[1900]: Chunk: 0        -1        -1        0        492        40        2
févr. 16 23:10:07 paul snapclient[1900]: Chunk: 0        0        -1        0        500        40        2
févr. 16 23:10:08 paul snapclient[1900]: Chunk: 0        0        0        0        500        40        0
févr. 16 23:10:09 paul snapclient[1900]: Chunk: 0        0        0        0        500        39        0
févr. 16 23:10:10 paul snapclient[1900]: Chunk: -1        0        0        0        500        39        0
févr. 16 23:10:11 paul snapclient[1900]: Chunk: 0        0        0        0        500        39        0
févr. 16 23:10:12 paul snapclient[1900]: Chunk: -1        -1        0        0        500        39        0
févr. 16 23:10:13 paul snapclient[1900]: Chunk: -1        0        0        0        500        39        0
févr. 16 23:10:14 paul snapclient[1900]: Chunk: 0        0        0        0        500        40        0
févr. 16 23:10:15 paul snapclient[1900]: Chunk: -1        0        0        0        500        40        0
févr. 16 23:10:16 paul snapclient[1900]: Chunk: -1        -1        0        0        500        39        0
févr. 16 23:10:17 paul snapclient[1900]: Chunk: 2        -1        -1        0        500        39        0
févr. 16 23:10:18 paul snapclient[1900]: Chunk: -1        -1        -1        0        500        40        2
févr. 16 23:10:19 paul snapclient[1900]: Chunk: 0        0        -1        0        500        40        2
févr. 16 23:10:20 paul snapclient[1900]: Chunk: 0        0        0        0        500        40        0
févr. 16 23:10:21 paul snapclient[1900]: Chunk: 0        0        0        0        500        39        0
févr. 16 23:10:22 paul snapclient[1900]: Chunk: 0        0        0        0        500        40        0
févr. 16 23:10:23 paul snapclient[1900]: Chunk: 0        0        0        0        500        39        0
févr. 16 23:10:24 paul snapclient[1900]: Chunk: -1        0        0        0        500        39        0
févr. 16 23:10:25 paul snapclient[1900]: Chunk: 0        0        0        0        500        40        0
févr. 16 23:10:25 paul snapclient[1900]: Exception: Not enough frames available, requested frames: 1920, available: 1536
févr. 16 23:10:25 paul snapclient[1900]: Failed to get chunk
févr. 16 23:10:25 paul snapclient[1900]: Waiting for chunk
févr. 16 23:10:25 paul snapclient[1900]: Waiting for chunk
févr. 16 23:10:25 paul snapclient[1900]: Waiting for chunk
févr. 16 23:10:25 paul snapclient[1900]: XRUN while waiting for PCM: Broken pipe
févr. 16 23:10:25 paul snapclient[1900]: age > 0: 241ms, dropping old chunks
févr. 16 23:10:25 paul snapclient[1900]: age: -972, requested chunk_duration: 80, duration: 24
févr. 16 23:10:25 paul snapclient[1900]: Silent frames: 3840, frames: 3840, age: -972.014
févr. 16 23:10:26 paul snapclient[1900]: Silent frames: 1468, frames: 1920, age: -30.604
févr. 16 23:10:26 paul snapclient[1900]: Chunk: 0        0        0        0        1        40        0
févr. 16 23:10:27 paul snapclient[1900]: Chunk: 0        0        0        0        14        40        0
févr. 16 23:10:28 paul snapclient[1900]: Chunk: 0        0        0        0        39        39        0
févr. 16 23:10:29 paul snapclient[1900]: Chunk: 0        0        0        0        64        39        0
févr. 16 23:10:30 paul snapclient[1900]: Chunk: 0        0        0        0        89        39        0
févr. 16 23:10:31 paul snapclient[1900]: Chunk: -1        0        0        0        115        40        0
févr. 16 23:10:32 paul snapclient[1900]: Chunk: 0        0        0        0        140        40        0
févr. 16 23:10:33 paul snapclient[1900]: Chunk: -1        0        0        0        165        40        0
févr. 16 23:10:34 paul snapclient[1900]: Chunk: -1        0        0        0        190        40        0
févr. 16 23:10:35 paul snapclient[1900]: Chunk: 0        -1        0        0        215        40        0
févr. 16 23:10:36 paul snapclient[1900]: Chunk: -1        -1        0        0        240        40        0
févr. 16 23:10:37 paul snapclient[1900]: Chunk: -1        -1        -1        0        265        40        0
févr. 16 23:10:38 paul snapclient[1900]: Chunk: -1        -1        -1        0        290        40        2
févr. 16 23:10:39 paul snapclient[1900]: Chunk: 0        0        -1        0        315        40        2
févr. 16 23:10:40 paul snapclient[1900]: Chunk: 0        0        0        0        340        40        1
févr. 16 23:10:41 paul snapclient[1900]: Chunk: 0        0        0        0        365        40        0
févr. 16 23:10:42 paul snapclient[1900]: Chunk: 0        0        0        0        390        40        0
févr. 16 23:10:43 paul snapclient[1900]: Chunk: 0        0        0        0        415        40        0
févr. 16 23:10:44 paul snapclient[1900]: Chunk: 0        0        0        0        440        40        0
févr. 16 23:10:45 paul snapclient[1900]: Chunk: 0        0        0        0        465        40        0
févr. 16 23:10:46 paul snapclient[1900]: Chunk: 0        0        0        0        490        40        0
févr. 16 23:10:47 paul snapclient[1900]: Chunk: 0        0        0        0        500        39        0
févr. 16 23:10:48 paul snapclient[1900]: Chunk: 0        0        0        0        500        40        0
févr. 16 23:10:49 paul snapclient[1900]: Chunk: 0        0        0        0        500        40        0
févr. 16 23:10:50 paul snapclient[1900]: Chunk: -1        -1        0        0        500        40        0
févr. 16 23:10:51 paul snapclient[1900]: Chunk: 0        0        0        0        500        39        0
févr. 16 23:10:52 paul snapclient[1900]: Chunk: 0        0        0        0        500        40        0
févr. 16 23:10:53 paul snapclient[1900]: Chunk: -1        0        0        0        500        40        0
févr. 16 23:10:54 paul snapclient[1900]: Chunk: -1        -1        0        0        500        40        0
févr. 16 23:10:55 paul snapclient[1900]: Chunk: -1        -1        -1        0        500        40        0
févr. 16 23:10:56 paul snapclient[1900]: Chunk: -1        -1        -1        0        500        40        2
févr. 16 23:10:57 paul snapclient[1900]: Chunk: 0        0        -1        0        500        40        1
févr. 16 23:10:58 paul snapclient[1900]: Chunk: 0        0        0        0        500        39        0
févr. 16 23:10:59 paul snapclient[1900]: Chunk: 0        -1        0        0        500        40        0
févr. 16 23:11:00 paul snapclient[1900]: Chunk: 0        0        0        0        500        40        0
févr. 16 23:11:00 paul snapclient[1900]: Exception: Not enough frames available, requested frames: 1928, available: 904
févr. 16 23:11:00 paul snapclient[1900]: Failed to get chunk
févr. 16 23:11:00 paul snapclient[1900]: Waiting for chunk
févr. 16 23:11:00 paul snapclient[1900]: Waiting for chunk
févr. 16 23:11:00 paul snapclient[1900]: Waiting for chunk
févr. 16 23:11:01 paul snapclient[1900]: Waiting for chunk
févr. 16 23:11:01 paul snapclient[1900]: XRUN while waiting for PCM: Broken pipe
févr. 16 23:11:01 paul snapclient[1900]: age > 0: 403ms, dropping old chunks
févr. 16 23:11:01 paul snapclient[1900]: age: -951, requested chunk_duration: 80, duration: 24
févr. 16 23:11:01 paul snapclient[1900]: Silent frames: 3840, frames: 3840, age: -951.817
févr. 16 23:11:01 paul snapclient[1900]: Silent frames: 493, frames: 1920, age: -10.283
févr. 16 23:11:01 paul snapclient[1900]: Chunk: 0        0        0        0        1        40        0
févr. 16 23:11:02 paul snapclient[1900]: Chunk: 0        0        0        0        2        40        0
févr. 16 23:11:03 paul snapclient[1900]: Chunk: 0        0        0        0        27        39        0
févr. 16 23:11:04 paul snapclient[1900]: Chunk: 0        0        0        0        52        39        0
févr. 16 23:11:05 paul snapclient[1900]: Chunk: 0        0        0        0        77        40        0
févr. 16 23:11:06 paul snapclient[1900]: Chunk: 0        0        0        0        102        40        0
févr. 16 23:11:07 paul snapclient[1900]: Chunk: 0        0        0        0        127        40        0
févr. 16 23:11:08 paul snapclient[1900]: Chunk: 0        0        0        0        152        40        0
févr. 16 23:11:09 paul snapclient[1900]: Chunk: 0        0        0        0        177        40        0
févr. 16 23:11:10 paul snapclient[1900]: Chunk: 0        0        0        0        202        40        0
févr. 16 23:11:11 paul snapclient[1900]: Chunk: 0        0        0        0        227        40        0
févr. 16 23:11:12 paul snapclient[1900]: Chunk: 0        0        0        0        252        40        0
févr. 16 23:11:13 paul snapclient[1900]: Chunk: 0        0        0        0        277        39        0
févr. 16 23:11:14 paul snapclient[1900]: Chunk: 0        0        0        0        302        40        0
févr. 16 23:11:14 paul snapclient[1900]: Exception: Not enough frames available, requested frames: 1920, available: 1261
févr. 16 23:11:14 paul snapclient[1900]: Failed to get chunk
févr. 16 23:11:14 paul snapclient[1900]: Waiting for chunk

I hope it helps.

Best regards,

@badaix
Copy link
Owner

badaix commented Feb 16, 2021

There is no USER_OPTS, the user is configured in the systemd unit file. Also there is no -s option for the server, the server is fully configured in /etc/snapserver.conf.
Your problem is not related to the issue discussed in this thread. It rather looks like you're having regular buffer underruns.
If you are streaming spotify, you should use 44100 Hz or resample to 48000 Hz. Seems your feeding a sporitfy signal with 44100 Hz into the fifo and reading it with 48000 Hz, so the stream will play 10% faster and will eventually under run. This would also explain the state changes on your server (1 is idle, 2 is playing).

@badaix
Copy link
Owner

badaix commented Feb 17, 2021

@sebirdman PulseAudio is using alsa as backend to play audio. Did I understand right that you don't have any problems with a 32bit OS and dropouts on 64bit?
Can you paste the output of

cat /proc/asound/card*/*/sub0/hw_param

and of

pacmd list-sinks

for both cases, once while playing audio with alsa and once with pulse?

@mattmofr
Copy link

There is no USER_OPTS, the user is configured in the systemd unit file. Also there is no -s option for the server, the server is fully configured in /etc/snapserver.conf.

Thanks for the explanation. If I understand well the stream is fully configured in /etc/snapserver.conf and the /etc/default/snapserver is only for extra config I guess ?

Your problem is not related to the issue discussed in this thread. It rather looks like you're having regular buffer underruns.
If you are streaming spotify, you should use 44100 Hz or resample to 48000 Hz. Seems your feeding a sporitfy signal with 44100 Hz into the fifo and reading it with 48000 Hz, so the stream will play 10% faster and will eventually under run. This would also explain the state changes on your server (1 is idle, 2 is playing).

I changed the configuration to 44100 Hz in Mopidy and Snapserver.conf like you suggested but it didn't solve the issue. (I also removed wavenc as mentionned in #592 and according to https://github.com/badaix/snapcast/blob/master/doc/player_setup.md)

Config and logs below :

mopidy.conf

[audio]
output = audioresample ! audioconvert ! audio/x-raw,rate=44100,channels=2,format=S16LE ! filesink location=/tmp/snapfifo

snapserver.conf

[stream]
source = pipe:///tmp/snapfifo?name=default&sampleformat=44100:16:2

I don't understand why snapserver switches states.

snapserver log

févr. 17 22:17:49 paul snapserver[461]: State changed: default, state: 2 => 1
févr. 17 22:17:49 paul snapserver[461]: onStateChanged (default): 1
févr. 17 22:17:54 paul snapserver[461]: State changed: default, state: 1 => 2
févr. 17 22:17:54 paul snapserver[461]: onStateChanged (default): 2

Maybe the issue comes from Mopidy. I will investigate further. Let me know if you want me to move posts to somewhere else.

Thanks for your help.

@badaix
Copy link
Owner

badaix commented Feb 19, 2021

It's actually recommended to use the alsa loopback device instead of the snapfifo file, I read in other issues that mopdiy (gstreamer) playback is not really stable when using the filesink.

@jampr21
Copy link

jampr21 commented Feb 25, 2021

Hi, I have also dropouts and I am not able to solve it. My combination, that works better is 0.22 on server and 0.24 on clients. There I have some dropouts only very sproradic (one over 10 Minutes). With 0.22 on client it is getting worse over time.

I have tried several value combinations of --player alsa:buffer_time=200,fragments=4. Some worse, some better. But none without problems, when I use 0.24 on the server. I am using USB-sound speakers on Raspi4 and ZeroW.

What I didn't test yet, is to replace filesink whith alsa loopback. Linux sound is not my favorite piece of software. MPD is sending music to snapcast via filesink here

@mattmofr
Copy link

Hi,

I investigated the issue further and in my case drop outs were coming from the upstream (before the pipe).

I ended up with a restart from scratch with my rpi 3B+ instead of rpi 0 W, with a different SD card (smaller 16GB instead of 32GB) and configuring alsa loopback instead of filesink.

CONCLUSION : It worked perfectly with snapcast version 0.23 with default configuration of buffer/fragments/bitrate.

I'm now thinking that the issue was probably the SD card, filesink or rpi 0 W or a combination of those.

For those interested you may find my config files below :

System : RPI 3B+ with Hifiberry miniamp

/etc/modules

snd-aloop

/etc/asound.conf

pcm.!default {
    type            plug
    slave.pcm       "softvol"   #make use of softvol
}

pcm.softvol {
    type            softvol
    slave {
        pcm         "hw:1,0"      
    }
    control {
        name        "PCM" 
	card	    1
    }
}

/boot/config.txt

#dtparam=audio=on
dtoverlay=hifiberry-dac

/etc/mopidy/mopidy.conf

[audio]
output = audioresample ! audioconvert ! audio/x-raw,rate=48000,channels=2,format=S16LE ! alsasink device=hw:0,0,0
mixer = alsamixer

[alsamixer]
card = 1
control = PCM
volume_scale = linear

[http]
hostname = ::

[spotify]
client_id = myclient_id
client_secret = myclient_secret
username = myusername
password = mypassword
bitrate = 320

[iris]
country = FR
locale = fr_FR

[local]
media_dir = /my/dir/to/music

/etc/default/snapclient

START_SNAPCLIENT=true
USER_OPTS="--user snapclient:audio"
SNAPCLIENT_OPTS="-h 127.0.0.1 -s 1"

/etc/snapserver.conf

source = alsa://?name=default&sampleformat=48000:16:2&device=hw:0,1,0

Hope it helps and thank you @badaix for your help and suggestions 👍

@daniele-athome
Copy link

daniele-athome commented Feb 25, 2021

To anybody reading this: please also consider WiFi-related issues such as network congestion. In my case I had to reduce the number of connected clients because all my WiFi clients - including laptops - on the 2.4 GHz band in my place are suffering systemic latency drops every 30 seconds or so (maybe it's a router issue? I don't know, I don't have other routers to try). That causes problems to snapcast because the flow of packets must be steady. To make it work perfectly I have to increase snapcast latency to 2-3 seconds.

@badaix
Copy link
Owner

badaix commented Feb 26, 2021

There are many reasons for stuttering audio

What you can do:

  • check if it's server sided, you can connect two clients and check if both have the same drop outs
  • check connectivity issues: let the client run on the server host or ping the server from the client host
  • check if the on-board sound device is also having drop-outs (configure the device with -s on the client)
  • search through the issues, install the latest Snapcast version
  • Check your input source on the server, is the sample rate configured correctly (48kHz vs 44.1kHz)?
  • When using gstreamer (Mopidy uses gstreamerr), consider switching to the alsa loopback stream source instead of the pipe source
  • ...

@daniele-athome
Copy link

Thanks @badaix. You should really write a wiki page or something with all this stuff collected :-) It's been really hard gathering all the information around.

I did my research and practically tried all of the above. In my case it's clearly a wireless issue. The problem is very clear and reproducible (traffic analysis, ping tests). I tried disabling some stuff polluting the 2.4 GHz band and I had some improvement, but then I had to enable them back, so... I guess the real solution would be to switch the RPi ZW to 5 GHz but I need an external WiFi controller. I'll think about it.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug next release fixed in develop branch and will be part of the next release
Projects
None yet
Development

No branches or pull requests