I have also experienced these rebuffering problems. I have moved house recently, moved my server from Windows to Ubuntu, and upgraded to 7.3.3 (& then to 7.3.4 to try and fix the internet conection/DNS problem). So it has taken a bit of time to get everything sorted out, and to identify the source of the problem.

I get regular and frequent dropouts and breaks in my music due to rebuffering. My wifi strength varies throughout the house, but the problems continue even when the SB is 10ft from my router/AP and the signal strength is c 90%. There are no other wifi networks in the vicinity, and I've checked the signal strength with Network Stumbler on a laptop - it is consistently strong over long periods. 

Having had my squeezebox system for 4 years, and run it in 3 different properties, I have a good feel for the performance over wifi, and have not had this behaviour with earlier versions of SS/SC, unless the signal strength dropped to about 30% or thereabouts.

I have also used the SC network perforamnce test and everything looks good, so I believe there is a bug.

My router (a Netgear DG834G) has worked well for years now, so I doubt that is the source of the problem.

I have just finished the ethernet cabling in the new house, and so all my SBs are now hardwired and the rebuffering problem has gone away.

SB2, 2 x SB3, TP, Duet - Ubuntu 9.04, SC 7.3.4 27392, Dual core Xeon server

A couple of thoughts:

While it shouldn't be considered a duplicate, there *may* be a relationship between this and Bug 9393.  Just a possibility to keep in mind.

On test methodology, I think we need to distinguish between bandwidth constriction as it occurs on the internet compared to how it occurs on a shared wireless medium. Using tc to simulate router-based packet delay and loss, as was done to investigate 9393, is quite clever and appropriate for that particular bug.

What might be more appropriate to *this* investigation, however, is to have actual collisions, random backoff and retries on a shared medium. What happens when CSMA/CA based in protocols are in use with some alien beacons and traffic from co-channel WLAN signals?  What happens when some of the traffic is protected by RTS/CTS protocol and others not (e.g. in mixed .11b and .11g networks? What happens when a SB hears an RTS but is too far away to hear the corresponding CTS?  

My overall point is that a congested wireless medium can trigger different failure mechanisms than distant routers on the internet dropping packets, so different test procedures would be needed for each.

Bug 9517 meant that, prior to 7.3 (SB fw 117, TR fw 67, SBR fw 52, SBB fw 37), FLAC playback was almost incapable of generating the necessary underrun events to provoke rebuffering. There may have been gappy playback but no "rebuddering" would have occoured.

I guess that it is possible that there is some other f/w bug that means that underrun events are now being generated unnecessarily, in turn provoking rebuffering when it is not needed.

I use an ethernet connection to my SB3 (I stream FLAC almost exclusively), and I still get rebuffering and "gappy playback".  I use a Linksys router that has worked well for me for several years.

I haven't been able to make heads or tails of what may be causing it or what may alleviate the problem.  Sometimes it seems to help if I reset the SB3, other times not.  Resetting my Readynas Duo unit doesn't seem to help.  I do find that I have more problems with playback breaking up and stopping (and sometimes not restarting for as long as half an hour or more) after I browse my collection, either at the unit or on the pc.  It may be that the problems I'm experiencing are actually multiple problems with multiple causes, I'm not sure.

(In reply to comment #4)
> I use an ethernet connection to my SB3 (I stream FLAC almost exclusively), and
> I still get rebuffering and "gappy playback".  I use a Linksys router that has
> worked well for me for several years.
> 
> I haven't been able to make heads or tails of what may be causing it or what
> may alleviate the problem.  Sometimes it seems to help if I reset the SB3,
> other times not.  Resetting my Readynas Duo unit doesn't seem to help.  I do
> find that I have more problems with playback breaking up and stopping (and
> sometimes not restarting for as long as half an hour or more) after I browse my
> collection, either at the unit or on the pc.  It may be that the problems I'm
> experiencing are actually multiple problems with multiple causes, I'm not sure.

Chris,

Is there any chance you could try running SC with a more powerful machine, just for debugging purposes?  This would obviously cost you time and effort, but would help divide issues related to lack of CPU bandwidth from lack of Network bandwidth. It is quite possible that ReadyNas Duo is occasionally too busy with other tasks to properly serve the stream. And MySQL itself has been known to create bursts of heavy demand on the CPU for no apparent reason. 

Don't get me wrong, I think it may well be something other than the ReadyNas CPU limitation, but we shouldn't jump to conclusions with supporting data.

> CPU limitation, but we shouldn't jump to conclusions with supporting data.

That would be *without* supporting data!

Something I just realized is that about the same time I started having the rebuffering problems, I stopped seeing so many "Can't connect" messages on my SB3s.  I hadn't really thought about the possible connection until the comment activity on bug 10393 started up again and I realized that particular annoyance hadn't been an issue for me in awhile.  As I recall, there were supposed to be improvements in network performance with this latest release...I wonder if perhaps instead of losing the connection completely, some of us are getting limited connections that result in the rebuffering.

Maybe no relationship at all, but I thought I'd throw it out there for consideration.

(In reply to comment #4)
> I use an ethernet connection to my SB3 (I stream FLAC almost exclusively), and
> I still get rebuffering and "gappy playback".  I use a Linksys router that has
> worked well for me for several years.
> I haven't been able to make heads or tails of what may be causing it or what
> may alleviate the problem.

I had a problem with my SBR this past weekend.  It got into a state where it just would not play music without rebuffering.  Factory reset/power cycle, different playlist - nothing worked.

What did work was power cycling my Linksys router.

You might give that a try.

Tonight I decided to dig a bit deeper into the rebuffering issue of 7.3.3. I wanted to run a network trace on my network to capture the data that gets transmitted between one SB3 and SC. Due to that, I had to hook up a HUB between my existing switch and my AP. I connected my PC also to this HUB. This way my PC is able to see the traffic on the AP. I ran some traces but I couldn’t capture any traffic between my SB3 and SC. What protocol is SC using to stream the music to the SB3?

The HUB has some LED status indicators. I noticed that the bandwidth consumption of the steaming is around 15% (this is a 10Mb HUB). At the end of a song it goes up to 30%, which is quite heavy network traffic. I’m streaming wav.
Also, my SB3’s are sending out ARP’s every minute, requesting the MAC address of my ReadyNAS NV+, which is running SC. Is that normal?

Since I couldn’t get to capture any data with the network sniffer, I decided to downgrade SC to 7.2.1. First impressions are good: I didn’t experience any rebuffering until now. With 7.3.3. I always experienced a rebuffering when playback starts. With 7.2.1 I don’t experience that anymore even when SC is rescanning my library at the same instance. The SB3’s are still ARPing the SC machine every minute with 7.2.1.

Hello Pascal,

There are two TCP connections used between SC and the SB3: port 3483 for the control protocol (Slimproto) and port 9000 for the streaming. A new streaming connection is made for each track.

A burst of traffic near the end of a track (starting about 10s before the end) is normal. At this point SC starts to stream the new track to the player and it starts off by refilling its buffer (3MB), using all the available bandwidth.

If you are prepared to reinstall 7.3.3 then, in addition to trying again to get a network capture (armed with the information above) then another useful diagnostic tool would be logging from SC. If you enable logging for network.protocol.slimproto at level INFO and can capture a sequence including the rebuffering problem then this would be very useful. Please attach a (compressed) copy of the logfile to this bug. It would be useful to include a significant period of logging before the actual rebuffering problem so that I can see the pattern. 

I you are able to capture a simultaneous network trace then this too could be helpful - you could limit the capture to the first 120 bytes of each packet.

There have been a variety of reports similar to yours, although each rather different in detail. In some cases there has been a clear explanation. We have been unable to reproduce these problems internally so any support that you can give us in capturing diagnostic information would be much appreciated.

Cab you confirm what format of music you are streaming (MP3, FLAC, ...).

I cannot answer the ARP questions.

Chris, Charles,

If you enable logging for network.protocol.slimproto at level INFO and can capture a sequence including the rebuffering problem then this would be very useful. Please attach a (compressed) copy of the logfile to this bug. 

I have a nasty suspicion that this problem may be related to something more low-level in the networking protocols that the logging will show, although the logging should still give us a strong pointer. If either of you have the technical knowledge and opportunity to also do a network trace then that could provide additional information.

I am changing the title to restrict this bug to streaming of local FLAC tracks only. There are other cases where rebuffering can be a problem but, upon investigation, these can usually be explained. There remain a number of reports about local FLAC streaming where we have no good explanation and this bug report should focus on that.

Alan,

I’m streaming WAV, not FLAC.

I have retired my old file server some time ago. I will first try to reproduce the rebuffering on that computer. (I don’t like to fiddle too much with my ReadyNAS NV+).
I will report back here when I have the required info for you.

(In reply to comment #13)

> I’m streaming WAV, not FLAC.

Are you streaming from WAV files or is there some transcoding going on?

(In reply to comment #14)
> (In reply to comment #13)
> > I’m streaming WAV, not FLAC.
> Are you streaming from WAV files or is there some transcoding going on?


No transcoding, I'm streaming WAV files. I need WAV format for other digital media players and I want one single music database for all my players (easier to manage).

I’m preparing a system to capture the required traces. How do I enable the requested logging: “network.protocol.slimproto at level INFO”?

Some more feedback on 7.2.1: I haven’t experienced any rebuffering until now. This version also feels a lot more responsive than version 7.3.3 on my ReadyNAS NV+. For example: shutting down the SC service is instant with 7.2.1 – with 7.3.3 it takes about a minute before my SB’s go blank. Maybe there is a lot more code running in 7.3.3? And maybe not all systems do require some parts of the code (due to components in the system). If that’s the case then we might look into the option of making SC more modular – let some parts be enabled or disabled depending on the hardware in the system.

Hi Pascal -

Are you absolutely sure you are not transcoding?  As far as I recall, if you play a wav file on a squeezebox, the default configuration is for it to transcode it to FLAC on the server before it sends the data to the player.  Unless you explicitly changed that, you are probably actually streaming FLAC.

Rich

(In reply to comment #16)
> Hi Pascal -
> Are you absolutely sure you are not transcoding?  As far as I recall, if you
> play a wav file on a squeezebox, the default configuration is for it to
> transcode it to FLAC on the server before it sends the data to the player. 
> Unless you explicitly changed that, you are probably actually streaming FLAC.
> Rich

Hi Rich,

I was not aware of that. I never changed any configuration parameters that would change the behaviour of streaming WAV. So I guess I must be streaming FLAC then (transcoding).

Created attachment 5656 [details]
Rebuffering logs

I reinstalled 7.3.3 on my NV+.
I enabled the logging as requested. It took a while before I experienced a rebuffering. Usually, I get one a the beginning of random song mix. Since I was logging right after a re-install of SC, SC was still scanning my library. After a while I decided to sync my two SB3’s but even that did not force a rebuffering event. So, I then loaded the webpage on SC – pressed F5 and then pressed FWD on the remote. That does trigger a rebuffering event (SC was still scanning my library). 
I have attached three rebuffering logs. The filename holds the time when the rebuffering occured (example Rebuffering 20-19.rtf holds the data of rebuffering occured at 20:19 or 8:19 PM for some of us). For the third rebuffering I also have captured a TOP listing of my NAS. Hope it contains useful data.

Created attachment 5657 [details]
Rebuffering events after library scan - see additional post.

One other event noticed: round 21:07 SC finished scanning my library. At that time my SB3 when silent for several minutes. The displayed was frozen on the analogue VU meter. During this whole event my SB did not respond to any remote commands. The log showed this line:

[09-08-21 21:07:52.9207] Plugins::LazySearch2::Plugin::scanDoneCallback (2059) Lazifying database items not already done

After SC finished scanning I got a lot of rebuffering events. I have attached one of those as well although I guess the information is the same as the previous ones. I noticed that CPU consumption of SC is very high (around 80% and it fluctuates around this number). MySQL events seems to consume a lot of CPU as well. Maybe SC is optimizing the DB after a library scan(?). 
Anyway, this is very annoying behavior and didn’t happen at all with 7.2.1.

I captured a network trace of a rebuffering event. 
Again I sync’d my two SB3’s. Load the webpage of SC on IE. Press F5 to refresh and then press FWD on the SB3 remote. My SB stopped playing the next song at 20:07:34. It continued playing at 20:07:38.
At first glance, this is what I believe is happening: pressing F5 causing SC to reload the webpage on IE. Since I also pressed FWD on the SB remote, the SB now needs to load its buffer with the next song. But the reloading of the webpage gets all the attention, leaving almost no room for the SB to receive buffer data. This leaves the SB with insufficient data in its buffer to play continuously. 

Since the streaming data is important and it creates quite a lot of traffic on the network, the streaming task should have higher priority than other tasks (such as the HTTP traffic to reload a SC webpage). The streaming packets are quite large since most of them get fragmented over several TCP packets. I counted over 34000 packets per minute (2 SB’s sync’d).

SC is running on my NV+ which has IP 20.108.5.4.  My SB’s have IP’s 20.108.10.2 and .3. My laptop has 20.108.10.4. You can read the capture with Microsoft Network Monitor which can be downloaded from their website for free.
Hope this is useful data too. 


EDIT: I tried to upload the captured file (zipped) but it still is too large. Is there an FTP server that I can upload it to?

Pascal,

Thank you for taking the trouble to capture these lofgile and the network trace. I will see if I can find a place where you can upload the network capture but it may not be relevant - see below.

Only one of your logfiles actually shows a rebuffering event. You need to include a much larger portion of the logfile. Also, it would be better if you could just attach the plain text logfiles (or a zipped version of them) rather than converting them to RTF.

But I suspect that it does not much matter. The short section from the one file that does show a rebuffering event is clear enough; the player runs out of data. The question is why?

You say that you had to load up your ReadyNAS NV+ by syncing a couple of players, reloading the web page, and skipping a track, possibly also sometimes with DB scanning in progress or additional activities by a third-party plugin (LazySearch) in order to provoke the buffering. Perhaps not all these were happening at once but nonetheless, the ReadyNAS is a critically underpowered server and it does not surprise me that is sometimes fails to keep up, especially when heavy DB or web activities are under-way.

I also realise that you are concerned that the issue is the change in behaviour between SC 7.2.1 and 7.3.3. In fact, the streaming code in 7.3 is both smaller and faster than that in 7.2, although the Web-UI is probably quit a bit more resource-intensive.

Are you using any other third-party plugins? You might try disabling all such plugins to see if the behaviour changes. At least some of them will likely have changed with the upgrade to 7.3 and could possibly be interfering with streaming. It is particular the case that activities that happen around a track transition are most likely to cause a problem with streaming (although in the case of the example in your logfile this was clearly not the case as it was more than 200s in to the track).

On the issue of WAV vs FLAC streaming. If your files are WAV files then, exceptionally on the ReadyNas platform, they will indeed be streamed as WAV. On other platforms they would be transcoded to FLAC. Note that WAV files are typically more than twice the size of the equivalent FLAC files and consequently need that much more effort to stream them.

Another line of investigation that could be tried is to enable performance monitoring in SC. This might reveal what activities are stealing the CPU for long enough to interrupt streaming.

This tends to tie in with what I'm seeing. 7.3.3 appears to be much more CPU intensive thanb previous versions. At the moment I have an Athlon XP 3200 running Small Business server. Although I have server priority set to the maximum I rarely see squeezecentre at the top of the taskmanager list ordered by CPU usage, but it uses more than it ever has before.

I'm sure when I migrate to a Quad core media server it will improve, but if possible I'd like any efficiency added to the code to help those of us who are running on older hardware.

Turning off virus scanning on read for the music folder helps too.

Tim

Hi Paul,

The loggings that I uploaded where logs where I forced SC to go into a rebuffering state. That is why I did all those things (sync, loading web pages, scanning lib, etc). In a normal situation, these things would not happen at the same time. I usually experience rebuffering at the start of a playlist (in random song play mode) and then sporadically during playback. I have experienced rebuffering events where I know that my NAS wasn’t under heavy loads – cases where SC was basically the only service that was used. No users where accessing the NAS. Because of the fact that it does not always happen, it is not easy to capture the required logs in such situation. Therefore I logged the “forced rebufferings”. 

I understand that the NV+ isn’t the most powerful machine in the world, but that should not be the reason why the rebuffering occurs. The NV+ has a gigabit Ethernet interface to be able to provide high speed network shares. There are lots of people who use these NASes for video streaming too. Video streaming would generate a lot heavier loads. 
The rebuffering does not happen at all with 7.2.1 and as you say, the streaming engine of 7.3.3 is supposed to be a lot smaller and better performing. That is why it is not logic why the rebuffering would appear on 7.3.3. There are even people with Windows machines that experience the same behaviour. It is clear that something is wrong with 7.3.3.

SC should be a small and tiny service that runs on a “server machine”. Server machine could be anything from file servers to a NAS. It should be able to run just fine on slower, less performing hardware. If SC would require a huge and powerful machine then there is something wrong with the concept. SC is only an audio streaming engine. The NV+ is able to copy large files at high rates. See the specs here: http://www.readynas.com/?p=331#Performance 
There is no reason why a WAV file would bring down the NAS to its knees. 

I’m sure there is lots of room for performance improvements in SC. For example: the web pages that SC generates are very nice to look at but they are extremely heavy. In the network capture that I made this is very obvious. There are lots of HTML packets that are spread over multiple TCP packets. You know that a TCP packet can be 1500 bytes large (of course that includes different headers of the TCP layers). So you understand this is heavy. For now I have configured SC to use the Classic web pages look and that is a lot better in terms of page load time. I have no need for fancy web pages since I only use them to setup and configure SC. I don’t use those pages to control SC – I have the remotes for that purpose and iPeng on my iPod (with works fine).
One thing that was obvious in the network traces is that SC doesn’t seem to provide higher priority for the more important processes such as the streaming process. When I pressed F5 on the web browser, SC gave all its attention to reload the HTML page. That is the reason why the system ran into a rebuffering event in the above tests. Again, this would not happen during normal system usage. So your question is still a valid one: why does the SB run out of buffer under normal circumstances? We already have a good idea why it happens under the “forced” environment. I’m very happy to assist anywhere I can. So let me know what other captures you need in order to investigate further. 
I will turn off the Lazy Search plugin because obviously that plugin can generate a lot CPU load. 

You mentioned to enable the performance monitor on SC. I have searched for that switch but didn’t find it. Can you explain how to enable that feature?

(In reply to comment #25)
> Hi Paul,


That should have read "Hi Alan". Sorry for the mistake.

this is an administrative shuffle on priority fields to help make better judgment on the top end of the priority list. P4->P5, P3->P4, and P2->P3.

Your can enable performance monitoring with the following flags:

--perfmon --perfwarn=0.5

This will cause it to log any events which take longer than 0.5 seconds.

Since I have configured SC to use the Classic UI, I haven’t experienced any rebuffering until now with 7.3.3. I didn’t change anything else either. LazySearch plug-in is still running. This is very strange. I can’t believe that the webpage UI would have any effect on playback of the system. Weird...

Yes, I find that a little surprising. I think perhaps that the new WebUI does more-frequent asynchronous updates which overload teh server in some way. Do you tend to use/have long playlists.

I think that the performance-monitoing mentioned earlier could still be useful. Especially if you can provoke the rebuffering again by using the default Web UI.

> Yes, I find that a little surprising. I think perhaps that the new WebUI  
> does more-frequent asynchronous updates which overload teh server in  
> some way.

The web UI hasn't seen anything but minor changes (mostly cosmetic) in  
months. The polling did not change. Maybe the request handler did?

Yes, and I need to mention that I don’t use the web UI during normal playback either. I only did that to force a rebuffering event faster. So, which UI interface is configured should not matter at all. 

Just for my information: I have entered the performance command (as above) in the CLI. Is that the correct way to do it? And do I need to switch it off in some way?

You need to start SqueezeCenter with those additional arguments.

SC is running on my NV+. I have no idea how to do that since SC is controlled through FrontView. It runs as a service. Do you know how to do that?

Michael, can you help?

This would require some command line editing in vi... There's no easy UI for this, I'm sorry.

(In reply to comment #36)
> This would require some command line editing in vi... There's no easy UI for
> this, I'm sorry.

I could copy that particular file to a share and then edit through notepad on a Windows computer. After editing, I simply copy it back to its original location.
Which file would need editing?

In /etc/default there's a file squeezecenter (or squeezebox or similar - depending on the exact revision you're running). Add the above params to the "SLIMOPTIONS" line:

SLIMOPTIONS="--perfmon --perfwarn=0.5"

Okay, that part went well. I know have an additional log called “Performance Log File” under the information tab. I had a quick glance at it and it already had some entries. 
Still no rebuffering though. Since you confirmed that the webpages UI would not interfere with playback performance I have enabled the default skin again. 

There are other people here who also experienced rebuffering events. I believe it would be a good thing for those people to try and capture logs too.

(In reply to comment #39)

> There are other people here who also experienced rebuffering events. I believe
> it would be a good thing for those people to try and capture logs too.

Yes, after several months looking at this issue, I think that performance logs could indeed be useful.

Created attachment 5866 [details]
Performance log

Hi Alan,

Up until now, I haven’t experienced any rebuffering event. It is quite strange because the system configuration has not changed at all. Nevertheless, I have uploaded a performance log. I hope it will tell you something.

Thank you for the log. There are many interesting things in there.

But first a few things about what you are streaming and some information about how SC works.

Earlier you said that you are streaming WAV files and I suggested that these should be transcoded to FLAC by default. This is probably a wrong observation for the ReadyNAS, as it generally does not have enough CPU power to transcode to FLAC. So indeed you probably are streaming WAV. You could check this via the WebUI: Settings / Advanced / File Types and look at the entry for 'WAV'; it will probably just say 'Native'.

So, if you are streaming WAV then (assuming 44100 samples/s, stereo, 16-bit samples) the audio data rate will be 176kB/s. An SB3 has two buffers: one for decoded data which holds 10s of audio, and one for encoded data of 8MB which, for WAV, will hold 17s of audio data. So, if both buffers are full and there is some interruption to streaming then you have a maximum of 27s of data before audio will underrun and rebuffering will occur.

At track start it is more complicated. For an unsynchronized player, playback will start after 255kB of data has been received, which for WAV will be 1.4s of audio. It is not possible to set this period any higher.

For synchronized players this startup period is even smaller - by default 4kB => 23ms, although in practice the various protocol exchanges that occur as part of synchronized track start mean that considerably more data will likely have been buffered before audio starts. This is probably a hangover from the days when it was necessary stop and restart playback between tracks for synchronized players (and therefore things like gapless and crossfade did not work) and which (with 7.3) is no longer the case; it should probably be increased to 255kb. There is a per-player server preference for this value but it is not exposed by any UI. It could be set via the CLI. There is another variable that is exposed by via the WebUI: Settings / Advanced / Network / Synchronized Players Startup Delay (ms). Increasing this from its default of 100ms would allow time for more audio data to be buffered before playback starts.

The times discussed in the preceeding two paragraphs only relate to playback that starts when you press Play, or otherwise intervene to tell the SBs what to play. When one track follows another then the new track starts streaming 10s before the previous one ends. If you are using the crossfade feature, then this headroom is effectively reduced by the duration of the crossfade that you have configured.

SC is a single-threaded application. That is, internally, it only does one thing at a time. If something causes it to do a long database query, for example, no streaming will occur while that query is in progress. SC uses a number of mechanisms internally, such as asynchronous queued event dispatch and the servicing of high-priority tasks (such as streaming) within the main loops of certain long-duration tasks, to mitigate against the problems that could be caused by its single-threaded nature. But single-threaded it is.

Given the numbers above, it should be obvious that any actions which occur around the time a track starts could potentially interrupt streaming sufficiently to starve a player of data before it has time to fill its buffers. This is clealy worse for the first track played [14s] (especially for synchronized players [0.023s]) than for subsequent tracks [10s]. Any network congestion or reliability issues will clearly exacerbate these issues.

I would observe that the combination of WAV streams and a ReadyNas is far from ideal. The ReadyNas is very short of CPU power (probably only around 1/10th that of the minimum recommend system with a 733MHz Pentium class CPU) and so routine events can take so much longer on it. The lack of compression in WAV streams means that these interruptions, and any network congestion, are more likely to cause problems.

So, on to your performance logfile. As you said, you did not actually experience any rebuffering problems during this period, but there are still several incidents of note:

[09-09-01 21:31:48.0054] Database Access  >   0.5 :  0.77365  SELECT COUNT( DISTINCT( me.id ) ) FROM tracks me WHERE ( me.audio = ? ): `1'
[09-09-01 21:31:48.0256] Request Task     >   0.5 :  1.43856  Execute: Slim::Control::Queries::serverstatusQuery
[09-09-01 21:31:48.0424] Select Task      >   0.5 :  1.48832  Slim::Web::HTTP::processHTTP
[09-09-01 21:31:48.0691] Response Time    >   0.5 :  1.51573  

I guess that this was when you had the WebUI open in the default skin. It performs a regular poll and it appears that this includes a pretty inefficient query. We will look into fixing that. The 'Classic' skin does not do this polling.

[09-09-01 21:34:33.9927] Response Time    >   0.5 :  0.95589  
[09-09-01 21:34:36.8462] Request Task     >   0.5 :  1.66910  Notify: Slim::Plugin::RandomPlay::Plugin::commandCallback

When using RandomPlay, there is a callback that occurs when a track starts playing. It looks like this could be a particular problem in your set of circumstance, especially for the first track.

[09-09-02 10:30:41.1330] Timer Task       >   0.5 :  9.78112  Plugins::WeatherTime::Plugin::tictac
[09-09-02 10:30:41.1402] Response Time    >   0.5 :  9.78870  
[09-09-02 10:30:50.9113] Timer Task       >   0.5 :  9.75579  Plugins::WeatherTime::Plugin::tictac
[09-09-02 10:30:50.9184] Response Time    >   0.5 :  9.76337  

You are using a third-party plugin called WeatherTime. Once an hour this does two 10s duration operations, back to back. Clearly these would be a problem if they happened at an inconvenient moment.

[09-09-03 02:38:17.0751] Database Access  >   0.5 :  0.86419  SELECT me.id, me.artwork, me.title, contributor.name, contributor.namesort, me.titlesort, me.musicmagic_mixable, me.disc, me.discc FROM albums me  JOIN contributors contributor ON ( contributor.id = me.contributor ) GROUP BY me.id, me.artwork, me.title, contributor.name, contributor.namesort, me.titlesort, me.musicmagic_mixable, me.disc, me.discc ORDER BY concat('0', contributor.namesort),concat('0', me.titlesort),me.disc LIMIT 975: 
[09-09-03 02:38:44.0889] Request Task     >   0.5 : 28.12800  Execute: Slim::Control::Queries::albumsQuery
[09-09-03 02:38:46.7161] Database Access  >   0.5 :  1.63148  SELECT me.id, me.name, me.namesort, me.musicmagic_mixable, me.namesearch, me.musicbrainz_id FROM contributors me LEFT JOIN contributor_album contributorAlbums ON ( contributorAlbums.contributor = me.id ) WHERE ( ( ( contributorAlbums.role IN ( ?, ? ) ) ) ) GROUP BY me.id ORDER BY me.namesort LIMIT 2228: `1', `5'
[09-09-03 02:39:13.1377] Request Task     >   0.5 : 28.54264  Execute: Slim::Control::Queries::artistsQuery
[09-09-03 02:39:14.9791] Request Task     >   0.5 :  1.69319  Execute: Slim::Control::Queries::genresQuery
[09-09-03 02:39:16.0264] Database Access  >   0.5 :  0.81966  SELECT me.id, me.artwork, me.title, contributor.name, contributor.namesort, me.titlesort, me.musicmagic_mixable, me.disc, me.discc FROM albums me  JOIN contributors contributor ON ( contributor.id = me.contributor ) GROUP BY me.id, me.artwork, me.title, contributor.name, contributor.namesort, me.titlesort, me.musicmagic_mixable, me.disc, me.discc ORDER BY concat('0', contributor.namesort),concat('0', me.titlesort),me.disc LIMIT 975: 
[09-09-03 02:39:43.0166] Request Task     >   0.5 : 27.97168  Execute: Slim::Control::Queries::albumsQuery
[09-09-03 02:39:45.6156] Database Access  >   0.5 :  1.61824  SELECT me.id, me.name, me.namesort, me.musicmagic_mixable, me.namesearch, me.musicbrainz_id FROM contributors me LEFT JOIN contributor_album contributorAlbums ON ( contributorAlbums.contributor = me.id ) WHERE ( ( ( contributorAlbums.role IN ( ?, ? ) ) ) ) GROUP BY me.id ORDER BY me.namesort LIMIT 2228: `1', `5'
[09-09-03 02:40:12.5719] Request Task     >   0.5 : 29.05459  Execute: Slim::Control::Queries::artistsQuery
[09-09-03 02:40:14.5243] Request Task     >   0.5 :  1.78681  Execute: Slim::Control::Queries::genresQuery
[09-09-03 02:40:14.5469] Request Task     >   0.5 : 118.63036  Notify: Slim::Control::Jive::buildCaches
[09-09-03 02:40:14.5540] Response Time    >   0.5 : 121.01908  

Whenever SC starts or a rescan completes, a series of caches are built. This activity takes around two minutes on your server and no streaming occurs the whole time. I will look to see if this can be improved.

[09-09-03 02:38:15.1612] Database Access  >   0.5 :  1.45106  SELECT COUNT( * ) FROM tracks me  JOIN albums album ON ( album.id = me.album ) WHERE ( ( ( me.customsearch NOT LIKE ? ) OR ( me.customsearch IS NULL ) ) ): `%|%'
[09-09-03 02:38:15.1704] Request Task     >   0.5 :  1.59952  Notify: Plugins::LazySearch2::Plugin::scanDoneCallback
[09-09-03 02:40:16.5978] Database Access  >   0.5 :  1.25192  SELECT me.id, me.title, me.customsearch, album.id, album.titlesort, album.contributor, album.compilation, album.year, album.artwork, album.disc, album.discc, album.musicmagic_mixable, album.titlesearch, album.replay_gain, album.replay_peak, album.musicbrainz_id, album.title FROM tracks me  JOIN albums album ON ( album.id = me.album ) WHERE ( ( ( me.customsearch NOT LIKE ? ) OR ( me.customsearch IS NULL ) ) ): `%|%'
[09-09-03 02:40:17.0992] Scheduler Task   >   0.5 :  1.79319  Plugins::LazySearch2::Plugin::encodeTask
[09-09-03 02:40:17.1059] Response Time    >   0.5 :  1.80132  
[09-09-03 02:40:18.1272] Scheduler Task   >   0.5 :  0.50902  Plugins::LazySearch2::Plugin::encodeTask
[09-09-03 02:40:18.1339] Response Time    >   0.5 :  0.51707  
[09-09-03 02:40:19.1695] Scheduler Task   >   0.5 :  0.51389  Plugins::LazySearch2::Plugin::encodeTask
[09-09-03 02:40:19.1762] Response Time    >   0.5 :  0.52202  
[09-09-03 02:40:20.2520] Scheduler Task   >   0.5 :  0.51956  Plugins::LazySearch2::Plugin::encodeTask
[09-09-03 02:40:20.2587] Response Time    >   0.5 :  0.52764  
[09-09-03 02:40:21.2798] Scheduler Task   >   0.5 :  0.50477  Plugins::LazySearch2::Plugin::encodeTask
[09-09-03 02:40:21.2865] Response Time    >   0.5 :  0.51293  
[09-09-03 02:40:22.3249] Scheduler Task   >   0.5 :  0.52202  Plugins::LazySearch2::Plugin::encodeTask
[09-09-03 02:40:22.3316] Response Time    >   0.5 :  0.53024  
[09-09-03 02:40:23.3579] Scheduler Task   >   0.5 :  0.50597  Plugins::LazySearch2::Plugin::encodeTask
[09-09-03 02:40:23.3714] Response Time    >   0.5 :  0.52086  
[09-09-03 02:40:24.9003] Scheduler Task   >   0.5 :  0.50974  Plugins::LazySearch2::Plugin::encodeTask
[09-09-03 02:40:24.9714] Response Time    >   0.5 :  0.55112  
[09-09-03 02:40:26.0171] Scheduler Task   >   0.5 :  0.50711  Plugins::LazySearch2::Plugin::encodeTask
[09-09-03 02:40:26.0238] Response Time    >   0.5 :  0.51515  
[09-09-03 02:40:27.0457] Scheduler Task   >   0.5 :  0.50683  Plugins::LazySearch2::Plugin::encodeTask
[09-09-03 02:40:27.0524] Response Time    >   0.5 :  0.51487  
[09-09-03 02:40:28.0721] Scheduler Task   >   0.5 :  0.50539  Plugins::LazySearch2::Plugin::encodeTask
[09-09-03 02:40:28.0791] Response Time    >   0.5 :  0.51371  
[09-09-03 02:40:29.1029] Scheduler Task   >   0.5 :  0.50874  Plugins::LazySearch2::Plugin::encodeTask
[09-09-03 02:40:29.1097] Response Time    >   0.5 :  0.51687  
[09-09-03 02:40:30.6643] Scheduler Task   >   0.5 :  0.51479  Plugins::LazySearch2::Plugin::encodeTask
[09-09-03 02:40:30.6710] Response Time    >   0.5 :  0.53733  
[09-09-03 02:40:31.7094] Scheduler Task   >   0.5 :  0.50659  Plugins::LazySearch2::Plugin::encodeTask
[09-09-03 02:40:31.7161] Response Time    >   0.5 :  0.52920  
[09-09-03 02:40:33.6789] Scheduler Task   >   0.5 :  0.51168  Plugins::LazySearch2::Plugin::encodeTask
[09-09-03 02:40:33.6856] Response Time    >   0.5 :  0.53445  
[09-09-03 02:40:34.7580] Scheduler Task   >   0.5 :  0.52108  Plugins::LazySearch2::Plugin::encodeTask
[09-09-03 02:40:34.7649] Response Time    >   0.5 :  0.53457  
[09-09-03 02:40:35.9424] Scheduler Task   >   0.5 :  0.50429  Plugins::LazySearch2::Plugin::encodeTask
[09-09-03 02:40:35.9492] Response Time    >   0.5 :  0.51735  
[09-09-03 02:40:36.9734] Scheduler Task   >   0.5 :  0.50162  Plugins::LazySearch2::Plugin::encodeTask
[09-09-03 02:40:36.9801] Response Time    >   0.5 :  0.51463  
[09-09-03 02:40:37.9967] Scheduler Task   >   0.5 :  0.50200  Plugins::LazySearch2::Plugin::encodeTask
[09-09-03 02:40:38.0034] Response Time    >   0.5 :  0.51489  

You are using a third-party plugin called LazySearch. This also runs for an extended period after a scan, although streaming probably gets to run between each of the sub-tasks.

None of this specifically points to anything that is likely to be different in 7.3 vs 7.2. Please let us see what the perflog shows if you do experience rebuffering in the course of normal usage.

Update time worked

Hi Alan,

Thank you for the very detailed response on the topic. It now is a bit more clear to me how SC works. And I’m glad the performance log did actually tell something useful.

Your assumption on my WAV files is correct; they are 44100 samples/s - Stereo - 16 bit. And my SC is configured to stream WAV native. I feel better now to know that the SB3 has a total of 27 seconds buffer. That should be enough to overcome most critical situations. If network congestion would come into play that would mean the system is on a very bad designed network. 

I usually do not run any SB’s synchronized (I only did that during the testing phase as an attempt to maximize the load on the system), so I guess I’m usually in the 1,4 second area. I can understand that this is more critical for less powerful systems (such as a typical NAS). If any other lengthy event would occur at this point then a rebuffering is likely to occur. You mentioned that this is a fixed value – is that related to some hardware restrictions?
I could live with a system that takes a bit more time to load a buffer before the initial playback starts. The SB3 could display something like “receiving buffer data” to tell the user that the SB3 is preparing for playback. As I understand it, this would only be the case for the very first song starts to play. In between songs there is a 10 second overlap and I guess that is enough to overcome a buffer under run event. But please correct me if my assumption is not correct.

I am a bit amazed by the 23ms thing for synchronized players though. Even on fast performing systems this could possibly be an issue. 

I am using the crossfade feature and I mostly use the random play feature as well. My crossfade time is set to 10 seconds (default). So I guess this means that my system does not have a lot of room left for “buffer” between songs (?). But I guess this means that also this feature could be a potential risk for high performance systems. Can you comment on this assumption?

The fact that SC is single threaded does explain why rebuffering can occur when reloading the web pages while the system is in playback mode. I guess this is something for your developers to look into. I noticed that SC spends its time on transmitting the web page data and stops sending out buffer data at this point (network traces). On slower systems such as a NAS this is a possible cause for rebuffering events. Of course I need to add that I normally do not use the web pages. Nevertheless, the feeding of buffer data must have absolute priority in the system. 

I understand your statement about WAV streaming on a NAS. But that would mean that no decent quality music streaming would be ideal on a NAS. That is something I find sad to hear.  I’m pretty sure that some performance tweaking should be possible in order to give SC a bit more room for high quality music streaming. If there is a way to improve the 1,4 second buffer at the start of a song I’m confident that this would improve a lot already.  Another candidate is the callback (random play) – maybe there is some room here for optimization too (just guessing). 

I have configured SC to rescan my library at night. So, the rescanning event would not interfere with playback (I’m usually asleep when SC is rescanning my library). So that is no big deal for me. I noticed that the LazySearch plugin does use a lot of processing power after SC finishes a library rescan. But this is not a real issue in my case since that event would also occur when I’m asleep. And if it would bother me too much I can still disable this plugin. 

I will continue to use SC with the performance log activated. If I experience a rebuffering event then I will upload a new log file.

I sure would like to see other users jump in here too. There are quite a few people who complained about rebuffering events. So, I invite anyone who complained about it to enable the performance logs and upload logs of rebuffering events. 
  
Thanks again Alan for your time and effort on this topic.

(In reply to comment #44)


> I am a bit amazed by the 23ms thing for synchronized players though. Even on
> fast performing systems this could possibly be an issue.

Like I said, other protocol exchange have to happen after the 23ms point has been reached, and there is also
the 100ms (default) startup time after this, so in practice more gets buffered. Of couse, most people 
stream FLAC or MP3s, so they get that much more audio time in the same volume of data.

> I am using the crossfade feature and I mostly use the random play feature as
> well. My crossfade time is set to 10 seconds (default). So I guess this means
> that my system does not have a lot of room left for “buffer” between songs
> (?). But I guess this means that also this feature could be a potential risk
> for high performance systems. Can you comment on this assumption?

In practice, all that will happen is that the crossfade will not be as smooth as it should be. Setting the
crossfade period down a couple of seconds should provide comfortable headroom.

 == Auto-comment from SVN commit #28579 to the slim repo by ayoung ==
 == https://svn.slimdevices.com/slim?view=revision&revision=28579 ==

bug 13092: 
Give streaming more room when servicing potentially long-running requests and building Jive caches.

Experienced the same rebuffering issue running 7.3.3 from a synology NAS.  My connection between Squeezecentre and Squeezbox is on wired ethernet, but I still get rebuffering errors consistently since upgrading to 7.3.3.  What is surprising that these errors disappear completely as soon as I turn my computer on that happens to be connected to the same network segment on my Zyxel router.  As soon as the computer goes to standby the rebuffering error appears almost instantenaeously.

Hi Alan,

I’m a bit concerned about the status changes. First priority went down and now the target release went back. I understand that there are a limited amount of people experiencing this issue but I would hate to have to live with this issue for too long.
Do you have a target date on version 7.5.0?

Are you still looking for additional information on this bug?  It started happening to me, too.  Here are details, but as I describe below, I will try to do additional testing in the next week.

First, I have an SB3 and a Boom.  My server is an Ubuntu 9.04 system on an Atom 330 box (1gb RAM).  The server is hard-wired to the router, the Boom and SB3 connect wirelessly.  The Boom is on the same floor but different room from the router.  The SB3 is on one floor below and almost directly underneath the router.  The Boom consistently gets 85-90% signal; the SB3 consistently gets 93-99% signal.  My collection is a mix of flac and mp3.  I usually use the most recent stable release, so I've been using 7.3.3 and then 7.4.  The problem did not occur when I upgraded to 7.3.3; rather I used 7.3.3 for a while and only recently did it show up.

I've owned the SB3 for a while now and I never had a single instance of rebuffering until about two weeks ago.  I should note that I did replace my router about a month and a half ago, but everything worked perfectly for about a month with the new router before I got any rebuffering.  Over the last couple weeks I would notice it occasionally, perhaps every other day, once over the course of a few hours of listening (often close to when I started listening).  I thought perhaps upgrading to 7.4 would change something, so I tried that.  After that, flac files became unlistenable.  Rebuffering constantly occurs, often multiple times within a song.  I have rebooted everything--SB3, router, and server--still no luck.  Hardwiring the SB3 to the router fixes the problem, at least as long as I've had it wired up (I've only tried it for about a half hour).

It looks like the problem only occurs with the SB3 and not the Boom (at least not yet), even though the signal strength for the SB3 is better than for the Boom.  I also used the Network Test function on the SB3 and Boom and there is clearly something wrong with the SB3's connection.  With the Boom, I can get up to about 2500K before things start dropping under 100%, and then the drop is gradual and the system is always responsive.  With the SB3 as soon as I get above 1000K (and sometimes before that), it drops consistently and shows additional problems:

Once I try running above 1000K, the SB3 gets unresponsive and sometimes will lose connection with the server completely.  If I keep the test at 500K it will stay connected and never get unresponsive.  This unresponsiveness and loss of connection is identical to what happens when I play music.  If I stream internet radio or play mp3s, there are no problems at all. If I stream flacs, the SB3 often gets unresponsive, the files rebuffer, and sometimes I lose connection to the server altogether (at least temporarily).

Is there any additional info that I can provide to help get this fixed?  This week (not sure when I'll get to it) I'm going to try varying a bunch of factors.  I'll start with a new install on a more powerful system.  Then I'll test:

SC version (7.2.1, 7.3.3, 7.4)
Router (my old one and my new one)
Location (separate floor, next to router)
Wireless security (no security, WEP, which is what I used to use, and WPA2, which is what I now use)

Any other variables I should try and any log information that would be useful?

My guess is that this is a network problem. Either the new router, or some newly arrived wireless interference - perhaps a neighbour. You really need to be able to get to 1000K with the network test for FLAC to stream reliably.

You do not say what OS the server is running.

If you want to try to see if it is the server getting congested then you could try running with performance monitoring enabled. Start the server with the following options added: --perfmon --perfwarn=0.5.

This is definitely an issue for.  I just upgraded to 7.4.0

Moving these bugs to P4 to make room for moving P1.5 bugs to P2

Administrative move of 7.5 bugs. All P2, P3, P4 being downgraded one level. Will then split P1s.

Some improvements have been mad on the embedded branch that may be relevant. These will get merged to the trunk at some stage.