PDA

View Full Version : SB1 syncing tips?



sander
2009-04-04, 11:23
As the proud new owner of an original Squeezebox, I'm having a problem when it syncs with the newer units in my house.

Specifically new songs pause twice at consistent intervals when they start on all units and it takes a couple of seconds until the SB1 syncs up correctly.

Does anyone know of a setting that can be made to fix this or is it a limitation of this model.

TIA

peterw
2009-04-05, 13:13
What version of SqueezeCenter do you use? If you don't have any Booms, you might try SqueezeCenter 7.2. Version 7.3 introduced a new syncing framework that's great with SB2 and newer, but IIRC some here have said it's worse with SB1 and Slimp3 players.

-Peter

sander
2009-04-05, 14:53
I use 7.3.2, and I have one of each of the newer units, Squeezebox3, duet, and boom, so I can't go back too much farther. I saw a SqueezeBox1 wired-only on craigslist (for $25 :) ) so I thought I'd add it to my office as the software clients can't sync reliably either.

Unfortunately about half the time the SB1 starts playing just a little later and the newer units pause for it to catch up about 5 seconds into playing. For streaming and podcasts its not an issue, but in normal playback its very annoying.

I tried playing with the Audio Startup time on the SB1, but I didn't seem to make a difference, and unfortunately the rest of the players started behaving unusual (not syncing and starting late) so I undid all the changes.

7.3.x has been bulletproof with syncing between the SB2+ style hardware for me.

My understanding was the syncing problems were due to the peculiarities in the SqueezePlay code the inability of the other software clients to poll the hardware on PCs to the same extent they can on hardware clients.

The hardware polling isn't an issue, obviously since it does sync up unlike the software clients, but I'm trying to figure out why the SB1 is starting late and is there anything I can do to fix it.

funkstar
2009-04-06, 01:45
How about turning off internal Flac decoding for the SB2+ units?

Thats likely to be the issue for older hardware, it doesn't support Flac decoding natively. Syncing is supposed to handle this, there are obviously issues with it though.

Have a look in Bugzilla (http://bugs.slimdevices.com) to see if there is anything relating to sync in there.

awy
2009-04-06, 04:26
As the proud new owner of an original Squeezebox, I'm having a problem when it syncs with the newer units in my house.

Specifically new songs pause twice at consistent intervals when they start on all units and it takes a couple of seconds until the SB1 syncs up correctly.


With just a single SB1 in the mix, sync should work fine (with 7.3.2).

Can you capture a log at level player.source=info, player.sync=debug, and networking.protocol.slimproto=info? Upload it here, along with a description of what happened and at what time.

strmtrupr2
2009-04-06, 06:25
Hi,

I was wondering what the best and easiest way would be to re-sync my players. I listen to a lot of Internet radio, and every few days they get out of sync. Do you know what the best way is to shock them back into sync again?

So far, I've only changed one setting in attempt to keep them in sync, and that's the Minimum Synchronization Adjustment (ms), I set it to 10 from 30.

I have 2 receivers, one boom, and one box. Two are wired and two are wireless.

Thanks for your advice.

Scott

awy
2009-04-06, 07:09
No obvious, specific advice. Does restarting the station (press <<) not fix the problem? A log of player.sync=debug, when the problem occurs, could be helpful.

strmtrupr2
2009-04-06, 07:26
Hello,

Here is a snippet from my log:



[09-04-04 16:04:58.0275] Slim::Networking::SqueezeNetwork::Players::_player s_error (146) Unable to get players from SN: Timed out waiting for data, retrying in 300 seconds
[09-04-04 17:25:03.0162] Slim::Networking::SqueezeNetwork::Players::_player s_error (146) Unable to get players from SN: Timed out waiting for data, retrying in 300 seconds
[09-04-04 18:30:09.0193] Slim::Networking::SqueezeNetwork::Players::_player s_error (146) Unable to get players from SN: Timed out waiting for data, retrying in 300 seconds
[09-04-04 23:40:17.0163] Slim::Networking::SqueezeNetwork::Players::_player s_error (146) Unable to get players from SN: Timed out waiting for data, retrying in 300 seconds
[09-04-04 23:42:13.9873] Slim::Utils::Misc::msg (1122) Warning: [23:42:13.9869] Use of uninitialized value in subtraction (-) at /<C:\PROGRA~1\SQUEEZ~1\server\SQUEEZ~1.EXE>Slim/Buttons/Common.pm line 993.
[09-04-04 23:42:15.1150] Slim::Utils::Misc::msg (1122) Warning: [23:42:15.1146] Use of uninitialized value in subtraction (-) at /<C:\PROGRA~1\SQUEEZ~1\server\SQUEEZ~1.EXE>Slim/Buttons/Common.pm line 993.
[09-04-04 23:42:16.6081] Slim::Utils::Misc::msg (1122) Warning: [23:42:16.6077] Use of uninitialized value in subtraction (-) at /<C:\PROGRA~1\SQUEEZ~1\server\SQUEEZ~1.EXE>Slim/Buttons/Common.pm line 993.
[09-04-05 12:35:28.0162] Slim::Networking::SqueezeNetwork::Players::_player s_error (146) Unable to get players from SN: Timed out waiting for data, retrying in 300 seconds
[09-04-05 13:35:37.0542] Slim::Networking::SqueezeNetwork::Players::_player s_error (146) Unable to get players from SN: Timed out waiting for data, retrying in 300 seconds
[09-04-05 13:55:44.0142] Slim::Networking::SqueezeNetwork::Players::_player s_error (146) Unable to get players from SN: Timed out waiting for data, retrying in 300 seconds
[09-04-05 17:15:22.0981] Slim::Player::Song::open (341) Error: Couldn't create command line for m3u playback for [http://opml.radiotime.com/Tune.ashx?id=s96389&username=strmtrupr2&partnerId=16]
[09-04-05 18:15:49.0152] Slim::Networking::SqueezeNetwork::Players::_player s_error (146) Unable to get players from SN: Timed out waiting for data, retrying in 300 seconds
[09-04-05 18:45:54.0143] Slim::Networking::SqueezeNetwork::Players::_player s_error (146) Unable to get players from SN: Timed out waiting for data, retrying in 300 seconds
[09-04-05 18:55:59.0155] Slim::Networking::SqueezeNetwork::Players::_player s_error (146) Unable to get players from SN: Timed out waiting for data, retrying in 300 seconds
[09-04-05 20:23:42.7074] Slim::Player::Song::open (341) Error: Couldn't create command line for m3u playback for [http://opml.radiotime.com/Tune.ashx?id=s96389&username=strmtrupr2&partnerId=16]
[09-04-05 20:23:46.8743] Slim::Player::Song::open (341) Error: Couldn't create command line for m3u playback for [http://opml.radiotime.com/Tune.ashx?id=s96389&username=strmtrupr2&partnerId=16]
[09-04-05 20:23:50.5713] Slim::Player::Song::open (341) Error: Couldn't create command line for m3u playback for [http://opml.radiotime.com/Tune.ashx?id=s96389&username=strmtrupr2&partnerId=16]
[09-04-06 07:43:19.1370] Slim::Utils::Scanner::Remote::__ANON__ (206) Error: Can't connect to remote server to retrieve playlist: Connect timed out: Bad file descriptor.


Thank you very much for looking.

Scott

awy
2009-04-06, 09:27
It does not look like you set the log level I requested.

strmtrupr2
2009-04-06, 09:57
Would you mind reminding me which file that debug level is set in please?

Thank you very much.

Scott

awy
2009-04-06, 10:12
Use the Web interface (localhost:9000) and open the Settings page. Go to Advanced / Logging and select the level from the appropriate drop-down menu

strmtrupr2
2009-04-06, 11:49
Hi,

I setup the debug log level; however, it's not exhibiting the issue anymore. I'll have to wait a day or so for it to come back, do you think I should turn the logging back to normal until the issue comes back, then turn it back on?

-thanks

Scott

awy
2009-04-06, 12:36
If you have enough disk space then just leave the log running. It will compress well (with ZIP or whatever) when you are ready to upload it. Or, for this case, you could turn it off now and turn it back on when it happens. That may mean that we don't see the trigger to the problem. In any case, a snippet of the current log would be good to see now.

strmtrupr2
2009-04-06, 14:00
Hi,

Sounds great, I'll leave it running.

Here is a sample:



[09-04-06 15:04:21.0041] Slim::Player::Player::trackJiffiesEpoch (927) 00:04:20:07:f1:7d adjust jiffies epoch -0.001s
[09-04-06 15:06:51.0177] Slim::Player::Player::trackJiffiesEpoch (927) 00:04:20:1e:0b:26 adjust jiffies epoch -0.001s
[09-04-06 15:07:46.0142] Slim::Player::Player::trackJiffiesEpoch (927) 00:04:20:1e:0b:26 adjust jiffies epoch -0.002s
[09-04-06 15:08:41.0110] Slim::Player::Player::trackJiffiesEpoch (927) 00:04:20:1e:0b:26 adjust jiffies epoch -0.001s
[09-04-06 15:21:46.0061] Slim::Player::Player::trackJiffiesEpoch (927) 00:04:20:1e:0b:26 adjust jiffies epoch -0.001s
[09-04-06 15:22:51.0063] Slim::Player::Player::trackJiffiesEpoch (927) 00:04:20:1e:0b:26 adjust jiffies epoch -0.002s
[09-04-06 15:25:16.0060] Slim::Player::Player::trackJiffiesEpoch (927) 00:04:20:1e:0b:26 adjust jiffies epoch -0.001s
[09-04-06 15:34:11.0060] Slim::Player::Player::trackJiffiesEpoch (927) 00:04:20:16:60:05 adjust jiffies epoch -0.001s
[09-04-06 15:34:11.0177] Slim::Player::Player::trackJiffiesEpoch (927) 00:04:20:1e:0b:26 adjust jiffies epoch -0.002s
[09-04-06 15:34:46.0059] Slim::Player::Player::trackJiffiesEpoch (927) 00:04:20:1e:0b:26 adjust jiffies epoch -0.001s
[09-04-06 15:35:06.0146] Slim::Player::Player::trackJiffiesEpoch (927) 00:04:20:1e:0b:26 adjust jiffies epoch -0.001s
[09-04-06 15:35:56.0060] Slim::Player::Player::trackJiffiesEpoch (927) 00:04:20:1e:0b:26 adjust jiffies epoch -0.001s
[09-04-06 15:37:06.0046] Slim::Player::Player::trackJiffiesEpoch (927) 00:04:20:16:74:dc adjust jiffies epoch -0.001s
[09-04-06 15:45:26.0170] Slim::Player::Player::trackJiffiesEpoch (927) 00:04:20:1e:0b:26 adjust jiffies epoch -0.001s
[09-04-06 15:58:26.0060] Slim::Player::Player::trackJiffiesEpoch (927) 00:04:20:1e:0b:26 adjust jiffies epoch -0.001s


Thanks for your help!

Scott

sander
2009-04-06, 16:14
If you have enough disk space then just leave the log running. It will compress well (with ZIP or whatever) when you are ready to upload it. Or, for this case, you could turn it off now and turn it back on when it happens. That may mean that we don't see the trigger to the problem. In any case, a snippet of the current log would be good to see now.

Thanks for taking the time to look at this! Those settings generate an awful lot of information in a short time, so I can generate more, but I'm going to run into the limit of what I can upload here.

In this section, right after I unpause and skip the next song my receiver (00:04:20:16:70:70) starts playing and the Squeezebox1 (00:04:20:05:81:a2) lags and catches up about 4 seconds into the song. I'm pretty sure I captured it, but I can send more examples in email as its fairly easy to reproduce if I keep skipping to the next song.

Let me know what's helpful to you and I'll give you as much information as I can.

Thanks again!

awy
2009-04-06, 23:40
Hi,

Sounds great, I'll leave it running.

Here is a sample:



[09-04-06 15:04:21.0041] Slim::Player::Player::trackJiffiesEpoch (927) 00:04:20:07:f1:7d adjust jiffies epoch -0.001s
[09-04-06 15:06:51.0177] Slim::Player::Player::trackJiffiesEpoch (927)
...





Are you sure that your have two players synced and playing. That log does not indicate that.

You do have player.sync=debug, don't you?

strmtrupr2
2009-04-07, 04:51
Hello,

The previous log snippet I posted was from right after I turned on the debug setting. I'll throw down another snippet after running for a day; however, I must say it hasn't gotten out of sync yet.



[09-04-07 06:47:38.1788] Slim::Player::StreamingController::_CheckSync (459) playPoints: 00:04:20:16:74:dc: 1239102242.014, 00:04:20:16:60:05: +9, 00:04:20:07:f1:7d: +6, 00:04:20:1e:0b:26: +10
[09-04-07 06:47:38.1793] Slim::Player::StreamingController::_CheckSync (492) 00:04:20:1e:0b:26 resync: skipAhead 10ms
[09-04-07 06:47:40.1791] Slim::Player::StreamingController::_CheckSync (459) playPoints: 00:04:20:16:74:dc: 1239102242.015, 00:04:20:16:60:05: +8, 00:04:20:07:f1:7d: +4, 00:04:20:1e:0b:26: +0
[09-04-07 06:47:41.1785] Slim::Player::StreamingController::_CheckSync (459) playPoints: 00:04:20:16:74:dc: 1239102242.015, 00:04:20:16:60:05: +8, 00:04:20:07:f1:7d: +4, 00:04:20:1e:0b:26: +0
[09-04-07 06:47:42.1785] Slim::Player::StreamingController::_CheckSync (459) playPoints: 00:04:20:16:74:dc: 1239102242.015, 00:04:20:16:60:05: +8, 00:04:20:07:f1:7d: +5, 00:04:20:1e:0b:26: +0
[09-04-07 06:47:43.1788] Slim::Player::StreamingController::_CheckSync (459) playPoints: 00:04:20:16:74:dc: 1239102242.015, 00:04:20:16:60:05: +8, 00:04:20:07:f1:7d: +4, 00:04:20:1e:0b:26: +0
[09-04-07 06:47:44.1783] Slim::Player::StreamingController::_CheckSync (459) playPoints: 00:04:20:16:74:dc: 1239102242.014, 00:04:20:16:60:05: +9, 00:04:20:07:f1:7d: +6, 00:04:20:1e:0b:26: +


I was a little worried you may get confused by the other posting in between mine. Thanks for staying on top of it.

I promise to post a snippet once the players get out of sync again; it may be a couple days before that happens.

Scott

awy
2009-04-07, 05:40
In this section, right after I unpause and skip the next song my receiver (00:04:20:16:70:70) starts playing and the Squeezebox1 (00:04:20:05:81:a2) lags and catches up about 4 seconds into the song. I'm pretty sure I captured it, but I can send more examples in email as its fairly easy to reproduce if I keep skipping to the next song.


With newer players (SB2 and up), SC can send the start request to the player ahead of time. That is, it tells the player to start at X, where X is some time in the future (default 100ms). For an SB1 it does not have this option, and SC sets a high-priority timer to send the start command at the relevant time, allowing for normal network latency. This mechanism is inevitably a bit hit-and-miss because SC is single-threaded and other activities can delay the firing of a timer.

From the log, I see two things:

The start command (strm-u) to the SBR only gets acknowledged after 448ms.
The start command to the SB1 gets sent after the SB2 has already started.


Please check that you have undone all the changes on the Settings / Player / <player> / Synchronization page for each player.

It could also be that SC is just busy at the start of a track. Do you have any plugins installed? Were you using random-play?

I guess that this could be a problem with network saturation at the beginning of tracks. You could try increasing the 'Synchronization Start Delay' parameter (not sure of the exact name) under Settings / Network (or is that Settings / Advanced / Network?).

awy
2009-04-07, 05:47
I was a little worried you may get confused by the other posting in between mine. Thanks for staying on top of it.

Well, a separate thread would have made things easier ...


I promise to post a snippet once the players get out of sync again; it may be a couple days before that happens.
Scott
Ok. The current trace looks fine. Post a longer snippet when you do.

sander
2009-04-07, 19:54
Please check that you have undone all the changes on the Settings / Player / <player> / Synchronization page for each player.

OK, I only did this the SB1, but I checked the settings on the others and they appear to be OK


It could also be that SC is just busy at the start of a track. Do you have any plugins installed? Were you using random-play?

I have about a dozen plugins, MusicIP and a fairly large library (~120K tracks) so that could be the issue. However I do have Core Duo 2.5Ghz with 2 GB of RAM so that should help, however I did notice another problem (occasional sound drop out) coincided with my using the cover finder plugin so it could be Squeezecenter getting overwhelmed.


I guess that this could be a problem with network saturation at the beginning of tracks. You could try increasing the 'Synchronization Start Delay' parameter (not sure of the exact name) under Settings / Network (or is that Settings / Advanced / Network?).

I tried this and it was a little better, but there were still delays. How big can I make this buffer?

What I'm unclear of is why the SB1 is starting late? I understand the other devices can push themselves up in the queue, but it is on a wired connection opposite the other players which are all wireless. The latency is less than half a millisecond with constant bandwidth. Is it the small buffer that makes it so vulnerable to the server being overwhelmed?

Thanks again for your help.

awy
2009-04-08, 00:12
What is the list of third-party plugins you are running? Please try disabling them all and, if that fixes thing, enabling them one by one.

There are/have been a number of third-party plugins that listen for track-start events and then do clever stuff. If this takes more than about 50ms then it risks interfering with the synchronized start logic. This will especially hit SB1s (and SliMP3s) - see my previous explanation.

sander
2009-04-08, 16:58
What is the list of third-party plugins you are running? Please try disabling them all and, if that fixes thing, enabling them one by one.

Well, I disabled a bunch at once and including trackstat and along with others which I really didn't use as much as I thought, and it works! There's still the occasional hiccup, about a second once every 10 songs, but nothing like before.

I currently have the following plugins enabled:
Auto Dim Display
Date and Time
Extension Downloader
Find Cover Art
Lazy Search
Line In
Music Information Screen
MusicIP (A biggie for me!)
NPR Radio
Other Players
Podcasts
Radiotime
Rescan Music Library
Server and Network Health
Sleepfade
Spicefly SugarCube (another biggie I was afraid would be a culprit)
Superdate Time Screensaver (essential)
Visualizer Screensaver

I've meant to use Dynamic Playlists and I occasionally look at TrackStat, but to be honest I let MusicIP be the guide most of the time so I can do without them for now.

If any of these others might cause a problem let me know.

Thanks so much for your help. Maybe when the schema is updated in 8.0 I can regain this functionality, but this is great for now, and I know where to look in the future.

awy
2009-04-09, 01:03
Your best bet is probably to wind Synchronization Start Delay up as far as you can bear: maybe 1-2 seconds. As I said, syncing is always a little hit and miss with SB1s because of the older protocol limitations.

Trackstat may have been it, although I thought that Erland had updated his plugins not to do stuff at track start. I don't know when Find Cover Art comes into play, and I have no idea what Spicefly SugarCube does.

Good luck.

bpa
2009-04-09, 01:34
FindArt will do nothing until its menu item is selected. Even then I think the only time there may be a processing delay would when saving cover art.

sander
2009-04-09, 07:23
...and I have no idea what Spicefly SugarCube does.

Sugarcube is an on-the-fly extension to MusicIP, which adds a new song to the end of the playlist based on the current song playing. It seems like a natural candidate for these delays, but it looks like it makes the calculation after the song starts.

I have the sync delay set at 1 second currently, which appears to be enough as I played music for about 2 hours last night and I only experienced the delay with a couple of songs. If I experience more I may make it longer.

I don't know if there may have been other issues related to this problem, or if they were caused by some combination of the plugins, but I did experience the following problems:

After removing the plugins last night the nightly rescan appears to have blown up the database, sending Squeezecenter into a crash loop, but it is rebuilding now.

And since I added the SB1, I did notice the occasional complete disconnect in stream information, where Squeezecenter will report a completely different song playing opposite the actual song that is playing. This may be a side effect of the sync delay. I've noticed Squeezecenter having trouble with shuffling the playlist right before the track changes, but generally it would just stall, not play the wrong song.

Also, as I noticed earlier, sometimes the SB1 would just drop the audio output, but would otherwise be functioning normally according to its own feedback and Squeezecenter.

All that said I consider this issue resolved. I'm always impressed at the underlying engineering that went into the Squeezecenter design. The fact that the remote architecture is such that my SB1, SB3 and Boom remotes are all interchangeable, and that the SB1, with its outdated underlying hardware is still viable client which can leverage the latest server, is further testament to this.

I also appreciate the help from the community and Logitech which has helped me make the most of this system.

Thanks again for helping me resolve this issue.

strmtrupr2
2009-04-12, 14:12
Ok. The current trace looks fine. Post a longer snippet when you do.

Hi,

Sync started flaking out again today. I attached the log.

Thanks for looking.

Scott

awy
2009-04-14, 02:12
What version of SC are you running?

Does you server running SC go to sleep and do these sync problems occur after it has woken up? In which case you are probably suffering from bug 10634 (http://bugs.slimdevices.com/show_bug.cgi?id=10634), which should have been fixed in SC 7.3.2.

strmtrupr2
2009-04-14, 05:13
Hi,

Here is my SC info:


Version: 7.3.2 - 24695 @ Mon Jan 19 18:55:04 PST 2009
Hostname: Ajihad
IP: 192.168.76.132
HTTP Port: 9000
OS: Windows Vista - EN - cp1252
Platform: 586
Perl Version: 5.8.8 - MSWin32-x86-multi-thread
MySQL Version: 5.0.22-community-nt
Total Players Recognized: 4


The computer is not set to sleep. If there was an easy way to 'reset' the playback and re-sync all players with the touch of a button / manually, I'd be happy.

Thanks for looking into the issue!

Scott

awy
2009-04-14, 07:33
Hmm, the log show that SC's idea of the players' time epoch is way out compared with that of the server (probably about 23s at the time you took the log snapshot). Every few seconds SC adjust its idea of the players' epochs by 5ms, so it is going to take around 6 hours to get back in sync.

Given that you server does not sleep, is there anything else which could cause its time to jump, and possibly jump back again?

strmtrupr2
2009-04-14, 08:00
Hi,

All sorts of things could mess with this Microsoft OS! Scan disk, windows time update, etc.

Any quick way to shock it into action?

Scott

awy
2009-04-14, 08:14
Any quick way to shock it into action?

Not short of restarting SC or each of the players.

strmtrupr2
2009-04-14, 08:49
Hi,

I'll try restarting SC next time. Too bad there isn't a setting I can change to allow a more swift catchup. At least, now I know what to look for, drastic time changes on the SC host.

Thanks for your help.

Scott