PMS crashes everytime scanning music dir

Plex Media Server NAS & Devices
1

Everything else seems to work fine (films, tv), but whenever I scan my music directory it crashes the host. I’ve enabled debug and verbose logging, and used ‘docker attach’ to attach to the running container to watch it before it crashes, but I see nothing interesting, just the occasional reference to metadata lookups, then it freezes.

It’s headless so once my ssh connection is dead I have to hard reboot the box and any chance of further investigation of the container is gone. The host is very far gone at this point too; no ports responding, not pingable, and not able to recognise a ubs keryboard (as I tried to insert one so I could SysRq).

I’ve ensured only media files are present in the music directory, and made sure there are no lower-case filename extensions present, as I know both these things can cause issues. But still it happens. Where to look next? Is there a definitive list of file types that are acceptable? Maybe I’ve got some file type that i think is acceptable that isn’t. I dunno.

PMS Version: 1.12.0.4829
Docker: 17.09.1-ce
Linux 4.9.76-gentoo-r1

Thanks in advance

2

if a file type wasn’t supported it would just be skipped not cause a crash. I would look at server and scanner logs after a the crash (i would turn off verbose logging unless really necessary) what was last file/album it was scanning? or getting metadata for?

3

Not sure how to tell. there are no errors in the scanner logs, but several in the Plex Media Server logs:

`Mar 18, 2018 21:04:23.204 [0x7f79d77fd700] WARN - Took too long (0.130000 seconds) to start a transaction on …/Library/MetadataItem.cpp:924
Mar 18, 2018 21:04:23.204 [0x7f79d77fd700] WARN - Transaction that was running was started on thread 0x7f79d77fd700 at …/Library/MetadataRelation.cpp:107
Mar 18, 2018 21:04:43.771 [0x7f79d2ff4700] ERROR - Error issuing curl_easy_perform(handle): 28
Mar 18, 2018 21:04:50.073 [0x7f79d1ff2700] ERROR - Error issuing curl_easy_perform(handle): 28
Mar 18, 2018 21:04:57.464 [0x7f79cdfea700] ERROR - Error issuing curl_easy_perform(handle): 28
Mar 18, 2018 21:04:58.645 [0x7f79cc7e7700] WARN - Took too long (0.130000 seconds) to start a transaction on …/Library/MetadataItem.cpp:924
Mar 18, 2018 21:04:58.645 [0x7f79cc7e7700] WARN - Transaction that was running was started on thread 0x7f79cc7e7700 at …/Library/MetadataRelation.cpp:107
Mar 18, 2018 21:05:02.366 [0x7f79cc7e7700] WARN - Took too long (0.110000 seconds) to start a transaction on …/Library/MetadataItem.cpp:6781
Mar 18, 2018 21:05:02.366 [0x7f79cc7e7700] WARN - Transaction that was running was started on thread 0x7f79cc7e7700 at …/Library/MetadataItem.cpp:924

Mar 18, 2018 21:47:19.800 [0x7f087bffc700] ERROR - Error issuing curl_easy_perform(handle): 28
Mar 18, 2018 21:47:19.821 [0x7f087b5e0700] ERROR - Error issuing curl_easy_perform(handle): 7
Mar 18, 2018 21:47:19.823 [0x7f087b5e0700] WARN - HTTP error requesting POST http://127.0.0.1:32600/devices/discover (0, No error) (Failed connect to 127.0.0.1:32600; Connection refused)
Mar 18, 2018 21:47:19.824 [0x7f087b5e0700] ERROR - Error parsing content.
Mar 18, 2018 21:47:21.291 [0x7f087b5e0700] ERROR - Error parsing XML.
Mar 18, 2018 21:47:40.939 [0x7f0876ff9700] WARN - Held transaction for too long (…/Library/MetadataCollection.cpp:232): 0.110000 seconds
Mar 18, 2018 21:47:41.771 [0x7f0878ffd700] ERROR - Network Service: Error in browser handle read: 125 (Operation canceled) socket=-1
Mar 18, 2018 21:47:41.872 [0x7f0878ffd700] INFO - Network Service: Abandoning browse socket, it was closed.
Mar 18, 2018 21:47:45.728 [0x7f08787fc700] WARN - Sync: Couldn’t get sync lists without subscription.
Mar 18, 2018 21:47:45.966 [0x7f0879fff700] INFO - Refreshing paths watched by LibraryUpdateManager
Mar 18, 2018 22:26:25.270 [0x7f08787fc700] WARN - SLOW QUERY: It took 240.000000 ms to retrieve 1 items.
Mar 18, 2018 22:26:25.272 [0x7f0875fff700] WARN - SLOW QUERY: It took 270.000000 ms to retrieve 1 items.
Mar 18, 2018 22:26:25.272 [0x7f08707fc700] WARN - SLOW QUERY: It took 240.000000 ms to retrieve 1 items.

Mar 18, 2018 22:28:38.458 [0x7f08653f1700] WARN - SLOW QUERY: It took 500.000000 ms to retrieve 1 items.
Mar 18, 2018 22:28:38.460 [0x7f08633ed700] WARN - SLOW QUERY: It took 540.000000 ms to retrieve 1 items.
Mar 18, 2018 22:29:04.059 [0x7f085f3e5700] WARN - SLOW QUERY: It took 280.000000 ms to retrieve 1 items.
Mar 18, 2018 22:30:51.486 [0x7f085cbe0700] WARN - Took too long (0.650000 seconds) to start a transaction on …/Statistics/StatisticsManager.h:191
Mar 18, 2018 22:30:51.486 [0x7f085cbe0700] WARN - Transaction that was running was started on thread 0x7f0870ffd700 at …/Statistics/StatisticsManager.h:191

Mar 19, 2018 22:52:18.889 [0x7f677b7f4700] WARN - Transaction that was running was started on thread 0x7f677b7f4700 at …/Library/MetadataItem.cpp:924
Mar 19, 2018 22:52:36.352 [0x7f6779ff1700] WARN - Waited one whole second for a busy database.
Mar 19, 2018 22:52:37.538 [0x7f6779ff1700] ERROR - Failed to begin transaction (…/Library/MediaPart.cpp:894) (tries=1): Cannot begin transaction. database is locked
Mar 19, 2018 22:52:41.789 [0x7f6779ff1700] WARN - Waited one whole second for a busy database.
Mar 19, 2018 22:52:42.656 [0x7f6777fed700] WARN - Waited one whole second for a busy database.
Mar 19, 2018 22:52:42.793 [0x7f6779ff1700] WARN - Took too long (0.360000 seconds) to start a transaction on …/Library/MetadataItem.cpp:924
Mar 19, 2018 22:52:42.794 [0x7f6779ff1700] WARN - Transaction that was running was started on thread 0x7f6779ff1700 at …/Library/MetadataRelation.cpp:107`

Seems like slow queries are an issue but I haven’t seen any evidence of high wait times from here or from any of the other boxes which use this NFS server (storage is mounted NFS) so I don’t know why they are happening. CPU is not powerful but should be enough for this. RAM not an issue.

4

Here’s a shot in the dark. Look for a file name that has a weird character like a comma (,) or a super long name. Maybe it’s getting hung up on the special character.

5

Loading in a lot of music fragments the database VERY quickly as evidenced by

Mar 18, 2018 22:26:25.270 [0x7f08787fc700] WARN - SLOW QUERY: It took 240.000000 ms to retrieve 1 items.
Mar 18, 2018 22:26:25.272 [0x7f0875fff700] WARN - SLOW QUERY: It took 270.000000 ms to retrieve 1 items.
Mar 18, 2018 22:26:25.272 [0x7f08707fc700] WARN - SLOW QUERY: It took 240.000000 ms to retrieve 1 items.

Mar 18, 2018 22:28:38.458 [0x7f08653f1700] WARN - SLOW QUERY: It took 500.000000 ms to retrieve 1 items.
Mar 18, 2018 22:28:38.460 [0x7f08633ed700] WARN - SLOW QUERY: It took 540.000000 ms to retrieve 1 items.
Mar 18, 2018 22:29:04.059 [0x7f085f3e5700] WARN - SLOW QUERY: It took 280.000000 ms to retrieve 1 items.

Cancel the scan.
Optimize the database.
Add the music library in smaller pieces (e.g. each major subdirectory, not the whole parent) , optimizing the database after each individual subdirectory is added)
Upon completing all additions, Optimize the Database one more time.

6

More oddness. I deleted the ‘Music’ library from plex, then emptied the music directory on the server. I then created a new ‘Music’ library in plex, and added the (now empty) music directory location.
I intended to add content a bit at a time to the directory, scanning and optimising as I went, as suggested, but thought I’d run a ‘Scan library files’ on the ‘Music’ library first while it’s still empty, just to see what happened. Surprising then to see errors in the pms log when I run a scan:
Mar 23, 2018 11:34:09.852 [0x7f10a4bff700] WARN - SLOW QUERY: It took 300.000000 ms to retrieve 39 items. Mar 23, 2018 11:34:09.888 [0x7f10a6ffc700] WARN - SLOW QUERY: It took 260.000000 ms to retrieve 38 items. Mar 23, 2018 11:34:10.211 [0x7f10a03fd700] WARN - SLOW QUERY: It took 260.000000 ms to retrieve 46 items. Mar 23, 2018 11:34:15.184 [0x7f10a03fd700] WARN - SLOW QUERY: It took 300.000000 ms to retrieve 39 items. Mar 23, 2018 11:34:15.220 [0x7f10a6ffc700] WARN - SLOW QUERY: It took 280.000000 ms to retrieve 38 items. Mar 23, 2018 11:34:15.460 [0x7f10a4bff700] WARN - SLOW QUERY: It took 250.000000 ms to retrieve 46 items.
What items is it retrieving? there’s no content in that directory at all. And why the slow queries? I’ve tried this several times and it happens every time. Again there is no resource issue on the host at all.

7

Do me a favor please?

Go into the shell environment, dig down into the Plug-in Support/Databases directory and look at the number and size of the files.

Next, and with PMS stopped, open sqlite3 as root

sqlite3  com.plexapp.plugins.library.db
select count(*) from metadata_item_views;
select count(*) from metadata_items;
select count(*) from media_items;

also please obtain a numeric count of how many files (movies, episodes, songs, and photos) are actually indexed in PMS

find /media-dir-1 /media-dir-2 -type f -print | wc -l (where ‘media-dir-1’ and ‘-2’ are the actual pathnames at the Linux shell level)

This will print out all ‘files’ and then count the number of names printed.

8

Sure:

$ du -hs *
69K	com.plexapp.dlna.db
33K	com.plexapp.dlna.db-shm
393K	com.plexapp.dlna.db-wal
393K	com.plexapp.plugins.library.blobs.db
33K	com.plexapp.plugins.library.blobs.db-shm
512	com.plexapp.plugins.library.blobs.db-wal
11M	com.plexapp.plugins.library.db
137K	com.plexapp.plugins.library.db-shm
26M	com.plexapp.plugins.library.db-wal

sqlite> select count(*) from metadata_item_views;
8
sqlite> select count(*) from metadata_items;
1248
sqlite> select count(*) from media_items;
1145

$ find _Music/ Videos/ -type f | wc -l
15033
9

When’s the last time you manually optimized the DB?
Is database optimization enabled in your Scheduled Tasks and is the container running during that time?

I’m tracking cases where the DB is 500 - 1.4GB. I don’t think yours is quite at that level yet :slight_smile:

10

I optimised it just before deleting the Music library. The container is always running, except for when these crashes happen of course.

I do have it set to optimise every week, along with these other options selected:
Optimize database every week
Remove old bundles every week
Remove old cache files every week
Refresh local metadata every three days

 Upgrade media analysis during maintenance
 Refresh metadata periodically
 Perform extensive media analysis during maintenance
 Perform refresh of program guide data.
11

I just ran a manual optimise again and straight away these errors:

    Mar 23, 2018 13:27:33.769 [0x7f4732ffe700] WARN - Held transaction for too long (../Library/DatabaseFixups.cpp:191): 0.210000 seconds
    Mar 23, 2018 13:27:34.140 [0x7f4732ffe700] WARN - Held transaction for too long (../Library/FullTextSearch.cpp:17): 0.270000 seconds
    Mar 23, 2018 13:27:34.726 [0x7f4732ffe700] WARN - Held transaction for too long (../Library/FullTextSearch.cpp:27): 0.350000 seconds
    Mar 23, 2018 13:27:38.436 [0x7f4732ffe700] WARN - Held transaction for too long (../Library/FullTextSearch.cpp:38): 3.190000 seconds
    Mar 23, 2018 13:27:40.840 [0x7f4732ffe700] WARN - Held transaction for too long (../Library/FullTextSearch.cpp:48): 2.060000 seconds
    Mar 23, 2018 13:27:44.805 [0x7f4732ffe700] INFO - SQLITE3:0x10, 17, statement aborts at 57: [select * from metadata_items limit 1] database schema has changed
    Mar 23, 2018 13:27:44.830 [0x7f4732ffe700] INFO - SQLITE3:0x10, 17, statement aborts at 57: [select * from metadata_items limit 1] database schema has changed
    Mar 23, 2018 13:27:44.856 [0x7f4732ffe700] INFO - SQLITE3:0x10, 17, statement aborts at 57: [select * from metadata_items limit 1] database schema has changed
    Mar 23, 2018 13:27:44.880 [0x7f4732ffe700] INFO - SQLITE3:0x10, 17, statement aborts at 57: [select * from metadata_items limit 1] database schema has changed
    Mar 23, 2018 13:27:44.904 [0x7f4732ffe700] INFO - SQLITE3:0x10, 17, statement aborts at 57: [select * from metadata_items limit 1] database schema has changed
12
  1. I need your logs (settings - server - help - download logs). The full ZIP file
  2. Schema change immediately after an optimize is normal. It’s recreating index entries because optimization invalidated the old index entires.
13

Here you go…

14

Thanks.

I found your problem. You have an Atom 230 CPU. It has a Passmark rating of 307.
https://www.cpubenchmark.net/cpu.php?cpu=Intel+Atom+230+%40+1.60GHz&id=603

Simply put, it’s too darn slow. The minimum needed is 700 Passmarks.

Well past time to update the box. It owes you nothing.
If you’re running PMS in Docker on a NAS, use the NAS as it’s intended. Export the Docker and run it elsewhere

15

Also, the DB shows as locked… Time for a FULL restart of the machine and the DB but, if already done, it’s getting hung up in the locks because you’re running on Gentoo. (Linux container on an otherwise untested Linux)

16

Hmm. Sounds a bit like wintel support :wink: . I don’t see any evidence of it being cpu bound or resource starved in any way so I’m still to be convinced. Is this minimum cpu requirement documented anywhere do you know? I have seen other threads on here where people use this exact chip successfully with pms (they are a few years old though to be fair).

I’d also be interested why you think the fact that docker is running on Gentoo is causing locking issues. I built the kernel based on a list of kernel requirements I got from docker, and other containers work a treat. The container is ubuntu and doesn’t share any libraries with the host does it?.

It’s regularly restarted btw due to the crashes, but these aren’t graceful restarts unfortunately so something could easily be corrupted.

17

I can only tell you what I’ve seen and resolved for others. I also just went through qualifying CPUs for the NAS Compatibility Guide. The ‘700 Passmark’ minimum is published in the support pages. Per your request, please consider https://support.plex.tv/articles/201774043-what-kind-of-cpu-do-i-need-for-my-server/

The decision to accept my advice is indeed yours. I am not here to ‘convince’ you. Frankly, I don’t have the time. If you’re confident what you have works, that’s fine. I am only speaking from 35 years of experience with Unix/Linux and almost 5 years of experience now with Plex.

18

I realise you don’t have to convince me of anything, it’s just a turn of phrase – I’m trying to understand what the root issue is here. And I could just use a more powerful box of course but I like to make use of what I have where possible, partly because it’s a learning experience.

I do see however that on that page you linked to the minimum recommended grunt for even basic use is a 1.6GHz Core2Duo, which is rated 945 on passmark, so I’m well below even that. I’ll see if I can work some faster IO somehow and see if that helps the locking then probably just abandon it.

thanks

19

It worked. I attached an old 5400rpm disk locally, copied everything from /config across to it, then restarted the container and ran a full scan. Everything scanned in no problem. The CPU was pushed hard though so I wouldn’t have liked to do anything else on that box while the scan was running, and there were lots of ‘Held transaction for too long’ warnings in the log.

It ticks along nicely now though – no transcoding possible of course, but I never expected that. Don’t write off those old atom CPUs so fast! :smiley:
ta

20

My PC had no problem browsing all my music without crashing. Why does the Plex app on my iPhone crash when I browse large lists of music now?

I have an AMD Phenom 1090T 3.2GHz and 16 GB of RAM.