Bugzilla – Bug 13215
Very slow odd queries repeated often...
Last modified: 2009-10-05 14:36:50 UTC
I see this occurring over and over in my logs on r28001: [09-08-03 09:32:02.0680] Slim::Schema::Storage::throw_exception (82) Error: Carp::Clan::__ANON__(): DBI Exception: DBD::mysql::st execute failed: Error writing file '/tmp/MYIHqYcN' (Errcode: 28) [for Statement "SELECT COUNT( * ) FROM (SELECT me.id FROM tracks me WHERE ( me.audio = ? ) GROUP BY me.id, me.url, me.content_type, me.title, me.titlesort, me.titlesearch, me.album, me.primary_artist, me.tracknum, me.timestamp, me.filesize, me.disc, me.remote, me.audio, me.audio_size, me.audio_offset, me.year, me.secs, me.cover, me.vbr_scale, me.bitrate, me.samplerate, me.samplesize, me.channels, me.block_alignment, me.endian, me.bpm, me.tagversion, me.drm, me.musicmagic_mixable, me.musicbrainz_id, me.lossless, me.lyrics, me.replay_gain, me.replay_peak, me.extid) count_subq" with ParamValues: 0=1] at /usr/share/perl5/Slim/Schema/Storage.pm line 86 [09-08-03 09:32:02.0691] Slim::Schema::Storage::throw_exception (82) Backtrace: frame 0: Slim::Utils::Log::logBacktrace (/usr/share/perl5/Slim/Schema/Storage.pm line 82) frame 1: Slim::Schema::Storage::throw_exception (/usr/share/squeezecenter/CPAN/DBIx/Class/Storage/DBI.pm line 429) frame 2: DBIx::Class::Storage::DBI::dbh_do (/usr/share/squeezecenter/CPAN/DBIx/Class/Storage/DBI/Cursor.pm line 97) frame 3: DBIx::Class::Storage::DBI::Cursor::next (/usr/share/squeezecenter/CPAN/DBIx/Class/Storage/DBI.pm line 1317) frame 4: DBIx::Class::Storage::DBI::count (/usr/share/squeezecenter/CPAN/DBIx/Class/Storage/DBI.pm line 1354) frame 5: DBIx::Class::Storage::DBI::count_grouped (/usr/share/squeezecenter/CPAN/DBIx/Class/ResultSet.pm line 1155) frame 6: DBIx::Class::ResultSet::count (/usr/share/perl5/Slim/Control/Queries.pm line 3145) frame 7: Slim::Control::Queries::serverstatusQuery (/usr/share/perl5/Slim/Control/Request.pm line 1907) frame 8: (eval) (/usr/share/perl5/Slim/Control/Request.pm line 1907) frame 9: Slim::Control::Request::execute (/usr/share/perl5/Slim/Web/JSONRPC.pm line 354) frame 10: Slim::Web::JSONRPC::requestMethod (/usr/share/perl5/Slim/Web/JSONRPC.pm line 201) frame 11: (eval) (/usr/share/perl5/Slim/Web/JSONRPC.pm line 201) frame 12: Slim::Web::JSONRPC::handleURI (/usr/share/perl5/Slim/Web/HTTP.pm line 484) frame 13: Slim::Web::HTTP::processHTTP (/usr/share/perl5/Slim/Networking/IO/Select.pm line 133) frame 14: (eval) (/usr/share/perl5/Slim/Networking/IO/Select.pm line 119) frame 15: Slim::Networking::IO::Select::__ANON__ (/usr/share/perl5/Slim/Networking/IO/Select.pm line 177) frame 16: (eval) (/usr/share/perl5/Slim/Networking/IO/Select.pm line 177) frame 17: Slim::Networking::IO::Select::loop (/usr/sbin/squeezecenter-server line 605) frame 18: main::idle (/usr/sbin/squeezecenter-server line 574) frame 19: main::main (/usr/sbin/squeezecenter-server line 1084) Yes, there is a disk write error because this creates a temporary table exceeding 250M.... mysql-slow.log shows it is taking 13 seconds to run this query. I don't see the reason for all the variables being included in the subselect, especially since the main select is just getting a count. I guess it ensures things are unique, but me.url should be more than sufficient for that. Something somewhere is fluffing up this query to make it painfully complicated and require a temporary table... "SELECT COUNT( * ) from tracks where ( audio = 1 ) group by id, url" Would be much more efficient and return the same result (and could probably drop at least one of the two 'group' selectors... possibly both). This showed up after the big mysql-merge-back, though it may have been in place with sqlite, just hidden (which would explain why some of us think the sqlite was slow after scans... even without the temp table this is a painful select).
a bit more fiddling, and this comes from the fab4: T 192.168.2.17:32987 -> 192.168.2.101:9000 [AP] POST /cometd HTTP/1.1..User-Agent: SqueezePlay-fab4/7.4-r6887 (armv6l)..Content-Length: 343..Host: 192.168.2.101:9000. .Content-Type: text/json..Accept-Language: en....[{"id":1,"data":{"request":["",["serverstatus",0,50,"subscribe:60"]], "response":"\/74f49dff\/slim\/serverstatus"},"channel":"\/slim\/subscribe"},{"id":2,"data":{"request":["",["firmwareup grade","firmwareVersion:7.4 r6887","inSetup:1","machine:fab4","subscribe:0"]],"response":"\/74f49dff\/slim\/firmwarest atus"},"channel":"\/slim\/subscribe"}] ## T 192.168.2.101:9000 -> 192.168.2.17:32987 [AP] HTTP/1.1 200 OK..Server: Squeezebox Server (7.4 - 28008)..Cache-Control: no-cache..Pragma: no-cache..Content-Length: 1 08..Content-Type: application/json..Expires: -1..X-Time-To-Serve: 5.00864481925964....[{"error":"request failed with e rror: Bad dispatch!","id":1,"channel":"/slim/subscribe","successful":false}] Since I don't have 200M free on /tmp, this fails... I don't think I should need that sort of space on /tmp, though... the query is very silly.
Does the same thing happen in other SqueezePlay based players?
(In reply to comment #2) > Does the same thing happen in other SqueezePlay based players? I believe it does.. it would explain why my SBC has had a red icon for the past few days. The Fab4 just plain didn't work (it would try to connect to the server and fail). The SBC now works (as does fab4)... I cheated and changed one line in /usr/share/perl5/Slim/Control/Queries.pm: # $request->addResult("info total songs",Slim::Schema->rs('Track')->browse->count); $request->addResult("info total songs", 29730); It seems that Slim::Schema->rs('Track')->browse->count is making a very complex query, which is forcing mysql to make huge temporary tables for the subselect.
Andy - Brandon: any idea what's happening here?
This is fixed, those "total" queries have been commented out.
(In reply to comment #5) > This is fixed, those "total" queries have been commented out. And now they are back, and still end up writing some horribly slow SQL query... frame 0: Slim::Utils::Log::logBacktrace (/usr/share/perl5/Slim/Schema/Storage.pm line 82) frame 1: Slim::Schema::Storage::throw_exception (/usr/share/squeezebox/CPAN/DBIx/Class/Storage/DBI.pm line 429) frame 2: DBIx::Class::Storage::DBI::dbh_do (/usr/share/squeezebox/CPAN/DBIx/Class/Storage/DBI/Cursor.pm line 97) frame 3: DBIx::Class::Storage::DBI::Cursor::next (/usr/share/squeezebox/CPAN/DBIx/Class/Storage/DBI.pm line 1317) frame 4: DBIx::Class::Storage::DBI::count (/usr/share/squeezebox/CPAN/DBIx/Class/Storage/DBI.pm line 1354) frame 5: DBIx::Class::Storage::DBI::count_grouped (/usr/share/squeezebox/CPAN/DBIx/Class/ResultSet.pm line 1155) frame 6: DBIx::Class::ResultSet::count (/usr/share/perl5/Slim/Schema.pm line 2998) frame 7: Slim::Schema::totals (/usr/share/perl5/Slim/Control/Queries.pm line 3147) frame 8: Slim::Control::Queries::serverstatusQuery (/usr/share/perl5/Slim/Control/Request.pm line 1914) frame 9: (eval) (/usr/share/perl5/Slim/Control/Request.pm line 1914) frame 10: Slim::Control::Request::execute (/usr/share/perl5/Slim/Web/Cometd.pm line 793) frame 11: Slim::Web::Cometd::handleRequest (/usr/share/perl5/Slim/Web/Cometd.pm line 444) frame 12: Slim::Web::Cometd::handler (/usr/share/perl5/Slim/Web/Cometd.pm line 108) frame 13: Slim::Web::Cometd::webHandler (/usr/share/perl5/Slim/Web/HTTP.pm line 484) frame 14: Slim::Web::HTTP::processHTTP (/usr/share/perl5/Slim/Networking/IO/Select.pm line 133) frame 15: (eval) (/usr/share/perl5/Slim/Networking/IO/Select.pm line 119) frame 16: Slim::Networking::IO::Select::__ANON__ (/usr/share/perl5/Slim/Networking/IO/Select.pm line 177) frame 17: (eval) (/usr/share/perl5/Slim/Networking/IO/Select.pm line 177) frame 18: Slim::Networking::IO::Select::loop (/usr/sbin/squeezebox-server line 609) frame 19: main::idle (/usr/sbin/squeezebox-server line 574) frame 20: main::main (/usr/sbin/squeezebox-server line 1092) [09-08-14 22:38:36.2431] Slim::Control::Request::execute (1918) Error: While trying to run function coderef [Slim::Control::Queries::serverstatusQuery]: [Carp::Clan::__ANON__(): Carp::Clan::__ANON__(): DBI Exception: DBD::mysql::st execute failed: Error writing file '/tmp/MYeieMmM' (Errcode: 28) [for Statement "SELECT COUNT( * ) FROM (SELECT me.id FROM tracks me WHERE ( me.audio = ? ) GROUP BY me.id, me.url, me.content_type, me.title, me.titlesort, me.titlesearch, me.album, me.primary_artist, me.tracknum, me.timestamp, me.filesize, me.disc, me.remote, me.audio, me.audio_size, me.audio_offset, me.year, me.secs, me.cover, me.vbr_scale, me.bitrate, me.samplerate, me.samplesize, me.channels, me.block_alignment, me.endian, me.bpm, me.tagversion, me.drm, me.musicmagic_mixable, me.musicbrainz_id, me.lossless, me.lyrics, me.replay_gain, me.replay_peak, me.extid) count_subq"] at /usr/share/perl5/Slim/Schema/Storage.pm line 86 This is with r28186. How is no one else seeing this awful query (other than my low /tmp means it bombs completely..) This is a painfully slow query on a library of any decent size with the totally pointless subselect.
I'll port them to native DBI next week.
== Auto-comment from SVN commit #28391 to the slim repo by andy == == https://svn.slimdevices.com/slim?view=revision&revision=28391 == Fixed bug 13215, don't use DBIC to count track totals
This bug has been marked as fixed in the 7.4.0 release version of SqueezeBox Server! * SqueezeCenter: 28672 * Squeezebox 2 and 3: 130 * Transporter: 80 * Receiver: 65 * Boom: 50 * Controller: 7790 * Radio: 7790 Please see the Release Notes for all the details: http://wiki.slimdevices.com/index.php/Release_Notes If you haven't already, please download and install the new version from http://www.logitechsqueezebox.com/support/download-squeezebox-server.html If you are still experiencing this problem, feel free to reopen the bug with your new comments and we'll have another look.