FTS crashes with Out Of Memory error (using 1,6 GB of RAM)

[frank1969]

> Slightly off topic but I notice recent LMS updates have lots of logging
> enabled by default for playlists. Is that intentional?

This should not have changed at all. Are you looking at a new
installation? Or did you forget to reset some logging you enabled at
some point?

[frank1969]

FTS crashes with Out Of Memory error (using 1,6 GB of RAM)

Since doing an initial scan, I'm experiencing a few more problems with full text search.

To explain:
I'm using full text search since Michael invented the "new" FTS and it worked fine - maybe 1 out of 10 "new&changed scans" failed while building the FTS index, but then I started another one and everything was fine again.

After an initial scan on weekend it fails EVERY TIME (see below).
What makes me wonder:
The 4 fulltext indexes are built correctly - and while starting "optimizing" it fails within a second with an out of memory error.
At the time the crash happens, LMS is using "only" 1,6 GB of Memory (= 38 %) (I have 16 GB installed, though I guess LMS is 32 Bit (windows) it should have no problems to use up to 4 GB).

By the way:
It is the same data that worked fine before the initial scan (and if I switch back to an old copy before the initial scan. If I switch back to a copy of my db before the initial scan (with the same amount of data) FTS works fine again.

And of course, I know, I can turn off FTS and LMS works fine again - but I don't see the reason for this behaviour...
Any idea what "really" causes the error or what I could do?



[22-04-27 12:40:23.9131] main::init (377) Starting Logitech Media Server (v8.3.0, 1651050550, Wed Apr 27 11:17:09 WEDT 2022) perl 5.014001 - MSWin32-x86-multi-thread
[22-04-27 12:40:25.1630] Slim::Utils::Misc::msg (1325) Warning: [12:40:25.1629] DBIx::Class::ResultSet::update_or_create(): Query returned more than one row. SQL that returns multiple rows is DEPRECATED for ->find and ->single at /<C:\PROGRA~2\SQUEEZ~1\server\SQUEEZ~3.EXE>Slim/Schema.pm line 1927
[22-04-27 12:40:25.5422] Plugins::UPnPBridge::Plugin::initPlugin (76) $VAR1 = {
'binArch' => 'MSWin32-x86-multi-thread',
'fsType' => 'NTFS',
'uid' => 'moviemaster',
'osName' => 'Windows 11',
'osArch' => 8664,
'isWin6+' => 1,
'os' => 'Windows'
};
[22-04-27 12:40:25.8858] Slim::Plugin::FullTextSearch::Plugin::_initPopular Terms (580) Fulltext index missing or outdated - re-building
[22-04-27 12:40:25.8859] Slim::Plugin::FullTextSearch::Plugin::_rebuildInde x (475) Starting fulltext index build
[22-04-27 12:40:25.8860] Slim::Plugin::FullTextSearch::Plugin::_rebuildInde x (479) Initialize fulltext table
[22-04-27 12:40:26.8445] Slim::Plugin::FullTextSearch::Plugin::_rebuildInde x (492) Create fulltext index for tracks
[22-04-27 12:46:04.5846] Slim::Plugin::FullTextSearch::Plugin::_rebuildInde x (502) Create fulltext index for albums
[22-04-27 12:47:29.5829] Slim::Plugin::FullTextSearch::Plugin::_rebuildInde x (511) Create fulltext index for contributors
[22-04-27 12:47:33.0643] Slim::Plugin::FullTextSearch::Plugin::_rebuildInde x (521) Create fulltext index for playlists
[22-04-27 12:47:56.7747] Slim::Plugin::FullTextSearch::Plugin::_rebuildInde x (536) Optimize fulltext index
[22-04-27 12:47:58.3318] Slim::Schema::Storage::throw_exception (121) Error: DBI Exception: DBD::SQLite::db do failed: out of memory [for Statement "INSERT IGNORE INTO fulltext(fulltext) VALUES('optimize');"]
[22-04-27 12:47:58.3320] Slim::Schema::Storage::throw_exception (121) Backtrace:

frame 0: Slim::Utils::Log::logBacktrace (/<C:\PROGRA~2\SQUEEZ~1\server\SQUEEZ~3.EXE>Slim/Schema/Storage.pm line 121)
frame 1: Slim::Schema::Storage::throw_exception (/<C:\PROGRA~2\SQUEEZ~1\server\SQUEEZ~3.EXE>DBIx/Class/Storage/DBI.pm line 1006)
frame 2: DBIx::Class::Storage:BI::__ANON__ (C:/PROGRA~2/SQUEEZ~1/server/Slim/Plugin/FullTextSearch/Plugin.pm line 540)
frame 3: Slim::Plugin::FullTextSearch::Plugin::_rebuildInde x (C:/PROGRA~2/SQUEEZ~1/server/Slim/Plugin/FullTextSearch/Plugin.pm line 583)
frame 4: Slim::Plugin::FullTextSearch::Plugin::_initPopular Terms (C:/PROGRA~2/SQUEEZ~1/server/Slim/Plugin/FullTextSearch/Plugin.pm line 173)
frame 5: Slim::Plugin::FullTextSearch::Plugin::initPlugin (/<C:\PROGRA~2\SQUEEZ~1\server\SQUEEZ~3.EXE>Slim/Utils/PluginManager.pm line 387)
frame 6: (eval) (/<C:\PROGRA~2\SQUEEZ~1\server\SQUEEZ~3.EXE>Slim/Utils/PluginManager.pm line 387)
frame 7: Slim::Utils::PluginManager::load (slimserver.pl line 591)
frame 8: main::init (slimserver.pl line 669)
frame 9: main::main (slimserver.pl line 129)
frame 10: PerlSvc::Interactive (/<C:\PROGRA~2\SQUEEZ~1\server\SQUEEZ~3.EXE>PerlSvc. pm line 99)
frame 11: PerlSvc::_interactive (slimserver.pl line 0)
frame 12: (eval) (slimserver.pl line 0)

[22-04-27 12:47:58.3322] Slim::Utils::PluginManager::load (389) Warning: Couldn't call Slim::Plugin::FullTextSearch::Plugin->initPlugin: Carp::Clan::__ANON__(): DBI Exception: DBD::SQLite::db do failed: out of memory [for Statement "INSERT IGNORE INTO fulltext(fulltext) VALUES('optimize');"] at /<C:\PROGRA~2\SQUEEZ~1\server\SQUEEZ~3.EXE>Slim/Schema/Storage.pm line 125
[22-04-27 12:48:04.7719] Slim::Utils::PluginManager::shutdownPlugins (414) Warning: error running Slim::Plugin::UPnP::Plugin->shutdownPlugin: Can't locate object method "shutdown" via package "Slim::Plugin::UPnP::MediaRenderer" at C:/PROGRA~2/SQUEEZ~1/server/Slim/Plugin/UPnP/Plugin.pm line 58.

[mherger]

FTS crashes with Out Of Memory error (using1, 6 GB of RAM)

> As the time the crash happens, LMS is using "only" 1,6 GB of Memory (=
> 38 %) (I have 16 GB installed, though I guess LMS is 32 Bit (windows) it
> should have no problems to use up to 4 GB).

The indexing is done in the scanner process (scanner.exe). Please
monitor its memory consumption when you reach this stage of the scan.

Can you remind me of the DB memory usage setting you're using in
Settings/Advanced/Performance? I thought I had implemented something
that would not use RAM for temporary tables to prevent this issue.

> (/<C:\PROGRA~2\SQUEEZ~1\server\SQUEEZ~3.EXE>Slim/Schema/Storage.pm line

Hmm... that's the server indeed? Not the scanner? Why would LMS run the
indexing?!? I'm a little confused. Did the previous scan end correctly?
Anything in scanner.log?

[frank1969]

Hmm... that's the server indeed? Not the scanner? Why would LMS run the
indexing?!? I'm a little confused. Did the previous scan end correctly?
Anything in scanner.log?

OK, I guess the reason why it is server is this way:
- I did the initial scan (without FTS) - this ran ok (scanner).
- The day later I did a new&changed (still without FTS) - this ran ok, too (scanner).
- After that I turned FTS on
- I restarted LMS and LMS tries to built the FTS within the starting progress.
- So it is server that fails...

Can you remind me of the DB memory usage setting you're using in
Settings/Advanced/Performance? I thought I had implemented something
that would not use RAM for temporary tables to prevent this issue.

The setting is on maximum ("for db with more than 50.000 tracks and 2 GB RAM and more").
(by the way, "shuffle method" is on "use more balanced" - this one of just a few options, I don't know what they're about...)

[mherger]

FTS crashes with Out Of Memory error (using1, 6 GB of RAM)

> OK, I guess the reason why it is server is this way:
> - I did the initial scan (without FTS) - this ran ok (scanner).
> - The day later I did a new&changed (still without FTS) - this ran ok,
> too (scanner).
> - After that I turned FTS on

Ok, that makes sense.

> (by the way, "shuffle method" is on "use more balanced" - this one of
> just a few options, I don't know what they're about...)

Basically this:
https://engineering.atspotify.com/20...shuffle-songs/. People
expect shuffled playlists not to be randomly distributed, but evenly.
Whatever.

[frank1969]

A few tests - and another initial scan - later I am still at a loss.

If I switch back to my old database (even 2,27 GB), grown over weeks or months, FTS runs fine.
If I switch to my new database (just 1,57 GB) - just after initial scan - FTS runs out of memory.

So scanning an "old" database (that is nearly 50 "larger", though it contains the same tracks, btw) is handled "better" than a "new" and smaller database...
Makes no sense to me.

I also checked if it depends on the LMS version I use for building the FTS - it doesn't.
I experience the same errors with older versions from march 2022.

So I can also GUESS it depends on the version I do the initial scan with and the "newer" versions produce a database that uses more memory while building the FTS?

Is there any workaround? I don't see that spending 1,7 GB RAM is "too much" on a 16 GB RAM system with 10 GB free at this point...?

Thanks
Frank

[mherger]

FTS crashes with Out Of Memory error (using1, 6 GB of RAM)

> If I switch back to my old database (even 2,27 GB), grown over weeks or
> months, FTS runs fine.

How old is this? As you're saying LMS version from March would show the
same behaviour?

> Is there any workaround? I don't see that spending 1,7 GB RAM is "too
> much" on a 16 GB RAM system with 10 GB free at this point...?

What about disk space on your C: drive? What is the 1.7 GB RAM number
based on?

[frank1969]

>How old is this? As you're saying LMS version from March would show the
same behaviour?

The database had an initial scan from february and was updated (new&changed) nearly daily.
I tested with r1647754697 (march 20th, I guess)

What about disk space on your C: drive? What is the 1.7 GB RAM number
based on?

Free disk space on C:\ is around 300 GB.
The 1,7 GB RAM is taken from windows task manager used by process from SqueezeSvr - it "usually" uses abou 0,9 - 1 GB RAM and it grows up to 1,7 during starting process while building FTS index.

If I understand right, FTS index is completely re-built with every new&changed, right?
Is there any difference between building the FTS index at the end of a new&changed-scan and the end of a initial scan?

[mherger]

FTS crashes with Out Of Memory error (using1, 6 GB of RAM)

> If I understand right, FTS index is completely re-built with every
> new&changed, right?

Yes, there's no incremental update or something.

> Is there any difference between building the FTS index at the end of a
> new&changed-scan and the end of a initial scan?

No.

Is LMS crashing due to that indexing? Can you check
prefs/plugin/fulltext.prefs to see whether there are any values after

popularTerms:
- in
- interpret
- mp3
- music
- of

or similar? LMS should _not_ trigger the scan on startup if that list
existed (the scanner would). So if you can make sure that list exists
_before_ starting LMS you should be able to start up LMS, then launch a
scan. Would that scan succeed?

[frank1969]

Is LMS crashing due to that indexing? Can you check
prefs/plugin/fulltext.prefs to see whether there are any values after

popularTerms:
- in
- interpret
- mp3
- music
- of

or similar? LMS should _not_ trigger the scan on startup if that list
existed (the scanner would). So if you can make sure that list exists
_before_ starting LMS you should be able to start up LMS, then launch a
scan. Would that scan succeed?

OK, thanks for Your hints, I could fix it with this - I'll describe what I did and what happened, maybe it gives You a hint, why LMS crashes on initial scan.

1. I Checked the content of my fulltext.prefs. It was:
---
_version: 1

(Remark: After FTS crashed, I deactivated it again, so maybe therefore it was "empty").

2. I modified the fulltext.prefs (using some terms of my old installation like):
---
_ts_popularTerms: 1650471674
_version: 1
popularTerms:
- '16'
- '2021'
- '2022'
- '256000'
- 256kbps
- '320000'
- 320kbps
- '44'
- '44100'
- album
- albumartist
- artist
- artists
- compilations
- composer

3. Started LMS - this time it started without crashing

4. Started a "new&scan" - "new&scan" run fine (and created a 71 kb sized fulltext.prefs again)

What I find interesting is, what I watched concerning RAM usage:

- Usually server uses 0,9 - 1 GB of RAM.

- When LMS tried to build the FTS on server start, usage from server grew up to 1,7 GB RAM - and then crashed

- When I did the "new&changed", scanner more or less constantly used 0,3 GB RAM

- server used from 0,9 up to 1,2 GB RAM during the new&changed scan.

So
- on scenario 1 (building FTS on startup), server uses more and more RAM till it crashes with an out of memory error.
- on scenario 2 (building FTS while n&c scanning), server uses just a little more RAM and scanner's RAM use stays constantly...

btw:
This time the FTS is in scanner.log - and the step, that let it crash while startup before (Slim::Plugin::FullTextSearch::Plugin::_rebuildInd ex (536) Optimize fulltext index) is only taking 5 sec ...)

[22-04-30 15:27:25.4391] Slim::Music::Import::runImporter (579) Starting Slim::Plugin::FullTextSearch::Plugin scan
[22-04-30 15:27:25.4397] Slim::Plugin::FullTextSearch::Plugin::_rebuildInde x (475) Starting fulltext index build
[22-04-30 15:27:25.4400] Slim::Plugin::FullTextSearch::Plugin::_rebuildInde x (479) Initialize fulltext table
[22-04-30 15:27:25.4415] Slim::Plugin::FullTextSearch::Plugin::_rebuildInde x (492) Create fulltext index for tracks
[22-04-30 15:33:11.7830] Slim::Plugin::FullTextSearch::Plugin::_rebuildInde x (502) Create fulltext index for albums
[22-04-30 15:37:13.4179] Slim::Plugin::FullTextSearch::Plugin::_rebuildInde x (511) Create fulltext index for contributors
[22-04-30 15:37:20.0594] Slim::Plugin::FullTextSearch::Plugin::_rebuildInde x (521) Create fulltext index for playlists
[22-04-30 15:38:08.3578] Slim::Plugin::FullTextSearch::Plugin::_rebuildInde x (536) Optimize fulltext index
[22-04-30 15:38:13.9458] Slim::Plugin::FullTextSearch::Plugin::_rebuildInde x (551) Fulltext index build done!
[22-04-30 15:38:13.9462] Slim::Music::Import::endImporter (711) Completed Slim::Plugin::FullTextSearch::Plugin Scan in 648.507 seconds.

[frank1969]

Another observation.
library.db after initial scan had been 1,57 GB (as I told before)
now - one "new&changed" with FTS later - it is 2,27 GB again...

And:
Another old "bastard" is back

=> I had a file with "Jeanette" and "Jeanette Biedermann" as (track) artist.
=> I deleted "Jeanette" as artist
=> did a new&changed
=> browsing artists it STILL appears calling artist "Jeanette" AND "Jeanette Biedermann" - but when I call it from "Jeanette" it is ... "empty" (just the cover and artist name appearing).
I will examine this further the next days.
(unfortunately I obviously have set back the logging/debugging options so I have nothing about this change/handling in scanner.log... - will change logging-setting back)

[mherger]

FTS crashes with Out Of Memory error (using1, 6 GB of RAM)

> So
> - on scenario 1 (building FTS on startup), server uses more and more RAM
> till it crashes with an out of memory error.
> - on scenario 2 (building FTS while n&c scanning), server uses just a
> little more RAM and scanner's RAM use stays constantly...

Now that's interesting. The database indeed is configured differently in
the server (mostly read-only) vs. the scanner (lots of writing going
on). Cache and buffer sizes are different in these two environments.

You could probably test this by setting the db memory to high instead of
max, wipe the "popularTerms" and restart LMS to launch a re-build in the
server. If my theory was right, that would run successfully, whereas
"max" would make LMS crash.

Your setup exposes quite some weaknesses and poor assumptions in LMS :-).

> This time the FTS is in scanner.log - and the step, that let it crash
> while startup before
> (Slim::Plugin::FullTextSearch::Plugin::_rebuildInd ex (536) Optimize
> fulltext index) is only taking 5 sec ...)

Here I don't have any idea why that would be.

[mherger]

FTS crashes with Out Of Memory error (using1, 6 GB of RAM)

> You could probably test this by setting the db memory to high instead of
> max, wipe the "popularTerms" and restart LMS to launch a re-build in the
> server. If my theory was right, that would run successfully, whereas
> "max" would make LMS crash.

I've applied a change which _should_ address this case (if this
configuration difference indeed was the reason for the crash). So no
need to change the db memory setting if you tested with the latest LMS
8.3 build.

[frank1969]

> I've applied a change which _should_ address this case (if this
configuration difference indeed was the reason for the crash). So no
need to change the db memory setting if you tested with the latest LMS
8.3 build.

Yes, I tested with latest nightly ( r1651071091 ).

Did some test scans to loacate the other bug (not-deleting deleted artists on a track), will try to analyze later.

[frank1969]

I reported the "not-deleted artist-thing" in an issue

https://github.com/Logitech/slimserver/issues/787