Scan taking hours instead of minutes on recent nightlies

[testmatch]

Hi,

I'm seeing a consistent change in scanning in the most recent nightlies. LogitechMediaServer-8.0.0-1599321733 (from September 6th) completes scans within minutes as normal, but all the nightlies after that take several hours to scan. The logjam is in the Albums section (2 of 7) of the 'Building full text index' stage of the scan. That used to take 40 seconds or so, but now takes just short of three hours. I can't see anything odd in the logs - it just runs really slowly through that stage, with the rest of the scan happening at the same speed as normal.

If I revert to 8.0.0-1599321733, the scan times go back to normal.

This is on macOS 10.13.6, 2.3 GHz Intel Core i5, 16GB RAM.

Has anyone else seen this?

Would logs help? If so, which ones?

Thanks

[mherger]

> I'm seeing a consistent change in scanning in the most recent nightlies.
> LogitechMediaServer-8.0.0-1599321733 (from September 6th) completes
> scans within minutes as normal, but all the nightlies after that take
> several hours to scan. The logjam is in the Albums section (2 of 7) of
> the 'Building full text index' stage of the scan. That used to take 40
> seconds or so, but now takes just short of three hours. I can't see
> anything odd in the logs - it just runs really slowly through that
> stage, with the rest of the scan happening at the same speed as normal.

But does it finish successfully? Would you have many playlists, or large
playlists?

--

Michael

[testmatch]

>
But does it finish successfully? Would you have many playlists, or large
playlists?

Thanks Michael,

Yes - it finishes successfully. I ran the scan a second time in case it was one of those things that takes ages the first time and then is faster subsequently, but it makes no difference to the scan time. The scan information for that second scan says:

iTunes Import (40885 of 40885) Complete 00:01:42

iTunes Playlist Import (31 of 31) Complete 00:02:24

Building full text index (7 of 7) Complete 02:40:39

Create library views (5 of 5) Complete 00:00:01

Find updated coverart files (1549 of 1549) Complete 00:00:01

Database Optimize (2 of 2) Complete 00:00:05

The server has finished scanning your media library.
Total Time: 02:44:52 (Friday, September 11, 2020 / 6:54 PM)

I'd normally see the full text index taking less than a minute to complete, and the whole scan just over four minutes.

Those 31 playlists vary in size, but the biggest of them is 3,800 items. The next biggest is 1500.

Does that give you any clues as to what's changed?

John

[mherger]

> I'd normally see the full text index taking less than a minute to
> complete, and the whole scan just over four minutes.

I've indeed applied a change to the FTS plugin a few days ago. Could you
please enable logging for plugin.fulltext and re-run a scan?

--

Michael

[testmatch]

I've indeed applied a change to the FTS plugin a few days ago. Could you
please enable logging for plugin.fulltext and re-run a scan?

I've done that, Michael, but don't see much in the scanner log (below) or server log. Should I have enabled anything else in the logging? The only ones at debug level for this were plugin.fulltext and scan.auto (which was like that before).

John

[20-09-12 07:48:15.9962] Slim::Music::Import::runImporter (577) Starting Slim::Media::MediaFolderScan scan
[20-09-12 07:48:15.9965] Slim::Music::Import::endImporter (709) Completed Slim::Media::MediaFolderScan Scan in 0 seconds.
[20-09-12 07:48:15.9969] Slim::Music::Import::runImporter (577) Starting Slim::Plugin::iTunes::Importer scan
[20-09-12 07:52:35.9071] Slim::Music::Import::endImporter (709) Completed Slim::Plugin::iTunes::Importer Scan in 259 seconds.
[20-09-12 07:52:35.9110] Slim::Music::Import::runImporter (577) Starting Slim::Plugin::ExtendedBrowseModes::Libraries scan
[20-09-12 07:52:35.9113] Slim::Music::Import::runImporter (577) Starting Slim::Plugin::FullTextSearch::Plugin scan
[20-09-12 07:52:35.9118] Slim::Plugin::FullTextSearch::Plugin::_rebuildIndex (442) Starting fulltext index build
[20-09-12 07:52:35.9119] Slim::Plugin::FullTextSearch::Plugin::_rebuildIndex (446) Initialize fulltext table
[20-09-12 07:52:36.0251] Slim::Plugin::FullTextSearch::Plugin::_rebuildIndex (459) Create fulltext index for tracks
[20-09-12 07:52:45.0663] Slim::Plugin::FullTextSearch::Plugin::_rebuildIndex (469) Create fulltext index for albums
[20-09-12 07:52:49.0455] Slim::Plugin::FullTextSearch::Plugin::_rebuildIndex (478) Create fulltext index for contributors
[20-09-12 07:52:49.4831] Slim::Plugin::FullTextSearch::Plugin::_rebuildIndex (488) Create fulltext index for playlists
[20-09-12 11:10:59.3181] Slim::Plugin::FullTextSearch::Plugin::_rebuildIndex (503) Optimize fulltext index
[20-09-12 11:10:59.7622] Slim::Plugin::FullTextSearch::Plugin::_rebuildIndex (518) Fulltext index build done!
[20-09-12 11:10:59.7625] Slim::Music::Import::endImporter (709) Completed Slim::Plugin::FullTextSearch::Plugin Scan in 11903 seconds.
[20-09-12 11:10:59.7634] Slim::Music::Import::runImporter (577) Starting Slim::Music::VirtualLibraries scan
[20-09-12 11:11:00.7056] Slim::Music::Import::endImporter (709) Completed Slim::Music::VirtualLibraries Scan in 0 seconds.
[20-09-12 11:11:00.8217] Slim::Music::Artwork::updateStandaloneArtwork (234) Starting updateStandaloneArtwork for 1549 albums
[20-09-12 11:11:01.2910] Slim::Music::Artwork::__ANON__ (349) updateStandaloneArtwork finished in 0.464868068695068
[20-09-12 11:11:01.3116] Slim::Music::Artwork::precacheAllArtwork (659) Starting precacheArtwork for 0 albums
[20-09-12 11:11:01.3125] Slim::Music::Import::endImporter (709) Completed precacheArtwork Scan in 0 seconds.
[20-09-12 11:11:01.3141] Slim::Music::Import::runScanPostProcessing (479) Starting Database optimization.
[20-09-12 11:11:07.1345] Slim::Music::Import::endImporter (709) Completed dbOptimize Scan in 5 seconds.

[mherger]

> I've done that, Michael, but don't see much in the scanner log (below)

I see this:

> [20-09-12 07:52:49.4831]
> Slim::Plugin::FullTextSearch::Plugin::_rebuildInde x (488) Create
> fulltext index for playlists
> [20-09-12 11:10:59.3181]
> Slim::Plugin::FullTextSearch::Plugin::_rebuildInde x (503) Optimize
> fulltext index

Which tells me that most of the time indeed is spent in the playlist
processing, which I fixed a few days ago. Previously it wouldn't include
track information in the playlist index. While I do understand that it's
taking longer now, I need to investigate why it would take _that_ much
longer...

How technical would you be? I don't have playlists that large to test
with. If I posted a change, would you be able to apply the code change
to re-test with your collection (probably won't happen over the weekend)?
--

Michael

[testmatch]

How technical would you be? I don't have playlists that large to test
with. If I posted a change, would you be able to apply the code change
to re-test with your collection (probably won't happen over the weekend)?

Mildly technical from a software perspective - what would I need to do? If you can point me to some general guidance I can see if I'm comfortable with it. I can follow instructions, and do spend time tinkering with Python and assorted Raspberry Pi hardware and software, but might not have the time to try too many new things.
In the meantime, I'll revert to the version before you made the changes because it makes life simpler.

Thanks,

John

[mherger]

Could you please share your library.db with me?

https://www.dropbox.com/request/T3RctyzGgNg0oFDubq6a


--

Michael

[testmatch]

Could you please share your library.db with me?

https://www.dropbox.com/request/T3RctyzGgNg0oFDubq6a

Done.

John

[testmatch]

Mildly technical from a software perspective - what would I need to do?

I've found where the full text search plugin lives and am happy to edit the .pm file if there are changes you'd like me to make. I've done that with several of the third party plugins to update them, so if that's the level of tinkering needed, I'm sure I can handle that.

John