Bugzilla – Bug 3401
Sync broken in Random Mix playback
Last modified: 2008-09-15 14:39:24 UTC
Sync'd playback is broken when using Random Mix playback using two SB2s. At the end of each track the players initially begin playback of the next track w/o issue. A few seconds into the next track one or both players will stop playback. After a second or two, playback will resume, but is often unsynchronized after this occurs. Between the dropouts and loss of sync, it makes this mode basically unusable. My suspicion is that the database call to load up a new track at the end of the Random Mix playlist is bogging down the server and starving the players. Timing may be a factor, as the new track probably hasn't time to load up in buffer when the starvation occurs. And when the players recover, they do so at different rates and don't resync. In the past, I've successfully worked around this by disabling the option to "Add new items when old ones finish". Since 6.5b this doesn't seem to work, at least when Random Mix is invoked from the player interface. Server: WinXP SP2 Athlon XP 2.4 1GB RAM ~50,000 tracks, mixed FLAC and MP3 Network: SlimServer is wired 100Mbps Ethernet SB2s are wireless 802.11g No issues when using other playback modes SlimServer: problem has been present over various versions including the all 6.x versions tried. Suggestions for resolution: 1) Investigate and fix performance issue when adding new songs to a Random Mix playlist. Consider using a new SQL call optimized for this purpose. 2) Change the timing of the add new song function. If this call were delayed until after the buffers had filled the problem might be resolved (at least for SB2 and SB3 users). Alternately, consider making the call a few seconds before the previous track ends. 3) Detect buffer underruns on the players and, if playing sync'd, perform a resync upon restart of playback. This behavior might correct some other sync issues as well. 4) Fix the disabling of the Random Mix "Add new items when old ones finish" feature as a workaround. If there are any log captures that would help you evaluate this issue, please let me know and I'll try to provide.
Interesting. I've seen exactly this behaviour with synced playback but never linked it with random mix. I just put it down to syncing not really working with my setup and stopped trying to use sync. I can't confirm whether or not this issue is related to random mix, but it certainly sounds plausible. You could try switching to the split scanner branch as Dan has already stated that this contains some much optimised random mix code.
as of change 7412, the option to add songs should disable properly (at least it did for my tests). please update svn or try the May 13 build.
Thanks kdf. Confirming that disabling "Add new items when old ones finish" is now functional in v6.5b1 - 7412. This provides a usable workaround for this issue. Very helpful. I'm on the 6.5b1 branch, not split-scanner. Not seeing significant changes in 6.5b1 in the SQL select performance. Enabling "Add new items when old ones finish" continues to cause the issue. Logging d_sql, d_stream and d_sync shows as below at track transition. Looks like there is some level of buffer fullness required before players are unpaused. Not sure what units the 131072 number is in or how that would translate to seconds of playback when streaming FLAC. Given current query times on my install, it would probalby take about 5 to 8 seconds to safely buffer through the starvation. Perhaps waiting for a larger initial buffer fullness value, and/or waiting a few seconds after unpausing players to run SQL, would help alleviate the issue. 00:04:20:05:a4:2c has run out of data, checking to see if we can push on... 00:04:20:05:a4:2c has run out of data, checking to see if we can push on... 00:04:20:05:ac:69 has run out of data, checking to see if we can push on... everybody's run out of data. Let's start them up... 00:04:20:05:ac:69 checking buffer fullness: 0 00:04:20:05:ac:69 checking buffer fullness: 0 00:04:20:05:ac:69 checking buffer fullness: 0 00:04:20:05:ac:69 checking buffer fullness: 0 00:04:20:05:ac:69 checking buffer fullness: 0 00:04:20:05:ac:69 checking buffer fullness: 0 00:04:20:05:ac:69 checking buffer fullness: 0 00:04:20:05:ac:69 checking buffer fullness: 0 00:04:20:05:ac:69 checking buffer fullness: 0 00:04:20:05:a4:2c checking buffer fullness: 0 00:04:20:05:a4:2c checking buffer fullness: 0 00:04:20:05:a4:2c checking buffer fullness: 0 00:04:20:05:a4:2c checking buffer fullness: 0 00:04:20:05:a4:2c checking buffer fullness: 0 00:04:20:05:a4:2c checking buffer fullness: 0 00:04:20:05:a4:2c checking buffer fullness: 0 00:04:20:05:a4:2c checking buffer fullness: 0 00:04:20:05:ac:69 checking buffer fullness: 0 00:04:20:05:a4:2c checking buffer fullness: 0 00:04:20:05:ac:69 checking buffer fullness: 131072 00:04:20:05:ac:69 is ready to sync 1147545740.17953 00:04:20:05:a4:2c checking buffer fullness: 131072 00:04:20:05:a4:2c is ready to sync 1147545740.18083 all clients ready to sync now. unpausing them. Running SQL query: [SELECT DISTINCT genres.id AS id,genres.name AS name,genres.namesort AS namesort,genres.moodlogic_id AS moodlogic_id,genres.moodlogic_mixable AS moodlogic_mixable,genres.musicmagic_mixable AS musicmagic_mixable FROM genres ] Start and End node: [default:default] Start and End node: [genre:default] Field query. Need additional join. start and End node: [genre:genre] Running SQL query: [SELECT DISTINCT tracks.id AS id,tracks.url AS url,tracks.content_type AS content_type,tracks.title AS title,tracks.titlesort AS titlesort,tracks.titlesearch AS titlesearch,tracks.album AS album,tracks.tracknum AS tracknum,tracks.timestamp AS timestamp,tracks.customsearch AS customsearch,tracks.filesize AS filesize,tracks.tag AS tag,tracks.disc AS disc,tracks.thumb AS thumb,tracks.remote AS remote,tracks.audio AS audio,tracks.audio_size AS audio_size,tracks.audio_offset AS audio_offset,tracks.year AS year,tracks.secs AS secs,tracks.cover AS cover,tracks.vbr_scale AS vbr_scale,tracks.bitrate AS bitrate,tracks.samplerate AS samplerate,tracks.samplesize AS samplesize,tracks.channels AS channels,tracks.block_alignment AS block_alignment,tracks.endian AS endian,tracks.bpm AS bpm,tracks.tagversion AS tagversion,tracks.drm AS drm,tracks.moodlogic_id AS moodlogic_id,tracks.moodlogic_mixable AS moodlogic_mixable,tracks.musicmagic_mixable AS musicmagic_mixable,tracks.musicbrainz_id AS musicbrainz_id,tracks.playcount AS playcount,tracks.lastplayed AS lastplayed,tracks.lossless AS lossless,tracks.lyrics AS lyrics,tracks.rating AS rating,tracks.replay_gain AS replay_gain,tracks.replay_peak AS replay_peak FROM tracks, genre_track, genres WHERE genre_track.track = tracks.id AND genres.id = genre_track.genre AND ( tracks.audio = ? ) ORDER BY RANDOM() LIMIT 2] Bind arguments: [1] Start and End node: [default:default] Start and End node: [default:default] Running SQL query: [SELECT DISTINCT tracks.id AS id,tracks.url AS url,tracks.content_type AS content_type,tracks.album AS album FROM tracks, albums WHERE albums.id = tracks.album AND ( tracks.audio = ? AND tracks.id = ? ) ORDER BY albums.titlesort, tracks.disc, tracks.tracknum, tracks.titlesort] Bind arguments: [1, 41722]
SlimServer Version: 6.5b1 - 8199 - Windows XP - EN - cp1252 I synced two players, selected random mix, and hit play. They sync'd just fine! In other words I was unable to verify this bug... You say you saw this on other 6.x versions, did you try 6.3.0? Could you try your players over ethernet and see if they still do not sync properly? What is the make / model number / firmware version of your wireless router/access point?
As noted in original post, sync issue doesn't occur for me until the random mix progresses to a new track. Even then it occurs somewhat intermittently, and only when the "Add new items when old ones finish" option is set. Please confirm that your testing covered these conditions.
Does something in the RandomMix plugin need to be aware of sync?
hi I use a linksys NSLU2 for serving. while this is probably the smallest working platform, it does work, even crossfades. however, Random Mix exhibits the exact symptoms described above (first 2-5 seconds of the next track play fine, then it stops for 5 secs, plays 1 sec, stops again for 2 seconds, then plays the rest of the song fine). This behavior only happens when I skip a track manually, even after pausing. I play FLAC files, only one SB2 involved, no syncing or whatsoever. I suspect that switching a track manually provokes some action on the database which lets the buffer run dry... regards nicola
Andy - could your fix for the STAT race condition have fixed this as well? Thanks
I don't think so, the symptom of the race condition is that the next track fails to start at all. This one sounds like that large DB query is blocking the server for too long.
So I just did a bunch of testing on 6.5, with the most recent code (post split-scanner merge) - and sync works for me. The addition of tracks to the list is done when the last track in the list starts playing - so there's plenty of buffer room. The SQL query is as optimized as it can be (with the genre limiting): 2006-07-31 13:56:48.2264 SELECT me.id, me.url, me.content_type, me.title, me.titlesort, me.titlesearch, me.album, me.tracknum, me.timestamp, me.filesize, me.tag, me.disc, me.thumb, me.remote, me.audio, me.audio_size, me.audio_offset, me.year, me.secs, me.cover, me.vbr_scale, me.bitrate, me.samplerate, me.samplesize, me.channels, me.block_alignment, me.endian, me.bpm, me.tagversion, me.drm, me.moodlogic_id, me.moodlogic_mixable, me.musicmagic_mixable, me.musicbrainz_id, me.playcount, me.lastplayed, me.lossless, me.lyrics, me.rating, me.replay_gain, me.replay_peak FROM tracks me LEFT JOIN genre_track genreTracks ON ( genreTracks.track = me.id ) WHERE ( audio = ? AND genreTracks.genre IN ( ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ? ) ) ORDER BY RAND() LIMIT 1: '1', '11', '21', '7', '17', '2', '22', '18', '16', '13', '6', '3', '9', '20', '14', '15', '4', '19', '10', '5' 2006-07-31 13:56:48.2768 RandomPlay: Find returned 1 items Which took 0.0504 seconds