Waiting for Database & missing movies

General Discussions
1

I’m currently running version 1.14.1.5488 on Windows and have been having some trouble with my install over the last few days. Intermittently when I attempt to watch a tv show or movie nothing will play. The movie/show background will load like its going to play but then nothing nothing ever comes on the screen.

I checked the console and saw a few errors like ‘Waited one whole second for a busy database.’ & ‘Took too long (0.937500 seconds) to start a transaction on …\Library\MediaStreamSetting.cpp:2’.

Searching for those errors told me to optimize the database. That resolved things for a day or two but now the issue has cropped back up again and optimizing the database doesn’t seem to do anything anymore.

I’ve also had a number of movies go ‘missing’ as well. For example I have all of the Iron Man movies but nothing shows up when you search for them except the empty collection. I assume the issues are related and would appreciate some help troubleshooting the issues.

Thank you.

2

Is your media storage separate from the Plex server machine? (external or networked drives)

Check for database corruption:

  1. activate debug logging (not ‘verbose’!)
  2. quit Plex Server
  3. wait 1 minute
  4. start Plex Server
  5. wait 5 minutes
  6. fetch log files and attach them here

Or inspect them yourself. Take a look at the Plex Media Server.log file and seek for messages about database corrupt or malformed.
If you find these, you may have to repair your database.
https://support.plex.tv/articles/201100678-repair-a-corrupt-database/

3

Yes, my media storage is on a NAS and is not local to the plex server. Does that matter?

Restarting plex per your instructions seems to have temporarily resolved the issue. I’ve had debug logging on for some time though and looking through past logs shows no ‘corrupt’ or ‘malformed’ messages.

Once the application gets into a failed state again I will upload my most recent log.

**Edit - Shortly after posting this I was able to re-create the failure. My most recent log is attached.Plex Media Server.zip (210.0 KB)

4

Yes, the ‘missing movies’ issue is very likely caused by this.
With external storage you must disable
Settings - Server - Library - “Empty trash automatically after every scan”

You must also make sure that the server machine is running during the maintenance hours. The media storage must be available during this time as well.

I see you are running PMS as a Windows system service.
I am dpoing the same, but you might wanna add -noninteractive as a commandline parameter to the start command.
Then the WARN - Shell_NotifyIcon(NIM_ADD) failed: 0x0 lines will vanish from the log.

You have set up a custom security certificate (why?) for Plex Server but it is not configured correctly.
Error opening file '"D:\Plex\AppData\Plex Media Server\Cache\OCSP\custom.der"' - No such file or directory

What kind of drive is D:?
How much free space does it have?

Are you running PMS in a virtualization container or are you using several routers?
I can see that your server has an IP of 10.10.0.10
But it gets client requests from 192.168.2.10:50176 (WAN) which is also a private IP space but it is classified by PMS as ‘WAN’ (which may trigger unnecessary transcoding).

Are you using (or did you use to use) an external software for gathering statistics from your plex server, like PlexPy, Tautulli, PlexWatch, Plexivity etc. pp. ?

I can see a repeated error near the end of the log which appears to have something to do with statistics
ERROR - Failed to begin transaction (C:\O\Statistics\StatisticsManager.h:201) (tries=3): Cannot begin transaction. database is locked
But I’m not sure whether this is a cause or just a symptom.

Having some of the other log files too (particularly the com.plexapp.system.log) would’ve been better.

5

Unfortunately, I do not believe that my particular issue with missing movies is caused by having external storage. Mainly because my storage is highly available and has a signficantly higher uptime than my plex server. I also would have noticed that type of issue sometime over the several years that my setup has been configured this way. None the less I changed that setting though after a day of having the setting on nothing appears to be different but I’ll keep monitoring.

I also failed to mention that my movies library actually shows itself as having roughly 110% of the number of movies I actually have. If I sort by resolution, or any other file attribute category, the correct number of movies is shown. I mostly forgot to mention this as I thought the DB issue was more urgent but thinking about it more it seems increasingly related.

Another thing I forgot to mention is that I upgraded plex from version 1.13.9.5439 to version 1.14.1.5488 shortly before these issues started happening.

Thanks for the tip. I’ve made that change.

I have a custom cert for my domain applied and Plex has been showing this correctly for years (at least to my browser).

D:\ is an extendable virtual machine drive. It has roughly 55gigs of free space.

I am running plex on a virtual windows server. I also have a large network.

Yes, I am currently running Plexpy/Tautulli. I think that error is a symptom as the error is not occuring during normal operations.

After additional testing I have found that the issue seems to occur most often when more than one user is attempting to watch things at the same time.

I appreciate your help troubleshooting this issue. I have attached my most recent set of logs.
Plex Media (170.6 KB)

6

This is due to Collections, which are shown in the default sorting. Each collection counts as one additional item. https://support.plex.tv/articles/201273953-collections/

Thanks for the logs! I will need to get a second opinion on them.

7

Have been looking at the logs and picked on one example where requests for a couple of media items ended up with extensive database lockout.

Tried to replicate the requests by firing simultaneous requests using curl.exe to see if they lock each other out and that did not happen.

It is more likely to be your setup or may be the volume - how big is the database ? D:\Plex\AppData\Plex Media Server\Plug-in Support\Databases\com.plexapp.plugins.library.db ? How many TV episodes ? movies?

You mentioned that the disc drive from the database is a virtual extendable drive - it would be an idea to run some read / write / seek speed tests on it to see what the performance

You could
These were two requests that i looked into

Jan 07, 2019 18:21:19.667 [3848] DEBUG - Request: [192.168.2.32:56652 (WAN)] GET /library/metadata/39290?includeConcerts=1&includeExtras=1&includeOnDeck=1&includePopularLeaves=1&includePreferences=1&includeChapters=1&includeStations=1&asyncAugmentMetadata=1&asyncCheckFiles=1&asyncRefreshAnalysis=1&asyncRefreshLocalMediaAgent=1 (33 live) TLS GZIP Signed-in Token (fidnadiddat@gmail.com)

Jan 07, 2019 18:21:19.667 [3464] DEBUG - Request: [192.168.2.32:56670 (WAN)] GET /library/metadata/39292?includeConcerts=1&includeExtras=1&includeOnDeck=1&includePopularLeaves=1&includePreferences=1&includeChapters=1&includeStations=1&asyncAugmentMetadata=1&asyncCheckFiles=1&asyncRefreshAnalysis=1&asyncRefreshLocalMediaAgent=1 (33 live) TLS GZIP Signed-in Token (fidnadiddat@gmail.com)

They came in at the same time and each instigated a metadata refresh activity - so we ended up with 4 threads running and it appears that both of the 2 refresh activities threads ended up with database locks - I am not sure if there is a third factor here - something else locking out the database for both of these threads or if it is slow disk writes for one impacting the other

I am going to go into a bit of detail here. So we had threads [3848] and [3464] deal with these 2 requests. Each created another thread for a refresh of metadata

Jan 07, 2019 18:21:19.682 [4708] DEBUG - Activity: updated activity 56f196f5-d5ec-4a89-8458-5cd7325daa09 - completed 0% - Refreshing

Jan 07, 2019 18:21:19.682 [5868] DEBUG - Activity: updated activity 290de964-e29d-42e2-a42a-49cbb9fd0901 - completed 0% - Refreshing

so we now have threads [4708] and [5868] doing refreshes. Both of these ended up being locked out repeatedly

Jan 07, 2019 18:21:23.120 [4708] WARN - Waited one whole second for a busy database.
Jan 07, 2019 18:21:23.120 [5868] WARN - Waited one whole second for a busy database.
Jan 07, 2019 18:21:26.464 [4708] WARN - Waited one whole second for a busy database.
Jan 07, 2019 18:21:26.464 [5868] WARN - Waited one whole second for a busy database.
Jan 07, 2019 18:21:29.808 [5868] WARN - Waited one whole second for a busy database.
Jan 07, 2019 18:21:29.808 [4708] WARN - Waited one whole second for a busy database.
Jan 07, 2019 18:21:33.151 [4708] WARN - Waited one whole second for a busy database.
Jan 07, 2019 18:21:33.151 [5868] WARN - Waited one whole second for a busy database.
Jan 07, 2019 18:21:36.495 [4708] WARN - Waited one whole second for a busy database.
Jan 07, 2019 18:21:36.495 [5868] WARN - Waited one whole second for a busy database.
Jan 07, 2019 18:21:39.839 [5868] WARN - Waited one whole second for a busy database.
Jan 07, 2019 18:21:39.839 [4708] WARN - Waited one whole second for a busy database.
Jan 07, 2019 18:21:43.183 [4708] WARN - Waited one whole second for a busy database.
Jan 07, 2019 18:21:43.183 [5868] WARN - Waited one whole second for a busy database.
Jan 07, 2019 18:21:46.526 [4708] WARN - Waited one whole second for a busy database.
Jan 07, 2019 18:21:46.526 [5868] WARN - Waited one whole second for a busy database.

if your disk speed tests do not show any issue, and if the above scenario is easily reproducible - eg through a batch file that executes the requests using curl.exe

example of batch file to run - this executes the above 2 requests 3 times and attempts to do it in parallel - you will need to put in the server security token instead of the xxxxxxxxxxxxx (see https://support.plex.tv/articles/204059436-finding-an-authentication-token-x-plex-token/)

start curl "http://10.10.0.10:32400/library/metadata/39290?includeConcerts=1&includeExtras=1&includeOnDeck=1&includePopularLeaves=1&includePreferences=1&includeChapters=1&includeStations=1&asyncAugmentMetadata=1&asyncCheckFiles=1&asyncRefreshAnalysis=1&asyncRefreshLocalMediaAgent=1&X-Plex-Token=xxxxxxxxxxxxxxxx" > "%LocalAppData%\39290a.xml"

start curl "http://10.10.0.10:32400/library/metadata/39292?includeConcerts=1&includeExtras=1&includeOnDeck=1&includePopularLeaves=1&includePreferences=1&includeChapters=1&includeStations=1&asyncAugmentMetadata=1&asyncCheckFiles=1&asyncRefreshAnalysis=1&asyncRefreshLocalMediaAgent=1&X-Plex-Token=xxxxxxxxxxxxxxxx" > "%LocalAppData%\39292a.xml"


start curl "http://10.10.0.10:32400/library/metadata/39290?includeConcerts=1&includeExtras=1&includeOnDeck=1&includePopularLeaves=1&includePreferences=1&includeChapters=1&includeStations=1&asyncAugmentMetadata=1&asyncCheckFiles=1&asyncRefreshAnalysis=1&asyncRefreshLocalMediaAgent=1&X-Plex-Token=xxxxxxxxxxxxxxxx" > "%LocalAppData%\39290b.xml"

start curl "http://10.10.0.10:32400/library/metadata/39292?includeConcerts=1&includeExtras=1&includeOnDeck=1&includePopularLeaves=1&includePreferences=1&includeChapters=1&includeStations=1&asyncAugmentMetadata=1&asyncCheckFiles=1&asyncRefreshAnalysis=1&asyncRefreshLocalMediaAgent=1&X-Plex-Token=xxxxxxxxxxxxxxxx" > "%LocalAppData%\39292b.xml"


start curl "http://10.10.0.10:32400/library/metadata/39290?includeConcerts=1&includeExtras=1&includeOnDeck=1&includePopularLeaves=1&includePreferences=1&includeChapters=1&includeStations=1&asyncAugmentMetadata=1&asyncCheckFiles=1&asyncRefreshAnalysis=1&asyncRefreshLocalMediaAgent=1&X-Plex-Token=xxxxxxxxxxxxxxxx" > "%LocalAppData%\39290c.xml"

start curl "http://10.10.0.10:32400/library/metadata/39292?includeConcerts=1&includeExtras=1&includeOnDeck=1&includePopularLeaves=1&includePreferences=1&includeChapters=1&includeStations=1&asyncAugmentMetadata=1&asyncCheckFiles=1&asyncRefreshAnalysis=1&asyncRefreshLocalMediaAgent=1&X-Plex-Token=xxxxxxxxxxxxxxxx" > "%LocalAppData%\39292c.xml"

So if the database lockouts as seen above arise with this script then could do a test with Sysinternals Process Monitor running to see what else may be accessing the database - download from https://docs.microsoft.com/en-us/sysinternals/downloads/procmon)
Capturing all events and saving unfiltered to a PML file. It will be big but it zips very well.

That together with the logs could help the investigation

I see you have multiple subnets with server on 10.10.0.10 and requests coming in from 192.168.xx.xx - you could look into network performance tests as well

For the zipped logs you provided - did you zip the files yourself ? I could only see current ,log files and not previous log files eg .1 and .2 etc - it is always best to zip whole set - that would give more insight into the problem

8

The issue appears to have been a bad drive that the database was sitting on. Unfortunately I’m not 100% sure that is the cause as I had to reinstall plex when I replaced the drive. Everything is working well now.

Thank you.

1 Like
9

This topic was automatically closed 90 days after the last reply. New replies are no longer allowed.