armv7l docker image: high cpu usage caused by "Error in pthread_cond_timedwait: 22"

[Hajuskin]

myMPD version: 6.11.0+

Describe the bug

I'm using myMPD in Docker on a Raspi 4 4GB. Since version 6.11.0 the log is flooded with "webserver Error in pthread_cond_timedwait: 22"-messages and the CPU usage is up to 50% when the page is opened in a browser.

To Reproduce

Just start myMPD 6.11.0+ in Docker

Server plattform (please complete the following information):

OS Information: linux armv7l Raspbian GNU/Linux 10 (buster)
Kernel Version: 5.10.11-v7l+
Total CPU: 4
Total memory: 4 GB

Docker Version: 20.10.3 (API: 1.41)

Debug logs (please attach if it can be usefull)

• myMPD debug log
  Log without webpage opened:

2021-02-19T18:54:57.662261364Z ERROR    mympdapi  nsec: 100000
2021-02-19T18:54:57.694269339Z ERROR    mpdworker Error in pthread_cond_timedwait: 22
2021-02-19T18:54:57.695945838Z ERROR    webserver Error in pthread_cond_timedwait: 22
2021-02-19T18:54:57.697115997Z ERROR    mpdclient Error in pthread_cond_timedwait: 22
2021-02-19T18:54:57.744559491Z ERROR    mpdworker Error in pthread_cond_timedwait: 22
2021-02-19T18:54:57.746112641Z ERROR    webserver Error in pthread_cond_timedwait: 22
2021-02-19T18:54:57.747271948Z ERROR    mpdclient Error in pthread_cond_timedwait: 22
2021-02-19T18:54:57.762378327Z ERROR    mympdapi  Error in pthread_cond_timedwait: 22
2021-02-19T18:54:57.762454399Z ERROR    mympdapi  nsec: 100000
...

Log with webpage open:

2021-02-19T18:42:58.614184294Z ERROR    webserver Error in pthread_cond_timedwait: 22
2021-02-19T18:42:58.614473214Z ERROR    webserver Error in pthread_cond_timedwait: 22
2021-02-19T18:42:58.615233366Z ERROR    webserver Error in pthread_cond_timedwait: 22
2021-02-19T18:42:58.615332141Z ERROR    webserver Error in pthread_cond_timedwait: 22
2021-02-19T18:42:58.615369418Z ERROR    webserver Error in pthread_cond_timedwait: 22
2021-02-19T18:42:58.615419065Z ERROR    webserver Error in pthread_cond_timedwait: 22
2021-02-19T18:42:58.615443324Z ERROR    webserver Error in pthread_cond_timedwait: 22
2021-02-19T18:42:58.615790928Z ERROR    webserver Error in pthread_cond_timedwait: 22
2021-02-19T18:42:58.615887408Z ERROR    webserver Error in pthread_cond_timedwait: 22
2021-02-19T18:42:58.616141810Z ERROR    webserver Error in pthread_cond_timedwait: 22
2021-02-19T18:42:58.616213734Z ERROR    webserver Error in pthread_cond_timedwait: 22
2021-02-19T18:42:58.616499691Z ERROR    webserver Error in pthread_cond_timedwait: 22
2021-02-19T18:42:58.616574412Z ERROR    webserver Error in pthread_cond_timedwait: 22
2021-02-19T18:42:58.616879591Z ERROR    webserver Error in pthread_cond_timedwait: 22
2021-02-19T18:42:58.616983922Z ERROR    webserver Error in pthread_cond_timedwait: 22
2021-02-19T18:42:58.617316360Z ERROR    webserver Error in pthread_cond_timedwait: 22
2021-02-19T18:42:58.617355063Z ERROR    webserver Error in pthread_cond_timedwait: 22
2021-02-19T18:42:58.617681260Z ERROR    webserver Error in pthread_cond_timedwait: 22
...

Configuration (please attach if it can be usefull)

• /etc/mympd.conf

# myMPD configuration file
#
# SPDX-License-Identifier: GPL-2.0-or-later
# myMPD (c) 2018-2021 Juergen Mang <mail@jcgames.de>
# https://github.com/jcorporation/mympd
#

[mpd]
#Connection to mpd, unix socket or host/port, socket preferred
#host = /run/mpd/socket
#host = 127.0.0.1
#port = 6600
pass = 
host = /run/mpd/socket

#absolut path of music_directory of mpd
#none = no local music_directory
#auto = get music_directory from mpd (only supported, if connected to mpd socket)
musicdirectory = /music/

#absolut path of mpd playlist_directory
playlistdirectory = /playlists/
#MPD compiled with regex support
regex = true

[webserver]
#Webserver options
webport = 8082

#Enable ssl
#Certificates are generated under /var/lib/mympd/ssl/
ssl = false
sslport = 443

#Publishes some mpd and myMPD directories
publish = true

#Webdav support, publish must be set to true
webdav = false

[mympd]
Loglevel
#0 = error
#1 = warn
#2 = info
#3 = verbose
#4 = debug
loglevel = 3

#myMPD user
#group is the primary group of this user
user = mympd

#Usage of stickers for play statistics
stickers = true

#Mixrampdb settings in gui
mixramp = false

#Enable system commands defined in syscmds section
syscmds = false

#Enable lua scripting
scripting = false

#Chroot to /var/lib/mympd
chroot = false
readonly = false

[syscmds]
Shutdown = sudo /sbin/halt
#To use this command add following lines to /etc/sudoers (without #)
#Cmnd_Alias MYMPD_CMDS = /sbin/halt
#mympd ALL=NOPASSWD: MYMPD_CMDS

Additional context

Aside the high CPU usage and log entries it still works fine, but with the last good version 6.10.0 the CPU usage hardly reaches 5% when in use.

[jcorporation]

Strange issue, I have not changed anything in the threading code.

Why do you not use an aarch64 based image?

CPU usage goes high because of the failing mutex waits.

myMPD runs fine in my test environments - dietpi 32bit, alpine aarch64, both on raspberry 4. But I do not use docker.

[Hajuskin]

I'm running 32-bit Raspberry OS because when setting up my system there was (and still is?) no official 64-bit version.
I must correct myself, this behaviour started with version 6.11.1, I just tested 6.11.0 and the image won't start in docker.
This is the error message from docker:
ERROR: for mympd Cannot start service mympd: OCI runtime create failed: container_linux.go:370: starting container process caused: exec: "/usr/bin/mympd": stat /usr/bin/mympd: no such file or directory: unknown
Don't know if this is related or helpful.

[jcorporation]

It seems the 6.11.0 docker image is defect. Docker does not find the myMPD executable.

Any other changes in your environment? The queue code that is failing was not touched for a long time.

[Hajuskin]

I'm just switching the myMPD docker images, nothing else is changed.

Is it possible that the Alpine Linux on which the image is based on has changed something?

[jcorporation]

The myMPD docker images are based on the latest alpine linux image. This release changes the definition of time_t on 32-bit systems.

Read https://wiki.alpinelinux.org/wiki/Release_Notes_for_Alpine_3.13.0#time64_requirements for further information.

Nothing to fix in the myMPD source code besides better error handling.

I can reproduce the error with myMPD from the 6.12.0 branch. The error handling is now improved and myMPD throws the following error and aborts.

01:18:56 ERROR    webserver /myMPD/src/tiny_queue.c:89: Error getting realtime: Operation not permitted

Not getting the realtime causes invalid arguments for pthread_cond_timedwait.

Afterwards I changed the seccomp profil as described in the link above and myMPD works like a charm.

[Hajuskin]

Sounds promising! Is there something I could test? (preferably without building the docker image myself :D )

[jcorporation]

You must reconfigure your docker daemon to run images based on alpine linux 3.13.x

[Hajuskin]

But I guess this would have no effect on myMPD 6.11.+?

[jcorporation]

All myMPD versions should run with the correct docker configuration. It is not a problem of myMPD. I implemented only correct failure handling. myMPD 6.12.0 does also not run without fixing the docker configuration as described in the link. The root cause is also described there.

Therefore, the following platforms are not suitable as Docker hosts for 32-bit Alpine Linux 3.13.0, due to containing out-of-date libseccomp: Amazon Linux 1 or 2, CentOS 7 or 8, Debian stable without debian-backports, Raspbian stable, Ubuntu 14.04 or earlier, and Windows.

[Hajuskin]

Thanks a lot, finaly got it working. Took a while to figure out that i put "--seccomp-profile=default.json" at the wrong location, but now myMPD 6.11.3 is running at ~0,5% cpu :)