search

owntone / owntone-server

Linux/FreeBSD DAAP (iTunes) and MPD audio server with support for AirPlay 1 and 2 speakers (multiroom), Apple Remote (and compatibles), Chromecast, Spotify and internet radio.
https://owntone.github.io/owntone-server
GNU General Public License v2.0
2.04k stars 234 forks source link

"mpc enable only $foo" is very slow #778

Open ben-willmore opened 5 years ago

ben-willmore commented 5 years ago

On my network, I have two forked-daapd servers and a few speakers. The forked-daapd servers can see the speakers correctly:

$ mpc outputs
Output 48705 (Dining Room) is enabled
Output 25313 (Elise 3) is disabled
Output 52801 (Headphones) is disabled
Output 57966 (Sitting Room) is disabled

I can turn the speakers on (and off) correctly:

$ mpc enable "Dining Room"
Output 48705 (Dining Room) is enabled
Output 25313 (Elise 3) is disabled
Output 52801 (Headphones) is disabled
Output 57966 (Sitting Room) is disabled

However, if I try to select a single speaker, the command takes a long time to return, and usually fails with a timeout:

$ mpc enable only "Dining Room"
mpd error: Timeout

If I look in the forked-daapd debug log while this is happening, I see tens of thousands of lines like:

[2019-07-21 04:50:01] [ INFO]      mpd: New mpd client connection accepted
[2019-07-21 04:50:01] [DEBUG]      mpd: MPD message: outputs
[2019-07-21 04:50:01] [DEBUG]      mpd: Message incomplete, waiting for more data
[2019-07-21 04:50:01] [DEBUG]      mpd: Message incomplete, waiting for more data
(last line is repeated many times)
[2019-07-21 04:50:04] [DEBUG]      mpd: MPD message: command_list_begin
[2019-07-21 04:50:04] [DEBUG]      mpd: MPD message: disableoutput "0"
[2019-07-21 04:50:04] [DEBUG]      mpd: MPD message: disableoutput "1"
[2019-07-21 04:50:04] [DEBUG]      mpd: MPD message: disableoutput "2"
[2019-07-21 04:50:04] [DEBUG]      mpd: MPD message: disableoutput "3"
[2019-07-21 04:50:04] [DEBUG]      mpd: MPD message: disableoutput "4"
[2019-07-21 04:50:04] [DEBUG]      mpd: MPD message: disableoutput "5"
[2019-07-21 04:50:04] [DEBUG]      mpd: MPD message: disableoutput "6"
[2019-07-21 04:50:04] [DEBUG]      mpd: MPD message: disableoutput "7"
[2019-07-21 04:50:04] [DEBUG]      mpd: MPD message: disableoutput "8"
[2019-07-21 04:50:04] [DEBUG]      mpd: MPD message: disableoutput "9"
[2019-07-21 04:50:04] [DEBUG]      mpd: MPD message: disableoutput "10"
[2019-07-21 04:50:04] [DEBUG]      mpd: MPD message: disableoutput "11"
...
[2019-07-21 04:51:41] [DEBUG]      mpd: MPD message: disableoutput "50760"
[2019-07-21 04:51:41] [DEBUG]      mpd: MPD message: disableoutput "50761"
[2019-07-21 04:51:41] [DEBUG]      mpd: MPD message: disableoutput "50762"

It looks like forked-daapd is incorrectly maintaining a list of tens of thousands of outputs (I have no idea where these come from) and trying to turn each one off individually, which takes a long time to achieve. I wonder if this may be related to other performance issues I have noticed.

ben-willmore commented 5 years ago

I did a bit more investigation. As far as I can see, the MPD protocol doesn't support "only", and so this is actually implemented in mpc here (line 159 onward). I don't fully understand the code but it does seems to be looping from 1 to the highest output ID, leading to problems if the output IDs are large. I guess MPC is assuming that output IDs will always be small numbers, and that assumption is broken by forked-daapd.

I guess this could be fixed in forked-daapd by remapping the output IDs that are provided to mpc, but perhaps it is not a big deal.

I worked around this with a bash script which disables all outputs, then enables the desired one:

function disableall() {
  /usr/bin/mpc outputs | sed "s|.*(\(.*\)).*|\1|" | while read -r output; do
    /usr/bin/mpc disable "${output}"
  done
}

disableall
/usr/bin/mpc enable "${1}"

I can't see any evidence elsewhere that forked-daapd is maintaining a huge list of outputs, so my idea that this might be related to performance issues is probably wrong.

ejurgensen commented 5 years ago

Thanks for the report and the excellent investigation. It sounds like you have found the cause and the possible fix. The mpd part of forked-daapd is maintained by @chme so he will decide if this should be changed.

chme commented 5 years ago

I think, the best way to address this, would be to always save the outputs to the database. Right now it is only done at shutdown. This would allow to have an autoincrement key, that could be used as the output id for mpd clients.

This might also allow to get the current outputs without blocking the player thread by reading them always from the database.

ejurgensen commented 5 years ago

Yes, sounds like a good solution!

jshep321 commented 4 years ago

@beniamino38 I had a similar patch solution which I merged with yours. It enables me to type only part of the speaker name to enable (which could have conflicts, so caveat emptor). I also changed your loop to only repeat for each enabled speaker. (Note that the last 2 lines are the entirety of my spkon bash script.)

!/bin/bash

function disableall() { /usr/bin/mpc outputs | grep enabled | sed "s|.((.)).*|\1|" | while read -r output; do /usr/bin/mpc disable "${output}" done }

disableall

spk=$1 mpc enable `mpc outputs |grep -i $spk |awk {'print $2'}`