librespot takes 97% CPU, music replay stutters

removogel commented 2 years ago

Compatible OS

[X] I'm running Raspotify on a compatible OS

Latest Version

[X] I'm running the latest version of Raspotify

Due Diligence

[X] I have done my due diligence

What happened?

Since a few days music replay is starting to stutter after a few minutes working fine. /usr/bin/libespot takes up to 97% CPU

Did a check with journalctl, there is an error writing to PCM

ALSA works fine, just testet with aplay as documented in log below

Relevant log output

Jan 23 15:25:21 raspberrypi librespot[459]: [2022-01-23T14:25:21Z WARN  librespot_playback::audio_backend::alsa] Error writing from AlsaSink buffer to PCM, trying to recover, ALSA function 'snd_pcm_writei'
Jan 23 15:25:21 raspberrypi librespot[459]: ALSA lib pcm.c:8424:(snd_pcm_recover) underrun occurred

sudo aplay -Dhw:0,0 --dump-hw-params /usr/share/sounds/alsa/Front_Right.wav
Playing WAVE '/usr/share/sounds/alsa/Front_Right.wav' : Signed 16 bit Little Endian, Rate 48000 Hz, Mono
HW Params of device "hw:0,0":
--------------------
ACCESS:  MMAP_INTERLEAVED RW_INTERLEAVED
FORMAT:  S16_LE
SUBFORMAT:  STD
SAMPLE_BITS: 16
FRAME_BITS: [16 32]
CHANNELS: [1 2]
RATE: [32000 48000]
PERIOD_TIME: [1000 8192000]
PERIOD_SIZE: [32 262144]
PERIOD_BYTES: [64 524288]
PERIODS: [2 1024]
BUFFER_TIME: (1333 16384000]
BUFFER_SIZE: [64 524288]
BUFFER_BYTES: [128 1048576]
TICK_TIME: ALL
--------------------

tobiasmcnulty commented 2 years ago

I just starting hitting this today, too. It was working fine before so I think it was caused by an OS or raspotify update.

systemctl restart raspotify fixes the issue temporarily, but then after about 15 minutes it starts stuttering and librespot takes near 100% of the CPU again. These errors start showing up in the logs (repeating every couple seconds until playback is stopped or raspotify is restarted again):

Jan 23 16:02:45 pi0 systemd[1]: Stopping Raspotify (Spotify Connect Client)...
Jan 23 16:02:45 pi0 systemd[1]: raspotify.service: Main process exited, code=killed, status=15/TERM
Jan 23 16:02:45 pi0 systemd[1]: raspotify.service: Succeeded.
Jan 23 16:02:45 pi0 systemd[1]: Stopped Raspotify (Spotify Connect Client).
Jan 23 16:02:45 pi0 systemd[1]: Started Raspotify (Spotify Connect Client).
Jan 23 16:21:49 pi0 librespot[461]: [2022-01-23T16:21:49Z WARN  librespot_playback::audio_backend::alsa] Error writing from AlsaSink buffer to PCM, trying to recover, ALSA function 'snd_pcm_writei' failed with error 'EPIPE: Broken pipe'
Jan 23 16:21:49 pi0 librespot[461]: ALSA lib pcm.c:8424:(snd_pcm_recover) underrun occurred
Jan 23 16:21:50 pi0 librespot[461]: [2022-01-23T16:21:50Z WARN  librespot_playback::audio_backend::alsa] Error writing from AlsaSink buffer to PCM, trying to recover, ALSA function 'snd_pcm_writei' failed with error 'EPIPE: Broken pipe'
Jan 23 16:21:50 pi0 librespot[461]: ALSA lib pcm.c:8424:(snd_pcm_recover) underrun occurred
Jan 23 16:21:52 pi0 librespot[461]: [2022-01-23T16:21:52Z WARN  librespot_playback::audio_backend::alsa] Error writing from AlsaSink buffer to PCM, trying to recover, ALSA function 'snd_pcm_writei' failed with error 'EPIPE: Broken pipe'
Jan 23 16:21:52 pi0 librespot[461]: ALSA lib pcm.c:8424:(snd_pcm_recover) underrun occurred
Jan 23 16:21:54 pi0 librespot[461]: [2022-01-23T16:21:54Z WARN  librespot_playback::audio_backend::alsa] Error writing from AlsaSink buffer to PCM, trying to recover, ALSA function 'snd_pcm_writei' failed with error 'EPIPE: Broken pipe'

Before the errors start happening, librespot takes < 30% of the CPU:

It's reproducible on two different Raspberry PIs (a v1 and a Zero), both of which are using HifiBerry DACs.

removogel commented 2 years ago

Maybe worth to mention, i'am running librespot 0.3.1 c6e97a7 (Built on 2022-01-18, Build ID: ZBF0gGFJ, Profile: release)

JasonLG1979 commented 2 years ago

It looks as though Spotify itself might be having issues? The desktop app will not load properly for me (the desktop app is basically a glorified browser frame) If that is the case a slow and/or unstable connection (on their side) could be starving the audio backend. So far Spotify Connect seems unaffected for me at least. Lets give it a little time to see if this is just an Spotify problem.

It's reproducible on two different Raspberry PIs (a v1 and a Zero), both of which are using HifiBerry DACs.

I also have a HifiBerry DAC (DAC+ ZERO) which is currently on my Pi 4. My PiZero + the DAC+ ZERO is my go to setup for testing when I hack on librespot and/or Raspotify.

removogel commented 2 years ago

Spotify-Electron app at Linux works for me (region Germany) as usual. I also believed that the files are downloaded in one piece, not livestreamed. QoS problems would therefore not explain the stuttering in a fixed frequency of a few seconds.

JasonLG1979 commented 2 years ago

Spotify-Electron app at Linux works for me (region Germany) as usual. I also believed that the files are downloaded in one piece, not livestreamed. QoS problems would therefore not explain the stuttering in a fixed frequency of a few seconds.

The files are downloaded and saved to disk or stored in memory but the player will start playback as soon as enough audio is there to play. It doesn't wait for the file to be completely downloaded. In theory if Spotify could not at least keep up with the audio in realtime it would starve the audio backend.

b0bbywan commented 2 years ago

I had the same issue with 0.31.6~librespot.v0.3.1-47-gc6e97a7 version too, downgrading fixed the problem.

JasonLG1979 commented 2 years ago

I had the same issue with 0.31.6~librespot.v0.3.1-47-gc6e97a7 version too, downgrading fixed the problem.

Which version did you downgrade too?

JasonLG1979 commented 2 years ago

The only difference between 0.31.6 and 0.31.5 is this commit. Which actually saves a tiny amount of CPU usage during dynamic volume normalization compared 0.31.5. Nothing related to the audio backend or network code changed between those versions.

I have been streaming all day with the same hardware/software combo as others who are affected. I still think that it's a network issue on Spotify's side as I can't reproduce.

pierreb204 commented 2 years ago

I confirm, on a fresh install on a PI-zero : music replay is starting to stutter after a few minutes working fine. /usr/bin/libespot takes up to 97% CPU

nOneKzero commented 2 years ago

Same here on a PI2 B+:

I just starting hitting this today, too. It was working fine before so I think it was caused by an OS or raspotify update.

systemctl restart raspotify fixes the issue temporarily, but then after about 15 minutes it starts stuttering and librespot takes near 100% of the CPU again. These errors start showing up in the logs (repeating every couple seconds until playback is stopped or raspotify is restarted again):

Jan 23 16:02:45 pi0 systemd[1]: Stopping Raspotify (Spotify Connect Client)...
Jan 23 16:02:45 pi0 systemd[1]: raspotify.service: Main process exited, code=killed, status=15/TERM
Jan 23 16:02:45 pi0 systemd[1]: raspotify.service: Succeeded.
Jan 23 16:02:45 pi0 systemd[1]: Stopped Raspotify (Spotify Connect Client).
Jan 23 16:02:45 pi0 systemd[1]: Started Raspotify (Spotify Connect Client).
Jan 23 16:21:49 pi0 librespot[461]: [2022-01-23T16:21:49Z WARN  librespot_playback::audio_backend::alsa] Error writing from AlsaSink buffer to PCM, trying to recover, ALSA function 'snd_pcm_writei' failed with error 'EPIPE: Broken pipe'
Jan 23 16:21:49 pi0 librespot[461]: ALSA lib pcm.c:8424:(snd_pcm_recover) underrun occurred
Jan 23 16:21:50 pi0 librespot[461]: [2022-01-23T16:21:50Z WARN  librespot_playback::audio_backend::alsa] Error writing from AlsaSink buffer to PCM, trying to recover, ALSA function 'snd_pcm_writei' failed with error 'EPIPE: Broken pipe'
Jan 23 16:21:50 pi0 librespot[461]: ALSA lib pcm.c:8424:(snd_pcm_recover) underrun occurred
Jan 23 16:21:52 pi0 librespot[461]: [2022-01-23T16:21:52Z WARN  librespot_playback::audio_backend::alsa] Error writing from AlsaSink buffer to PCM, trying to recover, ALSA function 'snd_pcm_writei' failed with error 'EPIPE: Broken pipe'
Jan 23 16:21:52 pi0 librespot[461]: ALSA lib pcm.c:8424:(snd_pcm_recover) underrun occurred
Jan 23 16:21:54 pi0 librespot[461]: [2022-01-23T16:21:54Z WARN  librespot_playback::audio_backend::alsa] Error writing from AlsaSink buffer to PCM, trying to recover, ALSA function 'snd_pcm_writei' failed with error 'EPIPE: Broken pipe'

Before the errors start happening, librespot takes < 30% of the CPU:

It's reproducible on two different Raspberry PIs (a v1 and a Zero), both of which are using HifiBerry DACs.

b0bbywan commented 2 years ago

I had the same issue with 0.31.6~librespot.v0.3.1-47-gc6e97a7 version too, downgrading fixed the problem.

Which version did you downgrade too?

I downgraded to 0.31.4~librespot.v0.3.1-34-ge5fd7d6.

I'm not sure about the Spotify backend issue, Spotify app was working fine on desktop and mobile when I experienced the issue.

kirenida commented 2 years ago

Same problem here. Selecting Raspotify from the desktop app - stuttering starts after some time. Playing through the desktop app and sending the audio to the pulseaudio server on the Raspberry - playback OK.

Edit: does this help?

Jan 24 21:22:04 raspberrypi librespot[2557]: [2022-01-24T20:22:04Z ERROR librespot_core::session] Connection reset by peer (os error 104)
Jan 24 21:22:04 raspberrypi librespot[2557]: [2022-01-24T20:22:04Z WARN  librespot_audio::fetch::receive] Error from channel for data receiver for range 10893516 (+16384).
Jan 24 21:22:04 raspberrypi librespot[2557]: [2022-01-24T20:22:04Z WARN  librespot_audio::fetch::receive] Error from channel for data receiver for range 10909900 (+16384).
Jan 24 21:22:04 raspberrypi librespot[2557]: [2022-01-24T20:22:04Z WARN  librespot_audio::fetch::receive] Error from channel for data receiver for range 10926284 (+16384).
Jan 24 21:22:04 raspberrypi librespot[2557]: [2022-01-24T20:22:04Z ERROR librespot_connect::spirc] subscription terminated
Jan 24 21:22:04 raspberrypi librespot[2557]: [2022-01-24T20:22:04Z WARN  librespot] Spirc shut down unexpectedly

JasonLG1979 commented 2 years ago

does this help?

Yes it tells me it's a network issue just like I suspected.

JasonLG1979 commented 2 years ago

I downgraded to 0.31.4~librespot.v0.3.1-34-ge5fd7d6.

I'm not sure about the Spotify backend issue, Spotify app was working fine on desktop and mobile when I experienced the issue.

That release corresponds to this commit.

Again nothing really changed much from 0.31.4 - 0.31.6.

Where (as far as country or geographical area) are people being affected by this? I am located in central Iowa in the Midwestern United States and can not reproduce this.

nOneKzero commented 2 years ago

I am located in mid Europa, yesterday once it lasts about half an hour, since it starts to stutter.

Are you working with cache? If so, whats your configuration? Maybe this will prevent the occurrence 🤔

b0bbywan commented 2 years ago

I'm in Western Europe

removogel commented 2 years ago

We know, every effect is possible. But this doesn't look like network issue for me

The frequency of dropouts is quit stable, even the length of dropouts is stable. A corrupted IP connect would vary and lead to random pattern of dropouts.
After the effect started, it's not recover of it's own. The systemctl restart raspotify solves the problem immedately, it has no impact on network availablity.
Pausing replay doesn't help. In a corrupted network setup i would expect a Pause loading the remaining part of the file.
After first appearance of the issue i suspected some local network issue. Thats why i started to ping the Spotify servers, answers have been stable +-50ms.

ssombra commented 2 years ago

I found this post because I am having similar issues on a RPi Zero with Spotify + Adafruit speaker bonnet. After a while (15- 20 mins) music starts stuttering. HTOP shows 98% of the CPU (around 20% before the problem). Pausing Spotify doesn't fix the problem. Edit: I am located in Mexico

kirenida commented 2 years ago

I'm in Norway.

Today I didn't have any dropouts, but I have updated the system with the latest packages, so maybe it was just some weird coincidence?

JasonLG1979 commented 2 years ago

We know, every effect is possible. But this doesn't look like network issue for me

I'm just guessing. I have no way to fix it because I can't reproduce it and so far all I've got is a lot of "Me to". Sorry, there's not much I can do about it but wait to see if it affects me or see it passes with time.

Are you working with cache? If so, whats your configuration? Maybe this will prevent the occurrence

My Raspberry Pi 4 doesn't run off of a micro sd card. Raspberry Pi OS is installed on a Kingston 120GB A400 SATA 3 2.5 SSD in a Inateck 2.5 Hard Drive Enclosure (with UASP), so there's plenty of room and I'm not really worried about wearing it out since it's a proper SSD and it only cost like $25.

I generally run it with 16G of audio file cache on the Pi 4. The cache locations are already taken care of and can't be changed without changing the systemd unit file.

All you have to do to duplicate my config as far as caching is edit /etc/raspotify/conf:

Comment out: LIBRESPOT_DISABLE_AUDIO_CACHE=

And uncomment and follow the instructions above it: #LIBRESPOT_CACHE_SIZE_LIMIT=

My Pi Zero runs off a micro sd card. I do not cache to disk on the Pi Zero because I don't want to prematurely kill my micro sd card.

When I'm hacking around on my desktop sometimes I run with a cache sometimes not depends on what bits in librespot on working on.

Today I didn't have any dropouts, but I have updated the system with the latest packages, so maybe it was just some weird coincidence?

It's hard to say? at this point it really could be anything?

JasonLG1979 commented 2 years ago

If anyone would like to help debug you can stop the Raspotify service (sudo systemctl stop raspotify) and run librespot directly from a terminal with librespot -v (don't forget your device arg if you specify one normally) and post any relevant log messages from around the time when you get the error. I'd also like to see what alsa is telling librespot what it's buffer size is.

Look for a section that looks like:

[2022-01-26T00:14:00Z TRACE librespot_playback::player] == Starting sink ==
[2022-01-26T00:14:00Z TRACE librespot_playback::audio_backend::alsa] Desired Frames per Buffer: 22050
[2022-01-26T00:14:00Z TRACE librespot_playback::audio_backend::alsa] Desired Frames per Period: 5512
[2022-01-26T00:14:00Z TRACE librespot_playback::audio_backend::alsa] Actual Frames per Buffer: 22050
[2022-01-26T00:14:00Z TRACE librespot_playback::audio_backend::alsa] Actual Frames per Period: 5512
[2022-01-26T00:14:00Z TRACE librespot_playback::audio_backend::alsa] Period Buffer size in bytes: 44096
[2022-01-26T00:14:00Z TRACE librespot_playback::audio_backend::alsa] Period Buffer capacity: 44096

ssombra commented 2 years ago

I would like to help debuging but I need some guidance, I don't understand much about RPi's, but I can follow instructions. I stopped the raspotify service and run librespot as suggested (not sure what is the device arg) and so far I haven't had any issues for 40 minutes which is a record, it usually starts failing between 15-20 mins. Now, I don´t know exactly what to look at or what to report. Edit: I have this on the terminal:

[2022-01-26T02:45:33Z TRACE librespot_playback::audio_backend::alsa] Buffer size: 8192
[2022-01-26T02:45:33Z TRACE librespot_playback::audio_backend::alsa] Desired Period Frame range: 819 (Buffer size / 10) - 2048 (Buffer size / 4)
[2022-01-26T02:45:33Z TRACE librespot_playback::audio_backend::alsa] Actual Period Frame range as reported by the device: 1024 - 1024
[2022-01-26T02:45:33Z TRACE librespot_playback::audio_backend::alsa] Failed to set Buffer and/or Period size, falling back to the device's defaults.
[2022-01-26T02:45:33Z TRACE librespot_playback::audio_backend::alsa] You may experience higher than normal CPU usage and/or audio issues.
[2022-01-26T02:45:33Z TRACE librespot_playback::audio_backend::alsa] Actual Frames per Buffer: 8192
[2022-01-26T02:45:33Z TRACE librespot_playback::audio_backend::alsa] Actual Frames per Period: 1024
[2022-01-26T02:45:33Z TRACE librespot_playback::audio_backend::alsa] Period Buffer size in bytes: 4096
[2022-01-26T02:45:33Z TRACE librespot_playback::audio_backend::alsa] Period Buffer capacity:4096

tobiasmcnulty commented 2 years ago

Interestingly, I tried running librespot -v and it played successfully for ~40 minutes. It does not appear that running this way picks up the config in /etc/raspotify/conf. This config is the default, except I changed the value for LIBRESPOT_NAME to a single word.

I re-ran via systemd, and it died again after 20 minutes with the same errors as before (repeating every couple seconds):

Jan 26 16:26:11 pi3 librespot[15192]: [2022-01-26T16:26:11Z WARN  librespot_playback::audio_backend::alsa] Error writing from AlsaSink buffer to PCM, trying to recover, ALSA function 'snd_pcm_writei' failed with error 'EPIPE: Broken pipe'

ssombra commented 2 years ago

Today I stopped again raspotify and run librespot -v and I have been playing music for more than an hour without any issues.

JasonLG1979 commented 2 years ago

To be clear, everyone is running the latest version of Raspberry Pi OS, the version based on Debian Bullseye and not the legacy version based on Debian Buster right? Because Buster is not supported.

Seal1984 commented 2 years ago

Hi, I also have the same issue. I am using a Raspberry PI Zero with Raspberry Pi OS Lite (Bullseye). The behavior is the same like ssombra's. I stopped raspotify and run librespot and could play music for hours.

ssombra commented 2 years ago

To be clear, everyone is running the latest version of Raspberry Pi OS, the version based on Debian Bullseye and not the legacy version based on Debian Buster right? Because Buster is not supported.

Yes, latest version (lite) Music still going since this morning, no issues with just librespot running.

JasonLG1979 commented 2 years ago

@ssombra those are some really low buffer numbers (sub 100ms). Have you configured your buffer size in /etc/asound.conf? That's unnecessarily small unless you're recording, just that by itself will cause higher CPU usage. You don't need that low a latency for playback. A reasonable buffer size for playback is something like 5 times that. That in and of itself is not your issue just an FYI. Some devices are worse than others and have bad drivers and you can't help it though because the buffer size can't be configured at all. If you haven't purposely set the buffer size that small that's prob the case.

But I digress...

Between what you, @tobiasmcnulty and @Seal1984 report it sounds like it's got something to do with the combination of Pi Zero + systemd? I can't reproduce on my Pi4 so I guess it's time to bust out the Pi Zero.

ssombra commented 2 years ago

@ssombra those are some really low buffer numbers (sub 100ms). Have you configured your buffer size in /etc/asound.conf? That's unnecessarily small unless you're recording, just that by itself will cause higher CPU usage. You don't need that low a latency for playback. A reasonable buffer size for playback is something like 5 times that. That in and of itself is not your issue just an FYI. Some devices are worse than others and have bad drivers and you can't help it though because the buffer size can't be configured at all. If you haven't purposely set the buffer size that small that's prob the case.

But I digress...

Between what you, @tobiasmcnulty and @Seal1984 report it sounds like it's got something to do with the combination of Pi Zero + systemd? I can't reproduce on my Pi4 so I guess it's time to bust out the Pi Zero.

@JasonLG1979 I am not sure. I don't really understand much about those configurations, I just installed a fresh Raspberry Pi OS version. Then I installed raspotify using the installation script. Finally, as I am using the Adafruit speaker bonnet, I run the script provided by them, which I think is the script that sets the buffer up (I am guessing here): curl -sS https://raw.githubusercontent.com/adafruit/Raspberry-Pi-Installer-Scripts/master/i2samp.sh | bash

which according to the website, is a copy of the script used by PhatDAC. That being said, I would love to try different values for the buffer if you can recommend some (along with instructions on how to change them).

removogel commented 2 years ago

Hi guys, this issue becomes a hobby

Shame on me, was running Buster. Did a distro upgrade few weeks ago. Thought I had upgraded to Bullseye, but was still one version back. But today I really did upgrade to Bullseye lsb_release -d Description: Raspbian GNU/Linux 11 (bullseye)

But anyway - the problem didn't disapear.

switch on and boot raspi
starting raspotify the normal way
errors after 15 minutes
stopped raspotify and started librespot
listening for more than 2 hours
stopped librespot without stopping replay and start raspotify demon
my Spotify Electron app crashes and does't recover until desktop reboot - @JasonLG1979 maybe thats the issue you faced in the beginning with the app
also the iOS Spotify wasn't able to connect to the raspotify anymore
reboot raspi
starting raspotify the normal way again
errors after 40 minutes
stopped raspotify and started librespot - listening now for more than 1 hour

My hardware setup: Raspberry Pi Zero W connected via WIFI card 1: PCM2702 [Burr-Brown Japan PCM2702], device 0: USB Audio [USB Audio]


[2022-01-26T23:24:14Z TRACE librespot_playback::audio_backend::alsa] Desired Frames per Buffer: 15052
[2022-01-26T23:24:14Z TRACE librespot_playback::audio_backend::alsa] No Desired Period size in range reported by the device.
[2022-01-26T23:24:14Z TRACE librespot_playback::audio_backend::alsa] Buffer size: 15052
[2022-01-26T23:24:14Z TRACE librespot_playback::audio_backend::alsa] Desired Period Frame range: 1505 (Buffer size / 10) - 3763 (Buffer size / 4)
[2022-01-26T23:24:14Z TRACE librespot_playback::audio_backend::alsa] Actual Period Frame range as reported by the device: 940 - 941
[2022-01-26T23:24:14Z TRACE librespot_playback::audio_backend::alsa] Failed to set Buffer and/or Period size, falling back to the device's defaults.
[2022-01-26T23:24:14Z TRACE librespot_playback::audio_backend::alsa] You may experience higher than normal CPU usage and/or audio issues.
[2022-01-26T23:24:14Z TRACE librespot_playback::audio_backend::alsa] Actual Frames per Buffer: 15052
[2022-01-26T23:24:14Z TRACE librespot_playback::audio_backend::alsa] Actual Frames per Period: 940
[2022-01-26T23:24:14Z TRACE librespot_playback::audio_backend::alsa] Period Buffer size in bytes: 3760
[2022-01-26T23:24:14Z TRACE librespot_playback::audio_backend::alsa] Period Buffer capacity: 3760

2022-01-26T23:45:37Z DEBUG librespot_playback::player] command=Preload(SpotifyId { id: 199700931088445468098460721733158558397, audio_type: Track })
[2022-01-26T23:45:37Z DEBUG librespot_playback::player] Preloading track
[2022-01-26T23:45:37Z INFO  librespot_playback::player] Loading <Low Violet> with Spotify URI <spotify:track:4zuJ1LXpRO7z3cRwDD17n7>
[2022-01-26T23:45:37Z DEBUG librespot_audio::fetch] Downloading file a074d9e263689deaa408d09cce399640063b4c86
[2022-01-26T23:45:37Z INFO  librespot_playback::player] <Low Violet> (261920 ms) loaded
[2022-01-26T23:45:59Z DEBUG librespot_audio::fetch] File a074d9e263689deaa408d09cce399640063b4c86 complete, saving to cache
[2022-01-26T23:46:07Z DEBUG librespot_connect::spirc] At track 11 of 51 <"spotify:track:12pP1b7tNXcRP1Jwsvqy7U"> update [false]

JasonLG1979 commented 2 years ago

Well, I am able to reproduce on my Pi Zero.

Watching htop my new working theory is that this commit pushed the CPU usage to right on the edge of what the Pi Zero can handle with volume normalization enabled. I can pretty easily trigger it going from Hey Jude to Runnin' With The Devil in this playlist. I think the combo of the spike of CPU usage because libresot is buffering the song and the normalizer dealing with that big sweep at the beginning of Runnin' With The Devil pegs the poor little CPU on the Zero. I even tried overclocking the Zero and no dice. That would explain why I can't reproduce it on my Pi 4, it can take the hit.

librespot -v will not reproduce it because volume normalization is not enabled by default in librespot but it is in the Raspotify config.

I can reproduce it with librespot -N -v (N enables volume normalization)

It's a sad day but it is what it is. My recommendation is to disable volume normalization in /etc/raspotify/conf by commenting out:

LIBRESPOT_ENABLE_VOLUME_NORMALISATION=

I will do the same in the next version and put a note in the config that a Pi Zero v1.x can't handle the CPU load of that feature.

JasonLG1979 commented 2 years ago

@ssombra I would try to change the values of period_size and buffer_size to 4410 for period_size and 22050 for buffer_size in /etc/asound.conf that would give you a 500ms (0.5 sec) buffer with 100ms (0.1 sec) segments.

ssombra commented 2 years ago

@ssombra I would try to change the values of period_size and buffer_size to 4410 for period_size and 22050 for buffer_size in /etc/asound.conf that would give you a 500ms (0.5 sec) buffer with 100ms (0.1 sec) segments.

Thank you, I will try those values along with the volume normalization suggestion. best

tobiasmcnulty commented 2 years ago

Between what you, @tobiasmcnulty and @Seal1984 report it sounds like it's got something to do with the combination of Pi Zero + systemd? I can't reproduce on my Pi4 so I guess it's time to bust out the Pi Zero.

@JasonLG1979 I was wondering if the issue might be happening on the Pi4, simply not apparent due to its more powerful CPU...

Do you have any thoughts on the errors I posted above (Error writing from AlsaSink buffer to PCM, trying to recover, ALSA function 'snd_pcm_writei' failed with error 'EPIPE: Broken pipe')? I should be clear they begin appearing exactly when the audio problems start occurring and when the CPU usage spikes... so they seem very much related. It does not seem to matter what track is playing in my case.

I also confirmed:

When downgrading to 0.31.4 as suggested by @b0bbywan, I see no errors and hear no stutter.
When upgrading to 0.31.5, the errors and stutter begin to appear.

This presumably would line up with your theory about the new dynamic limiter, since it looks like the only code changes between those versions were in librespot itself.

Thanks for your help debugging this (and more broadly for maintaining this project)!

removogel commented 2 years ago

Oh yes, can reproduce this librespot -v -n "MySpeaker" -b 320 -N --initial-volume 50 --device-type avr It didn't work with the songs you proposed, thats why i tried the longest ones, expecting a higher load to calculate them. Pigs of PinkFloyd did it for me.

As soon CPU hits 100% ALSA lib pcm.c:8545:(snd_pcm_recover) underrun occurred [2022-01-27T01:22:44Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPlay] [2022-01-27T01:22:44Z TRACE librespot_connect::spirc] ==> kPlayStatusPlay [2022-01-27T01:22:45Z WARN librespot_playback::audio_backend::alsa] Error writing from AlsaSink buffer to PCM, trying to recover, ALSA function 'snd_pcm_writei' failed with error 'EPIPE: Broken pipe'

JasonLG1979 commented 2 years ago

expecting a higher load to calculate them. Pigs of PinkFloyd did it for me

The calculation is done on the fly as the song plays.

JasonLG1979 commented 2 years ago

Spotify provides ReplayGain info and we then use that to normalize the track by adjusting the gain and then running it though a dynamic limiter.

JasonLG1979 commented 2 years ago

The ReplayGain spec is here:

https://wiki.hydrogenaud.io/index.php?title=ReplayGain_1.0_specification https://wiki.hydrogenaud.io/index.php?title=ReplayGain_2.0_specification

JasonLG1979 commented 2 years ago

Do you have any thoughts on the errors I posted above (Error writing from AlsaSink buffer to PCM, trying to recover, ALSA function 'snd_pcm_writei' failed with error 'EPIPE: Broken pipe')

I get the same error.

This explains the error. basically the Pi Zero can't keep the buffer full.

so they seem very much related. It does not seem to matter what track is playing in my case.

Even if the limiter is not engaged samples are still processed to change their gain at the rate of 88,200 samples a sec (44,100 stereo) and over all the sample pipeline is very inefficient in general in librespot. Samples are iterated over up to 3 different times by different components in the chain. (Normalizer, converter and software volume) It's on my list to write a proper audio pipeline whereas samples are only ever iterated over once. That should save a couple %'s but the Normalizer will always be expensive I wouldn't expect it to be enough but one can only hope.

ssombra commented 2 years ago

Just lo let you know that after the changes (volume normalization and buffer) everything is working good, almost 2 hours without issues. Thanks @JasonLG1979 for your support ont his issue

JasonLG1979 commented 2 years ago

I long for the day when Pi Zero v2's aren't basically unobtainium. I'd love to get my hands on one. I'd be willing to bet it could handle anything librespot could throw at it.

b0bbywan commented 2 years ago

I have Bullseye on an old Raspberry B+, always had volume-normalization disabled because the processor has never been able to handle it properly, even with modest overclocking, and the cache has always been disabled to save the SD card.

JasonLG1979 commented 2 years ago

I have Bullseye on an old Raspberry B+, always had volume-normalization disabled because the processor has never been able to handle it properly, even with modest overclocking, and the cache has always been disabled to save the SD card.

The Pi 1 and Zero have the same processor but I believe that the Zero has a higher stock clock though? I can overclock my Zero to about 1100Mhz before it gets unstable. The CPU on the Zero (and I would assume the 1?) is not thermally limited it's just that the processor physically can't run any faster than about 1100MHz.

nOneKzero commented 2 years ago

Thank you @JasonLG1979 ! Yesterday i was able to stream all day without any Trouble!

https://github.com/dtcooper/raspotify/issues/504#issuecomment-1022748136 solved it for my old raspberry pi 2 B :)

b0bbywan commented 2 years ago

I have Bullseye on an old Raspberry B+, always had volume-normalization disabled because the processor has never been able to handle it properly, even with modest overclocking, and the cache has always been disabled to save the SD card.

The Pi 1 and Zero have the same processor but I believe that the Zero has a higher stock clock though? I can overclock my Zero to about 1100Mhz before it gets unstable. The CPU on the Zero (and I would assume the 1?) is not thermally limited it's just that the processor physically can't run any faster than about 1100MHz.

Both processors are Broadcom BCM2835, but the pi Zero runs at 1GHz vs 700MHz (800MHz with modest overclocking) for the B+. I see the same error as you guys when I run librespot -v -n "MySpeaker" -b 320 -G --initial-volume 100 (no cache nor volume normalization) with 0.31.6 but not 0.31.4

JasonLG1979 commented 2 years ago

We might have to strike the Pi 1 off of the supported list then.

JasonLG1979 commented 2 years ago

The Pi 1 has been removed from the supported list.

In other sad news the soon-ish to be merged new-api branch of librespot fails to build with our current scripts here. I haven't looked to far into it yet, and I hope it's just a matter of just fixing up our build scripts but the issue so far seems to be ARMv6 specific so the possibility exists that at some point in the near future Raspotify will drop support for all ARMv6 Pi's which includes the Pi Zero v1.x.

ssombra commented 2 years ago

The Pi 1 has been removed from the supported list.

In other sad news the soon-ish to be merged new-api branch of librespot fails to build with our current scripts here. I haven't looked to far into it yet, and I hope it's just a matter of just fixing up our build scripts but the issue so far seems to be ARMv6 specific so the possibility exists that at some point in the near future Raspotify will drop support for all ARMv6 Pi's which includes the Pi Zero v1.x.

Sad news indeed. The Zero was a good option in terms of budget and form. I hope it is fixable.

JasonLG1979 commented 2 years ago

Sad news indeed. The Zero was a good option in terms of budget and form. I hope it is fixable.

If the Pi Zero v2 were not constantly sold out everywhere I would feel better about it since It's basically a drop-in replacement. But at this point it would be kinda shitty to say "Well just buy a Pi Zero v2." since you really can't.

nachoman42 commented 2 years ago

Although this is not a documented setting for raspotify, setting the normalisation method to basic as follows seems to resolve the issue for me without having to give up normalisation.

LIBRESPOT_NORMALISATION_METHOD="basic"

dtcooper / raspotify