Bugzilla – Bug 7695
synced players hanging on random mix
Last modified: 2009-09-08 09:16:31 UTC
a consistent problem in my system when my slimp3 and sb2 are in sync: when i select any dynamic playlist or use the built-in random mix option the system temporarily hangs before playing each song. the hang time varies between 5-10 secs and occasionally the system goes into full pause mode and does not return to playing. Also, sometimes a song starts playing and then after a couple of seconds it then hangs. This problem so far has only shown itself when my players are in sync.
Greg: Can you please turn DEBUG logging on for the the following; 1) (player.sync) - Multi-Player Synchronization Logging 2) (player.streaming) - All Player Streaming Logging Once the error has occurred, stop SC, then attach the server.log to this bug. Also include the info from your Status Page please.
Please also add player.source at level info to that trace specification. How are the players connected to the SC - wired or wireless?
Greg: can you help us out here?
(In reply to comment #1) > Greg: Can you please turn DEBUG logging on for the the following; > 1) (player.sync) - Multi-Player Synchronization Logging > 2) (player.streaming) - All Player Streaming Logging > > Once the error has occurred, stop SC, then attach the server.log to this bug. > > Also include the info from your Status Page please. > I'm currently at work so I will give this information to you asap.
(In reply to comment #2) > Please also add player.source at level info to that trace specification. > > How are the players connected to the SC - wired or wireless? > both players are hard wired. The sb2 is hard wired directly from my buffalo router but the slimp3 is hard wired through a netgear xe102 homeplug.
(In reply to comment #4) > (In reply to comment #1) > > Greg: Can you please turn DEBUG logging on for the the following; > > 1) (player.sync) - Multi-Player Synchronization Logging > > 2) (player.streaming) - All Player Streaming Logging > > > > Once the error has occurred, stop SC, then attach the server.log to this bug. > > > > Also include the info from your Status Page please. > > > here's the log: > [08-04-03 06:49:13.0919] Slim::Player::Sync::checkSync (675) 00:04:20:05:cb:33 resync: skipAhead 456ms [08-04-03 06:49:14.0756] Slim::Player::Player::apparentStreamStartTime (864) 00:04:20:04:15:b1 apparentStreamStartTime: 1207230546.13266 @ 1207230554.0462 timePlayed:7.91353782231459 (bytesReceived:252760 bufferFullness:1860) [08-04-03 06:49:15.0713] Slim::Player::Player::trackJiffiesEpoch (818) 00:04:20:05:cb:33 adjust jiffies epoch +0.005s [08-04-03 06:49:24.0037] Slim::Player::Player::trackJiffiesEpoch (794) 00:04:20:05:cb:33 adjust jiffies epoch -0.004s HTTP/1.1 200 OK Server: SqueezeCenter (7.0.1 - 17957) Connection: keep-alive Date: Thu, 03 Apr 2008 13:49:46 GMT Content-Length: 566 Content-Type: text/plain [08-04-03 06:49:13.0919] Slim::Player::Sync::checkSync (675) 00:04:20:05:cb:33 resync: skipAhead 456ms [08-04-03 06:49:14.0756] Slim::Player::Player::apparentStreamStartTime (864) 00:04:20:04:15:b1 apparentStreamStartTime: 1207230546.13266 @ 1207230554.0462 timePlayed:7.91353782231459 (bytesReceived:252760 bufferFullness:1860) [08-04-03 06:49:15.0713] Slim::Player::Player::trackJiffiesEpoch (818) 00:04:20:05:cb:33 adjust jiffies epoch +0.005s [08-04-03 06:49:24.0037] Slim::Player::Player::trackJiffiesEpoch (794) 00:04:20:05:cb:33 adjust jiffies epoch -0.004s [08-04-03 06:49:59.0075] Slim::Player::Player::trackJiffiesEpoch (818) 00:04:20:05:cb:33 adjust jiffies epoch +0.003s SqueezeCenter Status Information on all identified devices connected to SqueezeCenter Library statistics Total Tracks: 8,661 Total Albums: 690 Total Artists: 307 Total Genres: 41 Total Playing Time: 636:41:31 Music Scan Details ( of ) ( of ) ( of ) ( of ) ( of ) ( of ) ( of ) ( of ) ( of ) ( of ) ( of ) Progress information from the previous scan is not available. SqueezeCenter Information SqueezeCenter Version: 7.0.1 - 17957 - Mac OS X 10.4.10 (8R218) - EN - utf8 Server IP address: 192.168.11.5 Perl Version: 5.8.6 darwin-thread-multi-2level MySQL Version: 5.0.22-standard Platform Architecture: ppc Hostname: G4-5.local Server Port Number: 9000 Total Players Recognized: 2 Cache Folder: /Users/gregoryj/Library/Caches/SlimServer Preferences Folder: /Users/gregoryj/Library/Application Support/SqueezeCenter Plugin Folders: /Library/PreferencePanes/SqueezeCenter.prefPane/Contents/server/Slim/Plugin, /Users/gregoryj/Library/Application Support/SqueezeCenter/Plugins, /Library/Application Support/SqueezeCenter/Plugins, /Library/PreferencePanes/SqueezeCenter.prefPane/Contents/server/Plugins Player Information Name: Bedroom Model: slimp3 Firmware: 2.3 The IP address for this player is: 192.168.11.6:3483 The ethernet MAC address for this player is: 00:04:20:04:15:b1 Name: homebase Model: squeezebox2 Firmware: 86 The IP address for this player is: 192.168.11.2:44602 The ethernet MAC address for this player is: 00:04:20:05:cb:33 SqueezeCenter Log File SqueezeCenter keeps a log file for all application related activities (Audio Streaming, Infrared, etc) here: /Users/gregoryj/Library/Logs/SqueezeCenter/server.log Scanner Log File SqueezeCenter keeps a log file for all scanning related activities, including iTunes & MusicIP here: /Users/gregoryj/Library/Logs/SqueezeCenter/scanner.log
I am having the exact same issue after upgrading to 7.0: Here is my setup: SqueezeCenter on Microsoft Windows XP SP2 Transporter: Hardwired Squeezebox: Wireless connection ReadyNAS storage Music, WMA Lossless.
Mark, is that an original Squeezebox (v1) or a Squeezebox 2 or Squeezebox v3? Please enable logging for player.sync=debug and player.source=info and attach the resulting logfile to this bug report. Please describe when you hear the problem (the name of the track). Can you confirm that you are using SC 7.0 final and not a pre-release version.
James, Please enable logging for player.sync=debug and player.source=info and attach the resulting logfile to this bug report (better to upload as an attachment rather than include in the comments). Please include a larger portion of the logfile, preferably covering from the start of one track all the way through to the start of the next where you hear the problem. Please describe when you hear the problem (the name of the track). Thanks, Alan.
(In reply to comment #8) > Mark, is that an original Squeezebox (v1) or a Squeezebox 2 or Squeezebox v3? > Please enable logging for player.sync=debug and player.source=info and attach > the resulting logfile to this bug report. Please describe when you hear the > problem (the name of the track). > Can you confirm that you are using SC 7.0 final and not a pre-release version. Sorry... I have a Squeezebox v3. I am using the released version of SC 7.0 (not the nightly builds). I can't promise a quick response with the other info since I will be traveling but I will try to get to it before Monday.
Created attachment 3202 [details] log of my slim server debugging
I think I can see what is happening here, with either the SliMP3 or an SB1 (but this would not explain your problems, Mark). Since SC7, synchronized startup uses a more-sophisticaed mechanism to try and get all the players to start at the same moment. It used to issue unpause commands as fast as possible in the direction of each player. Now, for SB2s and newer, the firmware has been enhanced with (in effect) a 'start at time' command. But SliMP3s and SB1s do not have new firmware and so a cruder mechanism is used; this sets a high-priority timer within SC to send the unpause command (just before) the planned start time. But SC is single-threaded. If some other processing is going on at the critical moment, then the unpause may get delayed. Unfortunately, random play and similar feature hook into the start-of-play mechanism and may do some time-consuming stuff just at this critical moment. This can mean that the SliMP3 starts late and the SB2 has to pause and wait for it. I'm not sure what to do about this. If we do come up with a fix then I doubt that this will be for 7.0.1. Also, when play starts, it is generally the case that only a little data has been buffered by the player. Anything going on on SC at this time could cause the player to run out of data and then SC will pause it while it rebuffers. The more players in the sync-group, the more this can be a problem. You can compensate for this somewhat by increasing the startup delay (Settings / Advanced / Network / Synchronized Players Startup Delay - milliseconds). Mark, this might help you. If my theory is right, however, it would need to be big enough so that any random-play actions had time to complete, especially in the SliMP3/SB1 case.
Created attachment 3228 [details] My Server.log file.
Hello Alan, Sorry it took so long to get you this. I have been doing some investigating. The following is the list of actions I performed. (I have also attached the Server.Log file associated with these actions.) - cleared server.log file. - restarted SC - Turned on both Transporter and Squeezebox V3 - Selected Radom Mix --> Random songs. - Song #1 "Stereo MC - The End - Connected" stuttered at until all songs and artwork were loaded in the browser (about 10-15 sec.). - Played error free to the end of the song, however during this song, I tried to add more songs (clicked "+" on Random songs and tried to add an album) but they never loaded. (no list of songs with the "loading..." message showing). - Restarted the browser session and list came up with new album selection appended to the end (as I requested). - Once "Stereo MC - The End" finished playing, Duncan Sheik - In the Absence of Sun played without flaw. (no stuttering) - Next song stuttered. (Dada - Mary Sunshine Rain - Puzzle). - Next song stuttered. (Stevie Nicks - Edge of Seventeen - Bella Donna) - Cleared song list. - Added just "Alice in Chains - Unplugged" from "Home > Artist > Alice in Chains". (No random play). - Song #1 studdered (Alice in Chains - Nutshell - Unplugged). - Song #2 studdered (Alice in Chains - Brother - Unplugged). But only for a second. (It appeared that the studder stopped when the album art finished loading. - Skipped to the next song. (Alice in Chains - No Excuses - Unplugged). - Song studdered again for about 5 seconds. - Appended new album to the end of the playlist. (Album Dirt - Alice in Chains). - While No Excuses was playing, I clicked play on new song. (Alice in Chains - Them Bones - Dirt) - The song badly stuttered for about 10 seconds. My general observations seem to show that: - it has nothing to do with dynamic playlists like random play. - it seems to have some corrolation with loading artwork but this could be a red herring. I hope this is helpful. Mark
Just wanted to add another example with no Slimp3 or SB1 involved. Been noticing the dynamic playlist stuttering problem inconsistently since upgrading to 7.0. I am syncing an SB2 & SB3. Since I got a Controller, the stuttering problem happens much more consistently when the SB2 & SB3 are sync'd and the Controller in on. It also happens occasionally when just using the SB3 with the Controller. I have also occasionally had it actually stall completely for more than 30 seconds and then just skip to the next song or stop all together. If you would like to see more logs, just let me know which debugs to switch on now that I can consistently reproduce the stutter. I can try to catch the complete stall but it happens pretty rarely. --mike
Mark, Mike, Greg, Have you tried increasing the startup delay (Settings / Advanced / Network / Synchronized Players Startup Delay - milliseconds)? Please try this and let me know if it helps. It may be that the default for this, or the amount that the players buffer before starting (there is no UI for changing this preference) simply is not large enough. Mike, are one or both of your players connected wirelessly? Are the SC and music library on the same machine? If not, how are the two systems connected? Mark, are both your SqueezeCenter and ReadyNAS wired? Greg, Are the SC and music library on the same machine? If not, how are the two systems connected?
SB2 & SB3 are both wireless. SC runs on 1.5GHz P4 with 512MB RAM running Ubuntu 7.10 with the music on local 750GB IDE drive. The SC server is wired to a Belkin pre N router. I will try increasing the startup delay and report back. I am suspicious about there being more to this as it also happens when only using my SB3 (although with the Controller). The stutter occurs when a new song begins (a few notes and then the pause) while at the same time SC is adding a new song to the dynamic playlist and removing the oldest of the recently played songs (I have it set for 10 upcoming and 5 recent), loading appropriate artwork and sending these changes (playlist & artwork) to the Controller. The CPU always spikes at that point regardless of whether there is a stutter. Since the behavior is inconsistent when I am not syncing, I can't be certain, but it appeared to not stutter (or stutter less) when I did not have any browsers pointing to SC (more places to reflect updates to playlist & artwork). When I observed this yesterday the browser was open on a wired PC, but there have been other times when the browser is open on wireless PC. One thing I am pretty certain of is that since I started using the Controller it stutters more often. Is it fair to say that a sync'd player is another playlist that has to be updated? It would be interesting to test if it would stutter more when there are more Controllers connected to SC with just one player. SqueezeCenter Version: 7.0.1 - 18946 @ Sun Apr 20 00:41:25 PDT 2008 - Debian - EN - iso-8859-1 Perl Version: 5.8.8 i486-linux-gnu-thread-multi MySQL Version: 5.0.45-Debian_1ubuntu3.3 Platform Architecture: i686-linux
In reply to comment #16) > Mark, are both your SqueezeCenter and ReadyNAS wired? SqueezeCenter is Wireless. ReadyNAS is wired. I saw that delay setting but didn't try it yet. I will try it this week. Thanks,
I am reasonably confident that this is the result of (at least one) player in the sync group being starved of data immeidately after it starts to play a track. This is evidenced by the Source::outputUnderrun messages in the log. Increasing startup delay (milliseconds) is the easiest way to handle this. Better would be to increase the size of the syncBufferThreshold player-preference but there is no easy way to do this. It is specified in KB. The default is 4(KB) and the maximum would be around 3000 (KB). You could do this using the CLI if you are comfortable using it. Bug 7918 makes this problem worse than it needs to be. There is something of a dilemma here. Should we increase the default syncStartDelay and/or syncBufferThreshold values, which would increase the (default) inter-track gap, or should we leave things as they are and require users with 'difficult' environments to make configuration changes?
Just a general comment... I would not characterize my setup as a "difficult environment". Please remember that this was not an issue with the older version 6.x. The question is, why has it now become an issue now?
(In reply to comment #16) > Mark, Mike, Greg, Have you tried increasing the startup delay (Settings / > Advanced / Network / Synchronized Players Startup Delay - milliseconds)? Please > try this and let me know if it helps. It may be that the default for this, or > the amount that the players buffer before starting (there is no UI for changing > this preference) simply is not large enough. > > Mike, are one or both of your players connected wirelessly? Are the SC and > music library on the same machine? If not, how are the two systems connected? > > Mark, are both your SqueezeCenter and ReadyNAS wired? > > Greg, Are the SC and music library on the same machine? If not, how are the two > systems connected? > my setup: sc 7.0.1 is on a mac g4 with 1.5 mghz processor and 1 gig of ram. My music lives on two external firewire 800 drives. I have tried increasing the delay time and that seems to be helping a bit. also, when i just select one album to play there seems to be no trouble synching. It's when I select a dynamic playlist or a trackstat playlist that problems arise. My players are both hard wired through netgear xe102 homeplugs.
(In reply to comment #21) > also, when i just select one album to > play there seems to be no trouble synching. It's when I select a dynamic > playlist or a trackstat playlist that problems arise. My players are both hard > wired through netgear xe102 homeplugs. > Please verify if you have the same problem with the bundled Random Mix plugin. Dynamic playlists using the Dynamic PlayList plugin (such as those created with SQL Playlist and TrackStat) works similar to Random Mix. The different is that the SQL statement that retrieves new tracks might take a bit longer if the playlist is complex. New tracks are retrieved directly when a new song starts to play. Alan, do you think it would be preferable if new tracks was added in the middle of a song instead of directly when a new song starts ?
> Alan, do you think it would be preferable if new tracks was added in the middle > of a song instead of directly when a new song starts ? Yes, that would certainly help.
(In reply to comment #22) > (In reply to comment #21) > > also, when i just select one album to > > play there seems to be no trouble synching. It's when I select a dynamic > > playlist or a trackstat playlist that problems arise. My players are both hard > > wired through netgear xe102 homeplugs. > > > > Please verify if you have the same problem with the bundled Random Mix plugin. > > Dynamic playlists using the Dynamic PlayList plugin (such as those created with > SQL Playlist and TrackStat) works similar to Random Mix. The different is that > the SQL statement that retrieves new tracks might take a bit longer if the > playlist is complex. New tracks are retrieved directly when a new song starts > to play. > > Alan, do you think it would be preferable if new tracks was added in the middle > of a song instead of directly when a new song starts ? > yes, the problem also presents itself when i use random mix.
(In reply to comment #20) > Just a general comment... I would not characterize my setup as a "difficult > environment". Please remember that this was not an issue with the older > version 6.x. The question is, why has it now become an issue now? I meant 'difficult' in a technical sense. Wireless networks are more difficult than wired ones because they tend to suffer more from congestion. Fileserver separate from SC is more difficult than local storage, especially when using Microsoft Windows (and hence the stupefyingly inefficient SMB network filesystem protocol). A wireless link between SC and storage is likely to be particularly 'difficult'. Or course, all of this works just fine most of the time. It is different in SC 7 for two reasons: (1) because SC tries not only to start all the players in a sync-group at the same time, it also tries to keep them synced (which you can disable with the maintainSync player preference - Settings / Player / <player> / Audio / Maintain Synchronization); and (2) a starved player can interact badly with the sync-maintenance commands (bug 7918). With 6.x, players that got out of sync at the start of a track, or later due to buffer starvation, would just stay that way until the end of the track.
I understand. Thanks for clarifying. I will play around with the sync setting this week.
(In reply to comment #19) > I am reasonably confident that this is the result of (at least one) player in > the sync group being starved of data immeidately after it starts to play a > track. Alan, what is the explanation for when this is happening when I am only playing my SB3 by itself (no sync'd players)? I am using a Controller. Is that similar to syncing with a player? It plays gapless with the Controller which made me believe it is not similar to syncing.
(In reply to comment #27) > Alan, what is the explanation for when this is happening when I am only playing > my SB3 by itself (no sync'd players)? I am using a Controller. Is that > similar to syncing with a player? It plays gapless with the Controller which > made me believe it is not similar to syncing. No, I don't think that this can be the same thing. Do you get this with all tracks or just the 'first' track? With the 'first' track I can see that wireless network congestion / file-system delays on the server could sometimes lead to starvation but this should not happen for subsequent tracks; SC starts stream the new track when there are still 10s worth of the current track left to play. I cannot see how the set of things that happen at track start could cause that much delay - we are really talking about problems in the 100-1000ms range here. How long is your CPU spike?
(In reply to comment #28) > No, I don't think that this can be the same thing. Do you get this with all > tracks or just the 'first' track? With the 'first' track I can see that > wireless network congestion / file-system delays on the server could sometimes > lead to starvation but this should not happen for subsequent tracks; SC starts > stream the new track when there are still 10s worth of the current track left > to play. I cannot see how the set of things that happen at track start could > cause that much delay - we are really talking about problems in the 100-1000ms > range here. How long is your CPU spike? Never the first track. It happens on subsequent tracks when I am playing a Dynamic Playlist. It stutters 1-5 seconds typically a few notes after the next song starts. I am only looking at the CPU spike on the Ubuntu System Monitor so it is not that precise. I would guess it is about 1-2 seconds. The spike occurs every time the song changes regardless of whether it stutters. This is the same time that tracks are being added and removed from the playlist. When I sync SB2 & SB3 (both wireless) and have the Controller on, the stutter happens more often then not (more than 80%). With one player and the Controller on or both players sync'd and the Controller off it happens less consistently (might do it 3 songs in a row and then be fine for several songs). With one player and the Controller off, I think it has stuttered, but very infrequently (not 100% sure). Maybe I should look at upgrading my server. I would have thought that 1.5GHz P4 running Ubuntu would be plenty for SC.
Per Alan's request (via email), I have created Bug 7935 for the issue I have been observing. He felt it was separate and unrelated to the syncing problem.
Created attachment 3319 [details] Duplicate SC button controls. I have been playing around with a few settings and this is what I have found. I hate to keep saying this but after long observations, this issue really looks like it is related in some way to loading artwork. Stuttering always seems to happen when the UI is updating artwork. The more artwork (new song list) the worse it is. Setting #1: Advanced/Performance/Artwork Resampling Set from “Resample Artwork (Slower, Better Quality)” to “Resize Artwork (Faster, Lower Quality)” Changing this setting had a noticeable effect and made things MUCH better but not perfect. Stutters on occasion, but not very often, when starting the next song, either naturally or skipping to the next song. Stutters more consistently when pressing next 2 or 3 times in succession. (i.e. skipping ahead 2 or 3 songs.) Stutters a lot when creating the initial Random Song play list. It stutters until artwork is loaded. Once the list is finished loading, songs start much better. When it does stutter, it is when the SB3 is "Rebuffering". Setting #2: Advanced/Network/Synchronize players startup delay Changing from default to 200ms. Changing only this setting did NOT have a noticeable effect. Changing both #1 and #2 did NOT have a noticeable improvement over #1 alone. Another observation... While skipping back and forth between songs, I ended up with duplicate button controls (Artwork, Save, and Clear controls) at the bottom right of the SC window. This occurred when the Music was having a lot of stuttering problems. Mark
Mark - what is the load on your CPU like when it stutters? This sounds very similar to the problem I am having that Alan asked me to create a new Bug 7935 . My CPU hits 100% for few seconds every time the new song starts, but stutters only some of the time. It does appear that when it stutters the CPU is at 100% for more time. In my case a big difference is whether or not the new Squeezebox Controller is on or off. When it is on, it is just another interface that needs to be updated including artwork when playlist changes. One difference I have observed from you is that I never have observed a stutter when initiating the playlist although it often takes about 10-20 seconds to start playing.
Andy speculates that perhaps this bug is just the result of several factors. However, if Wallace can reproduce this, he can try erland's patch to see if it works.
In the absence of a reproducible test case I am pushing this off to 7.2. QA, please try to get a test-case together for this.
how much time/bytes are we talking about here? it's important that this is reliable.
I was unable to reproduce this on either my slow or fast test systems. This problem is certainly made worse by bug 7918 and would be made better by enhancement bug 6442. For synced players (this bug), increasing the syncBufferThreshold is a workaround in some cases but is not always sufficient. In SC7.2-new-streaming this problem is alleviated for SB2+ players (note the original reporter was using a SliMP3) as there is no stop between tracks (gapless sync) which would lessen the impact of increasing syncBufferThreshold (now only applies to first track). The Controller playlist-reload and artwork downloading that occurs on track start hits the server hard and makes this problem worse than it might otherwise be. So do the Web-UI updates. So does the Random-play updates. But without a reproducible test-case it not possible to determine what actual changes will improve and/or resolve the situation.
If this is strictly a SLIMP3 issue now, the priority is lower (and we shouldn't compromise performance on the other players). I say we punt it back to QA to try to reproduce and if/when we get a reproduceable case, we re-target it.
It is not strictly a SliMP3 issue. the original reporter was using SliMP3 + SB2. Another reporter was using SB3 + TP.
Has anyone seeing this tried it with the 7.1 build? Save me a bit of time :)
I will give it a try this week. I don't have my TP right now as I had to send it in for repair so I cannot check out my original setup. But I do have 2 SB3s hooked up. I'll let you know.
Bumping to 7.3, please re-post if anyone can reproduce this issue.
My apologies, I just moved and haven't had my equipment up and running yet. I will test it as soon as I am able.
Tested 7.2.1 for 4 days with different players synced. So far no problems. Please reopen the bug if you can still reproduce this issue.
This bug has been fixed in the 7.3.0 release version of SqueezeCenter! Please download the new version from http://www.slimdevices.com/su_downloads.html if you haven't already. If you are still experiencing this problem, feel free to reopen the bug with your new comments and we'll have another look.
Reduce number of active targets for SC