PDA

View Full Version : perfmon: 10 second lags



Leigh
2010-02-14, 15:11
So I'm trying to troubleshoot the laggy problems I'm having recently. I have no problems with the network tests, I can stream 5000 kb/s, the max setting, 99%.

What is happening is I'll click on a song or change the volume or whatever from the web interface and it will just sit there and not take the command for about 10 seconds. Sometimes the same thing happens from the remote.

So I fired up squeezeboxserver from the command line with --perfwarn 0.5 and I get some interesting results:



fuggle:/var/log/squeezeboxserver% cat perfmon.log
[10-02-14 16:47:44.3190] Logging Request > 0.50000s
[10-02-14 16:47:44.3193] Logging AnyEvent CB > 0.50000s
[10-02-14 16:47:44.3194] Logging Template > 0.50000s
[10-02-14 16:47:44.3195] Logging Async HTTP > 0.50000s
[10-02-14 16:47:44.3196] Logging Timer > 0.50000s
[10-02-14 16:47:44.3198] Logging Page Build > 0.50000s
[10-02-14 16:47:44.3199] Logging IR Delay > 0.50000s
[10-02-14 16:47:44.3200] Logging DB Access > 0.50000s
[10-02-14 16:47:44.3201] Logging Notify > 0.50000s
[10-02-14 16:47:44.3202] Logging IO > 0.50000s
[10-02-14 16:47:44.3203] Logging Scheduler > 0.50000s
[10-02-14 16:47:45.9641] IO 0.56167 : Slim::Web::HTTP::processHTTP
[10-02-14 16:50:00.7447] IO 10.01028 : Slim::Web::HTTP::processHTTP
[10-02-14 16:50:11.3956] IO 10.00485 : Slim::Web::HTTP::processHTTP
[10-02-14 16:51:16.9753] IO 10.01027 : Slim::Web::HTTP::processHTTP
[10-02-14 16:51:27.1883] IO 10.00606 : Slim::Web::HTTP::processHTTP
[10-02-14 16:52:47.8184] Request 1.10759 : Slim::Control::Commands::timeCommand
[10-02-14 16:52:47.8187] IO 1.11093 : Slim::Web::HTTP::processHTTP
[10-02-14 16:56:39.6612] IO 10.00668 : Slim::Web::HTTP::processHTTP
[10-02-14 16:56:49.9046] IO 10.00423 : Slim::Web::HTTP::processHTTP
[10-02-14 16:58:31.1340] IO 10.01019 : Slim::Web::HTTP::processHTTP
[10-02-14 16:58:41.7696] IO 10.00874 : Slim::Web::HTTP::processHTTP

What would cause exactly 10 second lags?? That can't be a coincidence. Any suggestions for what kind of logging to turn on to diagnose this?

BTW this is from a fresh re-install, today, of 7.4.1 on a Fedora 12 64 bit machine. I wiped the cache before running and rescanned the library. I even reinstalled the latest firmware on the SB3. Still I get the lags. Sometimes it will freeze while playing which is extremely annoying. I never used to have this kind of problem.

Thanks for any pointers.

Edit:

Followup. I turned on logging. The freezing occurs after the first line. So, Reading request... sits there for 10 seconds and then the rest of the stuff barfs to the screen at once. hence, the time stamping is odd, as the next line does not show up as being 10 seconds later, but just a fraction of a second later (but perfmon.log does register the 10 second lag)



[10-02-14 17:29:14.1413] Slim::Web::HTTP::processHTTP (351) Reading request...
[10-02-14 17:29:14.1423] Slim::Web::HTTP::processHTTP (368) HTTP request: from 192.168.3.4:37407 (Slim::Web::HTTP::ClientConn=GLOB(0x7ea0408)) for GET HTTP/1.1 /status.html?player=00%3A04%3A20%3A07%3A4b%3Af1&ajaxRequest=1&s=0.7350180522879528&light=1
[10-02-14 17:29:14.1429] Slim::Web::HTTP::processHTTP (375) Raw request headers: [
GET /status.html?player=00%3A04%3A20%3A07%3A4b%3Af1&ajaxRequest=1&s=0.7350180522879528&light=1 HTTP/1.1
Connection: keep-alive
Accept: text/javascript, text/html, application/xml, text/xml, */*
Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7
Accept-Encoding: gzip,deflate
Accept-Language: en-us,en;q=0.5
Host: fuggle:9000
Referer: http://fuggle:9000/status.html
User-Agent: Mozilla/5.0 (X11; U; Linux i686; en-US; rv:1.9.1.6) Gecko/20100107 Fedora/3.5.6-1.fc12 Firefox/3.5.6
Cookie: SqueezeCenter-player=00%3A04%3A20%3A07%3A4b%3Af1; SqueezeCenter-Browserpage=BROWSE_NEW_MUSIC; Fishbone-Style=null; Squeezebox-player=00%3A04%3A20%3A07%3A4b%3Af1; Squeezebox-Browserpage=BROWSE_MUSIC_FOLDER; show_filter=true; show_inspector=true; filter=all; Squeezebox-albumView=; Squeezebox-fishbone-showtext=0; sort_method=queue_order; sort_direction=descending; g3sid=258e656c7c2a2e617d37f2398cf5cf436ec189dd%7Ea vjks3r77c3klp0k517q00ari4
Keep-Alive: 300
X-Prototype-Version: 1.5.1.1
X-Requested-With: XMLHttpRequest

]
[10-02-14 17:29:14.1436] Slim::Web::HTTP::processHTTP (475) Raw path is [/status.html]
[10-02-14 17:29:14.1452] Slim::Web::HTTP::processHTTP (594) HTTP parameter player = 00:04:20:07:4b:f1
[10-02-14 17:29:14.1456] Slim::Web::HTTP::processHTTP (594) HTTP parameter ajaxRequest = 1
[10-02-14 17:29:14.1459] Slim::Web::HTTP::processHTTP (594) HTTP parameter s = 0.7350180522879528
[10-02-14 17:29:14.1462] Slim::Web::HTTP::processHTTP (594) HTTP parameter light = 1
[10-02-14 17:29:14.1469] Slim::Web::HTTP::processHTTP (719) Processed request headers: [
GET /status.html?player=00%3A04%3A20%3A07%3A4b%3Af1&ajaxRequest=1&s=0.7350180522879528&light=1 HTTP/1.1
Connection: keep-alive
Accept: text/javascript, text/html, application/xml, text/xml, */*
Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7
Accept-Encoding: gzip,deflate
Accept-Language: en-us,en;q=0.5
Host: fuggle:9000
Referer: http://fuggle:9000/status.html
User-Agent: Mozilla/5.0 (X11; U; Linux i686; en-US; rv:1.9.1.6) Gecko/20100107 Fedora/3.5.6-1.fc12 Firefox/3.5.6
Client-Date: Sun, 14 Feb 2010 22:29:14 GMT
Cookie: SqueezeCenter-player=00%3A04%3A20%3A07%3A4b%3Af1; SqueezeCenter-Browserpage=BROWSE_NEW_MUSIC; Fishbone-Style=null; Squeezebox-player=00%3A04%3A20%3A07%3A4b%3Af1; Squeezebox-Browserpage=BROWSE_MUSIC_FOLDER; show_filter=true; show_inspector=true; filter=all; Squeezebox-albumView=; Squeezebox-fishbone-showtext=0; sort_method=queue_order; sort_direction=descending; g3sid=258e656c7c2a2e617d37f2398cf5cf436ec189dd%7Ea vjks3r77c3klp0k517q00ari4
Keep-Alive: 300
X-Prototype-Version: 1.5.1.1
X-Requested-With: XMLHttpRequest

]
[10-02-14 17:29:14.1472] Slim::Web::HTTP::processURL (790) processURL Clients: 192.168.3.5:45742 192.168.3.6:18868
[10-02-14 17:29:14.1478] Slim::Web::HTTP::generateHTTPResponse (1000) Generating response for (htm, text/html) status.html
[10-02-14 17:29:14.1483] Slim::Web::Template::NoWeb::_generateContentFromFi le (66) generating from include.html with type: fill
[10-02-14 17:29:14.1488] Slim::Web::Template::NoWeb::fixHttpPath (177) Found path /usr/share/squeezeboxserver/HTML/EN/include.html
[10-02-14 17:29:14.1493] Slim::Web::HTTP::sendStreamingResponse (1893) sendStreaming response begun...
[10-02-14 17:29:14.1498] Slim::Web::HTTP::sendStreamingResponse (2018) (audio: 32768 bytes)
[10-02-14 17:29:14.1501] Slim::Web::HTTP::sendStreamingResponse (2168) Streamed 32768 to 192.168.3.6
[10-02-14 17:29:14.1521] Slim::Web::Template::NoWeb::_generateContentFromFi le (66) generating from select_option.html with type: fill
[10-02-14 17:29:14.1523] Slim::Web::Template::NoWeb::fixHttpPath (177) Found path /usr/share/squeezeboxserver/HTML/EN/select_option.html
[10-02-14 17:29:14.1535] Slim::Web::Template::NoWeb::_generateContentFromFi le (66) generating from select_option.html with type: fill
[10-02-14 17:29:14.1537] Slim::Web::Template::NoWeb::fixHttpPath (177) Found path /usr/share/squeezeboxserver/HTML/EN/select_option.html
[10-02-14 17:29:14.1636] Slim::Web::Template::NoWeb::_generateContentFromFi le (66) generating from playlist.html with type: fill
[10-02-14 17:29:14.1639] Slim::Web::Template::NoWeb::fixHttpPath (177) Found path /usr/share/squeezeboxserver/HTML/Fishbone/playlist.html
[10-02-14 17:29:14.1661] Slim::Web::Template::NoWeb::_generateContentFromFi le (66) generating from status.html with type: fill
[10-02-14 17:29:14.1663] Slim::Web::Template::NoWeb::fixHttpPath (177) Found path /usr/share/squeezeboxserver/HTML/Fishbone/status.html
[10-02-14 17:29:14.1720] Slim::Web::HTTP::processHTTP (745) Response Headers: [
HTTP/1.1 200 OK
Connection: keep-alive
Date: Sun, 14 Feb 2010 22:29:14 GMT
Content-Length: 1277
Content-Type: text/html; charset=utf-8
Set-Cookie: Squeezebox-player=00%3A04%3A20%3A07%3A4b%3Af1; path=/; expires=Mon, 14-Feb-2011 22:29:14 GMT
X-Time-To-Serve: 0.0303819179534912

]
[10-02-14 17:29:14.1722] Slim::Web::HTTP::processHTTP (748) End request: keepAlive: [17] - waiting for next request for Slim::Web::HTTP::ClientConn=GLOB(0x7ea0408) on connection = keep-alive
[10-02-14 17:29:14.1727] Slim::Web::HTTP::sendStreamingResponse (1893) sendStreaming response begun...
[10-02-14 17:29:14.1730] Slim::Web::HTTP::sendStreamingResponse (2018) (audio: 32768 bytes)
[10-02-14 17:29:14.1732] Slim::Web::HTTP::sendStreamingResponse (2168) Streamed 32768 to 192.168.3.6
[10-02-14 17:29:14.1734] Slim::Web::HTTP::sendResponse (1775) Sent 1605 to 192.168.3.4:37407
[10-02-14 17:29:14.1736] Slim::Web::HTTP::sendResponse (1781) No more segments to send to 192.168.3.4:37407
[10-02-14 17:29:14.1740] Slim::Web::HTTP::sendResponse (1733) No segment to send to 192.168.3.4:37407, waiting for next request...
[10-02-14 17:29:14.1749] Slim::Networking::Async::HTTP::_http_read (323) Headers read. code: 200 status: OK
[10-02-14 17:29:14.1755] Slim::Networking::Async::HTTP::_http_read (324) bless({
"cache-control" => "no-cache",
connection => "close",
"content-encoding" => "gzip",
"content-length" => 41,
"content-type" => "text/x-json",
date => "Sun, 14 Feb 2010 22:29:14 GMT",
server => "lighttpd/1.4.13",
"set-cookie" => "sdi_squeezenetwork_session=1403562%3A3qfDyZbk6e71y TAzcbNNkW3vSCg; path=/; expires=Mon, 14-Feb-2011 22:29:14 GMT",
vary => "Accept-Encoding",
}, "HTTP::Headers")
[10-02-14 17:29:14.1759] Slim::Networking::Async::HTTP::_http_read_body (407) Read body: [41] bytes
[10-02-14 17:29:14.1762] Slim::Networking::Async::disconnect (237) Close Slim::Networking::Async::Socket::HTTP=GLOB(0x72a94 48) => 23
[10-02-14 17:29:14.1764] Slim::Networking::Async::HTTP::_http_read_body (470) Body read

JJZolx
2010-02-15, 08:07
Is this using the Fishbone skin? If so, do you see the same behavior using the default web skin?

Leigh
2010-02-15, 09:09
Is this using the Fishbone skin? If so, do you see the same behavior using the default web skin?

Yes it's the fishbone skin. I have been using it for years. Have not tried the default.