Plugin to test database tweaks

[JJZolx]

Full scan times are back to what they were previously, so it looks like the reinstatement of the missing index has fixed that. Buffer values don't appear to have much effect on my system, which stores the cache on SSD.

[Mnyb]

FYI after you do this vacuum operation , you may have to flush iPengs cache to get artwork at single album level when browsing .

[Mnyb]

FYI after you do this vacuum operation , you may have to flush iPengs cache to get artwork at single album level when browsing .

I may just see things but iPeng apear faster and do not "flicker" when updating art ?

[PasTim]

The custom scan after the last LMS scan I did took around 1.5 hours. This is around half the time it took before I started using the auto-vacuum and large buffer size.

I then deleted the indices, restarted LMS, and did another full scan. There's no change. A few seconds here or there at most.

Later I will reduce the buffer to 20MB and report.

The Custom Scan 'info' output is below. It still took almost exactly 1.5 hours. I include this in case Erland is interested.

[14-05-06 18:53:37.5855] Plugins::CustomScan::Scanner::fullRescan (678) Performing rescan
[14-05-06 18:53:37.6016] Plugins::CustomScan::Scanner::fullRescan (690) Starting scanning with Custom Tag
[14-05-06 18:53:37.6027] Plugins::CustomScan::Scanner::fullRescan (690) Starting scanning with Rating Tag
[14-05-06 18:53:37.6037] Plugins::CustomScan::Scanner::fullRescan (690) Starting scanning with Mixed Tag
[14-05-06 18:53:37.6050] Plugins::CustomScan::Scanner::refreshData (1944) Refresh triggered by module: LastFM
[14-05-06 18:53:37.6058] Plugins::CustomScan::Scanner::refreshData (1955) CustomScan: Synchronizing Custom Scan data, please wait...
[14-05-06 18:53:37.6066] Plugins::CustomScan::Scanner::refreshData (1957) Starting to update musicbrainz id's in custom scan artist data based on names
[14-05-06 18:53:37.6166] Plugins::CustomScan::Scanner::refreshData (1981) Finished updating musicbrainz id's in custom scan artist data based on names, updated 0 items : It took 0.009859 seconds
[14-05-06 18:53:37.6185] Plugins::CustomScan::Scanner::refreshData (1987) Starting to update custom scan artist data based on musicbrainz ids
[14-05-06 18:53:37.6201] Plugins::CustomScan::Scanner::refreshData (2010) Finished updating custom scan artist data based on musicbrainz ids, updated 0 items : It took 0.001563 seconds
[14-05-06 18:53:37.6214] Plugins::CustomScan::Scanner::refreshData (2017) Starting to update custom scan artist data based on names
[14-05-06 18:53:37.6229] Plugins::CustomScan::Scanner::refreshData (2040) Finished updating custom scan artist data based on names, updated 0 items : It took 0.001406 seconds
[14-05-06 18:53:37.6238] Plugins::CustomScan::Scanner::refreshData (2047) Starting to update musicbrainz id's in custom scan album data based on titles
[14-05-06 18:53:37.6253] Plugins::CustomScan::Scanner::refreshData (2071) Finished updating musicbrainz id's in custom scan album data based on titles, updated 0 items : It took 0.001434 seconds
[14-05-06 18:53:37.6262] Plugins::CustomScan::Scanner::refreshData (2077) Starting to update custom scan album data based on musicbrainz ids
[14-05-06 18:53:37.6277] Plugins::CustomScan::Scanner::refreshData (2100) Finished updating custom scan album data based on musicbrainz ids, updated 0 items : It took 0.001453 seconds
[14-05-06 18:53:37.6286] Plugins::CustomScan::Scanner::refreshData (2106) Starting to update custom scan album data based on titles
[14-05-06 18:53:37.6301] Plugins::CustomScan::Scanner::refreshData (2129) Finished updating custom scan album data based on titles, updated 0 items : It took 0.001406 seconds
[14-05-06 18:53:37.6310] Plugins::CustomScan::Scanner::refreshData (2135) Starting to update musicbrainz id's in custom scan track data based on urls
[14-05-06 18:53:52.4797] Plugins::CustomScan::Scanner::refreshData (2159) Finished updating musicbrainz id's in custom scan track data based on urls, updated 0 items : It took 14.84864 seconds
[14-05-06 18:53:52.5375] Plugins::CustomScan::Scanner::refreshData (2165) Starting to update custom scan track data based on musicbrainz ids
[14-05-06 18:53:56.1836] Plugins::CustomScan::Scanner::refreshData (2261) Finished updating custom scan track data based on musicbrainz ids, updated 1157 items : It took 3.646018 seconds
[14-05-06 18:53:56.2403] Plugins::CustomScan::Scanner::refreshData (2267) Starting to update custom scan track data based on urls
[14-05-06 18:56:56.7353] Plugins::CustomScan::Scanner::refreshData (2290) Finished updating custom scan track data based on urls, updated 473284 items : It took 180.494953 seconds
[14-05-06 18:56:56.8511] Plugins::SrvrPowerCtrl::Watchdog::OnWakeupWatchdog (647) Wakeup Call!!
[14-05-06 18:56:56.9982] Plugins::CustomScan::Scanner::refreshData (2297) Start optimizing SQLite database
[14-05-06 18:57:17.3130] Plugins::CustomScan::Scanner::refreshData (2303) Finished optimizing SQLite database : It took 20.314617 seconds
[14-05-06 18:57:17.3138] Plugins::CustomScan::Scanner::refreshData (2305) CustomScan: Synchronization finished
[14-05-06 18:57:18.4164] Plugins::TrackStat::Storage::refreshTracks (1237) TrackStat: Synchronizing TrackStat data, please wait...
[14-05-06 18:57:24.4583] Plugins::TrackStat::Storage::refreshTracks (1886) TrackStat: Synchronizing TrackStat data finished
[14-05-06 18:57:30.4800] Plugins::CustomScan::Scanner::fullRescan (678) Performing rescan
[14-05-06 18:57:30.4933] Plugins::CustomScan::Scanner::fullRescan (681) CustomScan: Scanning already in progress, wait until its finished
[14-05-06 18:57:30.4947] Plugins::TrackStat::Storage::refreshTracks (1237) TrackStat: Synchronizing TrackStat data, please wait...
[14-05-06 18:57:35.2576] Plugins::TrackStat::Storage::refreshTracks (1886) TrackStat: Synchronizing TrackStat data finished
[14-05-06 18:57:37.2727] Plugins::CustomScan::Scanner::initTrackScan (1318) Clearing track data for mixedtag
[14-05-06 18:57:37.7588] Plugins::CustomScan::Scanner::initTrackScan (1356) Start clearing track data with drop
[14-05-06 18:58:21.7715] Plugins::CustomScan::Scanner::initDatabase (96) CustomScan: Creating database tables
[14-05-06 18:58:21.7771] Plugins::CustomScan::Scanner::executeSQLFile (498) Executing SQL file /var/lib/squeezeboxserver/cache/InstalledPlugins/Plugins/CustomScan/SQL/SQLite/dbcreate.sql
[14-05-06 18:58:21.8012] Plugins::CustomScan::Scanner::initDatabase (439) Creating indexes
[14-05-06 18:58:21.8026] Plugins::CustomScan::Scanner::executeSQLFile (498) Executing SQL file /var/lib/squeezeboxserver/cache/InstalledPlugins/Plugins/CustomScan/SQL/SQLite/dbindex.sql
[14-05-06 18:58:50.4562] Plugins::CustomScan::Scanner::initTrackScan (1396) Deleted track data after 73.183448 seconds
[14-05-06 18:58:50.4572] Plugins::CustomScan::Scanner::initTrackScan (1318) Clearing track data for ratingtag
[14-05-06 18:58:50.4648] Plugins::CustomScan::Scanner::initTrackScan (1336) Start clearing track data with delete
[14-05-06 18:58:53.1434] Plugins::CustomScan::Scanner::initTrackScan (1396) Deleted track data after 2.686274 seconds
[14-05-06 18:58:53.1443] Plugins::CustomScan::Scanner::initTrackScan (1318) Clearing track data for customtag
[14-05-06 18:58:53.3012] Plugins::CustomScan::Scanner::initTrackScan (1356) Start clearing track data with drop
[14-05-06 18:58:58.7119] Plugins::CustomScan::Scanner::initDatabase (96) CustomScan: Creating database tables
[14-05-06 18:58:58.7133] Plugins::CustomScan::Scanner::executeSQLFile (498) Executing SQL file /var/lib/squeezeboxserver/cache/InstalledPlugins/Plugins/CustomScan/SQL/SQLite/dbcreate.sql
[14-05-06 18:58:58.7248] Plugins::CustomScan::Scanner::initDatabase (439) Creating indexes
[14-05-06 18:58:58.7262] Plugins::CustomScan::Scanner::executeSQLFile (498) Executing SQL file /var/lib/squeezeboxserver/cache/InstalledPlugins/Plugins/CustomScan/SQL/SQLite/dbindex.sql
[14-05-06 18:58:58.9773] Plugins::CustomScan::Scanner::initTrackScan (1396) Deleted track data after 5.832959 seconds
[14-05-06 18:58:58.9852] Plugins::CustomScan::Scanner::initTrackScan (1406) Got 24687 tracks
[14-05-06 18:59:04.6256] Slim::Networking::IO::Select::__ANON__ (131) Error: Select task failed calling Slim::Networking::Async::HTTP::_http_read_body: illegal file descriptor or filehandle (either no attached file descriptor or illegal value):  at /usr/share/perl5/Slim/Networking/IO/Select.pm line 134.
; fh=Slim::Networking::Async::Socket::HTTP=GLOB(0xb342f28)
[14-05-06 20:20:03.0309] Plugins::CustomScan::Modules::MixedTag::exitScanTrack (227) MixedTag: Creating ARTIST tag data
[14-05-06 20:20:03.0620] Plugins::CustomScan::Modules::MixedTag::exitScanTrack (231) MixedTag: Creating ALBUMARTIST tag data
[14-05-06 20:20:26.2835] Plugins::CustomScan::Modules::MixedTag::exitScanTrack (235) MixedTag: Creating TRACKARTIST tag data
[14-05-06 20:21:01.7244] Plugins::CustomScan::Modules::MixedTag::exitScanTrack (239) MixedTag: Creating CONDUCTOR tag data
[14-05-06 20:21:10.1032] Plugins::CustomScan::Modules::MixedTag::exitScanTrack (243) MixedTag: Creating COMPOSER tag data
[14-05-06 20:21:22.2081] Plugins::CustomScan::Modules::MixedTag::exitScanTrack (247) MixedTag: Creating BAND tag data
[14-05-06 20:21:34.1983] Plugins::CustomScan::Modules::MixedTag::exitScanTrack (251) MixedTag: Creating ALBUM tag data
[14-05-06 20:21:48.0198] Plugins::CustomScan::Modules::MixedTag::exitScanTrack (255) MixedTag: Creating GENRE tag data
[14-05-06 20:22:08.0191] Plugins::CustomScan::Modules::MixedTag::exitScanTrack (259) MixedTag: Creating YEAR tag data
[14-05-06 20:22:24.1135] Plugins::CustomScan::Modules::MixedTag::exitScanTrack (275) MixedTag: Creating CustomTag based tag data
[14-05-06 20:23:47.2887] Plugins::CustomScan::Modules::MixedTag::exitScanTrack (292) MixedTag: Finished creating tag data
[14-05-06 20:23:47.2919] Plugins::SrvrPowerCtrl::Watchdog::OnWakeupWatchdog (647) Wakeup Call!!
[14-05-06 20:23:47.4725] Plugins::CustomScan::Scanner::exitScan (1014) Optimizing SQLite database
[14-05-06 20:23:56.5500] Plugins::CustomScan::Scanner::exitScan (1041) Rescan finished

[erland]

The Custom Scan 'info' output is below. It still took almost exactly 1.5 hours. I include this in case Erland is interested.

Thanks!

Looks like 1 hour and 21 minutes were spent in the Custom Tag scanning process which will iterate through all tracks in the database and:
- do a select towards tracks table for each track
- do a number of inserts into customscan_track_attributes table for each track (one for each tag you configured it to scan)
- commit after each track has been processed

The customscan_track_attributes table have a number of indexes so if the performance is limited by the database I suspect it might be index related.

In this case it could be better to disable the index during the scanning, at least in a large library, and enable them after the scanning process has finished. I need to experiment a bit and I think I also need to add some log point so we are sure the time is spend in the database and not in file I/O or caused by background scheduler running slowly to allow music playback during scanning. Custom Scan runs in the main LMS process and not in the scanner process as the main LMS scanner does.

[mherger]

Plugin to test database tweaks

> In this case it could be better to disable the index during the
> scanning, at least in a large library, and enable them after the
> scanning process has finished. I need to experiment a bit and I think I
> also need to add some log point so we are sure the time is spend in the
> database and not in file I/O or caused by background scheduler running
> slowly to allow music playback during scanning. Custom Scan runs in the
> main LMS process and not in the scanner process as the main LMS scanner
> does.

Check out NYTProf. It is an excellent tool! (though 1.5h worth of
scanning might take forever to analyze :-))

http://wiki.slimdevices.com/index.php/Profiling

It shows you where the program is spending time (queries, commits, file
reading etc.), even how many times a particular line was executed etc.

--

Michael

[PasTim]

Thanks!

Looks like 1 hour and 21 minutes were spent in the Custom Tag scanning process which will iterate through all tracks in the database and:
- do a select towards tracks table for each track
- do a number of inserts into customscan_track_attributes table for each track (one for each tag you configured it to scan)
- commit after each track has been processed

The customscan_track_attributes table have a number of indexes so if the performance is limited by the database I suspect it might be index related.

In this case it could be better to disable the index during the scanning, at least in a large library, and enable them after the scanning process has finished. I need to experiment a bit and I think I also need to add some log point so we are sure the time is spend in the database and not in file I/O or caused by background scheduler running slowly to allow music playback during scanning. Custom Scan runs in the main LMS process and not in the scanner process as the main LMS scanner does.

I'd be happy to try an Alpha test if it would help. If you wanted to supply me with a different 'create tables' script I could swap in, and maybe an almost null 'create indexes' script, I could probably manage to run that myself. I could then manually run the original create indexes scripts later.

For me I'd be happy not to attempt to play music during the custom scan because it has never worked well in the past, stopping and starting and being generally impossible to listen to. It may be that with a vacuumed system it would work better, but I haven't tried.

[PasTim]

> In this case it could be better to disable the index during the
> scanning, at least in a large library, and enable them after the
> scanning process has finished. I need to experiment a bit and I think I
> also need to add some log point so we are sure the time is spend in the
> database and not in file I/O or caused by background scheduler running
> slowly to allow music playback during scanning. Custom Scan runs in the
> main LMS process and not in the scanner process as the main LMS scanner
> does.

Check out NYTProf. It is an excellent tool! (though 1.5h worth of
scanning might take forever to analyze :-))

http://wiki.slimdevices.com/index.php/Profiling

It shows you where the program is spending time (queries, commits, file
reading etc.), even how many times a particular line was executed etc.

--

Michael

Erland, if you want me to try I'll could try to have a go, but I'd need a little help in getting it going. I currently run LMS as a service, and am not sure how this fits in with running it as a straight perl script.

[bwaldron]

Testing this with my low-end single core Atom server (2 GB RAM) running Windows 7 with 34K tracks (LMS 7.8.1 1398166241). Vacuumed the large databases -- didn't take all that long -- and set the buffer size to 100 MB (my library.db is 91.7 MB). My initial impression is that search performance via the web interface and with Orange Squeeze is dramatically improved.

Thanks, Michael!

[mherger]

Plugin to test database tweaks

> My impression is that reading the indices into memory was itself taking
> time, and that once done, and presumably some of the related data, all
> was well.

That's correct. And that's why a first search in the web UI could still
stall playback. But once the indices are fully buffered in memory,
things would be sped up considerably.

--

Michael

[mherger]

Plugin to test database tweaks

> Full scan times are back to what they were previously, so it looks like
> the reinstatement of the missing index has fixed that. Buffer values
> don't appear to have much effect on my system, which stores the cache on
> SSD.

Thanks for the confirmation: I experienced the same. No improvement
using a higher buffer. It's my understanding that scans still are
dominated by a.) reading the music files and b.) _writing_ to the
database. Profiling showed that the most expensive requests where the
inserts and updates.

--

Michael

[mherger]

Plugin to test database tweaks

> Check out NYTProf. It is an excellent tool! (though 1.5h worth of
> scanning might take forever to analyze :-))

I uploaded a sample profile from a test scan I did a few days ago:

http://www.herger.net/slim/nytprof/

It eg. shows that almost half the time of that scan was spent reading
the music files. Next is SQL execute with less than 10% of the time
spent. Details about those SQL statements can be got if you click the
entry in the list

http://www.herger.net/slim/nytprof/scanner-pl-1-line.html#DBI__st__execute

Unfortunately calls are ordered by the number of calls. I'd prefer by
the time spent. But that's a detail :-).

And it's still not clear to me why searching the persistent table would
be ranked so high up (time spent).

--

Michael

[PasTim]

I reduced the buffer size to 20MB, restarted LMS and did a full scan. Not knowing quite how all this works, I then wondered if there might be relevant data held in memory even when LMS is stopped, so I rebooted and repeated.

To be be brief I have not detected much difference in scan times with changes in buffer size or with/without the extra indices. Custom Scan is a few minutes quicker with a larger buffer, but it varies by several minutes each time anyway. The LMS scan varies by a minute or so.

By far the biggest improvement for me in scanning has been due to the vacuuming. I believe my Custom Scan scans are much quicker because they now start with a vacuumed library.db. Similarly the improvement in menu responsiveness is, as far as I can tell, mostly down to vacuuming. I'll try a test later without vacuuming.

[PasTim]

I reduced the buffer size to 20MB, restarted LMS and did a full scan. Not knowing quite how all this works, I then wondered if there might be relevant data held in memory even when LMS is stopped, so I rebooted and repeated.

To be be brief I have not detected much difference in scan times with changes in buffer size or with/without the extra indices. Custom Scan is a few minutes quicker with a larger buffer, but it varies by several minutes each time anyway. The LMS scan varies by a minute or so.

By far the biggest improvement for me in scanning has been due to the vacuuming. I believe my Custom Scan scans are much quicker because they now start with a vacuumed library.db. Similarly the improvement in menu responsiveness is, as far as I can tell, mostly down to vacuuming. I'll try a test later without vacuuming.

I turned off all vacuuming, rebooted and checked auto-vacuum was still off. Has something else changed in database tweak 0.6? I've rescanned since installing it, and library.db is always reported as having no waste. That wasn't the case when I first installed the previous version. The persist.db also seems to have low waste, but is ~30MB bigger than it was. Whilst custom scan scanning, the vacuum tick appeared against persist.db and then disappeared. I'm a little puzzled.

The LMS scans currently take about the same as before, ~19 minutes. The Custom Scans are back up from 1.5 to nearly 2 hours. Not the 3 hours that I recall, and I don't know why. It may be due to faulty memory (mine, not the computer!), being on the latest ubuntu 14.04 (which I only installed in mid April), or LMS 7.9, or some residual vacuuming going on.

Even the first execution of my Custom Scan menus is not quite as painfully slow as it was (~ 30 seconds).

I wonder whether doing repeated rescans on an unchanged library is causing less fragmentation than with a few changes or additions?

I still convinced by vacuuming, but am somewhat confused! I had expected different results, and I'm trying not to let my expectations drive my interpretation of the the results.

Edit - I have just re-vacuumed, and library.db shrank by around 2%, persist.db by around 8%. I'm not sure the renamed 'waste' column is doing what it says.

[DJanGo]

Hi i dont want to go into the deeeeeeeep but a few lines should be enough.

If you drop a table or database and create a new one there is no "trash" or "old" data that belongs to the trash (means no "fragmentation")

If you change some (may in your library) and do a rescan, there are some old datas, thats now trash or "fragmentation".
if you dont change nothing where should the "trash" / Old Data come from?

This is not a black hokuspokus, its pure logic.

If you dont believe - check the source from both plugins and "check" what it does.

To be be brief I have not detected much difference in scan times with changes in buffer size or with/without the extra indices.

I'd like to better understand how we could tune the LMS database to
improve performance. Please continue to read this posting if

- you have a decent collection of 20k+ tracks
- you run LMS 7.8/7.9
- you are willing to take the risk of applying some little tested
changes to your music server
- you have a server machine with a couple of gigabytes of RAM
- you think LMS usage (NOT the scanner!) is slow