cdda playback: frequent alsa xrun (about 5sec period)

[macmpi]

mpd 0.23.4, Alpinelinux 3.15.4, kernel 5.15.32, PiZeroW

Playing commercial AudioCD often produces sound hiccups and following messages in log: alsa_output: Decoder is too slow; playing silence to avoid xrun

CPU load is circa 30% max. Playback is on default hdmi output (have same on bluealsa headset when enabled). Log shows a puzzling period regularity of about 5sec. I tried to set buffering as per https://github.com/MusicPlayerDaemon/MPD/issues/1263 with no improvement.

Found some older issue with cdio_paranoia https://github.com/MusicPlayerDaemon/MPD/issues/149: unsure if related. Thanks for any thoughts.

Version

$ mpd -V
Music Player Daemon 0.23.4 (v3.15.0_rc1-158-gb912e4d084)
Copyright 2003-2007 Warren Dukes <warren.dukes@gmail.com>
Copyright 2008-2021 Max Kellermann <max.kellermann@gmail.com>
This is free software; see the source for copying conditions.  There is NO
warranty; not even MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.

Database plugins:
 simple proxy

Storage plugins:
 local smbclient nfs curl

Neighbor plugins:
 smbclient

Decoders plugins:
 [mad] mp3 mp2
 [vorbis] ogg oga
 [oggflac] ogg oga
 [flac] flac
 [opus] opus ogg oga
 [dsdiff] dff
 [dsf] dsf
 [hybrid_dsd] m4a
 [faad] aac
 [wavpack] wv
 [modplug] 669 amf ams dbm dfm dsm far it med mdl mod mtm mt2 okt s3m stm ult umx xm
 [ffmpeg] 16sv 3g2 3gp 4xm 8svx aa3 aac ac3 adx afc aif aifc aiff al alaw amr anim apc ape asf atrac au aud avi avm2 avs bap bfi c93 cak cin cmv cpk daud dct divx dts dv dvd dxa eac3 film flac flc fli fll flx flv g726 gsm gxf iss m1v m2v m2t m2ts m4a m4b m4v mad mj2 mjpeg mjpg mka mkv mlp mm mmf mov mp+ mp1 mp2 mp3 mp4 mpc mpeg mpg mpga mpp mpu mve mvi mxf nc nsv nut nuv oga ogm ogv ogx oma ogg omg opus psp pva qcp qt r3d ra ram rl2 rm rmvb roq rpl rvc shn smk snd sol son spx str swf tak tgi tgq tgv thp ts tsp tta xa xvid uv uv2 vb vid vob voc vp6 vmd wav webm wma wmv wsaud wsvga wv wve rtp:// rtsp:// rtsps://
 [pcm]

Filters:
 libsamplerate soxr

Tag plugins:
 id3tag

Output plugins:
 shout null fifo pipe alsa ao pipewire pulse jack httpd snapcast recorder

Encoder plugins:
 null vorbis opus lame wave flac

Archive plugins:
 [bz2] bz2
 [iso] iso

Input plugins:
 file archive alsa curl ffmpeg smbclient nfs cdio_paranoia

Playlist plugins:
 extm3u m3u pls xspf asx rss flac cue embcue

Protocols:
 file:// alsa:// cdda:// ftp:// ftps:// gopher:// hls+http:// hls+https:// http:// https:// mmsh:// mmst:// nfs:// rtmp:// rtmps:// rtmpt:// rtmpts:// rtp:// rtsp:// rtsps:// sftp:// smb:// srtp://

Other features:
 avahi epoll icu inotify ipv6 tcp un

mpd.conf

# An example configuration file for MPD.
# Read the user manual for documentation: http://www.musicpd.org/doc/user/

music_directory     "/var/lib/mpd/music"
playlist_directory      "/var/lib/mpd/playlists"
db_file         "/var/lib/mpd/tag_cache"
state_file      "/tmp/.mpd-state"

log_file        "syslog"
log_level      "default"

user        "mpd"
group       "audio"

bind_to_address     "any"

#required to allow playing music files outside of music_directory
bind_to_address "/run/mpd/socket"

zeroconf_enabled        "yes"
zeroconf_name           "myServer"

auto_update    "no"
#auto_update_depth "3"

# Input ##########################
input {
        plugin "curl"
#       proxy "proxy.isp.com:8080"
#       proxy_user "user"
#       proxy_password "password"
}

# Audio Output ########################
volume_normalization   "no"

audio_output {
    type        "alsa"
    name        "My ALSA Device"
##  device      "hw:0,0"        # optional
##  mixer_type      "hardware"  # optional
##  mixer_device    "default"   # optional
##  mixer_control   "PCM"       # optional
##  mixer_index "0"     # optional
}

#audio_output {
#        type            "alsa"
#        name            "Bluetooth speaker"
#        device     "bluealsa"
#        device          "speaker"
#        mixer_type      "software"
#}

Log

May 13 09:20:06 myServer daemon.err mpd: server_socket: bind to '0.0.0.0:6600' failed (continuing anyway, because binding to '[::]:6600' succeeded): Failed to bind socket: Address in use
May 13 09:20:08 myServer daemon.err mpd: output: Failed to open mixer for 'My ALSA Device': no such mixer control: PCM
May 13 09:20:45 myServer daemon.warn mpd: alsa_output: Decoder is too slow; playing silence to avoid xrun
May 13 09:20:53 myServer daemon.warn mpd: alsa_output: Decoder is too slow; playing silence to avoid xrun
May 13 09:20:58 myServer daemon.warn mpd: alsa_output: Decoder is too slow; playing silence to avoid xrun
May 13 09:21:03 myServer daemon.warn mpd: alsa_output: Decoder is too slow; playing silence to avoid xrun
May 13 09:21:08 myServer daemon.warn mpd: alsa_output: Decoder is too slow; playing silence to avoid xrun
May 13 09:21:13 myServer daemon.warn mpd: alsa_output: Decoder is too slow; playing silence to avoid xrun
May 13 09:21:19 myServer daemon.warn mpd: alsa_output: Decoder is too slow; playing silence to avoid xrun
May 13 09:21:24 myServer daemon.warn mpd: alsa_output: Decoder is too slow; playing silence to avoid xrun
May 13 09:21:40 myServer daemon.notice mpd: player: played "cdda:///2"
May 13 09:22:34 myServer daemon.warn mpd: alsa_output: Decoder is too slow; playing silence to avoid xrun
May 13 09:22:39 myServer daemon.warn mpd: alsa_output: Decoder is too slow; playing silence to avoid xrun
May 13 09:22:45 myServer daemon.warn mpd: alsa_output: Decoder is too slow; playing silence to avoid xrun
May 13 09:22:50 myServer daemon.warn mpd: alsa_output: Decoder is too slow; playing silence to avoid xrun
May 13 09:22:55 myServer daemon.warn mpd: alsa_output: Decoder is too slow; playing silence to avoid xrun
May 13 09:23:00 myServer daemon.warn mpd: alsa_output: Decoder is too slow; playing silence to avoid xrun
May 13 09:23:05 myServer daemon.warn mpd: alsa_output: Decoder is too slow; playing silence to avoid xrun
May 13 09:23:10 myServer daemon.warn mpd: alsa_output: Decoder is too slow; playing silence to avoid xrun
May 13 09:23:15 myServer daemon.warn mpd: alsa_output: Decoder is too slow; playing silence to avoid xrun
May 13 09:23:20 myServer daemon.warn mpd: alsa_output: Decoder is too slow; playing silence to avoid xrun
May 13 09:23:32 myServer daemon.notice mpd: player: played "cdda:///2"
May 13 09:29:41 myServer daemon.notice mpd: player: played "cdda:///3"
May 13 09:29:42 myServer daemon.warn mpd: alsa_output: Decoder is too slow; playing silence to avoid xrun
May 13 09:29:47 myServer daemon.warn mpd: alsa_output: Decoder is too slow; playing silence to avoid xrun
May 13 09:29:54 myServer daemon.warn mpd: alsa_output: Decoder is too slow; playing silence to avoid xrun
May 13 09:29:59 myServer daemon.warn mpd: alsa_output: Decoder is too slow; playing silence to avoid xrun
May 13 09:30:04 myServer daemon.warn mpd: alsa_output: Decoder is too slow; playing silence to avoid xrun
May 13 09:30:09 myServer daemon.warn mpd: alsa_output: Decoder is too slow; playing silence to avoid xrun
May 13 09:30:15 myServer daemon.warn mpd: alsa_output: Decoder is too slow; playing silence to avoid xrun
May 13 09:30:20 myServer daemon.warn mpd: alsa_output: Decoder is too slow; playing silence to avoid xrun
May 13 09:30:25 myServer daemon.warn mpd: alsa_output: Decoder is too slow; playing silence to avoid xrun
May 13 09:30:30 myServer daemon.warn mpd: alsa_output: Decoder is too slow; playing silence to avoid xrun
May 13 09:30:35 myServer daemon.warn mpd: alsa_output: Decoder is too slow; playing silence to avoid xrun
May 13 09:30:40 myServer daemon.warn mpd: alsa_output: Decoder is too slow; playing silence to avoid xrun
May 13 09:30:45 myServer daemon.warn mpd: alsa_output: Decoder is too slow; playing silence to avoid xrun
May 13 09:30:50 myServer daemon.warn mpd: alsa_output: Decoder is too slow; playing silence to avoid xrun
May 13 09:30:55 myServer daemon.warn mpd: alsa_output: Decoder is too slow; playing silence to avoid xrun
May 13 09:31:00 myServer daemon.warn mpd: alsa_output: Decoder is too slow; playing silence to avoid xrun
May 13 09:31:05 myServer daemon.warn mpd: alsa_output: Decoder is too slow; playing silence to avoid xrun
May 13 09:31:11 myServer daemon.warn mpd: alsa_output: Decoder is too slow; playing silence to avoid xrun
May 13 09:31:16 myServer daemon.warn mpd: alsa_output: Decoder is too slow; playing silence to avoid xrun
May 13 09:31:21 myServer daemon.warn mpd: alsa_output: Decoder is too slow; playing silence to avoid xrun
May 13 09:31:26 myServer daemon.warn mpd: alsa_output: Decoder is too slow; playing silence to avoid xrun
May 13 09:31:31 myServer daemon.warn mpd: alsa_output: Decoder is too slow; playing silence to avoid xrun
May 13 09:31:36 myServer daemon.warn mpd: alsa_output: Decoder is too slow; playing silence to avoid xrun
May 13 09:31:41 myServer daemon.warn mpd: alsa_output: Decoder is too slow; playing silence to avoid xrun
May 13 09:31:46 myServer daemon.warn mpd: alsa_output: Decoder is too slow; playing silence to avoid xrun
May 13 09:31:51 myServer daemon.warn mpd: alsa_output: Decoder is too slow; playing silence to avoid xrun
May 13 09:31:56 myServer daemon.warn mpd: alsa_output: Decoder is too slow; playing silence to avoid xrun
May 13 09:32:01 myServer daemon.warn mpd: alsa_output: Decoder is too slow; playing silence to avoid xrun
May 13 09:32:06 myServer daemon.warn mpd: alsa_output: Decoder is too slow; playing silence to avoid xrun

[MaxKellermann]

This is I/O bound, not CPU bound. If your CD drive can't deliver data quickly enough (in cdio_paranoia's error recovery mode), then MPD can't feed your audio driver quickly enough. Without cdio_paranoia, without error detection/correction, your drive may be fast enough, but that's not what this plugin does.

[macmpi]

Thanks for quick feedback. Some tracks on same disk, and some other disks are playing just fine on same setup though... How could I test/benchmark this throughput?

[MaxKellermann]

Maybe the disc is damaged at the location where this one track is located, and cdio_paranoia needs to read it over and over? I don't know. Try the cdio_paranoia command-line tool.

[macmpi]

Have the same thing on a x86_64 PC with a USB3 DVD drive. Is mpd enforcing any read-speed (like cdparanoia -S --force-read-speed ) by default, or is there an option to set it?

[MaxKellermann]

Why don't you ... read the fine manual? https://mpd.readthedocs.io/en/stable/plugins.html#cdio-paranoia

[macmpi]

sorry, but, I did try adding the following on mpd.conf

input {
    plugin "cdio_paranoia"
    speed "20"
}

restarted mpd, and it did not have any influence, either with speed 1 or 20. added an input_cache of few hundreds MB with no more success.

and Audio CD plays nicely with VLC on same machine and CD drive.

[macmpi]

Besides VLC which plays my Audio CD fine on same hardware, I tried other players like mplayer and mpv

It may be an issue related to libcdparanoia usage as per this comment. Default mplayer command shows fewer issues with same tracks, whereas mplayer -cache 1024 cdda:// trick indeed plays fine. mpv plays fine too. It seems VLC departed from libcdparanoia at some point (it used it circa 2008). It seems to use plain libcdio now, as the earlier post suggests for mplayer. Maybe libcdparanoia is best for extracting/ripping but not for playing for some reasons? libVLC (LGPL2.1) might solve this.

[macmpi]

followed your recommendation in https://github.com/MusicPlayerDaemon/MPD/issues/149#issuecomment-343903804 to strace -tttTp $(pidof mpd) -o /tmp/trace during the issue. Please find it below. Thanks for feedback

1654011773.779751 clock_gettime64(CLOCK_MONOTONIC, {tv_sec=4808, tv_nsec=504212026}) = 0 <0.000151>
1654011773.782092 epoll_pwait(4, [{events=EPOLLIN, data={u32=3196640924, u64=12994761296292929180}}], 16, 111290, NULL, 8) = 1 <103.496027>
1654011877.278712 read(3, "\1\0\0\0\0\0\0\0", 8) = 8 <0.000116>
1654011877.279356 futex(0xbe88dc40, FUTEX_WAIT_PRIVATE, 2, NULL) = 0 <0.032560>
1654011877.312336 clock_gettime64(CLOCK_MONOTONIC, {tv_sec=4912, tv_nsec=36402903}) = 0 <0.000104>
1654011877.313095 epoll_pwait(4, [], 16, 7758, NULL, 8) = 0 <7.858319>
1654011885.171841 clock_gettime64(CLOCK_MONOTONIC, {tv_sec=4919, tv_nsec=895908204}) = 0 <0.000097>
1654011885.172400 open("/tmp", O_WRONLY|O_NOCTTY|O_LARGEFILE|O_CLOEXEC|O_TMPFILE, 0666) = 18 <0.000267>
1654011885.173281 fcntl64(18, F_SETFD, FD_CLOEXEC) = 0 <0.000098>
1654011885.173694 mmap2(NULL, 36864, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xaf0b2000 <0.000143>
1654011885.174305 futex(0xaf727800, FUTEX_WAKE_PRIVATE, 1) = 1 <0.000116>
1654011885.174765 futex(0xb188dd90, FUTEX_WAKE_PRIVATE, 1) = 1 <0.000104>
1654011885.175887 futex(0xbe88dc70, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable) <0.000099>
1654011885.177499 write(18, "sw_volume: 100\naudio_device_stat"..., 1406) = 1406 <0.000199>
1654011885.178144 munmap(0xaf0b2000, 36864) = 0 <0.000194>
1654011885.178632 unlinkat(AT_FDCWD, "/tmp/.mpd-state", 0) = 0 <0.000308>
1654011885.179551 linkat(AT_FDCWD, "/proc/self/fd/18", AT_FDCWD, "/tmp/.mpd-state", AT_SYMLINK_FOLLOW) = 0 <0.000303>
1654011885.180556 close(18)             = 0 <0.000154>
1654011885.181025 futex(0xaf727800, FUTEX_WAKE_PRIVATE, 1) = 1 <0.000158>
1654011885.181494 futex(0xb188dd90, FUTEX_WAKE_PRIVATE, 1) = 1 <0.000180>
1654011885.181969 futex(0xbe88dcd8, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable) <0.000097>
1654011885.182478 epoll_pwait(4,  <detached ...>```

[MaxKellermann]

That strace is useless because it only shows the main thread. That other issue was about the main thread, this one here is not.

[macmpi]

Happy to provide some more useful log/trace/info if you direct me to some investigation clues. No idea what's happening for now, as same Audio CD with same HW plays nicely with other players as reported. Would need to have same performance with mpd, which is central for my project. Thanks for consideration.

[macmpi]

Did try to get strace from the right thread: hopefully it will give you more insight on what it happening during those alsa xrun. trace.txt Appreciate any feedback.

[macmpi]

I found another scenario which may point to some buffer management issue. Play any audio CD, and eject it during playback. Playback will continue until buffer is exhausted (about 16 sec in my case), and then log will start to show: mpd: alsa_output: Decoder is too slow; playing silence to avoid xrun which can be expected in such situation.

However, mpd will just become unresponsive to mpc stop command for a significant while (generating MPD error: Timeout), only releasing after about 1'44 (see below). Note the period of playing silence to avoid xrun is every 5sec as with previous usecase.

Jun 10 08:17:50 tiny-radiocd daemon.warn mpd: alsa_output: Decoder is too slow; playing silence to avoid xrun
Jun 10 08:17:55 tiny-radiocd daemon.warn mpd: alsa_output: Decoder is too slow; playing silence to avoid xrun
Jun 10 08:18:00 tiny-radiocd daemon.warn mpd: alsa_output: Decoder is too slow; playing silence to avoid xrun
Jun 10 08:18:05 tiny-radiocd daemon.warn mpd: alsa_output: Decoder is too slow; playing silence to avoid xrun
Jun 10 08:18:10 tiny-radiocd daemon.warn mpd: alsa_output: Decoder is too slow; playing silence to avoid xrun
Jun 10 08:18:15 tiny-radiocd daemon.warn mpd: alsa_output: Decoder is too slow; playing silence to avoid xrun
Jun 10 08:18:20 tiny-radiocd daemon.warn mpd: alsa_output: Decoder is too slow; playing silence to avoid xrun
Jun 10 08:18:25 tiny-radiocd daemon.warn mpd: alsa_output: Decoder is too slow; playing silence to avoid xrun
Jun 10 08:18:30 tiny-radiocd daemon.warn mpd: alsa_output: Decoder is too slow; playing silence to avoid xrun
Jun 10 08:18:35 tiny-radiocd daemon.warn mpd: alsa_output: Decoder is too slow; playing silence to avoid xrun
Jun 10 08:18:40 tiny-radiocd daemon.warn mpd: alsa_output: Decoder is too slow; playing silence to avoid xrun
Jun 10 08:18:45 tiny-radiocd daemon.warn mpd: alsa_output: Decoder is too slow; playing silence to avoid xrun
Jun 10 08:18:50 tiny-radiocd daemon.warn mpd: alsa_output: Decoder is too slow; playing silence to avoid xrun
Jun 10 08:18:55 tiny-radiocd daemon.warn mpd: alsa_output: Decoder is too slow; playing silence to avoid xrun
Jun 10 08:19:00 tiny-radiocd daemon.warn mpd: alsa_output: Decoder is too slow; playing silence to avoid xrun
Jun 10 08:19:05 tiny-radiocd daemon.warn mpd: alsa_output: Decoder is too slow; playing silence to avoid xrun
Jun 10 08:19:10 tiny-radiocd daemon.warn mpd: alsa_output: Decoder is too slow; playing silence to avoid xrun
Jun 10 08:19:15 tiny-radiocd daemon.warn mpd: alsa_output: Decoder is too slow; playing silence to avoid xrun
Jun 10 08:19:20 tiny-radiocd daemon.warn mpd: alsa_output: Decoder is too slow; playing silence to avoid xrun
Jun 10 08:19:25 tiny-radiocd daemon.warn mpd: alsa_output: Decoder is too slow; playing silence to avoid xrun
Jun 10 08:19:30 tiny-radiocd daemon.warn mpd: alsa_output: Decoder is too slow; playing silence to avoid xrun
Jun 10 08:19:34 tiny-radiocd daemon.notice mpd: player: played "cdda:///1"

[MaxKellermann]

@macmpi, the eject problem is due to a mistake in libcdio_paranoia; it checks for ENOMEDIUM https://github.com/rocky/libcdio-paranoia/blob/493702cfd256d34bc7197c24f00df0625dce47b5/lib/paranoia/paranoia.c#L3087= ... but on Linux, after ejecting the CD, the system call fails with EIO instead. Therefore, cdio_paranoia keeps on retrying, and because cdio_paranoia is a blocking library, there's no chance for MPD to get out of this loop. This is not fixable by MPD.

[MaxKellermann]

There are various improvements scheduled for 0.23.8 - please try that version as soon as it's out (later today).

[macmpi]

Thanks for the update & heads-up. Aside of the eject case, did the June 8th trace https://github.com/MusicPlayerDaemon/MPD/issues/1529#issuecomment-1150064913 bring some more relevant info on the initial use-case?

I won't have access to my test environment before mid-next week, so will fully test and report then. I'll try to check in the meantime on some other environment.

[macmpi]

Unfortunately it seems issue is still here with mpd 0.23.8. I attach a new strace of the supposedly culprit process. Let me know what you think, or any additional debug info needed. trace.txt

[MaxKellermann]

That's all that can be optimized inside MPD. The rest is just libcdio_paranoia being slow. What we can do is add an option to disable certain correction features, or to limit the number of retries. This gives up some audio quality; libcdio_paranoia's ultimate goal is pulling the best quality out of a (scratched) CD, but not being fast. For real-time playback, this may be overkill.

[macmpi]

Yes libcdio_paranoia is essentially meant for ripping exact samples rather than for listening, hence its overkill bias for data accuracy. That's why some other players (vlc, mpv & al) are using other libs to focus on actual playback. Being able to eventually tune current plugin parameter might be an interesting workaround (cache, retries, etc), as I assume changing lib would be too much of a rework.

[macmpi]

FWIW, in case it can help setting default settings & parameters for libcdio_paranoia, mpv's logic & defaults seem to work just fine.

 --cdda-cdtext                    Flag (default: no)
 --cdda-overlap                   Integer (0 to 75) (default: -1)
 --cdda-paranoia                  Integer (0 to 2) (default: 0)
 --cdda-sector-size               Integer (1 to 100) (default: 0)
 --cdda-skip                      Flag (default: yes)
 --cdda-span                      removed [deprecated]
 --cdda-span-a                    Integer (default: 0)
 --cdda-span-b                    Integer (default: 0)
 --cdda-speed                     Integer (1 to 100) (default: 0)
 --cdda-toc-bias                  Integer (default: 0)
 --cdda-toc-offset                Integer (default: 0)

[macmpi]

What we can do is add an option to disable certain correction features, or to limit the number of retries.

Would be nice indeed, leveraging above mpv default settings & 3-steps "mode" for instance: proved quite successful on my CD collection. Thanks for consideration.

[macmpi]

Thanks a lot! Will try as soon as I get back to my setup again. No sure doc explains what are the default values for mode & skip: I assume full paranoia & yes?

[macmpi]

Can confirm CDs play perfectly now with the following in mpd.conf:

input {
    plugin "cdio_paranoia"
    speed "8"
    mode "disable"
    skip "yes"
}

Thanks

[MaxKellermann]

Yay!

[macmpi]

can param values (in general) be within a variable, whose definition is included in another file? like:

include "other.conf"

input {
    plugin "cdio_paranoia"
    speed "$SPEED"
    mode "disable"
    skip "yes"
}

with

cat /etc/other.conf
SPEED="8"

[volumio]

Thanks to @MaxKellermann and @macmpi for the joint work in making CD playback better, this is a very welcome impro!