Page 1 of 2

MPD slow startup

Posted: March 25th, 2020, 7:32 pm
by skidoo

Code: Select all

# systemd-analyze blame
26.866s mpd.service 
 7.026s systemd-logind.service 
 5.606s systemd-journald.service
 5.216s systemd-networkd-wait-online.service
 4.840s systemd-networkd.service  
(...)
MPD from git, compiled with GCC 10 on Debian testing, x64, headless, Atom CPU, 1.66 GHz, > 180.000 tracks on local SATA harddrive. Startup time ok or something to worry?

Re: MPD slow startup

Posted: March 26th, 2020, 12:48 pm
by max
26s doesn't look OK at all. What is it waiting for? Maybe strace would show the timings?

Re: MPD slow startup

Posted: March 26th, 2020, 6:59 pm
by skidoo
MPD takes more than 9 seconds to write out its pid. /run is located on tmpfs less the 3 MB in use from 94 MB.

Code: Select all

 # strace -r /usr/local/bin/mp
 (...) 
     0.000137 setgroups(1, [29])        = 0
     0.000257 getuid()                  = 0
     0.000186 setuid(109)               = 0
     0.000179 chdir("/")                = 0
     0.000213 openat(AT_FDCWD, "/run/mpd/pid", O_WRONLY|O_CREAT|O_NOCTTY|O_TRUNC|O_CLOEXEC, 0666) = 12
     0.000324 pipe([13, 14])            = 0
     0.000273 clone(child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7fb4d8a36410) = 7243
     0.003387 close(14)                 = 0
     0.000470 read(13, "\0\0\0\0", 4)   = 4
     9.037524 write(12, "7243\n", 5)    = 5
     0.000555 close(12)                 = 0
     0.006477 munmap(0x7fb4e73f0000, 16384) = 0
     0.005147 exit_group(0)             = ?
     0.012170 +++ exited with 0 +++

Re: MPD slow startup

Posted: March 29th, 2020, 4:02 pm
by max
You should use the strace `-T` flag to show system call durations.
This strace doesn't give enough information because it is with daemonization enabled - try `mpd --no-daemon` instead.

Re: MPD slow startup

Posted: March 29th, 2020, 6:45 pm
by skidoo
About 35 M text output. Where to put?

Lots of stat eg

Code: Select all

stat("/C64Music/MUSICIANS/H/Hubbard_Rob/Thrust.sid", {st_mode=S_IFREG|0644, st_size=3710, ...}) = 0 <0.000045>

Re: MPD slow startup

Posted: March 30th, 2020, 10:17 am
by max
If it stats all your music files, then it updates the database - this can mean that MPD can't save the database or you didn't configure a database file. Check your configuration!

Re: MPD slow startup

Posted: March 30th, 2020, 3:19 pm
by skidoo

Code: Select all

database {
	plugin		"simple"
	path			"/var/lib/mpd/tag_cache"
	compress		"yes"
}

Code: Select all

$ ls -la /var/lib/mpd/
-rw-r--r--  1 mpd  audio 6285026 Mär 29 20:20 tag_cache
Deleting and rebuilding database takes way longer than 30 seconds for its >180k tracks. Partition is mounted with ext4 fs and nosuid,noatime options.

Re: MPD slow startup

Posted: March 30th, 2020, 3:41 pm
by max
Ok, next idea: do you happen to have `auto_update` enabled?

Re: MPD slow startup

Posted: March 30th, 2020, 4:00 pm
by skidoo

Code: Select all

auto_update                     "yes"
#auto_update_depth "3"

Re: MPD slow startup

Posted: March 30th, 2020, 4:03 pm
by max
That's it.
For auto_update to work, MPD needs to scan all directories on startup - unfortunately, there is no other way, because that's how Linux's inotify works.
Disable it, and the delay will be gone.

Re: MPD slow startup

Posted: March 30th, 2020, 5:14 pm
by skidoo

Code: Select all

$  systemd-analyze blame
13.394s mpd.service
 7.234s e2scrub_reap.service
 7.124s systemd-logind.service
 5.423s systemd-journald.service
 4.890s systemd-networkd.service
 3.797s systemd-networkd-wait-online.service
Better now. Thank you, Max!

Re: MPD slow startup

Posted: March 30th, 2020, 5:28 pm
by max
13s is still extremely slow. It shouldn't take longer than a second or so. If you upload a strace (with `-tttT`) somewhere, I'll check it out.

Re: MPD slow startup

Posted: March 31st, 2020, 6:51 am
by skidoo

Re: MPD slow startup

Posted: March 31st, 2020, 12:13 pm
by max
MPD spends nearly 10 seconds reading the database file (which is 6.2 MB, compressed). One thing you could try is patch the following line in the MPD source code:

https://github.com/MusicPlayerDaemon/MP ... er.hxx#L48

Change the 4096 to 65536. This will reduce I/O overhead, and may speed up MPD startup. Upload another strace with that setting.

I think this will not be enough - another candidate would be gzip decompression, but your CPU should be fast enough.
Which settings did you use to compile MPD? With debugging, with compiler optimization?
It might be helpful to see a "perf report", i.e. start MPD with "perf record mpd --no-daemon", let it finish startup, Ctrl-C to stop it, then "perf report >report.txt" and upload that file.

Re: MPD slow startup

Posted: March 31st, 2020, 3:53 pm
by skidoo
64k buffer strace https://paste.ee/p/l3Gj0

Code: Select all

$ systemd-analyze blame
13.399s mpd.service
 7.004s systemd-logind.service
 5.504s systemd-networkd-wait-online.service 
 5.471s systemd-journald.service
 4.785s systemd-networkd.service
 3.116s dev-sda1.device
 2.990s systemd-resolved.service
 2.690s systemd-timesyncd.service     
Sorry, no improvement.

perf report https://paste.ee/p/Uk3pI

Build Options

Code: Select all

$ meson . output -Dadplug=disabled -Dalsa=enabled -Dao=disabled -Daudiofile=enabled -Dbzip2=enabled -Dcdio_paranoia=disabled -Dcue=true -Dcurl=enabled -Ddatabase=true -Ddbus=enabled -Ddocumentation=false -Ddsd=false -Dexpat=enabled -Dfaad=enabled -Dffmpeg=enabled -Dfifo=true -Dflac=enabled -Dfluidsynth=enabled -Dgme=enabled -Dhttpd=true -Diconv=enabled -Dicu=enabled -Did3tag=enabled -Dinotify=true -Dipv6=disabled -Diso9660=enabled -Djack=disabled -Dlame=enabled -Dlibmpdclient=enabled -Dlibsamplerate=enabled  -Dlocal_socket=true -Dmad=enabled -Dmikmod=enabled -Dmms=enabled -Dmodplug=enabled -Dmpcdec=enabled -Dmpg123=enabled -Dneighbor=true -Dnfs=disabled -Dopenal=disabled -Dopus=enabled -Doss=disabled -Dpipe=true -Dpulse=disabled -Dqobuz=disabled -Drecorder=false -Dshine=disabled -Dshout=disabled -Dsidplay=enabled -Dsmbclient=disabled -Dsndfile=enabled -Dsndio=disabled -Dsolaris_output=disabled -Dsoundcloud=disabled -Dsoxr=enabled -Dsqlite=enabled -Dsyslog=enabled -Dsystemd=enabled -Dtcp=true -Dtest=false -Dtidal=disabled -Dtwolame=disabled -Dudisks=enabled -Dupnp=disabled -Dvorbis=enabled -Dvorbisenc=enabled -Dwave_encoder=false -Dwavpack=enabled -Dwebdav=disabled -Dwildmidi=enabled -Dyajl=disabled -Dzeroconf=avahi -Dzlib=enabled -Dzzip=enabled --includedir=/usr/local/include --infodir=/usr/local/share/info --libdir=/usr/local/lib/x86_64-linux-gnu --libexecdir=/usr/local/lib/x86_64-linux-gnu --localstatedir=/var --mandir=/usr/local/share/man --sysconfdir=/etc --buildtype=release -Db_ndebug=true

Re: MPD slow startup

Posted: March 31st, 2020, 4:22 pm
by max
Loading the database was 0.5 seconds faster, so there was an improvement, but a small one compared to the rest of your performance problem.
But your perf report gave me some hints on what to optimize. Since your music database is a lot larger than mine, and larger datasets are better for profilers, it could be helpful to have your database file - please send it to me (you can find my email address in the imprint).

Re: MPD slow startup

Posted: March 31st, 2020, 5:23 pm
by skidoo
Database is on its way.

Re: MPD slow startup

Posted: April 2nd, 2020, 4:27 pm
by max
MPD 0.21.22 and git master have a few optimizations, but there will be more.

Re: MPD slow startup

Posted: April 2nd, 2020, 5:11 pm
by skidoo
Already 20% faster startup :)

Re: MPD slow startup

Posted: April 24th, 2020, 7:04 pm
by max
More optimizations in git master.