GNOME Bugzilla – Bug 622826
User interface locked up by long SELECT queries
Last modified: 2010-07-11 21:52:15 UTC
I am seeing a lot of this type of query being run in the main thread locking up the interface. [2 Debug 16:59:00.412] Executed in 12625ms SELECT CoreTracks.Rating,CoreTracks.LastStreamError,CoreTracks.TrackID,CoreTracks.PrimarySourceID,CoreTracks.ArtistID,CoreTracks.AlbumID,CoreTracks.TagSetID,CoreTracks.MusicBrainzID,CoreTracks.MimeType,CoreTracks.FileSize,CoreTracks.FileModifiedStamp,CoreTracks.LastSyncedStamp,CoreTracks.Attributes,CoreTracks.Title,CoreTracks.TitleSort,CoreTracks.TrackNumber,CoreTracks.TrackCount,CoreTracks.Disc,CoreTracks.DiscCount,CoreTracks.Duration,CoreTracks.Year,CoreTracks.Genre,CoreTracks.Composer,CoreTracks.Conductor,CoreTracks.Grouping,CoreTracks.Copyright,CoreTracks.LicenseUri,CoreTracks.Comment,CoreTracks.BPM,CoreTracks.BitRate,CoreTracks.SampleRate,CoreTracks.BitsPerSample,CoreTracks.Score,CoreTracks.PlayCount,CoreTracks.SkipCount,CoreTracks.ExternalID,CoreTracks.LastPlayedStamp,CoreTracks.LastSkippedStamp,CoreTracks.DateAddedStamp,CoreTracks.DateUpdatedStamp,CoreTracks.Uri,CoreArtists.Name,CoreArtists.NameSort,CoreAlbums.Title,CoreAlbums.TitleSort,CoreAlbums.ArtistName,CoreAlbums.ArtistNameSort,CoreAlbums.IsCompilation,CoreAlbums.MusicBrainzID,CoreArtists.MusicBrainzID FROM CoreTracks,CoreArtists,CoreAlbums WHERE CoreArtists.ArtistID = CoreTracks.ArtistID AND CoreAlbums.AlbumID = CoreTracks.AlbumID AND CoreTracks.Uri = 'file:///home/david/Musik/Thomas%20Paine/The%20Age%20of%20Reason/20%20-%20Part%20Second,%20Section%205.mp3' LIMIT 1 It appears to happen as a result of having Banshee writing metadata to the files and having the update file name feature enabled. The most obvious way to trigger this is to change metadata, to import new music (either manually or using the library watcher) or if pending updates from a previous run exist (in which Banshees UI is locked up from the start). I think it may be a good place to begin looking: http://git.gnome.org/browse/banshee/tree/src/Core/Banshee.Services/Banshee.Metadata/SaveTrackMetadataJob.cs It appears that we may be doing fairly expensive IO as part of the query also I wonder if the (WriteMetadataEnabled || WriteRatingsAndPlayCountsEnabled) && RenameEnabled case could be optimized right now it seems like we do the IO twice. Also I have observed files having metadata changes done that do not affect the naming seeingly also undergo file name updating unneededly which could be optimized. The interface will unfreeze occasionally but remains effectively unusable on account of the short duration of these unfreezes.
Created attachment 164701 [details] Log of a Banshee run experiencing this problem As bugzilla rejected the log on account of it's size I have attached a compressed version instead.
This gets weirder, it seems we are doing the same expensive query over and over again. E.g. grep 'file:///home/david/Musik/Thomas%20Paine/The%20Age%20of%20Reason/21%20-%20Part%20Second,%20Section%206.mp3' banshee.log.bug622826 [2 Debug 22:20:35.066] Executed in 12241ms SELECT CoreTracks.Rating,CoreTracks.LastStreamError,CoreTracks.TrackID,CoreTracks.PrimarySourceID,CoreTracks.ArtistID,CoreTracks.AlbumID,CoreTracks.TagSetID,CoreTracks.MusicBrainzID,CoreTracks.MimeType,CoreTracks.FileSize,CoreTracks.FileModifiedStamp,CoreTracks.LastSyncedStamp,CoreTracks.Attributes,CoreTracks.Title,CoreTracks.TitleSort,CoreTracks.TrackNumber,CoreTracks.TrackCount,CoreTracks.Disc,CoreTracks.DiscCount,CoreTracks.Duration,CoreTracks.Year,CoreTracks.Genre,CoreTracks.Composer,CoreTracks.Conductor,CoreTracks.Grouping,CoreTracks.Copyright,CoreTracks.LicenseUri,CoreTracks.Comment,CoreTracks.BPM,CoreTracks.BitRate,CoreTracks.SampleRate,CoreTracks.BitsPerSample,CoreTracks.Score,CoreTracks.PlayCount,CoreTracks.SkipCount,CoreTracks.ExternalID,CoreTracks.LastPlayedStamp,CoreTracks.LastSkippedStamp,CoreTracks.DateAddedStamp,CoreTracks.DateUpdatedStamp,CoreTracks.Uri,CoreArtists.Name,CoreArtists.NameSort,CoreAlbums.Title,CoreAlbums.TitleSort,CoreAlbums.ArtistName,CoreAlbums.ArtistNameSort,CoreAlbums.IsCompilation,CoreAlbums.MusicBrainzID,CoreArtists.MusicBrainzID FROM CoreTracks,CoreArtists,CoreAlbums WHERE CoreArtists.ArtistID = CoreTracks.ArtistID AND CoreAlbums.AlbumID = CoreTracks.AlbumID AND CoreTracks.Uri = 'file:///home/david/Musik/Thomas%20Paine/The%20Age%20of%20Reason/21%20-%20Part%20Second,%20Section%206.mp3' LIMIT 1 occurs a staggering 1450 times.
upon further investigation I can reproduce this with WriteMetadataEnabled && RenameEnabled && send_anonymous_usage_data but not without send_anonymous_usage_data. It seems very reliable in it's reproduction on my machine.
strike that it is happening right now to a run after altering metadata with WriteMetadataEnabled && WriteRatingsAndPlayCountsEnabled && RenameEnabled. send_anonymous_usage_data just seems to make it easier to trigger for some reason.
Condensed from IRC. The machine is a dual core ATOM 330 with SMT with 3 gigs of ram and an ION chip. Running a SELECT query from the log outside of Banshee: david@sagan:~$ time sqlite3 ~/.config/banshee-1/banshee.db "SELECT CoreTracks.Rating,CoreTracks.LastStreamError,CoreTracks.TrackID,CoreTracks.PrimarySourceID,CoreTracks.ArtistID,CoreTracks.AlbumID,CoreTracks.TagSetID,CoreTracks.MusicBrainzID,CoreTracks.MimeType,CoreTracks.FileSize,CoreTracks.FileModifiedStamp,CoreTracks.LastSyncedStamp,CoreTracks.Attributes,CoreTracks.Title,CoreTracks.TitleSort,CoreTracks.TrackNumber,CoreTracks.TrackCount,CoreTracks.Disc,CoreTracks.DiscCount,CoreTracks.Duration,CoreTracks.Year,CoreTracks.Genre,CoreTracks.Composer,CoreTracks.Conductor,CoreTracks.Grouping,CoreTracks.Copyright,CoreTracks.LicenseUri,CoreTracks.Comment,CoreTracks.BPM,CoreTracks.BitRate,CoreTracks.SampleRate,CoreTracks.BitsPerSample,CoreTracks.Score,CoreTracks.PlayCount,CoreTracks.SkipCount,CoreTracks.ExternalID,CoreTracks.LastPlayedStamp,CoreTracks.LastSkippedStamp,CoreTracks.DateAddedStamp,CoreTracks.DateUpdatedStamp,CoreTracks.Uri,CoreArtists.Name,CoreArtists.NameSort,CoreAlbums.Title,CoreAlbums.TitleSort,CoreAlbums.ArtistName,CoreAlbums.ArtistNameSort,CoreAlbums.IsCompilation,CoreAlbums.MusicBrainzID,CoreArtists.MusicBrainzID FROM CoreTracks,CoreArtists,CoreAlbums WHERE CoreArtists.ArtistID = CoreTracks.ArtistID AND CoreAlbums.AlbumID = CoreTracks.AlbumID AND CoreTracks.Uri = 'file:///home/david/Musik/Thomas%20Paine/The%20Age%20of%20Reason/21%20-%20Part%20Second,%20Section%206.mp3' LIMIT 1" 0|0|18672|6|4872|538|0||taglib/mp3|10638055|1277738821|1278034208|5|21 - Part Second, Section 6||22|37|0|0|1330062|0|Audiobook||||||http://www.archive.org/details/age_reason_0910_librivox|50|64|22050|0|0|0|0|0|||1277554235|1278034197|file:///home/david/Musik/Thomas%20Paine/The%20Age%20of%20Reason/21%20-%20Part%20Second,%20Section%206.mp3|Thomas Paine||The Age of Reason||Thomas Paine||0|| real 0m30.323s user 0m13.440s sys 0m1.200s A run after performing: time sqlite3 ~/.config/banshee-1/banshee.db "vacuum; analyze;" real 0m11.319s user 0m11.090s sys 0m0.050s A marked improvement in real time but the bug is still triggerable at will and performance is still horrible. david@sagan:~$ sqlite3 --version 3.6.23.1 <gabaug> dnielsen: also include the output of running ".schema CoreTracks" sqlite cmd david@sagan:~$ ".schema CoreTracks" sqlite cmd david@sagan:~$ The bug also has a tendency to consume a lot of resources, halting the entire system. (could someone use this to bring a system down?)
The bug has been reproduced on a clean install of the OS and new user profile using only the existing data. The system is running Ubuntu Maverick x86_64 with Mono 2.6.x (but the but exists with 2.4.x as well). Information on how SQLite is configured can be found here: https://launchpad.net/ubuntu/maverick/+source/sqlite3
(In reply to comment #5) > <gabaug> dnielsen: also include the output of running ".schema CoreTracks" > sqlite cmd > > david@sagan:~$ ".schema CoreTracks" sqlite cmd > david@sagan:~$ What Gabriel meant is this: $ sqlite3 ~/.config/banshee-1/banshee.db ".schema CoreTracks"
david@sagan:~$ sqlite3 ~/.config/banshee-1/banshee.db ".schema CoreTracks" CREATE TABLE CoreTracks ( PrimarySourceID INTEGER NOT NULL, TrackID INTEGER PRIMARY KEY, ArtistID INTEGER, AlbumID INTEGER, TagSetID INTEGER, ExternalID INTEGER, MusicBrainzID TEXT, Uri TEXT, MimeType TEXT, FileSize INTEGER, BitRate INTEGER, SampleRate INTEGER, BitsPerSample INTEGER, Attributes INTEGER DEFAULT 5, LastStreamError INTEGER DEFAULT 0, Title TEXT, TitleLowered TEXT, TitleSort TEXT, TitleSortKey BLOB, TrackNumber INTEGER, TrackCount INTEGER, Disc INTEGER, DiscCount INTEGER, Duration INTEGER, Year INTEGER, Genre TEXT, Composer TEXT, Conductor TEXT, Grouping TEXT, Copyright TEXT, LicenseUri TEXT, Comment TEXT, Rating INTEGER, Score INTEGER, PlayCount INTEGER, SkipCount INTEGER, LastPlayedStamp INTEGER, LastSkippedStamp INTEGER, DateAddedStamp INTEGER, DateUpdatedStamp INTEGER, MetadataHash TEXT, BPM INTEGER, LastSyncedStamp INTEGER, FileModifiedStamp INTEGER ); CREATE INDEX CoreTracksAggregatesIndex ON CoreTracks(FileSize, Duration); CREATE INDEX CoreTracksCoverArtIndex ON CoreTracks (PrimarySourceID, AlbumID, DateUpdatedStamp); CREATE INDEX CoreTracksExternalIDIndex ON CoreTracks(PrimarySourceID, ExternalID); CREATE INDEX CoreTracksPrimarySourceIndex ON CoreTracks(ArtistID, AlbumID, PrimarySourceID, Disc, TrackNumber, Uri); CREATE INDEX CoreTracksUriIndex ON CoreTracks(PrimarySourceID, Uri);
David sent me his db. Removing the join on CoreArtists/Albums from the query puts the performance where it should be -- so it's the join that's the problem, no the URI condition.
Hrm, the joined query is just as slow on my own database. The only place I could find that query being produced was in the LibraryWatcher. I've committed a fix: commit de5134329120c9019d0e7fbb193a20bd51a31ba5 Author: Gabriel Burt <gabriel.burt@gmail.com> Date: Sun Jul 11 14:50:23 2010 [LibraryWatcher] Fix very slow query Adding a PrimarySourceID condition speeds things up greatly (bgo#622826)