badaix / snapcast

Synchronous multiroom audio player
GNU General Public License v3.0
6.22k stars 455 forks source link

Dropouts with snapclient v0.24 and ALSA backend stating pMiniBuffer->full #855

Closed garglkarg closed 3 years ago

garglkarg commented 3 years ago

snapclients errors with pMiniBuffer->full() && (abs(pMiniBuffer->mean()) > 50)

I have a snapserver supplying direct mpd and bluealsa PCMs as flac stream. This works fine on the raspberry on board audio and raspberry with HifiBerry Amp2. But I have dropouts on the environment below (I have dropouts on my raspberry with miniamp too but maybe this is related). I have read this #774 Ticket but playing with the buffer_time and fragments did not fix my issue. I tried to play around with my /etc/asound.conf but it seems to make no difference so I wiped it out again.

Environment details

logfile without /etc/asound and clean /etc/default/snapclient (except debug log output)

Apr 16 08:49:41 sundance systemd[1]: snapclient.service: Succeeded.
Apr 16 08:49:41 sundance snapclient[6837]: Version 0.24.0, revision 7eff45fd
Apr 16 08:49:41 sundance snapclient[6837]: (Browser) NEW: service 'Snapcast' of type '_snapcast._tcp' in domain 'local'
Apr 16 08:49:41 sundance snapclient[6837]: (Browser) CACHE_EXHAUSTED
Apr 16 08:49:41 sundance snapclient[6837]: Service 'Snapcast' of type '_snapcast._tcp' in domain 'local':
Apr 16 08:49:41 sundance snapclient[6837]: #011asterix.local:1704 (192.168.42.51)
Apr 16 08:49:41 sundance snapclient[6837]: #011TXT=
Apr 16 08:49:41 sundance snapclient[6837]: #011Proto=0
Apr 16 08:49:41 sundance snapclient[6837]: #011cookie is 0
Apr 16 08:49:41 sundance snapclient[6837]: #011is_local: 0
Apr 16 08:49:41 sundance snapclient[6837]: #011our_own: 0
Apr 16 08:49:41 sundance snapclient[6837]: #011wide_area: 0
Apr 16 08:49:41 sundance snapclient[6837]: #011multicast: 1
Apr 16 08:49:41 sundance snapclient[6837]: #011cached: 1
Apr 16 08:49:41 sundance snapclient[6837]: Found server 192.168.42.51:1704
Apr 16 08:49:41 sundance snapclient[6837]: Resolving host IP for: 192.168.42.51
Apr 16 08:49:41 sundance snapclient[6837]: Connecting
Apr 16 08:49:41 sundance snapclient[6837]: Connected to 192.168.42.51
Apr 16 08:49:41 sundance snapclient[6837]: My MAC: "b8:27:eb:7c:8f:fa", socket: 9
Apr 16 08:49:42 sundance snapclient[6837]: outstanding async_write
Apr 16 08:49:42 sundance snapclient[6837]: ServerSettings - buffer: 1000, latency: 0, volume: 58, muted: 0
Apr 16 08:49:42 sundance snapclient[6837]: Codec: flac, sampleformat: 48000:16:2
Apr 16 08:49:42 sundance snapclient[6837]: metadata:{"STREAM":"Mobile"}
Apr 16 08:49:42 sundance snapclient[6837]: Player name: alsa, device: default:CARD=sndrpihifiberry, description: snd_rpi_hifiberry_dacplus, HiFiBerry DAC+ HiFi pcm512x-hifi-0
Apr 16 08:49:42 sundance snapclient[6837]: Default Audio Device, idx: 1, sharing mode: unspecified, parameters: <none>
Apr 16 08:49:42 sundance snapclient[6837]: Mixer mode: software, parameters: <none>
Apr 16 08:49:42 sundance snapclient[6837]: Sampleformat: 48000:16:2, stream: 48000:16:2
Apr 16 08:49:42 sundance snapclient[6837]: Using default buffer_time: 80 ms, default fragments: 4
Apr 16 08:49:42 sundance snapclient[6837]: ACCESS:  MMAP_INTERLEAVED MMAP_NONINTERLEAVED MMAP_COMPLEX RW_INTERLEAVED RW_NONINTERLEAVED
Apr 16 08:49:42 sundance snapclient[6837]: 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
Apr 16 08:49:42 sundance snapclient[6837]: SUBFORMAT:  STD
Apr 16 08:49:42 sundance snapclient[6837]: SAMPLE_BITS: [4 64]
Apr 16 08:49:42 sundance snapclient[6837]: FRAME_BITS: [4 640000]
Apr 16 08:49:42 sundance snapclient[6837]: CHANNELS: [1 10000]
Apr 16 08:49:42 sundance snapclient[6837]: RATE: [4000 4294967295)
Apr 16 08:49:42 sundance snapclient[6837]: PERIOD_TIME: (83 8192000]
Apr 16 08:49:42 sundance snapclient[6837]: PERIOD_SIZE: (0 4294967295)
Apr 16 08:49:42 sundance snapclient[6837]: PERIOD_BYTES: (0 4294967295)
Apr 16 08:49:42 sundance snapclient[6837]: PERIODS: (0 4294967295]
Apr 16 08:49:42 sundance snapclient[6837]: BUFFER_TIME: [1 4294967295]
Apr 16 08:49:42 sundance snapclient[6837]: BUFFER_SIZE: [1 4294967294]
Apr 16 08:49:42 sundance snapclient[6837]: BUFFER_BYTES: [1 4294967295]
Apr 16 08:49:42 sundance snapclient[6837]: TICK_TIME: ALL
Apr 16 08:49:42 sundance snapclient[6837]: PCM name: default:CARD=sndrpihifiberry, sample rate: 48000 Hz, channels: 2, buffer time: 80000 us, periods: 4, period time: 20000 us, period frames: 960
Apr 16 08:49:42 sundance snapclient[6837]: Failed to start PCM: Broken pipe
Apr 16 08:49:42 sundance snapclient[6837]: Resizing buffer from 0 to 15360
Apr 16 08:49:42 sundance snapclient[6837]: No chunks available
Apr 16 08:49:42 sundance snapclient[6837]: Failed to get chunk
Apr 16 08:49:42 sundance snapclient[6837]: setVolume exp with base 10: 0.58 => 0.311322
Apr 16 08:49:42 sundance snapclient[6837]: diff to server [ms]: -9.66975e+06
Apr 16 08:49:43 sundance snapclient[6837]: Silent frames: 617, frames: 960, age: -12.866
Apr 16 08:49:43 sundance snapclient[6837]: Chunk: 0#0110#0110#0110#0111#01160#0110
Apr 16 08:49:44 sundance snapclient[6837]: Chunk: 0#0110#0110#0110#01143#01160#0110
Apr 16 08:49:45 sundance snapclient[6837]: Chunk: 0#0110#0110#0110#01193#01160#0110
Apr 16 08:49:46 sundance snapclient[6837]: Chunk: 0#0110#0110#0110#011141#01160#0110
Apr 16 08:49:47 sundance snapclient[6837]: Chunk: 0#0110#0110#0110#011190#01140#0110
Apr 16 08:49:47 sundance snapclient[6837]: pMiniBuffer->full() && (abs(pMiniBuffer->mean()) > 50): -179811
Apr 16 08:49:47 sundance snapclient[6837]: Silent frames: 952, frames: 960, age: -19.834
Apr 16 08:49:48 sundance snapclient[6837]: Chunk: 0#0110#0110#0110#01124#01160#0110
Apr 16 08:49:49 sundance snapclient[6837]: Chunk: 0#0110#0110#0110#01173#01160#0110
Apr 16 08:49:50 sundance snapclient[6837]: Chunk: -1#0110#0110#0110#011122#01159#0110
Apr 16 08:49:51 sundance snapclient[6837]: Chunk: 0#0110#0110#0110#011170#01160#0110
Apr 16 08:49:52 sundance snapclient[6837]: Chunk: 0#0110#0110#0110#011220#01160#0110
Apr 16 08:49:52 sundance snapclient[6837]: pMiniBuffer->full() && (abs(pMiniBuffer->mean()) > 50): -209035
Apr 16 08:49:52 sundance snapclient[6837]: Silent frames: 443, frames: 960, age: -9.233
Apr 16 08:49:53 sundance snapclient[6837]: Chunk: 0#0110#0110#0110#01123#01160#0110

Suggestions? Additional Infos needed?

Many thanks for this wonderfull project!! in combination with bluealsa it gives me the full control for my hifi system / real great work!

garglkarg commented 3 years ago

Ok seems directly related to Ticket #628 but snapclient keeps running with dropouts. I can clearify that this issue is related to the package _snapclient_0.24.0-1_without-pulsearmhf.deb from release page - tried raspian repo package version 15 which has no error in logs or maybe older versions just did not log the error?

badaix commented 3 years ago

is there a reason to not provide a debug log? Did you try a cable connection?

garglkarg commented 3 years ago

is there a reason to not provide a debug log? Did you try a cable connection?

it's a cabled connection. do you think it's a problem with the LAN? I can try to isolate this error by putting both on behind the same switch... that above is the debug log - or not? it's the output I get when using "--logfilter *:debug"

garglkarg commented 3 years ago

interestingly the dropout occurs exactly every 5 secs / on different servers and devices (after I upgraded all to 0.24.0-1)

Apr 16 15:10:31 ratzefatz snapclient[15068]: ServerSettings - buffer: 1000, latency: 500, volume: 55, muted: 0
Apr 16 15:10:31 ratzefatz snapclient[15068]: PCM name: default:CARD=Headphones, sample rate: 48000 Hz, channels: 2, buff
Apr 16 15:10:32 ratzefatz snapclient[15068]: pMiniBuffer->full() && (abs(pMiniBuffer->mean()) > 50): -181972
Apr 16 15:10:37 ratzefatz snapclient[15068]: pMiniBuffer->full() && (abs(pMiniBuffer->mean()) > 50): -164972
Apr 16 15:10:42 ratzefatz snapclient[15068]: pMiniBuffer->full() && (abs(pMiniBuffer->mean()) > 50): -190815
Apr 16 15:10:47 ratzefatz snapclient[15068]: pMiniBuffer->full() && (abs(pMiniBuffer->mean()) > 50): -209219
Apr 16 15:04:47 sundance snapclient[8082]: Sampleformat: 48000:16:2, stream: 48000:16:2
Apr 16 15:04:47 sundance snapclient[8082]: Using default buffer_time: 80 ms, default fragments: 4
Apr 16 15:04:47 sundance snapclient[8082]: PCM name: default:CARD=sndrpihifiberry, sample rate: 48000 Hz, channels: 2, buffer time: 80000 us, periods: 4, period time: 20000 us, period frames: 960
Apr 16 15:04:47 sundance snapclient[8082]: No chunks available
Apr 16 15:04:47 sundance snapclient[8082]: Failed to get chunk
Apr 16 15:04:52 sundance snapclient[8082]: pMiniBuffer->full() && (abs(pMiniBuffer->mean()) > 50): -212020
Apr 16 15:04:57 sundance snapclient[8082]: pMiniBuffer->full() && (abs(pMiniBuffer->mean()) > 50): -181919
Apr 16 15:05:02 sundance snapclient[8082]: pMiniBuffer->full() && (abs(pMiniBuffer->mean()) > 50): -180865
Apr 16 15:05:07 sundance snapclient[8082]: pMiniBuffer->full() && (abs(pMiniBuffer->mean()) > 50): -164307
Apr 16 15:05:12 sundance snapclient[8082]: pMiniBuffer->full() && (abs(pMiniBuffer->mean()) > 50): -179031
Apr 16 15:05:17 sundance snapclient[8082]: pMiniBuffer->full() && (abs(pMiniBuffer->mean()) > 50): -192176
Apr 16 15:05:22 sundance snapclient[8082]: pMiniBuffer->full() && (abs(pMiniBuffer->mean()) > 50): -185033

found out it's resync time on the server:

Apr 16 15:16:42 asterix snapserver[1555]: onResync (Wohnzimmer): 106.642 ms
Apr 16 15:16:47 asterix snapserver[1555]: onResync (Wohnzimmer): 102.478 ms
Apr 16 15:16:52 asterix snapserver[1555]: onResync (Wohnzimmer): 120.415 ms
Apr 16 15:16:57 asterix snapserver[1555]: onResync (Wohnzimmer): 112.148 ms
Apr 16 15:17:02 asterix snapserver[1555]: onResync (Wohnzimmer): 102.488 ms
Apr 16 15:17:07 asterix snapserver[1555]: onResync (Wohnzimmer): 121.031 ms

Server Environment details

using bluealsa and mpd for streaming to different fifo pcm both with the same problem server load is low

snapserver.conf

[stream]
source = pipe:///tmp/snapparent?name=Wohnzimmer
source = pipe:///tmp/snapchilds?name=Kinder
source = pipe:///tmp/snapblue?name=Mobile
garglkarg commented 3 years ago

it's all about the PCM. I switched all snapserver stream inputs to alsaloop device and it works without any hickups!

squat commented 2 years ago

Any idea why using PCM via pipes is causing the issue? I am experiencing something similar (documented here: https://github.com/badaix/snapcast/discussions/924#discussioncomment-2473737). Essentially, whenever sending audio via pipes, snapserver experiences regular resyncs, causing dropouts.