PDA

View Full Version : Problems caused by long waits to build web pages - any performance tweaks?



SadGamerGeek
2006-07-02, 10:15
I started a thread in the 3rd Party Plugins forum, about use of the web front end taking so many resources that (AlienBBC) streaming music freezes ("AlienBBC - radio stations interrupted by web page access")

After some suggestions I upgraded from 6.22 to the lastest 6.5 Beta, in the hope that the combination of MySQL and split-scanner might sort out my problems. This has certainly helped, and the freeezes are now less often.

I still get such problems though, and I assume these are down to lack of communication between the server & client. After a suggestion on the other thread I set --perfwarn=0.5.

I now get lots of log output, as just about anything web related seems to talke longer than half a second (even when nothing is happening).

To give some an extreme examples, here are the sort of things logged when I slect "All Songs" on the web page:



2006-07-02 17:40:25.0129 Timer Late > 0.5 : 2.54691505432129
2006-07-02 17:42:04.1963 Web Page Build > 0.5 : 204.450978040695
2006-07-02 17:42:04.2009 Generating page for browsedb.html
2006-07-02 17:42:04.2676 Select Task > 0.5 : 204.671139955521
2006-07-02 17:42:04.2857 Slim::Web::HTTP::processHTTP
2006-07-02 17:42:04.2884 IR Delay > 0.5 : 198.674467802048
2006-07-02 17:42:05.1504 Web Page Build > 0.5 : 0.698230028152466
2006-07-02 17:42:05.1545 Generating page for status_header.html
2006-07-02 17:42:05.1607 Select Task > 0.5 : 0.866274118423462
2006-07-02 17:42:05.1633 Slim::Web::HTTP::processHTTP
2006-07-02 17:42:05.9030 Select Task > 0.5 : 0.580109119415283
2006-07-02 17:42:05.9057 Slim::Web::HTTP::processHTTP
2006-07-02 17:42:05.9081 IR Delay > 0.5 : 0.678067922592163
2006-07-02 17:42:05.9293 IR Delay > 0.5 : 0.698479890823364
2006-07-02 17:42:05.9415 IR Delay > 0.5 : 0.709849119186401
2006-07-02 17:42:05.9535 IR Delay > 0.5 : 0.721158981323242
2006-07-02 17:42:05.9682 IR Delay > 0.5 : 0.733943939208984
2006-07-02 17:42:05.9820 IR Delay > 0.5 : 0.747066020965576
2006-07-02 17:42:36.1573 Select Task > 0.5 : 0.735414981842041



204 seems a lot of seconds to wait for a web page to come back. Also, during that time the squeezebox is completely unresponsive.
During this time slimserver.pl averages around 92% CPU, with flac, mplayer, mysql fighting for the rest.


It has been suggested to me that this might be best discussed in the Beta forum, so here I am.


My set-up:

I am running the very latest (at time of typing) SlimServer build - 6.5b1 - 8242.

My OS is Linux Fedora FC5 with no X-Windows or unneccessary services. I run this on an Epia Via motherboard with a 1Ghz processor and 512MB RAM. No other software (other than directly related to SlimServer) runs on this machine.

I have one client - a Squeezebox 3. I nornally run this wirelessly, but when I tried it wired I didn't see any obvious impreovement.

My music library contains 535 albums with 6451 songs by 232 artists.



I hoped that 512MB of RAM (with very little used by the OS) would allow for the database to do some really good caching (especially given the relatively small amount of music I have), thus giving quick web access. Is there anything I can do to force the database to use spare memory for cache? Any other suggestions gratefuly received...

Cheers,

Richard

Patrick Dixon
2006-07-02, 12:33
The only thing I can suggest is that you try using the Nokia770 skin as when I last tried it, it seemed faster to me.

Other than that I suspect you just need a faster processor. I recently ditched my old PII 300MHz server for a 2GHz Althon 64 and the web interface is like lightening by comparision!

Triode
2006-07-02, 12:42
Richard,

That doesn't show long "Response Time" which are the time between the server checking to see if the client needs more data. This is good - it should minimise the chance of audio streams stalling.

However the 204 seconds for a page build seems extremely long. I hope we can engage Dan here to see if there is anything which can be done about this. During this time the player user interface will be unresponsive.

Dan - any views? Is there any extra instrumentation I can add on the database calls now we have split scanner code introduced?

Adrian

Triode
2006-07-02, 12:57
As a datapoint, my server takes ~8 seconds to display All Songs from a database of 9000 songs after restaring slimserver. [but I guess the database files may be in memory]

Server is an AMD Gecode 1.4Mhz (linux 2.6 says 2777.08 BogoMIPS), 512M of ram.

Are you using the version of MySQL shipped with the server [test above is doing so]

SadGamerGeek
2006-07-02, 13:04
The only thing I can suggest is that you try using the Nokia770 skin as when I last tried it, it seemed faster to me.

OK - Thanks - I'll have to give that a go.




Other than that I suspect you just need a faster processor. I recently ditched my old PII 300MHz server for a 2GHz Althon 64 and the web interface is like lightening by comparision!

I'm sure a faster processor would help, but I can't help feeling that that just avoids the root cause of the problem. As I've just added to someone else's thread, I run twonkyvision on a Linksys NSLU2 with a 266Mhz processor and 32MB of RAM. It has a web interface for listing songs/albums/artists, and it responds (with exactly the same set of music files) in a fraction of the time of SlimServer.

There must surely be a config problem with my set-up. If not, there must be some pretty major potential performance improvemnt possibilities in the cuurent code...

I try to do my bit re. avoiding wasting energy, and as I want to run my music server 24/7, I was keen to find one with low power consumption. I'm running my 1Ghz Epia machine on a 65Watt power supply, so I don't feel too bad about leaving that running all the time. I'd feel somewhat worse about something soaking up many hundreds of watts of power all day.....

SadGamerGeek
2006-07-02, 13:06
A
Are you using the version of MySQL shipped with the server [test above is doing so]

Yep, I elected not to install MySQL as part of Fedora, so I only have the one that comes with SlimServer.

Oh, and I have a reported bogomips of 2001.17

Richard

Triode
2006-07-03, 11:42
As a datapoint, my server takes ~8 seconds to display All Songs from a database of 9000 songs after restaring slimserver. [but I guess the database files may be in memory]

Just repeated this after a server power cycle and got the same results so there is no extra caching going on.

This suggests there is something taking a long time on your server or due to your database. We need a better way of measuring what is going on.

Dan - any views?

Dan Sully
2006-07-03, 15:58
* Triode shaped the electrons to say...

>Dan - any views?

Running --d_sql will give you the queries with timestamps.

-D
--
Off the record, on the QT, and very hush-hush.

SadGamerGeek
2006-07-03, 16:21
Running --d_sql will give you the queries with timestamps.

No sooner said than done!

This is for listing "all songs" from the web page when my squeezbox is in standby. I turned on performance monitoring with a minimum time of 1 second plus the --d_sql param.

As you can see the web page build took 157 seconds this time, and there's a few "timer late" lines of up to 25 seconds.

I'm not familiar with these logs, but I couldn't help noticing what I assume is a track ID of 4403 showing up quite a bit. Could there be something dodgy about it? If so, how can I show what track that actually is?

Thanks for everyone's help so far,

Richard

SadGamerGeek
2006-07-03, 16:48
Oops - hadn't notice the file didn't upload due to its size. I've now chopped it down (hope I haven't lost anything important)

Dan Sully
2006-07-03, 17:15
* SadGamerGeek shaped the electrons to say...

>Oops - hadn't notice the file didn't upload due to its size. I've now
>chopped it down (hope I haven't lost anything important)

And what type of hardware are you running SlimServer on?

-D
--
"My pockets hurt." - Homer Simpson

Triode
2006-07-04, 11:08
I think the hardware is: Epia Via motherboard with a 1Ghz processor and 512MB RAM (more details higher up this thread)

This seems to record a similar bogomips to my server, so can't see why the performance is so much worse.

SadGamerGeek
2006-07-04, 12:54
To sumarise my details from earlier in this thread (plus a couple of bits of extra info):

I am running SlimServer build 6.5b1 - 8242. I recently rebuilt my OS & went straight for 6.5b1, so it has no remnants of 6.22 or 6.3. It should be using the MySQL that was delivered with SlimServer, as I elected to not install it with the OS. I have not done any tuning of MySQL as I don't know how to!

My OS is Linux Fedora FC5 (fully up to date with yum) with no X-Windows or unneccessary services. I run this on an Epia Via motherboard with a 1Ghz processor and 512MB RAM. It has one internal 3.5" 80GB IDE drive (ATA/IDE 133). No other software (other than directly related to SlimServer) runs on this machine.

I have a reported bogomips of 2001.17.

I have one client - a Squeezebox 3. I nornally run this wirelessly, but when I tried it wired I didn't see any obvious improvement. The IR responsiveness of this is mostly OK, but can sometimes be poor.

My music library contains 535 albums with 6451 songs by 232 artists. I have no playlists at this time.

Cheers,

Richard

Triode
2006-07-06, 10:49
Richard - probably need to see the lines you have deleted between 00:06:11.7150 and 2006-07-04 00:07:04.6416 to understand what it going on (the ones before entry saying Web Page Build - 157 secs.

Dan - is there a single location where we can instrument the database access with the new code, should this help understand this.

Must be something up to take 157 seconds to build the web page?

SadGamerGeek
2006-07-06, 12:08
Richard - probably need to see the lines you have deleted between 00:06:11.7150 and 2006-07-04 00:07:04.6416 to understand what it going on (the ones before entry saying Web Page Build - 157 secs.

That portion was too big to upload, but I've made the whole log available here:

http://home.btconnect.com/rharnwel/Misc/SlimServerLog.txt

Cheers,

Richard

Triode
2006-07-07, 13:45
Richard,

If you try the next nightly or subversion after 8323, you there is a performance graph for database access time in the server statistics page. If you set a high warning for this of 0.01, it will add an entry to the log each time a database access takes over 0.01 seconds. For your test web page I get one database access of 0.016 to 0.03 sec and all the rest are less than this - what do you see?

Adrian

SadGamerGeek
2006-07-08, 03:14
Richard,

If you try the next nightly or subversion after 8323, you there is a performance graph for database access time in the server statistics page. If you set a high warning for this of 0.01, it will add an entry to the log each time a database access takes over 0.01 seconds. For your test web page I get one database access of 0.016 to 0.03 sec and all the rest are less than this - what do you see?

Adrian

Thanks, I've now installed that.

With just that turned on I see this when selecting "All Songs":



2006-07-08 11:05:45.9803 Database Access > 0.01 : 0.234630823135376
2006-07-08 11:05:45.9809 select_single
2006-07-08 11:05:46.2885 Database Access > 0.01 : 0.0127701759338379
2006-07-08 11:05:46.2891 select_single
2006-07-08 11:05:46.8958 Database Access > 0.01 : 0.0128169059753418
2006-07-08 11:05:46.8963 select_single
2006-07-08 11:05:50.8092 Database Access > 0.01 : 0.0219011306762695
2006-07-08 11:05:50.8097 select_single
2006-07-08 11:05:52.0139 Database Access > 0.01 : 0.0137569904327393
2006-07-08 11:05:52.0144 select_single



The first one seems reasonably high, though I guess not high (or frequent) enough to explain my massive wait times...

Would you like to see that with some other warnings on at the same time?

Cheers,

Richard

Triode
2006-07-08, 03:39
Is the long time for the first one repeatable?

I don't every see a long time like this, but wonder whether this is just the first access.

Could you set the high threshold for "Timer Task" and "Select Task" to 0.01 at the same time and post the output of a page build. [reason is that for big pages, they can be interrupted by other tasks, so it may be these that are taking a long time]

SadGamerGeek
2006-07-08, 04:35
Is the long time for the first one repeatable?

I don't every see a long time like this, but wonder whether this is just the first access.

Could you set the high threshold for "Timer Task" and "Select Task" to 0.01 at the same time and post the output of a page build. [reason is that for big pages, they can be interrupted by other tasks, so it may be these that are taking a long time]

I think that was probably just the first access as you suspect. Here's the log for the time it took to build "all songs" with those warnings turned on:

http://home.btconnect.com/rharnwel/Misc/SlimServer_log3.txt

My squeezbeox was playing a song from my library at the time. It looks like there are only a couple of database access warnings, and they don't seem too bad.

I've hesitated to mention it before (as I realise this is alpha software, and I don't want to be seen as a general whinger!), but the remote to squeezebox response can sometimes be very poor (almost unuseable), even when the server isn't building any web pages. Example - I just had to press the forward button eight times (I waited a second between each press) before it would respond & move to the next track. This was when no web page build activity was happening.

One other thing (again, just in case it is relevant), I am getting lots of duplicate tracks within albums when browsing via the remote. They don't show up on the web interface, and I did a "delete & add" type rescan last night and it didn't fix them. If no-one thinks this relates to my main problem, I'll start a new thread for it or raise a bug.

Thanks again for ongoing help & patience,

Richard

Triode
2006-07-08, 06:01
Well there's nothing obviously wrong here in terms of an additional process stealing time.

However:
Timer Task > 0.1 : 0.112216949462891
2006-07-08 12:20:08.2847 Slim::Buttons::Common::_periodicUpdate

Is saying it every second, it is taking ~100 ms to update the display on the player. This is 10% of the cpu. [the equivalent on my server is around 10% of this..] Makes me wonder how fast the processor realy is at running perl..?

If you run the attached script - what's the output [may need to edit lib lines to point to slimsever location]. This essentially runs an infinite loop and times the time between each loop.

SadGamerGeek
2006-07-08, 08:01
If you run the attached script - what's the output

This is an example output. They all look pretty much the same:



Looptime:
< 0.001 : 404229 :100% #################################################
< 0.002 : 20 : 0%
< 0.005 : 23 : 0%
< 0.01 : 0 : 0%
< 0.015 : 0 : 0%
< 0.05 : 0 : 0%
< 0.1 : 0 : 0%
< 0.11 : 0 : 0%
< 0.12 : 7 : 0%
< 0.2 : 3 : 0%
>=0.2 : 0 : 0%
max : 0.122578
min : 0.000020
avg : 0.000025


This was running whilest slimserver was active & playing music from my library to my squeezebox

Cheers,

Richard

Triode
2006-07-08, 08:10
Hum - that about half the speed of my server, but no significant problems...

I'll send you a pm with some more thoughts..

SadGamerGeek
2006-07-15, 10:45
This is a quick update to let everyone know that Triode (Adrian) spent a great deal of his time last weekend (stopping only for the football!) investigating this problem for me.

My web page access is much improved now thanks to some well targeted fixes.

Thanks again Adrian!

Patrick Dixon
2006-07-15, 11:01
Adrian's definitely one of the good guys, although if you insult his mother he is quite likely to headbutt you in the chest.

So cumon, what were the fixes then? Or will the performance improvements just find their way into 6.5b1 in due course?

SadGamerGeek
2006-07-15, 11:14
They're now in 6.5b1 (except one, as it balances a loss of some functionality against performance).

I'll let Adrian explain what he did!

relen
2006-07-18, 15:11
I've been having problems with web sluggishness for the past week or so on 6.5b1. It's actually currently essentially unusable as I simply have to wait too long for anything to happen, and sometimes it never does (the browser, FF 1.5.0.4, times out): the remote is much easier (though not as pretty :-)).

The Nokia770 skin displays its 'framework' very quickly (on the N770) but the graphics take an age to appear (or never do); on my my other machines (Mac & Win), the main page takes 2-3 minutes just to start appearing (default or fishbone skins, no real difference).

This is a 1.3 GHz FC5 system with plenty of RAM and it's previously been extremely responsive: it's just the last week or two it's "gone off" and slowed to a crawl.

Music playout is unaffected for me; remote operation seems normal.

Anything I should be cleaning out, erasing, resetting?

Currently running 07/18 build on fc5, and happy to accept the penalties of living on the bleeding edge...

Thanks,
--Richard E

SadGamerGeek
2006-07-18, 15:26
Richard E,

You may have noticed another thread has just started about poor Perl performance in FC5:

http://forums.slimdevices.com/showthread.php?t=25559

I did as suggested in that thread and replaced my Perl 5.8.8-5 (seems to be standard with FC5) with 5.8.8-4. This game me a very noticeable improvement in response time of both web and and squeezebox access. Coupled with the improvements Triode has now built into the lastest releases, I'm finally happy with response times on my humble server!

The fact that you've only just started having poor performance may point to something else. A Perl downgrade is definately worth a try though.

Richard

relen
2006-07-19, 01:19
Hi, Richard...

Thanks for the tip - I had not noticed the other thread. I can't recall when Perl was last updated on my machine, but as I'm running SS and it uses Perl, I tend to keep Perl updated! So this is something I'll try in the very near future. And it's easy enough to test.

Hopefully that'll do the trick for now. Thanks again...
--Richard E

andyg
2006-07-19, 06:07
You may also be interested in trying the patch in this thread:
http://forums.slimdevices.com/showthread.php?t=25624

With that patch an SB1 no longer drops out while browsing via the web and streaming WAV.

relen
2006-07-19, 10:25
Thanks for the Perl downgrade suggestion. It appears to get me back to where I think I was the other week. I hope someone will mention when Perl is fixed in this respect.

As far as patching is concerned, I am not in a position to try that right now, though it sounds like a good idea. Is it likely to make it into the code? I notice you only just came up with it.

Thanks for the assistance, guys!
-Richard E