Bugzilla – Bug 16003
scanner/sbs deadlocks on tracks_persistant
Last modified: 2011-05-26 21:29:36 UTC
This one should be easy to reproduce, assuming a sufficient enough library size: 1) Do a 'clear and rescan' from the WebUI. 2) Play a track while the scan is running. This results in a contention fight over locks on tracks_persistant: From server.log: [10-04-05 15:55:13.1480] Slim::Schema::Storage::throw_exception (119) Error: Carp::Clan::__ANON__(): DBI Exception: DBD::SQLite::st execute failed: database is locked [for Statement "UPDATE tracks_persistent SET lastplayed = ?, playcount = ? WHERE ( id = ? )"] at /usr/share/perl5/Slim/Schema/Storage.pm line 123 [10-04-05 15:55:13.1491] Slim::Schema::Storage::throw_exception (119) Backtrace: frame 0: Slim::Utils::Log::logBacktrace (/usr/share/perl5/Slim/Schema/Storage.pm line 119) frame 1: Slim::Schema::Storage::throw_exception (/usr/share/squeezeboxserver/CPAN/DBIx/Class/Storage/DBI.pm line 598) frame 2: DBIx::Class::Storage::DBI::dbh_do (/usr/share/squeezeboxserver/CPAN/DBIx/Class/Storage/DBI.pm line 1297) frame 3: DBIx::Class::Storage::DBI::_execute (/usr/share/squeezeboxserver/CPAN/DBIx/Class/Storage/DBI.pm line 1419) frame 4: DBIx::Class::Storage::DBI::update (/usr/share/squeezeboxserver/CPAN/DBIx/Class/Row.pm line 490) frame 5: DBIx::Class::Row::update (/usr/share/squeezeboxserver/CPAN/DBIx/Class/Relationship/CascadeActions.pm line 35) frame 6: DBIx::Class::Relationship::CascadeActions::update (/usr/share/perl5/Slim/Schema/DBI.pm line 32) frame 7: Slim::Schema::DBI::update (/usr/share/perl5/Slim/Player/Song.pm line 631) frame 8: Slim::Player::Song::open (/usr/share/perl5/Slim/Player/StreamingController.pm line 1177) frame 9: Slim::Player::StreamingController::_Stream (/usr/share/perl5/Slim/Player/StreamingController.pm line 1271) frame 10: Slim::Player::StreamingController::_PlayIfReady (/usr/share/perl5/Slim/Player/StreamingController.pm line 288) frame 11: Slim::Player::StreamingController::_eventAction (/usr/share/perl5/Slim/Player/StreamingController.pm line 2031) frame 12: Slim::Player::StreamingController::playerStopped (/usr/share/perl5/Slim/Player/Squeezebox2.pm line 148) frame 13: Slim::Player::Squeezebox2::statHandler (/usr/share/perl5/Slim/Networking/Slimproto.pm line 870) frame 14: Slim::Networking::Slimproto::_stat_handler (/usr/share/perl5/Slim/Networking/Slimproto.pm line 407) frame 15: Slim::Networking::Slimproto::client_readable (/usr/share/perl5/Slim/Networking/IO/Select.pm line 139) frame 16: (eval) (/usr/share/perl5/Slim/Networking/IO/Select.pm line 123) frame 17: Slim::Networking::IO::Select::__ANON__ (/usr/share/perl5/Slim/Networking/IO/Select.pm line 183) frame 18: (eval) (/usr/share/perl5/Slim/Networking/IO/Select.pm line 183) frame 19: Slim::Networking::IO::Select::loop (/usr/sbin/squeezeboxserver line 697) frame 20: main::idleStreams (/usr/share/perl5/Slim/Plugin/AudioScrobbler/Plugin.pm line 881) frame 21: Slim::Plugin::AudioScrobbler::Plugin::submitScrobble (/usr/share/perl5/Slim/Utils/Timers.pm line 255) frame 22: (eval) (/usr/share/perl5/Slim/Utils/Timers.pm line 255) frame 23: Slim::Utils::Timers::__ANON__ (/usr/share/perl5/Slim/Networking/IO/Select.pm line 183) frame 24: (eval) (/usr/share/perl5/Slim/Networking/IO/Select.pm line 183) frame 25: Slim::Networking::IO::Select::loop (/usr/sbin/squeezeboxserver line 684) frame 26: main::idle (/usr/sbin/squeezeboxserver line 634) frame 27: main::main (/usr/sbin/squeezeboxserver line 1127) [10-04-05 15:55:13.1502] Slim::Networking::IO::Select::__ANON__ (146) Error: Select task failed calling Slim::Networking::Slimproto::client_readable: Carp::Clan::__ANON__(): Carp::Clan::__ANON__(): DBI Exception: DBD::SQLite::st execute failed: database is locked [for Statement "UPDATE tracks_persistent SET lastplayed = ?, playcount = ? WHERE ( id = ? )"] at /usr/share/perl5/Slim/Schema/Storage.pm line 123 ; fh=IO::Socket::INET=GLOB(0xce53368) And over in scanner.log: [10-04-05 15:55:16.9835] Slim::Schema::Storage::throw_exception (119) Error: DBI Exception: DBD::SQLite::st execute failed: database is locked [for Statement "INSERT INTO tracks_persistent (urlmd5,url,added) VALUES (?,?,?)"] [10-04-05 15:55:16.9846] Slim::Schema::Storage::throw_exception (119) Backtrace: frame 0: Slim::Utils::Log::logBacktrace (/usr/share/perl5/Slim/Schema/Storage.pm line 119) frame 1: Slim::Schema::Storage::throw_exception (/usr/share/squeezeboxserver/CPAN/DBIx/Class/Storage/DBI.pm line 1006) frame 2: DBIx::Class::Storage::DBI::__ANON__ (/usr/share/perl5/Slim/Schema.pm line 1388) frame 3: Slim::Schema::_createTrack (/usr/share/perl5/Slim/Schema.pm line 1615) frame 4: Slim::Schema::_newTrack (/usr/share/perl5/Slim/Schema.pm line 1813) frame 5: Slim::Schema::updateOrCreateBase (/usr/share/perl5/Slim/Utils/Scanner/Local.pm line 610) frame 6: Slim::Utils::Scanner::Local::__ANON__ (/usr/share/perl5/Slim/Utils/Scanner/Local.pm line 670) frame 7: Slim::Utils::Scanner::Local::new (/usr/share/perl5/Slim/Utils/Scanner/Local.pm line 289) frame 8: Slim::Utils::Scanner::Local::__ANON__ (/usr/share/perl5/Slim/Utils/Scanner/Local.pm line 305) frame 9: Slim::Utils::Scanner::Local::__ANON__ (/usr/share/perl5/Slim/Utils/Scanner/Local/Async.pm line 84) frame 10: Slim::Utils::Scanner::Local::Async::__ANON__ (/usr/share/perl5/Slim/Utils/Scanner/Local/Async.pm line 157) frame 11: Slim::Utils::Scanner::Local::Async::find (/usr/share/perl5/Slim/Utils/Scanner/Local.pm line 96) frame 12: Slim::Utils::Scanner::Local::find (/usr/share/perl5/Slim/Utils/Scanner/Local.pm line 385) frame 13: Slim::Utils::Scanner::Local::rescan (/usr/share/perl5/Slim/Music/MusicFolderScan.pm line 79) frame 14: Slim::Music::MusicFolderScan::startScan (/usr/share/perl5/Slim/Music/Import.pm line 475) frame 15: Slim::Music::Import::runImporter (/usr/share/perl5/Slim/Music/Import.pm line 304) frame 16: Slim::Music::Import::runScan (/usr/sbin/squeezeboxserver-scanner line 339) frame 17: (eval) (/usr/sbin/squeezeboxserver-scanner line 333) frame 18: main::main (/usr/sbin/squeezeboxserver-scanner line 530) [10-04-05 15:55:16.9857] main::main (345) Error: Failed when running main scan: [Carp::Clan::__ANON__(): DBI Exception: DBD::SQLite::st execute failed: database is locked [for Statement "INSERT INTO tracks_persistent (urlmd5,url,added) VALUES (?,?,?)"] at /usr/share/perl5/Slim/Schema/Storage.pm line 123] And the real clincher from scanner.log: [10-04-05 15:55:16.9864] main::main (346) Error: Skipping post-process & Not updating lastRescanTime! Which effectively ends the scan. The effect is: if anything plays while a clear-and-scan is running, the clear-and-scan is aborted. If this is the intention (which I doubt it is), then players should not be able to play while a scan is in process... Which will be painful for people with large libraries on slow machines that can take hours to complete a scan. So the 'real' fix should be some way around that lock, or to have something like a transaction log for the external scanner that can be initiated at the end of the scan (which will preserve data updated while the scan is in progress, and minimi9ze the downtime to just the time it takes to merge the transactions into the persistant db). (Note that playing while a scan is in progress is painful as well: there appears to be several attempts to wait out the lock, which causes a long delay between tracks before it gives up as an unbreakable lock.)
Voted, Is this the explanation for the 3 minutes of silence everytime i add an album while playing ?
*** Bug 16461 has been marked as a duplicate of this bug. ***
I also noticed in 7.6 that when you do a scan, either "look for new changes" or "clear and re-scan", the status link says "Scanning -view progress" and sit there displaying it. Once you click "view progress", then the page will refresh and show the correct info. Is this related?
Created attachment 7254 [details] scanning problems Scanning fails...
It looks like this happnes when any of my squeezeboxes has an 'paused' track, and a clear & rescan has been triggered.
[11-05-03 06:08:52.2136] Slim::Networking::IO::Select::__ANON__ (147) Error: Select task failed calling Slim::Web::HTTP::processHTTP: DBD::SQLite::st execute failed: database is locked at /<C:\PROGRA~2\SQUEEZ~1\server\SqueezeSvr.exe>Slim/Utils/ArtworkCache.pm line 132. ; fh=Slim::Web::HTTP::ClientConn=GLOB(0xa04205c) [11-05-03 06:08:52.6957] Slim::Networking::IO::Select::__ANON__ (147) Error: Select task failed calling Slim::Web::HTTP::processHTTP: DBD::SQLite::st fetchrow_array failed: database is locked at /<C:\PROGRA~2\SQUEEZ~1\server\SqueezeSvr.exe>Slim/Utils/ArtworkCache.pm line 134. ; fh=Slim::Web::HTTP::ClientConn=GLOB(0x8383fb4)
== Auto-comment from SVN commit #32476 to the slim repo by mherger == == http://svn.slimdevices.com/slim?view=revision&revision=32476 == Fixed Bug: 16003 Description: don't try to update the persistent DB while a scan is running