After an evaluation, GNOME has moved from Bugzilla to GitLab. Learn more about GitLab.
No new issues can be reported in GNOME Bugzilla anymore.
To report an issue in a GNOME project, go to GNOME GitLab.
Do not go to GNOME Gitlab for: Bluefish, Doxygen, GnuCash, GStreamer, java-gnome, LDTP, NetworkManager, Tomboy.
Bug 622826 - User interface locked up by long SELECT queries
User interface locked up by long SELECT queries
Status: RESOLVED FIXED
Product: banshee
Classification: Other
Component: general
git master
Other Linux
: Normal critical
: 1.x
Assigned To: Banshee Maintainers
Banshee Maintainers
Depends on:
Blocks:
 
 
Reported: 2010-06-26 20:36 UTC by David Nielsen
Modified: 2010-07-11 21:52 UTC
See Also:
GNOME target: ---
GNOME version: ---


Attachments
Log of a Banshee run experiencing this problem (152.79 KB, application/x-compressed-tar)
2010-06-26 20:38 UTC, David Nielsen
Details

Description David Nielsen 2010-06-26 20:36:26 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.
Comment 1 David Nielsen 2010-06-26 20:38:12 UTC
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.
Comment 2 David Nielsen 2010-06-27 21:39:42 UTC
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.
Comment 3 David Nielsen 2010-07-01 21:53:06 UTC
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.
Comment 4 David Nielsen 2010-07-06 00:14:29 UTC
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.
Comment 5 David Nielsen 2010-07-06 19:06:00 UTC
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?)
Comment 6 David Nielsen 2010-07-06 19:23:01 UTC
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
Comment 7 Alexander Kojevnikov 2010-07-07 01:31:19 UTC
(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"
Comment 8 David Nielsen 2010-07-07 03:52:55 UTC
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);
Comment 9 Gabriel Burt 2010-07-11 21:16:17 UTC
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.
Comment 10 Gabriel Burt 2010-07-11 21:52:15 UTC
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)