Bugzilla – Bug 8018
SC7.0 Sync fails with drifting server system clock
Last modified: 2008-08-02 22:23:52 UTC
I'm having serious sync problems with SqueezeCenter 7.0. My setup: - 3 x SB3 all connected wirelessly - Linksys WRT54GS wireless router - Xubuntu 7.10 on Via EN1200G 1GB ram The problem actually appears to be dependent on Squeezecenter uptime. If I restart Squeezecenter, I can sync any combination of players without a problem. However, after it's been running for a period of time, synchronisation cannot be obtained between any players and there are delays of up to 6s for one of them. I have tried a number of permutations: synching via the remote and through the web interface, unsynching and re-synching players, powering on in a different order... each with equally poor results. I have turned off a lot of the plugins, including last.fm, and currently have the following enabled: Alien BBC CLI Date and Time Screensaver Favorites Podcasts Random Mix Rescan Music Library Save Playlist Server & Network Health Slacker Snow Screensaver Sounds & Effects Visualizer Screensaver Note I had this problem prior to installing Alien BBC. I doubt I have an obvious wireless issue - signal strength ranges from 60% to 90% depending on the box, there are no drop outs when playing them independently, synch'ed (after a SC restart) and in some cases when they're supposed to be synch'ed and I just leave them playing. I have grabbed some information from the server.log (below) after setting Multi-Player Synchronization Logging to info. All 3 players are configured in a single group, Player 1 initially playing, Player 2 and then Player 3 powered on sequentially. I haven't really had synch problems with previous versions of SlimServer, which I ran on an XP machine. I have also tried SC7.0 on that machine but ecannot sync the players at all. Player 1 playing, switch on Player 2: 08-03-31 21:51:43.2127] Slim::Player::Sync::checkSync (505) 00:04:20:06:6f:7c is ready to sync [08-03-31 21:51:43.2158] Slim::Player::Sync::checkSync (496) 00:04:20:06:58:0c checking buffer fullness: 0 (threshold: 4096) [08-03-31 21:51:43.2213] Slim::Player::Player::trackJiffiesEpoch (819) 00:04:20:06:58:0c adjust jiffies epoch +0.005s [08-03-31 21:51:43.2238] Slim::Player::Sync::checkSync (496) 00:04:20:06:58:0c checking buffer fullness: 4380 (threshold: 4096) [08-03-31 21:51:43.2248] Slim::Player::Sync::checkSync (505) 00:04:20:06:58:0c is ready to sync [08-03-31 21:51:43.2259] Slim::Player::Sync::checkSync (530) all clients ready to sync now. unpausing them. [08-03-31 21:51:43.2274] Slim::Player::Squeezebox2::startAt (835) 00:04:20:06:58:0c startAt: 212592868 [08-03-31 21:51:43.2296] Slim::Player::Squeezebox2::startAt (835) 00:04:20:06:6f:7c startAt: 211794975 [08-03-31 21:51:43.2428] Slim::Player::Player::trackJiffiesEpoch (819) 00:04:20:06:6f:7c adjust jiffies epoch +0.005s [08-03-31 21:51:43.2447] Slim::Player::Sync::checkSync (609) 00:04:20:06:6f:7c bailing as no playPoint Players 1 & 2 playing (~1s out of synch), powering on Player 3: [08-03-31 21:52:33.4681] Slim::Player::Sync::checkSync (530) all clients ready to sync now. unpausing them. [08-03-31 21:52:33.4696] Slim::Player::Squeezebox2::startAt (835) 00:04:20:07:87:87 startAt: 212599336 [08-03-31 21:52:33.4717] Slim::Player::Squeezebox2::startAt (835) 00:04:20:06:6f:7c startAt: 211845173 [08-03-31 21:52:33.4743] Slim::Player::Squeezebox2::startAt (835) 00:04:20:06:58:0c startAt: 212643071 [08-03-31 21:52:34.0111] Slim::Player::Sync::checkSync (609) 00:04:20:06:6f:7c bailing as no playPoint [08-03-31 21:52:34.0240] Slim::Player::Player::trackJiffiesEpoch (819) 00:04:20:07:87:87 adjust jiffies epoch +0.005s [08-03-31 21:52:34.9814] Slim::Player::Sync::checkSync (609) 00:04:20:06:58:0c bailing as no playPoint [08-03-31 21:52:36.6359] Slim::Player::Sync::checkSync (609) 00:04:20:07:87:87 bailing as no playPoint [08-03-31 21:52:37.6344] Slim::Player::Sync::checkSync (609) 00:04:20:07:87:87 bailing as no playPoint [08-03-31 21:52:38.4391] Slim::Player::Player::trackJiffiesEpoch (819) 00:04:20:06:58:0c adjust jiffies epoch +0.005s [08-03-31 21:52:38.6346] Slim::Player::Sync::checkSync (609) 00:04:20:07:87:87 bailing as no playPoint [08-03-31 21:52:39.0069] Slim::Player::Player::trackJiffiesEpoch (819) 00:04:20:06:6f:7c adjust jiffies epoch +0.005s
Andy, your thoughts on this one?
Try setting player.sync to debug and attaching a longer log.
Created attachment 3323 [details] Server.log with sync debug server.log generated with sync set to debug.
I think that something went wrong with your attachment. It appears to be a gzip of a tar of a gzip of a file of NULs!
Are you using random-mix when you get this problem?
QA to investigate, provide logs if applicable
(In reply to comment #5) > Are you using random-mix when you get this problem? I am not using random-mix. I will attach the log later today.
Created attachment 3328 [details] sync debug log server.log debug when attempting to sync players 3 & 2.
There seems to be a problem with the clock on your SC host. You can see from your log that there is a constant stream of 'adjust jiffies epoch +0.005s' messages for all three players. 5ms is the maximum adjustment (until the offset exceeds 50s), so the actual offset (drift) could be much worse than the frequency of messages implies, Since the problem seems to happening with all three players, this leads me to believe that the problem is with the SC host. Does it keep proper time? We are talking about millisecond precision here.
(In reply to comment #9) > There seems to be a problem with the clock on your SC host. You can see from > your log that there is a constant stream of 'adjust jiffies epoch +0.005s' > messages for all three players. 5ms is the maximum adjustment (until the offset > exceeds 50s), so the actual offset (drift) could be much worse than the > frequency of messages implies, > > Since the problem seems to happening with all three players, this leads me to > believe that the problem is with the SC host. Does it keep proper time? We are > talking about millisecond precision here. > Alan, You're quite right - just checked and my SC host does not keep good time. Do you think that this will be compensated for if I enable ntd?
I guess you mean ntp. No, I do not think that this would help but I guess that it is possible. Can you get a measure of how far it is off - seconds/day or whatever? My guess this that you have some sort of kernel parameter configured incorrectly - clock frequency or some such. But I am afraid that I am out of date with respect to this aspect of configuring modern Linux systems to give you more precise guidance.
(In reply to comment #11) I am currently overseas and will be unable to progress this for the next 3 weeks or so. However, is it possible to get detailed information on the synchronisation process in the meantime?
(In reply to comment #12) > However, is it possible to get detailed information on the > synchronisation process in the meantime? A bit slow in finding this: http://forums.slimdevices.com/showthread.php?t=34535
reassigning to Alan for comments Nigel: Have you tested this with SC 7.0.1 to see if the issue is the same or if Sync has improved?
(In reply to comment #14) > reassigning to Alan for comments > Nigel: Have you tested this with SC 7.0.1 to see if the issue is the same or if > Sync has improved? James, Are there changes in 7.0.1 specifically for synchronisation? I am currently overseas and won't be returning until June but I can certainly look at it then.
Nigel, no, there is nothing in 7.0.1 which is likely to help your case. Can you quantify just how bad your system clock is? If the drift is < 1% then maybe NTP would be capable of fixing things - I'm not sure. I guess it is worth a try. Otherwise you need to investigate why your clock is so far off. A workaround may be to disable sync-maintenance for the players: Settings / Players / <player> / Audio / Maintain Synchronization. I'm going to close this bug as it seems clear that the problem is with your server, not with SqueezeCenter.
I have exactly the same problem (I think) 3 sb3, ss 7.1 release and Inguz, XP Last night I updated inguz, restarted, synch'd a wired and a wireless. In EQ I turned off room correction, hit play and got perfect sync. Awesome. Wake up this morning, machine has been on all night, hit play and had to wait 1 minute for any music to appear and it was massively (3s) out of sync. Since then I have tried all combos with the same result. I restarted the server and things were synching perfectly again. It even works with room correction on. I have had these problems for months with 7.0 and blamed inguz, it was only when I read the logs this morning and then found this bug did it all make sense. To add a spanner in the works this machine is time synching to time.microsoft.com and last did so last night. The motherboard is an Asus M2A VM HDMI on the latest bios. Its about a year old. I've added a log file, gvh.log.txt Tomorrow I am off on holiday for a week. I'll try again in the morning then leave the machine running for a week and see what we get. Let me know what I can do to help debug this. cheers
Created attachment 3732 [details] gareth hughes log file of sync issues
It's the next morning and it worked first time. There was a hilarious big stutter at the start while the hard disk came out of sleep and I now have a 9Gb log file. Included is the end portion. See you in a week.
Created attachment 3736 [details] End of log the next morning