Constant CPU usage

[497e0bdf29873]

If librespot is idle, it still causes a “typical of modern ****** busylooping apps” constant 1-5% CPU usage across the chain: all of librespot, pipewire, and pipewire-pulse processes are taking a few percent. Yes, it's not much for each of them, but they sum up, and apps shouldn't busyloop—it's as if they were all Electron apps, notorious for busylooping.

I've tried monitoring the processes with strace, and what I can observe is that

• if librespot is running, the pipewire-pulse process is repeatedly epolling at high speed.
• if I stop librespot, the hyperactive repetititve polling of pipewire-pulse diminishes (but it's still too much—it should just wait). There shouldn't be any other processes connected.
• pw-top gives similar results: it shows constant ALSA driver activity when librespot is running, but that disappears when librespot is not running

It's as if librespot would be constantly playing something.

However, if I attach strace to the librespot or pipewire processes, they are nicely epolling with semi-reasonable timeouts; no repetition with pipewire itself, and neither cause any of the hyperactivity of pipewire-pulse. So I'm not sure if this is a librespot bug, or the crappiness of pulseaudio/pipewire-pulse? It's constantly polling at hyperactive speeds when it has any connections to it, even if they're inactive?

But then again, according to htop, both the librespot and pipewire processes take respective ~3% and ~0.7% CPU, so pipewire must be doing something that it shouldn't be doing.

Any ideas?

---

strace pipewire-pulse (with librespot running, not playing anything)

This rolls at high hyperactive speeds even with nothing playing:

epoll_ctl(4, EPOLL_CTL_MOD, 27, {events=EPOLLIN|EPOLLOUT|EPOLLERR|EPOLLHUP, data={u32=26634848, u64=187651442764384}}) = 0
epoll_pwait(4, [{events=EPOLLOUT, data={u32=26634848, u64=187651442764384}}], 32, -1, NULL, 8) = 1
sendto(27, "\0\0\0\24\377\377\377\377\0\0\0\0\0\0\0\0\0\0\0\0", 20, MSG_DONTWAIT|MSG_NOSIGNAL, NULL, 0) = 20
sendto(27, "L\0\0\0=L\377\377\377\377L\0\0\0\0L\0\0:\320", 20, MSG_DONTWAIT|MSG_NOSIGNAL, NULL, 0) = 20
epoll_ctl(4, EPOLL_CTL_MOD, 27, {events=EPOLLIN|EPOLLERR|EPOLLHUP, data={u32=26634848, u64=187651442764384}}) = 0
epoll_pwait(4, [{events=EPOLLIN, data={u32=26634848, u64=187651442764384}}], 32, -1, NULL, 8) = 1
recvfrom(27, "\0\0:\320\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0", 20, MSG_DONTWAIT, NULL, NULL) = 20
recvfrom(27, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 15056, MSG_DONTWAIT, NULL, NULL) = 15056
recvfrom(27, 0xaaab0181913c, 20, MSG_DONTWAIT, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
epoll_pwait(4, [{events=EPOLLIN, data={u32=24835872, u64=187651440965408}}], 32, -1, NULL, 8) = 1
read(5, "\1\0\0\0\0\0\0\0", 8)          = 8
epoll_pwait(4, [{events=EPOLLIN, data={u32=24835872, u64=187651440965408}}], 32, -1, NULL, 8) = 1
read(5, "\1\0\0\0\0\0\0\0", 8)          = 8
epoll_ctl(4, EPOLL_CTL_MOD, 27, {events=EPOLLIN|EPOLLOUT|EPOLLERR|EPOLLHUP, data={u32=26634848, u64=187651442764384}}) = 0
epoll_pwait(4, [{events=EPOLLOUT, data={u32=26634848, u64=187651442764384}}], 32, -1, NULL, 8) = 1
sendto(27, "\0\0\0\24\377\377\377\377\0\0\0\0\0\0\0\0\0\0\0\0", 20, MSG_DONTWAIT|MSG_NOSIGNAL, NULL, 0) = 20
sendto(27, "L\0\0\0=L\377\377\377\377L\0\0\0\0L\0\0:\310", 20, MSG_DONTWAIT|MSG_NOSIGNAL, NULL, 0) = 20
epoll_ctl(4, EPOLL_CTL_MOD, 27, {events=EPOLLIN|EPOLLERR|EPOLLHUP, data={u32=26634848, u64=187651442764384}}) = 0
epoll_pwait(4, [{events=EPOLLIN, data={u32=26634848, u64=187651442764384}}], 32, -1, NULL, 8) = 1
recvfrom(27, "\0\0:\310\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0", 20, MSG_DONTWAIT, NULL, NULL) = 20
recvfrom(27, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 15048, MSG_DONTWAIT, NULL, NULL) = 15048
recvfrom(27, 0xaaab0181913c, 20, MSG_DONTWAIT, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
epoll_pwait(4, [{events=EPOLLIN, data={u32=24835872, u64=187651440965408}}], 32, -1, NULL, 8) = 1
read(5, "\1\0\0\0\0\0\0\0", 8)          = 8

strace librespot

This took several seconds to obtain, meanwhile the CPU usage is about 3%:

epoll_pwait(3, [], 1024, 905, NULL, 8)  = 0
epoll_pwait(3, [], 1024, 511, NULL, 8)  = 0
epoll_pwait(3, [], 1024, 57, NULL, 8)   = 0
epoll_pwait(3, [], 1024, 15813, NULL, 8) = 0
epoll_pwait(3, [], 1024, 8176, NULL, 8) = 0
epoll_pwait(3, [], 1024, 2934, NULL, 8) = 0
epoll_pwait(3, [], 1024, 44, NULL, 8)   = 0
write(4, "\1\0\0\0\0\0\0\0", 8)         = 8
writev(25, [{iov_base="\27\3\3\0\27r~\254Pr\364)T\"\221t\37\21\225\367\346\27\255\305\361\374\v\244", iov_len=28}], 1) = 28
epoll_pwait(3, [{events=EPOLLIN, data={u32=0, u64=0}}], 1024, 1100, NULL, 8) = 1
epoll_pwait(3, [{events=EPOLLIN|EPOLLOUT, data={u32=3765556864, u64=187650886719104}}], 1024, 1100, NULL, 8) = 1
recvfrom(25, "\27\3\3\0\23\376\367\343P\37\344\374\325\276\275\331\211e\330\205w\0175\254", 4096, 0, NULL, NULL) = 24
epoll_pwait(3, [], 1024, 990, NULL, 8)  = 0
epoll_pwait(3, [], 1024, 1854, NULL, 8) = 0
epoll_pwait(3, [], 1024, 39, NULL, 8)   = 0

pw-top (with librespot running, not playing anything):

S   29      0      0    ---     ---   ---   ---     0                  Dummy-Driver
S   30      0      0    ---     ---   ---   ---     0                  Freewheel-Driver
S   36      0      0    ---     ---   ---   ---     0                  Midi-Bridge
S   44      0      0    ---     ---   ---   ---     0                  alsa_output.platform-dp0-sound.stereo-fallback
R   45   1024  48000 365.5us  42.6us  0.02  0.00    0   S24_32 2 48000 alsa_output.platform-es8388-sound.stereo-fallback
R   66   1102  44100  88.1us 245.3us  0.00  0.01    0    F32LE 2 44100  + ALSA plug-in [librespot]
S   46      0      0    ---     ---   ---   ---     0                  alsa_input.platform-es8388-sound.stereo-fallback
S   47      0      0    ---     ---   ---   ---     0                  alsa_output.platform-hdmi0-sound.hdmi-stereo

pw-top (without librespot running):

S   29      0      0    ---     ---   ---   ---     0                  Dummy-Driver
S   30      0      0    ---     ---   ---   ---     0                  Freewheel-Driver
S   36      0      0    ---     ---   ---   ---     0                  Midi-Bridge
S   44      0      0    ---     ---   ---   ---     0                  alsa_output.platform-dp0-sound.stereo-fallback
S   45      0      0    ---     ---   ---   ---     0                  alsa_output.platform-es8388-sound.stereo-fallback
S   46      0      0    ---     ---   ---   ---     0                  alsa_input.platform-es8388-sound.stereo-fallback
S   47      0      0    ---     ---   ---   ---     0                  alsa_output.platform-hdmi0-sound.hdmi-stereo

[photovoltex]

Interesting investigation.

We have one main loop that handles the whole spotify connect logic and also the player. But that loop blocks until it receives a command. So that shouldn't be the issue you see. You can find the loop in spirc.rs in the connect crate. The loop is in SpircTask::run.

Anyhow I think I noticed something similar and it is the result of how we handle the player/mixer. The spirc (the spotify connect logic handling) takes our player and then uses it as needed. That itself isn't really the problem, but the player has always an active audio source/mixer. So even if we don't play anything there will be an instance of an audio mixer/sink/source for librespot.

So I think what you see might be the result of two different causes. The initial cause is, that we always have an active audio source/sink/mixer to the underlying audio backend. But the actual high idle usage might be the open connection to the audio backend, but that's more speculation than knowledge.

[497e0bdf29873]

I did a bit more experimenting and research: using the subprocess backend, librespot has zero idle CPU usage, so the idle CPU must come from the audio backend. It seems then that rodio::Sink::pause, which is called in librespot_playback::audio_backend::Sink::stop, does not properly stop the playback. I tried changing it torodio::Sink::stop, but that doesn't help, and causes some audible synchronisation issues. So I suppose the only option is to completely refactor the backends to open the connection on-demand.

[497e0bdf29873]

Actually, I hadn't tried/built to the direct pulseaudio backend. With that there is no noticeable idle CPU usage. So the problem is in Rodio.

[photovoltex]

And I'm back :D. It was actually quite a bit easier to only create/hold the sink when necessary.

As from what you described that might not be the main cause in the end, but could you give it (https://github.com/photovoltex/librespot/tree/reduced-sink-usage) a try nonetheless? For now it's just a rudimentary implementation but should show if that is the main cause of the issue. Testing for me currently is a bit limited because of bad network and time. But the general opening and closing seems to work.

Thanks in advance for the discovery and all the testing already :)

[simon-amadeus]

Hey @photovoltex , I can confirm that my idle cpu usage just dropped from ~40% to ~1% on raspberry pi 5.

I installed librespot yesterday with cargo install librespot but recognized unexpectedly high idle resource usage.
just found this discussion here and installed your version from the reduced-sink-usage branch.
now i only get 40% during active playback, otherwise ~1%.

40% during playback still seems high to me, but i can confirm that idle usage is much better :)

Thank you!

[photovoltex]

Very nice, thanks for the testing! Meaning I can clean up the branch and provide it as a PR later.