Fix intermittent stream interruptions with high CPU usage

[leo]

Hi,
I have set up an MPD server (0.21.4) on a NanoPi NEO with the most recent DietPi (Linux 5.4.45). Output is via a small USB soundcard.
I use Samba (cifs) to access my music library on a network file server which works without any problems.

However, when I listen to web radio streams I get intermittent breaks. Normal CPU of mpd (top) is about 12 %, during such a break it goes up to 200 % or sometimes more for about half a second. Other processes are not affected. No content is lost, in fact there is a slight repetition when playing resumes again. RAM usage is about 50 %, network bandwidth used is about 1 %. Interruptions are unpredictable, sometimes nothing for three minutes, then two breaks within 20 seconds. Enough to cause serious discomfort when listening. Happens with any stream, but only with streams, not networked music files.

Does anybody have an idea how this can be fixed?

Thanks, Leo

[max]

Your MPD version is 21 bug-fix releases behind. First you should update. If this still happens, post a "perf report" of this high CPU usage.

[leo]

Thanks for the quick reply...
I uninstalled mpd and re-installed as per instructions from kaliko's repository.
Now it won't start any more:

Code: Select all

● mpd.service - Music Player Daemon
   Loaded: loaded (/lib/systemd/system/mpd.service; disabled; vendor preset: enabled)
   Active: failed (Result: resources)
     Docs: man:mpd(1)
           man:mpd.conf(5)
           file:///usr/share/doc/mpd/html/user.html

Aug 19 09:33:46 MusicPi systemd[1]: mpd.service: Failed to loa
d environment files: No such file or directory
Aug 19 09:33:46 MusicPi systemd[1]: mpd.service: Failed to run
 'start' task: No such file or directory
Aug 19 09:33:46 MusicPi systemd[1]: mpd.service: Failed with r
esult 'resources'.
Aug 19 09:33:46 MusicPi systemd[1]: Failed to start Music Play
er Daemon.
Aug 19 09:34:28 MusicPi systemd[1]: mpd.service: Failed to loa
d environment files: No such file or directory
Aug 19 09:34:28 MusicPi systemd[1]: mpd.service: Failed to run
 'start' task: No such file or directory
Aug 19 09:34:28 MusicPi systemd[1]: mpd.service: Failed with r
esult 'resources'.
Aug 19 09:34:28 MusicPi systemd[1]: Failed to start Music Play
er Daemon.

A reboot didn't help. Any ideas?

[max]

Looks like you deleted the file /etc/default/mpd which is part of the package. You need to restore it.

[leo]

OK, I removed the newer version and installed the standard repository version (0.21.5-3) in the hope to get the file back, but no luck.
The file is not there (I didn't delete it manually, why would I).
I removed mpd again, did "apt autoremove", reinstalled from kaliko's repository again with all dependencies.
/etc/default/mpd is still missing.
What can I do to get the file back?

[leo]

I now installed mpd on another current Raspbian machine and copied the mpd file over.
Frankly it seems kind of pointless because it's just a few lines that are commented out, so a simple 'touch' would probably have been enough.
Anyway. I'm now running mpd 0.21.22-1~bpo10+1 according to 'apt-cache policy mpd', whereas 'mpc version' states "0.21.11".
Will check if the problem still exists and report back.

[leo]

The problem still exists but the b-b-b-b-b-e-e-e-e-e-h-h-h-h-h-h-a-a-a-a-a-v-v-v-v-v-i-i-i-i-i-o-o-o-o-o-r-r-r-r-r is now different.

I recorded perf data for about 30 seconds until there was high CPU load on mpd again. The perf report output is:

Code: Select all

Samples: 42K of event 'cycles', Event count (approx.): 4906548362
Overhead  Command          Shared Object             Symbol
   9,56%  swapper          [kernel.kallsyms]         [k] arch_cpu_idle               ◆
   4,27%  output:DietPi A  libsamplerate.so.0.1.8    [.] 0x00002818                  ▒
   3,91%  output:DietPi A  libm-2.28.so              [.] lrintf32x                   ▒
   3,83%  output:DietPi A  libsamplerate.so.0.1.8    [.] 0x0000279e                  ▒
   1,84%  output:DietPi A  libsamplerate.so.0.1.8    [.] 0x0000280c                  ▒
   1,82%  output:DietPi A  libsamplerate.so.0.1.8    [.] 0x00002792                  ▒
   1,74%  decoder:mad      libmad.so.0.2.1           [.] III_imdct_l                 ▒
   1,71%  output:DietPi A  libsamplerate.so.0.1.8    [.] 0x0000281c                  ▒
   1,62%  output:DietPi A  libsamplerate.so.0.1.8    [.] 0x000027a2                  ▒
   1,48%  output:DietPi A  libsamplerate.so.0.1.8    [.] 0x00002808                  ▒
   1,41%  top              libc-2.28.so              [.] _IO_vfscanf                 ▒
   1,30%  output:DietPi A  libsamplerate.so.0.1.8    [.] 0x0000278e                  ▒
   1,08%  output:DietPi A  libsamplerate.so.0.1.8    [.] 0x000027de                  ▒
   0,99%  output:DietPi A  libsamplerate.so.0.1.8    [.] 0x000027f4                  ▒
   0,94%  swapper          [kernel.kallsyms]         [k] finish_task_switch          ▒
   0,84%  output:DietPi A  libsamplerate.so.0.1.8    [.] 0x0000277a                  ▒
   0,80%  output:DietPi A  libsamplerate.so.0.1.8    [.] 0x00002762                  ▒
   0,70%  output:DietPi A  libsamplerate.so.0.1.8    [.] 0x000027d4                  ▒
   0,68%  output:DietPi A  libsamplerate.so.0.1.8    [.] 0x0000277e                  ▒
   0,67%  top              [kernel.kallsyms]         [k] mmioset                     ▒
   0,60%  output:DietPi A  libsamplerate.so.0.1.8    [.] 0x000027f8                  ▒
   0,54%  output:DietPi A  libsamplerate.so.0.1.8    [.] 0x00002772                  ▒
   0,52%  output:DietPi A  libsamplerate.so.0.1.8    [.] 0x000027d8                  ▒
   0,51%  output:DietPi A  libsamplerate.so.0.1.8    [.] 0x0000275c                  ▒
   0,50%  output:DietPi A  libsamplerate.so.0.1.8    [.] 0x00002776                  ▒
   0,50%  output:DietPi A  libsamplerate.so.0.1.8    [.] 0x00002810                  ▒
   0,50%  output:DietPi A  libsamplerate.so.0.1.8    [.] 0x000027ea                  ▒
   0,49%  output:DietPi A  libsamplerate.so.0.1.8    [.] 0x000027e8                  ▒
   0,48%  output:DietPi A  libsamplerate.so.0.1.8    [.] 0x0000276e                  ▒
Tip: Create an archive with symtabs to analyse on other machine: perf archive        ▒
[0] 0:perf_5.4*                                              "MusicPi" 11:19 19-Aug-20

Output of 'top' is:

Code: Select all

top - 11:23:35 up  1:50,  4 users,  load average: 0,07, 0,53, 0,54
Tasks: 104 total,   1 running, 103 sleeping,   0 stopped,   0 zombie
%Cpu(s):  2,9 us,  0,5 sy,  0,0 ni, 96,6 id,  0,0 wa,  0,0 hi,  0,0 si,  0,0 st
MiB Mem :    239,4 total,     91,2 free,     90,3 used,     57,9 buff/cache
MiB Swap:      0,0 total,      0,0 free,      0,0 used.    140,8 avail Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU  %MEM     TIME+ COMMAND
 3254 root      20   0  210876  12364   1740 S  10,7   5,0   7:38.92 mpd
 3478 dietpi    20   0    9244   1816   1340 R   1,9   0,7   0:24.73 top
   10 root      20   0       0      0      0 I   1,0   0,0   0:06.54 rcu_sched
    1 root      20   0   31896   2996   1380 S   0,0   1,2   0:24.76 systemd
    2 root      20   0       0      0      0 S   0,0   0,0   0:00.07 kthreadd

As I watch the %CPU of mpd on top goes up to 200 or more and then drops again.
The device has full network priority on the router but that didn't help.

It just occurred to me to check /var/log/mpd/mpd.log:

Code: Select all

Aug 19 11:17 : alsa_output: Decoder is too slow; playing silence to avoid xrun
Aug 19 11:17 : alsa_output: Decoder is too slow; playing silence to avoid xrun
Aug 19 11:20 : alsa_output: Decoder is too slow; playing silence to avoid xrun
Aug 19 11:20 : alsa_output: Decoder is too slow; playing silence to avoid xrun
Aug 19 11:24 : alsa_output: Decoder is too slow; playing silence to avoid xrun
Aug 19 11:25 : alsa_output: Decoder is too slow; playing silence to avoid xrun
Aug 19 11:26 : alsa_output: Decoder is too slow; playing silence to avoid xrun

I have reniced mpd to -20 now and will keep an eye on it.

[leo]

Nope, didn't work:

Code: Select all

Aug 19 11:34 : alsa_output: Decoder is too slow; playing silence to avoid xrun

Looks like an issue with the decoder library to me...

[max]

Nearly all CPU time is spent on resampling. Since I don't have any information about your setup, I can't give any help here. Read https://www.musicpd.org/help/ if you need more help.

But what I can say: renicing the process will not solve the problem. If MPD doesn't compete with other processes for CPU time, renicing will not have any effect. It will not magically make your CPU faster.

[leo]

Thanks for your help. I am trying streams with lower bitrate now. Seems to work ok so far.

[max]

A lower bit rate will not reduce the CPU load for resampling.

[leo]

Yes, I'm still getting these errors, even if the average CPU load seems a tiny bit lower.

Well, ok. I'l play around with the settings until I maybe find something that works.

[max]

Randomly playing around with settings seems more like a playful waste of time than productive problem solving.

[skidoo]

As Max stated above try to disable resampling in mpd.conf.

Code: Select all

resampler {
	plugin "libsamplerate"
 	type "Fastest Sinc Interpolator"
	enabled "false"
}

[leo]

try to disable resampling in mpd.conf

Did this but I'm still getting the "decoder too slow" messages.

[max]

Because the configuration sample is wrong. It doesn't disable resampling, because it is not possible to disable resampling. The option "enabled" does not exist in the "resampler" block. See https://www.musicpd.org/doc/html/plugin ... er-plugins

[leo]

I fixed it now... by replacing the NanoPi with a Raspberry.

[max]

So this was all about hardware which was too slow for the configuration you chose.