Working on a plugin - Scanning question

[mherger]

Working on a plugin - Scanning question

>> the involved sql queries are:
>
> Time each of these queries to figure out which one burns the most CPU
> cycle.
>
> my $t = time();
> runSQL1(); # whatever
> warn "SQL1: " . (time() - $t);
>
> Or similar. Poor man's instrumentation.

Oh, just saw that Erland did add a lot of timing measurements already.
Run LMS with debug mode for plugin.trackstat, then provide the
server.log file.

[mherger]

Working on a plugin - Scanning question

> Part 3: Analyze command
> https://github.com/erland/lms-tracks...orage.pm#L1406
> - Run analyze command to optimise the performance of TrackStat table
> - Not sure analyse is possible to run on per track basis so this should
> probably run as a post scan action. Don't think it's needed at LMS
> startup.

Analayze should certainly be run, but only once, at the end of a scan -
which LMS already does.

> Part 8: Update ratings in LMS database
> https://github.com/erland/lms-tracks...orage.pm#L1496
> - The purpose of this part is to update ratings in LMS tracks_persistent
> table with the value from TrackStat table.

So are you saying that you keep a separate database file around, then
duplicate the data to the persist database? That certainly would be one
good place to optimize...

> - Not really sure this is required any more, might be there for
> historical reason when tracks_persistent didn't always survived upgrades

Yep.

[mamema]

at the moment looking around to find some sqlite query tools which are able to execute those queries. A little bit difficult because those tools (DBeaver for example) are executing against ONE db file and i have to use the persistent.db and library.db

and Michael by the way, i've enabled debug level and the snippet about the 3.5 hours (above in thread) is the only time related message from trackstat

[erland]

at the moment looking around to find some sqlite query tools which are able to execute those queries. A little bit difficult because those tools (DBeaver for example) are executing against ONE db file and i have to use the persistent.db and library.db

If you want to run a SELECT statement it’s probably easiest to do that by creating a Free form query in Database Query plugin. By doing that you don’t have to care if the tables are in persist or library db.

i've enabled debug level and the snippet about the 3.5 hours (above in thread) is the only time related message from trackstat

That’s for the musicbrainz part, do you have the log entries for the other parts of the refresh operation also.

[mherger]

at the moment looking around to find some sqlite query tools which are able to execute those queries. A little bit difficult because those tools (DBeaver for example) are executing against ONE db file and i have to use the persistent.db and library.db

I'm using SQLiteStudio (https://sqlitestudio.pl). It allows you to "attach" additional files:

and Michael by the way, i've enabled debug level and the snippet about the 3.5 hours (above in thread) is the only time related message from trackstat

Wouldn't there be more information, like what step took how long?

[erland]

> Part 8: Update ratings in LMS database
> https://github.com/erland/lms-tracks...orage.pm#L1496
> - The purpose of this part is to update ratings in LMS tracks_persistent
> table with the value from TrackStat table.

So are you saying that you keep a separate database file around, then
duplicate the data to the persist database? That certainly would be one
good place to optimize...

Separate table in persist.db. So it’s the same database file but separate table.
Not sure it’s possible to avoid a separate table as long as LMS deletes the data in track_persistent it you rename or move a music file. Part 1 in my description takes care of recovering the old rating, play count and last played time by using musicbrainz id but that’s only possible if the old data hasn’t been deleted when this logic executes.

[mamema]

I'm using SQLiteStudio (https://sqlitestudio.pl). It allows you to "attach" additional files:

Wouldn't there be more information, like what step took how long?

thank you Michael for the hint with SQLiteStudio. Trying it.

And here is my trackstat debug time log

[21-02-26 01:37:49.3783] Plugins::TrackStat::Storage::refreshTracks (1242) TrackStat: Synchronizing TrackStat data, please wait...
[21-02-26 01:37:49.3791] Plugins::TrackStat::Storage::refreshTracks (1292) Starting to update urls in statistic data based on musicbrainz ids
[21-02-26 05:30:20.7908] Plugins::TrackStat::Storage::refreshTracks (1371) Finished updating urls in statistic data based on musicbrainz ids, updated 117340 items : It took 13951.384263 seconds
[21-02-26 05:30:20.8879] Plugins::TrackStat::Storage::refreshTracks (1377) Starting analyzing track_statistics table
[21-02-26 05:30:21.5194] Plugins::TrackStat::Storage::refreshTracks (1379) Finished analyzing track_statistics table : It took 0.631376 seconds
[21-02-26 05:30:21.5197] Plugins::TrackStat::Storage::refreshTracks (1387) Starting to update md5 in statistic data based on urls
[21-02-26 05:30:22.0579] Plugins::TrackStat::Storage::refreshTracks (1405) Finished updating md5 in statistic data based on urls, updated 0 items : It took 0.537993 seconds
[21-02-26 05:30:22.0582] Plugins::TrackStat::Storage::refreshTracks (1420) Starting to update musicbrainz id's in statistic data based on urls
[21-02-26 05:30:22.7297] Plugins::TrackStat::Storage::refreshTracks (1444) Finished updating musicbrainz id's in statistic data based on urls, updated 0 items : It took 0.670729 seconds
[21-02-26 05:30:22.7302] Plugins::TrackStat::Storage::refreshTracks (1458) Starting to add tracks without added times in statistic data based on urls
[21-02-26 05:30:26.2909] Plugins::TrackStat::Storage::refreshTracks (1482) Finished adding tracks without added times in statistic data based on urls, added 4661 items : It took 3.560551 seconds
[21-02-26 05:30:26.2912] Plugins::TrackStat::Storage::refreshTracks (1488) Starting analyzing track_statistics table
[21-02-26 05:30:26.7746] Plugins::TrackStat::Storage::refreshTracks (1490) Finished analyzing track_statistics table : It took 0.483141 seconds
[21-02-26 05:30:26.7749] Plugins::TrackStat::Storage::refreshTracks (1496) Starting to update ratings in standard slimserver database based on urls
[21-02-26 05:30:27.1342] Plugins::TrackStat::Storage::refreshTracks (1520) Finished updating ratings in standard slimserver database based on urls, updated 0 items : It took 0.359071 seconds
[21-02-26 05:30:27.1345] Plugins::TrackStat::Storage::refreshTracks (1534) Starting to update added times in statistic data based on urls
[21-02-26 05:30:27.7547] Plugins::TrackStat::Storage::refreshTracks (1558) Finished updating added times in statistic data based on urls, updated 1032 items : It took 0.619965 seconds
[21-02-26 05:30:27.7551] Plugins::TrackStat::Storage::refreshTracks (1564) Starting analyzing track_statistics table
[21-02-26 05:30:28.0165] Plugins::TrackStat::Storage::refreshTracks (1566) Finished analyzing track_statistics table : It took 0.26127 seconds
[21-02-26 05:30:28.0168] Plugins::TrackStat::Storage::refreshTracks (1572) Starting to update play counts in statistic data based on urls
[21-02-26 05:30:28.5684] Plugins::TrackStat::Storage::refreshTracks (1596) Finished updating play counts in statistic data based on urls, updated 0 items : It took 0.551176 seconds
[21-02-26 05:30:28.5688] Plugins::TrackStat::Storage::refreshTracks (1601) Starting to update last played times in statistic data based on urls
[21-02-26 05:30:29.2181] Plugins::TrackStat::Storage::refreshTracks (1625) Finished updating last played times in statistic data based on urls, updated 0 items : It took 0.647145 seconds
[21-02-26 05:30:29.2184] Plugins::TrackStat::Storage::refreshTracks (1639) Starting to update ratings in statistic data based on urls
[21-02-26 05:30:30.8542] Plugins::TrackStat::Storage::refreshTracks (1663) Finished updating ratings in statistic data based on urls, updated 1 items : It took 1.635594 seconds
[21-02-26 05:30:30.8545] Plugins::TrackStat::Storage::refreshTracks (1669) Starting analyzing track_statistics table
[21-02-26 05:30:31.1916] Plugins::TrackStat::Storage::refreshTracks (1671) Finished analyzing track_statistics table : It took 0.336865 seconds
[21-02-26 05:30:31.1919] Plugins::TrackStat::Storage::refreshTracks (1677) Starting to update unrated ratings in statistic data based on null
[21-02-26 05:30:31.2744] Plugins::TrackStat::Storage::refreshTracks (1697) Finished updating unrated ratings in statistic data based on null, updated 0 items : It took 0.079559 seconds
[21-02-26 05:30:31.2752] Plugins::TrackStat::Storage::refreshTracks (1713) Starting to update urls in track_history based on musicbrainz ids
[21-02-26 05:30:32.4584] Plugins::TrackStat::Storage::refreshTracks (1737) Finished updating urls in track_history based on musicbrainz ids, updated 70 items : It took 1.18328 seconds
[21-02-26 05:30:32.4587] Plugins::TrackStat::Storage::refreshTracks (1743) Starting analyzing track_history table
[21-02-26 05:30:32.4825] Plugins::TrackStat::Storage::refreshTracks (1745) Finished analyzing track_history table : It took 0.023579 seconds
[21-02-26 05:30:32.4828] Plugins::TrackStat::Storage::refreshTracks (1753) Starting to update md5 in track_history data based on urls
[21-02-26 05:30:32.4837] Plugins::TrackStat::Storage::refreshTracks (1771) Finished updating md5 in track_history data based on urls, updated 0 items : It took 0.00087 seconds
[21-02-26 05:30:32.4841] Plugins::TrackStat::Storage::refreshTracks (1786) Starting to update musicbrainz id's in track_history based on urls
[21-02-26 05:30:32.4848] Plugins::TrackStat::Storage::refreshTracks (1810) Finished updating musicbrainz id's in statistic data based on urls, updated 0 items : It took 0.000784 seconds
[21-02-26 05:30:32.4854] Plugins::TrackStat::Storage::refreshTracks (1824) Starting to add missing entries to history table
[21-02-26 05:30:32.5913] Plugins::TrackStat::Storage::refreshTracks (1844) Finished adding missing entries to history table, adding 1 items : It took 0.105577 seconds
[21-02-26 05:30:32.5919] Plugins::TrackStat::Storage::refreshTracks (1850) Starting analyzing track_history table
[21-02-26 05:30:32.5943] Plugins::TrackStat::Storage::refreshTracks (1852) Finished analyzing track_history table : It took 0.001823 seconds
[21-02-26 05:30:32.5946] Plugins::TrackStat::Storage::refreshTracks (1858) Starting to update unrated ratings in history table based on null
[21-02-26 05:30:32.5966] Plugins::TrackStat::Storage::refreshTracks (1878) Finished updating unrated ratings in history table based on null, updated 0 items : It took 0.001552 seconds
[21-02-26 05:30:32.5970] Plugins::TrackStat::Storage::refreshTracks (1891) TrackStat: Synchronizing TrackStat data finished
[21-02-26 05:30:32.5984] Plugins::TrackStat::Plugin::commandCallback65 (4175) Exiting commandCallback65


as you can see, the other queries are in the 0. range.

after this LMS scan, trackstat scan, the custom_scan took place and then again the trackstat_scan.
Thats also something i do not understand until now. trackstat runs twice triggered by normal scan and again through custom_scan

[mherger]

Working on a plugin - Scanning question

> Separate table in persist.db. So it’s the same database file but
> separate table.

Ok.

> Not sure it’s possible to avoid a separate table as long as LMS deletes
> the data in track_persistent it you rename or move a music file. Part 1

AFAIK it doesn't delete anything. My test database has 1300 tracks, but
more than twice that in tracks_persistent.

[mherger]

Add some more statements as outlined above to see whether it's the creation of the temp table or the second query churning for hours.

UPDATE track_statistics
   SET url = (
           SELECT url
             FROM temp_track_statistics
            WHERE musicbrainz_id = track_statistics.musicbrainz_id
       ),
       urlmd5 = (
           SELECT urlmd5
             FROM temp_track_statistics
            WHERE musicbrainz_id = track_statistics.musicbrainz_id
       )
 WHERE EXISTS (
    SELECT url
      FROM temp_track_statistics
     WHERE musicbrainz_id = track_statistics.musicbrainz_id
);

This really is asking for some refactoring. This is basically running the same select on temp_tracks_statistics three times for each track... While it's elegant to have one query do everything, it's often more efficient to implement simpler queries, glued by some code. What I could imagine here is to have one query for the last select ("SELECT temp_track_statistics.url, temp_track_statistics.urlmd5 FROM track_statistics, temp_track_statistics WHERE temp_track_statistics.musicbrainz_id = track_statistics.musicbrainz_id"), then loop over these results in Perl and run the UPDATE query with the url and md5 we gathered in the first query. This way you run only one select.

Adding an index to musicbrainz_id might help, too. To be confirmed, as I've seen cases where creating an index took more time than was gained by using it vs. without it.

Or... you skip this all together if you're not consistently using musicbrainz_id. Make that feature optional.

[mamema]

>Adding an index to musicbrainz_id might help, too. To be confirmed, as I've seen cases where creating an index took more time than was gained by using it vs. without it.

this index exists already

[erland]

> Not sure it’s possible to avoid a separate table as long as LMS deletes
> the data in track_persistent it you rename or move a music file. Part 1

AFAIK it doesn't delete anything. My test database has 1300 tracks, but
more than twice that in tracks_persistent.

Ok if that’s the case ratings could probably be taken from track_persistent and not duplicated.
However, TrackStat still have specific logic around play counts, last played time and added time so the separate table would probably still be needed for these.

Play counts and last played time isn’t updated in TrackStat until a certain amount of the track has been played, so if a user skip to next track right after a track has started to play it would not count it as played.

Added time is also different as it represent the time stamp for the track when it was first added to database, so if a user retag a file and change its file modification time TrackStat won’t change the added time. Makes it possible to have a New Music menu that shows which music you added most recently to the library rather than the music files you retagged most recently.

Would be great if this logic could be added to core LMS but I can understand if you don’t want to do that as it will increase the complexity.

[mamema]

> this index exists already

I don't see where it's created for the temporary table.

sorry, i meant the persistent and library dbs

so, after using your hint with sqlitestudio

creation of temp table 2.5 secs
UPDATE statement ..... crash of sqlitestudio :-)

but now i've try the create index on temp table route

[erland]

[21-02-26 05:30:26.2909] Plugins::TrackStat::Storage::refreshTracks (1482) Finished adding tracks without added times in statistic data based on urls, added 4661 items : It took 3.560551 seconds

I suspect the fact that it adds 4661 items if you haven’t added this amount of new music files is that you have several occurrences of the same musicbrainz Id in your library. If I remember correctly the behavior with several occurrences of the same musicbrainz id was that there are multiple occurrences of the same url in the track_statistics table. I think the result of this also might be that the temp table is nowhere near empty and without indexes in the temp table it could probably cause big performance issues.
Don’t ask me why the track_statistics table doesn’t have a unique index or primary key on the url column, probably I had a bad day when I wrote that code.

To get rid of the duplicated entries I think you will need to disable musicbrainz support, take a backup of TrackStat data, clear TrackStat data and restore the backup. The restore operation ensures only one entry is written back even if there are multiple entries in the database. Since it’s a bit risky with a large library like yours I’d make sure I have a complete backup of LMS database first. Of course, if the issue is caused by a single or a few tracks you can also delete the entries for these urls from track_statistics manually.

after this LMS scan, trackstat scan, the custom_scan took place and then again the trackstat_scan.
Thats also something i do not understand until now. trackstat runs twice triggered by normal scan and again through custom_scan

Can you see in LMS log if something in Custom Scan might trigger a second LMS scan ? TrackStat refresh is only triggered by “rescan done” event if I remember correctly so if it runs twice it feels like duplicate rescan done events are triggered for some reason.
You aren’t using any static playlist generation plugins ? If I remember correctly updating a playlist could trigger an LMS rescan for new/changed playlists. I think I had some issue with this in Playlist Generator or TrackStat Playlist plugins if I remember correctly.

[mamema]

i surely have double ids, as i have CDa with several diffrent releases but same content, eg 24 Bit, SACD, Japan issued, MFSL and so one. It's often the case that not all releases are available in musicbrainz db.


here is the log for the second trackstat run. I didn't see/have playlist stuff

[21-02-26 05:30:47.2248] Plugins::CustomScan::Scanner::refreshData (2007) Starting to update custom scan artist data based on musicbrainz ids
[21-02-26 05:30:58.1247] Plugins::CustomScan::Scanner::refreshData (2030) Finished updating custom scan artist data based on musicbrainz ids, updated 1186 items : It took 10.899812 seconds
[21-02-26 05:30:58.1846] Slim::Web::HTTP::acceptHTTP (290) Did not accept connection, couldn't get peer addr
[21-02-26 05:30:58.1864] Slim::Web::JSONRPC::handleURI (78) Aborting, client not connected: Slim::Web::HTTP::ClientConn=GLOB(0x5650b3af2e50)
[21-02-26 05:30:58.1869] Plugins::CustomScan::Scanner::refreshData (2037) Starting to update custom scan artist data based on names
[21-02-26 05:30:58.1931] Plugins::CustomScan::Scanner::refreshData (2060) Finished updating custom scan artist data based on names, updated 0 items : It took 0.00517 seconds
[21-02-26 05:30:58.1945] Slim::Web::HTTP::acceptHTTP (290) Did not accept connection, couldn't get peer addr
[21-02-26 05:30:58.1966] Plugins::CustomScan::Scanner::refreshData (2067) Starting to update musicbrainz id's in custom scan album data based on titles
[21-02-26 05:30:58.2377] Plugins::CustomScan::Scanner::refreshData (2091) Finished updating musicbrainz id's in custom scan album data based on titles, updated 0 items : It took 0.040984 seconds
[21-02-26 05:30:58.2404] Plugins::CustomScan::Scanner::refreshData (2097) Starting to update custom scan album data based on musicbrainz ids
[21-02-26 05:30:58.2415] Plugins::CustomScan::Scanner::refreshData (2120) Finished updating custom scan album data based on musicbrainz ids, updated 0 items : It took 0.001276 seconds
[21-02-26 05:30:58.2547] Slim::Web::HTTP::acceptHTTP (290) Did not accept connection, couldn't get peer addr
[21-02-26 05:30:58.2738] Plugins::CustomScan::Scanner::refreshData (2126) Starting to update custom scan album data based on titles
[21-02-26 05:30:58.2754] Plugins::CustomScan::Scanner::refreshData (2149) Finished updating custom scan album data based on titles, updated 0 items : It took 0.001385 seconds
[21-02-26 05:30:58.2781] Plugins::CustomScan::Scanner::refreshData (2155) Starting to update musicbrainz id's in custom scan track data based on urls
[21-02-26 05:31:00.9828] Plugins::CustomScan::Scanner::refreshData (2179) Finished updating musicbrainz id's in custom scan track data based on urls, updated 0 items : It took 2.704747 seconds
[21-02-26 05:31:00.9838] Slim::Web::HTTP::acceptHTTP (290) Did not accept connection, couldn't get peer addr
[21-02-26 05:31:01.0983] Plugins::CustomScan::Scanner::refreshData (2185) Starting to update custom scan track data based on musicbrainz ids
[21-02-26 05:31:24.2017] Plugins::CustomScan::Scanner::refreshData (2281) Finished updating custom scan track data based on musicbrainz ids, updated 119392 items : It took 23.103329 seconds
[21-02-26 05:31:24.2115] Slim::Web::HTTP::acceptHTTP (290) Did not accept connection, couldn't get peer addr
[21-02-26 05:31:24.2135] Plugins::CustomScan::Scanner::refreshData (2287) Starting to update custom scan track data based on urls
[21-02-26 05:31:24.7297] Plugins::CustomScan::Scanner::refreshData (2310) Finished updating custom scan track data based on urls, updated 0 items : It took 0.516293 seconds
[21-02-26 05:31:24.7371] Plugins::CustomScan::Scanner::refreshData (2317) Start optimizing SQLite database
[21-02-26 05:31:29.4656] Plugins::CustomScan::Scanner::refreshData (2323) Finished optimizing SQLite database : It took 4.728334 seconds
[21-02-26 05:31:29.4660] Plugins::CustomScan::Scanner::refreshData (2325) CustomScan: Synchronization finished
[21-02-26 05:31:29.7073] Plugins::CustomScan::Scanner::initArtistScan (1129) Got 5132 artists
[21-02-26 05:31:29.7090] Slim::Web::HTTP::acceptHTTP (290) Did not accept connection, couldn't get peer addr
[21-02-26 05:31:29.7178] Slim::Web::HTTP::acceptHTTP (290) Did not accept connection, couldn't get peer addr
[21-02-26 05:31:29.7237] Slim::Web::HTTP::acceptHTTP (290) Did not accept connection, couldn't get peer addr
[21-02-26 05:31:29.7443] Slim::Web::HTTP::acceptHTTP (290) Did not accept connection, couldn't get peer addr
[21-02-26 05:31:29.7536] Plugins::TrackStat::Plugin::commandCallback65 (4135) Entering commandCallback65
[21-02-26 05:31:29.7539] Plugins::TrackStat::Plugin::commandCallback65 (4140) Triggered by rescan done
[21-02-26 05:31:29.7543] Plugins::TrackStat::Storage::refreshTracks (1242) TrackStat: Synchronizing TrackStat data, please wait...
[21-02-26 05:31:29.7546] Plugins::TrackStat::Storage::refreshTracks (1292) Starting to update urls in statistic data based on musicbrainz ids

additionally i don't understand this "delete and backup" As i have started from scratch, scanned my whole library, added trackstat, knowing that duplicate musicbrainz_id are possible because of "by design", what do you expect here?

[erland]

i surely have double ids, as i have CDa with several diffrent releases but same content, eg 24 Bit, SACD, Japan issued, MFSL and so one. It's often the case that not all releases are available in musicbrainz db.


here is the log for the second trackstat run. I didn't see/have playlist stuff

The only thing I can see from the log is that TrackStat seems to be triggered by a rescan done event.
You probably need to enable debug logging related to LMS scanner to see what’s generating the second rescan done event.

additionally i don't understand this "delete and backup" As i have started from scratch, scanned my whole library, added trackstat, knowing that duplicate musicbrainz_id are possible because of "by design", what do you expect here?

If you don’t have any important data you want to keep I’d just disable musicbrainz support and perform a rescan or restart LMS so the TrackStat refresh runs without musicbrainz support.

There is a bug in TrackStat logic so it doesn’t handle multiple occurrences of same musicbrainz id correct, so until this has been corrected by someone I’d disable musicbrainz support in a production setup. The behavior with musicbrainz support enabled is that each time refresh operation runs it will duplicate entries in track_statistics table for the tracks with same musicbrainz id. Since the entries are duplicated each time it quickly adds up to a lot of entries after the refresh has executed a few times. I believe the bug is in the SQL you are investigating as it will change the url of all matching entries to the url of one of them and due to this one of the later parts will add back the entries that no longer exist again.

Would be great if someone finds a solution to this and release a new version of TrackStat where it’s fixed. If the CPU issue is caused by a large temp table solving the duplicate entries problem will likely also solve the CPU issue.

I’m not sure what the expected behavior would be besides that it shouldn’t result in duplicate entries in track_statistics for the same url. The scenario part 1 is all about is to try to recover lost data when someone renames/moves a file. In this case the old url will exist in track_statistics before refresh runs and the expected behavior would be to recover this and connect it to the new url using musicbrainz id which is the same before and after the track has been moved/renamed.

If it isn’t possible to recover the data for entries with multiple occurrences of same musicbrainz id this would probably be acceptable as long as data can be recovered for all other tracks with musicbrainz id tags.