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.09k stars 234 forks source link

Forked-daadp pauses local playback for about half a sec when adding a song to the playlist #271

Closed LordMyschkin closed 8 years ago

LordMyschkin commented 8 years ago

I recently noticed that with the most recent version of foked-daadp, local playback stops for about half a second when adding a song to the playlist. I tried this from ympd and from mPad as client and a quite recent build of forked-daapd on the RasPi as server. I did not notice that before.

ejurgensen commented 8 years ago

How new a version are you using? Current master? Did release 24.1 also have the problem? tir. 28. jun. 2016 kl. 17.07 skrev LordMyschkin notifications@github.com:

I recently noticed that with the most recent version of foked-daadp, local playback stops for about half a second when adding a song to the playlist. I tried this from ympd and from mPad as client and a quite recent build of forked-daapd on the RasPi as server. I did not notice that before.

— You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub https://github.com/ejurgensen/forked-daapd/issues/271, or mute the thread https://github.com/notifications/unsubscribe/ABGmToG42lvoRNkopao3YmJFrB49BT9Gks5qQTiTgaJpZM4JAM9o .

LordMyschkin commented 8 years ago

Yes, I am on 24.1. The same happens via airplay, btw. Just rebuilding to check If I am hunting a ghost issue...

LordMyschkin commented 8 years ago

Yes, the actual master shows the same behavior; beside a big improvment in scanning speed at startup (wir filescan disabled, it used to scan 42 secs and takes now 14 secs - very impressive indeed).

ejurgensen commented 8 years ago

I've tested and I could reproduce this. I also checked the code, and as far as can tell a pause is made on purpose. This is in the mpd implementation (line 1152), so perhaps you can check this, @chme?

Below is a log snippet from my test. The "play -1" will pause for a short while.

BTW I also noted some interruptions when adding to the queue with Remote, but I think the cause here is something entirely different. In this case it is not purposeful behavior.

[2016-06-28 22:17:38] [DEBUG]      mpd: MPD message: add "file:/mnt/sandisk/Musik/Djosos Krost/No Sign Of Bad/03 Earthball.m4a"
[2016-06-28 22:17:38] [DEBUG]       db: Running query 'SELECT COUNT(*) FROM files f WHERE f.disabled = 0 AND f.disabled = 0 AND f.virtual_path LIKE '/file:/mnt/sandisk/Musik/Djosos Krost/No Sign Of Bad/03 Earthball.m4a%';'
[2016-06-28 22:17:38] [DEBUG]       db: Starting query 'SELECT f.* FROM files f WHERE f.disabled = 0 AND f.disabled = 0 AND f.virtual_path LIKE '/file:/mnt/sandisk/Musik/Djosos Krost/No Sign Of Bad/03 Earthball.m4a%' ORDER BY f.album_artist_sort ASC, f.album_sort ASC, f.disc ASC, f.track ASC;'
[2016-06-28 22:17:38] [DEBUG]   player: Player queue query returned 1 items
[2016-06-28 22:17:38] [DEBUG]   player: Added song id 1658 (Earthball)
[2016-06-28 22:17:38] [DEBUG]       db: End of query results
[2016-06-28 22:17:38] [DEBUG]      mpd: Listener callback called with event type 2.
[2016-06-28 22:17:38] [DEBUG]      mpd: Notify clients waiting for idle results: 2
[2016-06-28 22:17:38] [DEBUG]      mpd: MPD message: play "-1"
[2016-06-28 22:17:38] [DEBUG]   player: Player status: playing
[2016-06-28 22:17:38] [DEBUG]     raop: Building FLUSH for Stuen
[2016-06-28 22:17:38] [DEBUG]    xcode: Seek wanted 18392 ms, got 18390 ms
[2016-06-28 22:17:38] [DEBUG]   player: Callback from AirPlay to device_command_cb
[2016-06-28 22:17:38] [DEBUG]     main: Command has 0 pending events
[2016-06-28 22:17:38] [DEBUG]      mpd: Listener callback called with event type 1.
[2016-06-28 22:17:38] [DEBUG]     main: Got worker execute request
[2016-06-28 22:17:38] [DEBUG]  artwork: Artwork request for item 347
[2016-06-28 22:17:38] [DEBUG]       db: Running query 'SELECT COUNT(*) FROM files f WHERE f.disabled = 0 AND id = 347;'
[2016-06-28 22:17:38] [DEBUG]       db: Starting query 'SELECT f.* FROM files f WHERE f.disabled = 0 AND id = 347 ;'
[2016-06-28 22:17:38] [DEBUG]    cache: Running query 'SELECT a.format, a.data FROM artwork a WHERE a.type = 0 AND a.persistentid = 3912468264592325648 AND a.max_w = 600 AND a.max_h = 600;'
[2016-06-28 22:17:38] [DEBUG]      mpd: Listener callback called with event type 1.
[2016-06-28 22:17:38] [DEBUG]    cache: Cache hit: SELECT a.format, a.data FROM artwork a WHERE a.type = 0 AND a.persistentid = 3912468264592325648 AND a.max_w = 600 AND a.max_h = 600;
[2016-06-28 22:17:38] [DEBUG]  artwork: Artwork for group 3912468264592325648 found in source 'cache'
[2016-06-28 22:17:38] [DEBUG]       db: Running query 'SELECT COUNT(*) FROM files f WHERE f.disabled = 0 AND id = 347;'
[2016-06-28 22:17:38] [DEBUG]       db: Starting query 'SELECT f.* FROM files f WHERE f.disabled = 0 AND id = 347 ;'
[2016-06-28 22:17:38] [DEBUG]     raop: Building SET_PARAMETER for Stuen
[2016-06-28 22:17:38] [DEBUG]     raop: Building SET_PARAMETER for Stuen
[2016-06-28 22:17:38] [DEBUG]     raop: Building SET_PARAMETER for Stuen
[2016-06-28 22:17:38] [DEBUG]      mpd: Notify clients waiting for idle results: 1
[2016-06-28 22:17:38] [DEBUG]      mpd: Notify clients waiting for idle results: 1
[2016-06-28 22:17:38] [DEBUG]      mpd: MPD message: status
[2016-06-28 22:17:38] [DEBUG]   player: Player status: playing (buffering)
[2016-06-28 22:17:38] [DEBUG]      mpd: MPD message: playlistinfo "-1"
[2016-06-28 22:17:38] [DEBUG]      mpd: Command 'playlistinfo' called with pos < 0 (arg = '-1'), ignore arguments and return whole queue
chme commented 8 years ago

I will check this evening, maybe i introduced this error by the refactoring of the commands execution.

chme commented 8 years ago

Sorry for the late response. I could only reproduce the error using Retune. Adding songs to the queue with mpd clients (mpc, MPDroid) did not lead to a pause in playback on my setup. I hope to have some time this weekend to take another look at it.

I created a pull request to address the "play -1" command @ejurgensen did notice in the log (is it from MPoD?). But i don't think it will fix the issue for ympd.

LordMyschkin commented 8 years ago

It seems it did indeed fix the issue - today (sorry, I do not often have time to play music) . No problems adding a song now - I recommend closing this issue if ejurgensen can also confirm the problem is gone.

chme commented 8 years ago

I am a bit surprised, that the change fixed the issue for ympd. May i ask which branch of ympd you are using (i tested with notandy's master branch)?

LordMyschkin commented 8 years ago

I tested with the same ympd version as you used, the most recent forked-daadp undmit mPAD and mPOD. No problem anywhere. Maybe it was something completly else, resolved through my updating raspian or upgrading my network card.