Database Slow Query, Unable to Load Episode, all Star Trek Series

General Discussions
1

I’m not entirely sure if this is related to post PMS-2058 issues or it’s a TVDB issue.

My issue is that it is occurring only TV Shows and only the Star Trek shows this is happening on. So Star Trek, Star Trek The Animated Series, Star Trek TNG, Star Trek DS9, Star Trek Voyager, Star Trek Enterprise, and Star Trek Discovery. Every day it refreshes metadata for these shows. It will replace any changes to the covers or posters that I’ve made. Of course it takes awhile for it to go through all the metadata on the shows. I’ve tried the media dance, clearing bundles, deleting trash, rebuilding the database (import/export), etc.

It’s only the Star Trek shows and I just don’t get why I cannot fix it.

Also seeing slow queries and unable to load episodes in the log:
Dec 11, 2019 05:00:46.891 [0x7f59cf7fe700] WARN - SLOW QUERY: It took 240.000000 ms to retrieve 51 items.
Dec 11, 2019 05:00:46.900 [0x7f591dffb700] WARN - SLOW QUERY: It took 310.000000 ms to retrieve 51 items.
Dec 11, 2019 05:00:46.916 [0x7f592e7fc700] WARN - SLOW QUERY: It took 3560.000000 ms to retrieve 51 items.
Dec 11, 2019 05:00:47.004 [0x7f594dffb700] WARN - SLOW QUERY: It took 340.000000 ms to retrieve 1 items.
Dec 11, 2019 05:00:48.543 [0x7f59cdffb700] WARN - Unable to load episode file [“seasons/1/episodes/15.xml”]
Dec 11, 2019 05:00:48.576 [0x7f59cdffb700] WARN - Unable to load episode file [“seasons/1/episodes/15.xml”]
Dec 11, 2019 05:00:5Dec 11, 2019 05:00:46.891 [0x7f59cf7fe700] WARN - SLOW QUERY: It took 240.000000 ms to retrieve 51 items.
Dec 11, 2019 05:00:46.900 [0x7f591dffb700] WARN - SLOW QUERY: It took 310.000000 ms to retrieve 51 items.
Dec 11, 2019 05:00:46.916 [0x7f592e7fc700] WARN - SLOW QUERY: It took 3560.000000 ms to retrieve 51 items.
Dec 11, 2019 05:00:47.004 [0x7f594dffb700] WARN - SLOW QUERY: It took 340.000000 ms to retrieve 1 items.
Dec 11, 2019 05:00:48.543 [0x7f59cdffb700] WARN - Unable to load episode file [“seasons/1/episodes/15.xml”]
Dec 11, 2019 05:00:48.576 [0x7f59cdffb700] WARN - Unable to load episode file [“seasons/1/episodes/15.xml”]
Dec 11, 2019 05:00:54.661 [0x7f5915ffb700] WARN - Unable to load episode file [“seasons/1/episodes/1.xml”]
Dec 11, 2019 05:00:55.233 [0x7f592cff9700] WARN - Unable to load episode file [“seasons/1/episodes/3.xml”]
Dec 11, 2019 05:00:55.686 [0x7f59cd7fa700] WARN - Unable to load episode file [“seasons/1/episodes/2.xml”]
Dec 11, 2019 05:00:56.162 [0x7f594cff9700] WARN - Unable to load episode file [“seasons/1/episodes/5.xml”]
Dec 11, 2019 05:00:57.156 [0x7f59cd7fa700] WARN - Unable to load episode file [“seasons/1/episodes/4.xml”]4.661 [0x7f5915ffb700] WARN - Unable to load episode file [“seasons/1/episodes/1.xml”]
Dec 11, 2019 05:00:55.233 [0x7f592cff9700] WARN - Unable to load episode file [“seasons/1/episodes/3.xml”]
Dec 11, 2019 05:00:55.686 [0x7f59cd7fa700] WARN - Unable to load episode file [“seasons/1/episodes/2.xml”]
Dec 11, 2019 05:00:56.162 [0x7f594cff9700] WARN - Unable to load episode file [“seasons/1/episodes/5.xml”]
Dec 11, 2019 05:00:57.156 [0x7f59cd7fa700] WARN - Unable to load episode file [“seasons/1/episodes/4.xml”]

2

  1. optimize the database (make sure it’s also set to automatic optimize in Scheduled Tasks)

  2. Per your earlier Star Trek naming.

Star Trek/Season 01:
total 19987588
drwsrwsrwx. 2 chuck chuck       4096 Aug  3 03:42 ./
drwsrwsrwx. 6 chuck chuck       4096 Aug  3 03:42 ../
-rw-r--r--. 1 chuck chuck  813020057 May 27  2018 Star Trek.S01E01.The Man Trap.mkv
-rw-r--r--. 1 chuck chuck  722977754 May 27  2018 Star Trek.S01E02.Charlie X.mkv
-rw-r--r--. 1 chuck chuck  798864906 May 27  2018 Star Trek.S01E03.Where No Man Has Gone Before.mkv
-rw-r--r--. 1 chuck chuck  675096579 May 27  2018 Star Trek.S01E04.The Naked Time.mkv
-rw-r--r--. 1 chuck chuck  639545179 May 27  2018 Star Trek.S01E05.The Enemy Within.mkv
-rw-r--r--. 1 chuck chuck  672329753 May 27  2018 Star Trek.S01E06.Mudd's Women.mkv
-rw-r--r--. 1 chuck chuck  718485422 May 27  2018 Star Trek.S01E07.What Are Little Girls Made Of.mkv
-rw-r--r--. 1 chuck chuck  725713301 May 27  2018 Star Trek.S01E08.Miri.mkv
-rw-r--r--. 1 chuck chuck  682244374 May 27  2018 Star Trek.S01E09.Dagger of the Mind.mkv
-rw-r--r--. 1 chuck chuck  689355562 May 27  2018 Star Trek.S01E10.The Corbomite Maneuver.mkv
-rw-r--r--. 1 chuck chuck  627409936 May 27  2018 Star Trek.S01E11.The Menagerie (1).mkv
-rw-r--r--. 1 chuck chuck  721960616 May 27  2018 Star Trek.S01E12.The Menagerie (2).mkv

Screenshot from 2019-12-11 17-06-23
Screenshot from 2019-12-11 17-06-23762×656 186 KB

3

The database optimization was already set.

Is there a list of the average size of files in the Plex directory. I run ZFS and my recordsize is set to 128K. Perhaps I’ll move the Plex database into it’s own dataset and set the recordsize to something more appropriate.

I don’t see how my file naming could cause this since I use underscores instead of periods and I have an extra underscore between season and episode. Plex has always matched everything in the TV Series just fine. Why would Plex keep trying to rematch and and overwrite my changes to the poster for only the seven Star Trek series and none of the other TV shows. I also don’t want put spaces, commas, or parentheses, or periods in my show names.

My six new 2TB SSDs arrive tomorrow. I’ll move the my zfs root pool over to the SSDs of which the plexmediaserver is part of and see if that makes a difference.

Currently I’m performing the media file dance again:
Moved the seven Star Trek series out of Plex. Empty Trash. Empty bundles. Optimize database. Shutdown Plex. Export and Import Database. Start Plex.

I also seems that Plex is consuming a huge mount of disk bandwidth which is probably where all the “WARN - SLOW QUERY: It took 1470.000000 ms to retrieve 37 items.” errors are coming from.
atop reports show Plex running full tilt on the disk and there really isn’t anything going on.

   PID                TID               RDDSK              WRDSK              WCANCL               DSK             CMD       1/151
 30925                  -                5.7G              3149K                  0K               95%             Plex Media Server
4

I’ve put the six new SSDs in and I’m still seeing slow queries. I’m starting to think something is wrong with my database. I turned on debugging and did the media dance. Chuck, if you have a few minutes, can you look at my logs and my database to see if there is anything going on.

5

Try that ALL over again please.

  1. Turn VERBOSE logging OFF (back to the default)
  2. Restart PMS
  3. Recreate the problem
  4. Download the Logs ZIP
  5. Attach here.

VERBOSE only lets me see 2 minutes of elapsed time – Grossly insufficient.

6

I’ve done the dance again and optimized the database. Here is the database and the logs:

I’ve changed the poster for each Star Trek Series. All the episodes were properly detected by Plex and the correct metadata is there.

At some point in the next 24 hours, Plex will detect each Star Trek series as new and refresh all of them. I’ve changed Plex to detect for changes every hour to hopefully speed up this issue. When it happens again, I’ll add additional logs and another database dump.

Is there an option to force debug through the init script or a variable that I can pass to turn on debug all the time?

7

Well, that did not take long. Changing it to detect for changes every hour caused it to refresh all the Star Trek series. I’ve uploaded the logs and the database again since the last ones. Hopefully somewhere in there the cause can be found why this is only affecting the Star Trek series.

9

@Ryushin

Please turn DEBUG logging back on? Keep VERBOSE off.
I can’t see what it’s doing with DEBUG off.

From the ERROR statements alone, it looks like there is ownership/permissions problems in the metadata directories. (sudo chown -R plex:plex /var/lib/plexmediaserver correction might be needed)

10

I’ve down the chown a few times. Did it again just for giggles.

I changed the library scan to every 30 minutes to get issue to happen again and it did. I did not do the Plex dance though. If I remember correctly, the issue will occur each time (I think) a scan occurs. I’ve put the debug logs and the database in the link above.

I’ve turned off the scan every 30 minutes for now. Hopefully there is enough information in the logs to diagnose this.

11

Testing with 1.18.3.2175, I created a completely new Television library.
I used all the defaults except: a) Collections and b) thumbnails.

There were no missed posters or descriptive text. No “Refresh” was required. Total run time for ~13000 episodes was 25 minutes.

As can be seen, Star Trek is solid.

At this point, File naming? Embedded naming/attributes in MP4/AVI ?

Screenshot from 2019-12-24 17-44-54
Screenshot from 2019-12-24 17-44-54756×541 57.5 KB
Screenshot from 2019-12-24 17-35-41
Screenshot from 2019-12-24 17-35-411257×398 275 KB

12

I’m going to make a new TV_Show library and just put the Star Trek in it and see what happens. My Star Trek series looks solid as well, all the shows have been detected and the metadata is downloaded. Just once a day, or if I configure the settings to scan for changes at a certain amount of time.

I’m still seeing a bunch of slow query errors. The Plex library is on six SSDs and there is a 8 core 16 thread processor handling it and 64GBs of RAM. So I don’t think it’s anything with the system. I’m seeing these slow queries with the system pretty much idle.
WARN - SLOW QUERY: It took 230.000000 ms to retrieve 50 items.
Not sure if there options to modify the sqlite3 database during creation to fix some of these.

13

Putting the Star Trek series into their own Library resulted in no problems. So the issue is with with my current TV Shows Library in the database. The many Slow Query warnings also appears to be some kind of database corruption.

Is there any way to debug the database. I’d rather not have have to create a new Library as it would take me ages to recreate some of the custom episode descriptions and content for some of the series.

Chuck, is there some kind of tool that can analyze the database and check for Plex errors. I’ve down the export/import of the database a few times already.

14

You can stop PMS, export the DB (which makes each table contiguous again, import again into a new database .

  1. Stop PMS
  2. sudo sh (to root)
  3. Drop one index and one table
  4. export to a .sql (ascii source)
  5. import back into a .db
  6. rename
sudo sh
cd "/var/lib/plexmediaserver/Library/Application Support/Plug-in Support/Databases"
sqlite3 com.plexapp.plugins.library.db "DROP index 'index_title_sort_naturalsort' "
sqlite3 com.plexapp.plugins.library.db "DELETE from schema_migrations where version='20180501000000'"
sqlite3 com.plexapp.plugins.library.db .dump > plexdb.sql
mv com.plexapp.plugins.library.db com.plexapp.plugins.library.db.orig
sqlite3 com.plexapp.plugins.library.db < plexdb.sql
chown plex:plex com.plexapp.plugins.library.db

The db will:

  1. Drop the two tables normal sqlite3 cannot understand (naturalsort)
  2. Export to ascii
  3. Import back from ascii (making tables contiguous)
15

I’ve done this a few times and I just did this again. I’m afraid this is not fixing it. Though, somewhere down the line the last few times, Star Trek Voyager seems to be fixed and it seems to be stable now.

I have the SQLite Browser. Are there any recommendations on how to find and delete corruption. Could a corrupted cache directory be causing the issues with the TV Shows? Where do I delete TheTVDB and the MoveDB cache directories?

16

I’m not thinking there is any actually corruption in the database, but malformed data somewhere.

Still seeing these kind of things in the logs:
Jan 02, 2020 06:49:40.145 [0x7fbf66ffd700] ERROR - Unknown metadata type: folder
Jan 02, 2020 06:49:40.615 [0x7fbf66ffd700] ERROR - Unknown metadata type: folder
Jan 02, 2020 06:49:40.711 [0x7fbf4dffb700] WARN - SLOW QUERY: It took 340.000000 ms to retrieve 51 items.
Jan 02, 2020 06:49:46.514 [0x7fbf66ffd700] WARN - SLOW QUERY: It took 260.000000 ms to retrieve 50 items.
Jan 02, 2020 06:49:46.520 [0x7fbf47fff700] ERROR - Unknown metadata type: folder
Jan 02, 2020 06:49:46.554 [0x7fbf55ffb700] WARN - SLOW QUERY: It took 300.000000 ms to retrieve 51 items.
Jan 02, 2020 06:49:46.561 [0x7fbf4dffb700] WARN - SLOW QUERY: It took 380.000000 ms to retrieve 51 items.
Jan 02, 2020 06:49:46.583 [0x7fbf66ffd700] ERROR - Unknown metadata type: folder
Jan 02, 2020 06:49:46.616 [0x7fbf6effd700] WARN - SLOW QUERY: It took 210.000000 ms to retrieve 51 items.

I can say for certain now that my storage is not the issue. ZFS and 32GB of ARC along with six SSDs. I have a 8 core 16 thread xeon v2 in the server and I’m not CPU bound.

17

the path to clear is in

/var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Data/*

18

Frankly, SLOW QUERY is directly related to filesystem performance.

PMS marks the time when the query begins. If, upon return, the ratio of time required to items returned exceeds a few ms, it will raise the warning. The logs show this.

The root cause may be the CPU, may be other tasks monopolizing the DB (unlikely but can happen), sheer size of the DB, or poor performance.

If the DB has been compacted at the SQLITE3 level, and the CPU more than fast enough, only two things remain:

  1. Number of indexed items exceeds design (which is extremely high)
  2. File system housing the DB is slow.
19

Thanks Chuck for you help. I got SQLite3 running better. I started to dig into how SQLite3 works and I’ve optimized it for my hardware. I am running ZFS. I’m posting some of my commands here in the hope that it will help others.

By default it seems that SQLite3 by default creates a page size of 4096:
sqlite> PRAGMA page_size;
4096

Cache size of -2000:
sqlite> PRAGMA default_cache_size;
-2000
Which according to the docs means the cache size is limited to 2048000 bytes of memory.

This is far to small for my database:
My page count is 71991 using a page size of 4096.
sqlite> PRAGMA page_count;
71991

Instead of increasing my cache size to 80000 (PRAGMA default_cache_size = 80000;) I thought it would best to create the SQLite database to have a page size of 16384 and align that with a zfs dataset record size of 16K. So I created a new zfs dataset for /var/lib/plexmediaserver to have the recordsize of 16K.

I exported the database according to this thread


In the dump.sql, I edited it and added “PRAGMA page_size=16384;” after the first statement of “PRAGMA foreign_keys=OFF;”

After importing the database back in, it now looks much better:
sqlite> PRAGMA page_size;
16384
sqlite> PRAGMA page_count;
17931

I increased my default cache size to 20000:
PRAGMA default_cache_size = 20000;

Now I’m no longer seeing slow queries. Still amazed I was seeing slow queries on a six drive SSD pool.

I’m still seeing errors like these though and I’ll dig through the forums to see what I can find:
Jan 11, 2020 06:52:03.848 [0x7f9899ffb700] ERROR - Unknown metadata type: folder
Jan 11, 2020 06:52:07.495 [0x7f9899ffb700] ERROR - Unknown metadata type: folder
Jan 11, 2020 06:52:36.256 [0x7f98d2ffd700] ERROR - Unknown metadata type: folder
Jan 11, 2020 06:52:41.249 [0x7f9899ffb700] ERROR - Unknown metadata type: folder
Jan 11, 2020 06:52:44.738 [0x7f9898ff9700] ERROR - Unknown metadata type: folder
Jan 11, 2020 07:03:58.166 [0x7f982f7fe700] ERROR - Unknown metadata type: folder
Jan 11, 2020 07:04:11.638 [0x7f9898ff9700] ERROR - Unknown metadata type: folder
Jan 11, 2020 07:04:15.087 [0x7f9899ffb700] ERROR - Unknown metadata type: folder
Jan 11, 2020 07:04:47.175 [0x7f982f7fe700] ERROR - Unknown metadata type: folder
Jan 11, 2020 07:04:56.322 [0x7f98d2ffd700] WARN - QueryParser: Invalid field ‘libraryHubsOnly’ found, ignoring.
Jan 11, 2020 07:04:56.357 [0x7f98d2ffd700] WARN - QueryParser: Invalid field ‘libraryHubsOnly’ found, ignoring.
Jan 11, 2020 07:04:56.388 [0x7f98d2ffd700] WARN - QueryParser: Invalid field ‘libraryHubsOnly’ found, ignoring.
Jan 11, 2020 07:04:56.422 [0x7f98d2ffd700] WARN - QueryParser: Invalid field ‘libraryHubsOnly’ found, ignoring.
Jan 11, 2020 07:04:56.457 [0x7f98d2ffd700] WARN - QueryParser: Invalid field ‘libraryHubsOnly’ found, ignoring.
Jan 11, 2020 07:05:12.321 [0x7f982f7fe700] ERROR - Unknown metadata type: folder
Jan 11, 2020 07:05:15.082 [0x7f982f7fe700] ERROR - Unknown metadata type: folder
Jan 11, 2020 07:05:35.472 [0x7f984d7fa700] ERROR - Unknown metadata type: folder
Jan 11, 2020 07:05:46.440 [0x7f982f7fe700] ERROR - Unknown metadata type: folder
Jan 11, 2020 07:05:55.886 [0x7f990db11700] ERROR - Unknown metadata type: folder
Jan 11, 2020 07:06:09.041 [0x7f98d2ffd700] ERROR - Unknown metadata type: folder
Jan 11, 2020 07:06:16.894 [0x7f98b0ff9700] ERROR - Unknown metadata type: folder
Jan 11, 2020 07:22:45.559 [0x7f990e7e0700] WARN - JobManager: Could not find job for handle 20724
Jan 11, 2020 07:23:03.436 [0x7f990e7e0700] WARN - JobManager: Could not find job for handle 25843
Jan 11, 2020 07:23:05.150 [0x7f990e7e0700] WARN - JobManager: Could not find job for handle 26919
Jan 11, 2020 07:23:33.918 [0x7f990e7e0700] WARN - JobManager: Could not find job for handle 29764
Jan 11, 2020 07:32:18.977 [0x7f98fe0e0700] ERROR - EventSource: Retrying in 15 seconds.

20

I was reading this thread:

So my items are:
sqlite> select count() from media_streams;
221689
sqlite> select count() from media_items;
89897

What are the supporting sqlite databases, com.plexapp.dlna.db and com.plexapp.plugins.library.blobs.db?

I know it’s been asked before, but it would be very nice for the devs to have mariadb as an optional database.

21

As the name implies, com.plexapp.plugins.dlna.db is the DLNA server data.

The blobs DB contains chunks of binary (just as the name also implies)

The warnings / errors surrounding libraryHubsOnly and folder can be safely ignored.

You’re seeing work in progress. The upstream is coordinating & sending the new information. Downstream clients & servers are being rolled out slowly to use this new information.

Non-related,
@Ryushin

The new scripting (debut in 1.18.5) is also LXC sensitive now. It will install in Init, Systemd, Docker, and LXC environments.

Following successful establishment in DEB packaging, it will also deploy to RPM packaging.