Constant server deadlocks/crashes recenty

baconator_admin · March 22, 2022, 2:21am

Plex Media Server 1.25.7.5604
Various Plex clients (Android, iOS, smart TVs, consoles, Roku, browsers…etc)
plexinc/pms-docker:latest (2b8a4565f9de)
Docker CE 20.10.12-3.el8
Red Hat Enterprise Linux 8.5
Dual CPU Xeon E5-2690 v4 (28 cores)
128 GB RAM (transcoding ramdisk)
Optane DC P4800X NVMe (database/metadata storage)

Starting within the past month or so, my server has been crashing or deadlocking several times a day. Sometimes it just slows down to a crawl and the web interface spins, eventually recovering on its own, and other times it goes completely offline and the container changes to unhealthy state and requires manual restart. It occurred on 1.25.6 and now on 1.25.7 too.

My assumption is a bad client player or bad file being accessed by a friend/family member is triggering the crash and after a while they give up and go do something else. The deadlocks seem to come in bursts and then will go away for a long period of time. I don’t know. I’ve never had this problem until recently.

Logs attached. These logs were collected after a period between 2:20 PM EDT and 3:15 PM EDT where the server deadlocked several times over and over.

Thanks for any help you can offer.

Plex Media Server Logs_2022-03-19_15-37-03.zip (12.4 MB)

ChuckPa · March 22, 2022, 3:11am

It’s pretty difficult to see anything.

You turned DEBUG logging OFF (apparently to save space but then set log retention to 25? ) What was the goal please?

This is disturbing.

Mar 19, 2022 14:16:22.386 [0x7f4a505e6b38] WARN - QueryParser: Invalid field 'pinnedContentDirectoryID' found, ignoring.
Mar 19, 2022 14:16:22.414 [0x7f4a54cb2b38] WARN - SLOW QUERY: It took 250.000000 ms to retrieve 1 items.
Mar 19, 2022 14:16:22.422 [0x7f4a4e8f6b38] WARN - SLOW QUERY: It took 280.000000 ms to retrieve 1 items.
Mar 19, 2022 14:16:22.425 [0x7f4a503f6b38] WARN - SLOW QUERY: It took 260.000000 ms to retrieve 1 items.
Mar 19, 2022 14:16:22.430 [0x7f4a51a41b38] WARN - SLOW QUERY: It took 270.000000 ms to retrieve 1 items.
Mar 19, 2022 14:16:22.444 [0x7f4a51aa7b38] WARN - SLOW QUERY: It took 250.000000 ms to retrieve 1 items.
Mar 19, 2022 14:16:22.465 [0x7f4a51d46b38] WARN - SLOW QUERY: It took 250.000000 ms to retrieve 1 items.
Mar 19, 2022 14:16:22.465 [0x7f4a4e8f6b38] WARN - SLOW QUERY: It took 260.000000 ms to retrieve 1 items.
Mar 19, 2022 14:16:22.473 [0x7f4a51a41b38] WARN - SLOW QUERY: It took 290.000000 ms to retrieve 1 items.
Mar 19, 2022 14:16:22.490 [0x7f4a51aa7b38] WARN - SLOW QUERY: It took 260.000000 ms to retrieve 1 items.
Mar 19, 2022 14:16:22.492 [0x7f4a51159b38] WARN - SLOW QUERY: It took 270.000000 ms to retrieve 1 items.
Mar 19, 2022 14:16:22.501 [0x7f4a50f52b38] WARN - SLOW QUERY: It took 240.000000 ms to retrieve 1 items.
Mar 19, 2022 14:16:22.538 [0x7f4a51159b38] WARN - SLOW QUERY: It took 320.000000 ms to retrieve 1 items.
Mar 19, 2022 14:16:22.545 [0x7f4a510b6b38] WARN - SLOW QUERY: It took 280.000000 ms to retrieve 1 items.
Mar 19, 2022 14:16:22.549 [0x7f4a50f52b38] WARN - SLOW QUERY: It took 330.000000 ms to retrieve 1 items.
Mar 19, 2022 14:16:22.556 [0x7f4a4e788b38] WARN - SLOW QUERY: It took 300.000000 ms to retrieve 1 items.
Mar 19, 2022 14:16:22.558 [0x7f4a50f75b38] WARN - SLOW QUERY: It took 260.000000 ms to retrieve 1 items.
Mar 19, 2022 14:16:22.574 [0x7f4a4e751b38] WARN - SLOW QUERY: It took 300.000000 ms to retrieve 1 items.
Mar 19, 2022 14:16:22.594 [0x7f4a54c4cb38] WARN - SLOW QUERY: It took 290.000000 ms to retrieve 1 items.
Mar 19, 2022 14:16:22.600 [0x7f4a50f75b38] WARN - SLOW QUERY: It took 250.000000 ms to retrieve 1 items.
Mar 19, 2022 14:16:22.603 [0x7f4a4e788b38] WARN - SLOW QUERY: It took 290.000000 ms to retrieve 1 items.
Mar 19, 2022 14:16:22.617 [0x7f4a518b5b38] WARN - SLOW QUERY: It took 250.000000 ms to retrieve 1 items.
Mar 19, 2022 14:16:22.622 [0x7f4a4e751b38] WARN - SLOW QUERY: It took 310.000000 ms to retrieve 1 items.
Mar 19, 2022 14:16:22.625 [0x7f4a4e939b38] WARN - SLOW QUERY: It took 290.000000 ms to retrieve 1 items.
Mar 19, 2022 14:16:22.634 [0x7f4a4e58eb38] WARN - SLOW QUERY: It took 250.000000 ms to retrieve 1 items.
Mar 19, 2022 14:16:22.643 [0x7f4a54c4cb38] WARN - SLOW QUERY: It took 250.000000 ms to retrieve 1 items.
Mar 19, 2022 14:16:22.663 [0x7f4a4e8f6b38] WARN - SLOW QUERY: It took 250.000000 ms to retrieve 1 items.
Mar 19, 2022 14:16:22.668 [0x7f4a4e939b38] WARN - SLOW QUERY: It took 250.000000 ms to retrieve 1 items.
Mar 19, 2022 14:16:22.676 [0x7f4a4e58eb38] WARN - SLOW QUERY: It took 250.000000 ms to retrieve 1 items.
Mar 19, 2022 14:16:22.686 [0x7f4a51a41b38] WARN - SLOW QUERY: It took 220.000000 ms to retrieve 1 items.
Mar 19, 2022 14:16:22.698 [0x7f4a4e8b3b38] WARN - SLOW QUERY: It took 260.000000 ms to retrieve 1 items.
Mar 19, 2022 14:16:22.704 [0x7f4a505e6b38] WARN - SLOW QUERY: It took 2990.000000 ms to retrieve 93 items.
Mar 19, 2022 14:16:22.704 [0x7f4a4e8f6b38] WARN - SLOW QUERY: It took 230.000000 ms to retrieve 1 items.
Mar 19, 2022 14:16:22.718 [0x7f4a51d46b38] WARN - SLOW QUERY: It took 210.000000 ms to retrieve 1 items.
Mar 19, 2022 14:16:22.728 [0x7f4a51a41b38] WARN - SLOW QUERY: It took 240.000000 ms to retrieve 1 items.
Mar 19, 2022 14:16:22.742 [0x7f4a4e8b3b38] WARN - SLOW QUERY: It took 300.000000 ms to retrieve 1 items.
Mar 19, 2022 14:16:22.748 [0x7f4a51159b38] WARN - SLOW QUERY: It took 270.000000 ms to retrieve 1 items.
Mar 19, 2022 14:16:22.753 [0x7f4a50f52b38] WARN - SLOW QUERY: It took 250.000000 ms to retrieve 1 items.
Mar 19, 2022 14:16:22.756 [0x7f4a4e85fb38] WARN - SLOW QUERY: It took 2730.000000 ms to retrieve 93 items.
Mar 19, 2022 14:16:22.787 [0x7f4a51159b38] WARN - SLOW QUERY: It took 240.000000 ms to retrieve 1 items.
Mar 19, 2022 14:16:22.794 [0x7f4a50f52b38] WARN - SLOW QUERY: It took 230.000000 ms to retrieve 1 items.
Mar 19, 2022 14:16:22.807 [0x7f4a50f75b38] WARN - SLOW QUERY: It took 240.000000 ms to retrieve 1 items.
Mar 19, 2022 14:16:22.817 [0x7f4a510b6b38] WARN - SLOW QUERY: It took 240.000000 ms to retrieve 1 items.
Mar 19, 2022 14:16:22.846 [0x7f4a50f75b38] WARN - SLOW QUERY: It took 250.000000 ms to retrieve 1 items.
Mar 19, 2022 14:16:24.505 [0x7f4a500d8b38] WARN - SLOW QUERY: It took 290.000000 ms to retrieve 50 items.

Either the database is HUGE (bloat or media) -OR- it’s fragmented (needs optimizing)

I have a single CPU 2690v4 and never have this kind of problem with it and 50+ TB of media.

Would it be possible to:

Turn DEBUG logging ON.
Reduce LogNumFiles=“10”

baconator_admin · March 22, 2022, 3:54am

Well that’s a shame that debug logging was not enabled. I know I had it on for the longest time and probably thought “eh, I don’t need this anymore.” As for the LogNumFiles – that’s doesn’t even look like a setting that I can adjust in the web UI. Perhaps that was the default some years ago? I have no explanation for how that got set that way.

I should mention that I have been carrying that same Application Support dir and database from version to version of Plex for the past, I don’t even know… 10 years maybe? Basically as long as Plex has existed.

I’ve had the slow query messages for a long time too – at least a couple years. My database optimization runs weekly and I’ve done several manual runs. With a decade old database, 100 TB of media, and 95 or so users, I think I’ve just totally run over what sqlite can handle. I’m storing the database on Optane, which is about the fastest thing I can run it on short of literal DRAM. If there is anything further I can do to improve database performance without nuking it and starting fresh, please let me know. I should say that I don’t notice any tangible end-user impact from these slow query warnings. If my database is slow, it sure doesn’t feel like it.

I will try to capture new logs of the deadlocks now that debug logging is enabled. It seems I can only change the LogNumFiles by editing the Preferences.xml and restarting the server? If so, I’ll have to wait for a maintenance (or crash) window to do that.

Thanks!

Edit with DB sizes:

[root@plex Databases]# ls -lh | grep -E 'db(-shm|-wal)?$'
-rwxr--r-- 1 plex plex 610K Jun  8  2015 com.plexapp.dlna.db
-rwxr--r-- 1 plex plex  32K Jun  8  2015 com.plexapp.dlna.db-shm
-rwxr--r-- 1 plex plex 1.1M Jun  8  2015 com.plexapp.dlna.db-wal
-rw-r--r-- 1 plex plex 2.5G Mar 21 16:56 com.plexapp.plugins.library.blobs.db
-rw-r--r-- 1 plex plex  32K Mar 21 22:36 com.plexapp.plugins.library.blobs.db-shm
-rw-r--r-- 1 plex plex 1.1M Mar 21 22:36 com.plexapp.plugins.library.blobs.db-wal
-rwxr--r-- 1 plex plex 924M Mar 22 00:08 com.plexapp.plugins.library.db
-rwxr--r-- 1 plex plex  32K Mar 22 00:08 com.plexapp.plugins.library.db-shm
-rwxr--r-- 1 plex plex 4.0M Mar 22 00:08 com.plexapp.plugins.library.db-wal
-rw-rw-r-- 1 plex plex 114M Mar 22 00:02 tv.plex.providers.epg.cloud-2339cadd-9fd1-458d-81f2-bb1133fce341.db
-rw-rw-r-- 1 plex plex  32K Mar 22 00:02 tv.plex.providers.epg.cloud-2339cadd-9fd1-458d-81f2-bb1133fce341.db-shm
-rw-rw-r-- 1 plex plex 1.1M Mar 22 00:02 tv.plex.providers.epg.cloud-2339cadd-9fd1-458d-81f2-bb1133fce341.db-wal

mjwsatx_gmail_com · March 22, 2022, 4:09am

Same here. Since the last update my server freezes regularly. I have to close it down through task manager and restart it. I think it happens when I access the server through any client - android, web or Roku. This is getting very frustrating. Up until now Plex has been rock solid.

ChuckPa · March 22, 2022, 5:56pm

@mjwsatx_gmail_com

Please provide log files which capture it – anything which might be of info from when it happens (maybe even while it’s hung before you restart).

Unfortunately “Me too” isn’t actionable .

mjwsatx_gmail_com · March 25, 2022, 8:12pm

ChuckPa
I was hoping that others were experiencing crashing problems due to the update. I have since installed the newest update and my problems persist, so the update is not the issue.
I have attached the log file which I created immediately after opening Plex after my server last crashed.
Another thing I’ve noticed is that Plex constantly swings from using few CPU resources to using 90% or more of my CPU resources. This happens even when I’m not recording or streaming anything and it seems to be a continuous cycle.
I have been able to use my Roku client to stream, but my Plex server still crashes at unpredictable times.
Thanks very much for your help. Mike ///////\///////

Plex Media Server Logs_2022-03-25_14-54-50.zip (5.8 MB)

ChuckPa · March 25, 2022, 9:32pm

@mjwsatx_gmail_com

Thanks for those logs but I can’t help for 2 reasons:

Windows (I’m a Linux guy)
I don’t have DVR so don’t even understand what I’m looking at.

Do you know what you were doing when it crashed?

Mar 25, 2022 14:01:02.156 [15832] INFO - Plex Media Server v1.25.8.5663-e071c3d62 - Microsoft PC x64 - build: windows-x86 windows - GMT -05:00
Mar 25, 2022 14:01:02.157 [15832] INFO - Windows version: 6.3 (Build 9600), language en-US
Mar 25, 2022 14:01:02.157 [15832] INFO - 4 3392 MHz processor(s): Architecture=0, Level=6, Revision=15363 Processor Identifier=Intel64 Family 6 Model 60 Stepping 3, GenuineIntel
Mar 25, 2022 14:01:02.157 [15832] INFO - Compiler is - MSVC 1924
Mar 25, 2022 14:01:02.157 [15832] DEBUG - "C:\Program Files (x86)\Plex\Plex Media Server\Plex Media Server.exe"

Activity –

Mar 25, 2022 14:01:13.660 [10268] DEBUG - Subscription: We want a premiere, and 'Schitt's Creek - E4 - Bad Parents' is an old airing, ignoring.
Mar 25, 2022 14:01:13.660 [10268] DEBUG - Subscription: We want a premiere, and 'Schitt's Creek - E5 - The Cabin' is an old airing, ignoring.
Mar 25, 2022 14:01:13.660 [10268] DEBUG - Subscription: We want a premiere, and 'Schitt's Creek - E6 - Wine and Roses' is an old airing, ignoring.
Mar 25, 2022 14:01:13.660 [10268] DEBUG - Subscription: We want a premiere, and 'Schitt's Creek - E7 - Turkey Shoot' is an old airing, ignoring.
Mar 25, 2022 14:01:13.660 [10268] DEBUG - Subscription: We want a premiere, and 'Schitt's Creek - E8 - Allez Vous' is an old airing, ignoring.
Mar 25, 2022 14:01:13.660 [10268] DEBUG - Subscription: We want a premiere, and 'Schitt's Creek - E11 - Little Sister' is an old airing, ignoring.
Mar 25, 2022 14:01:13.660 [10268] DEBUG - Subscription: We want a premiere, and 'Schitt's Creek - E12 - Surprise Party' is an old airing, ignoring.
Mar 25, 2022 14:01:13.662 [10268] DEBUG - Activity: updated activity 570f5a5a-dc7d-48ea-81aa-2fcec8a9374e - completed 0.0% - Refreshing Sub
Mar 25, 2022 14:01:13.662 [10268] DEBUG - Activity: Ended activity 570f5a5a-dc7d-48ea-81aa-2fcec8a9374e.
Mar 25, 2022 14:01:13.663 [10268] DEBUG - Activity: registered new activity ecc8d57e-c3fb-4238-8adf-36a915551914 - "Refreshing Sub"
Mar 25, 2022 14:01:13.668 [14304] DEBUG - [Transcode] Transcoder segment range: 0 - 3731 (3730)
Mar 25, 2022 14:01:13.671 [10268] DEBUG - Activity: updated activity ecc8d57e-c3fb-4238-8adf-36a915551914 - completed 0.0% - Refreshing Sub
Mar 25, 2022 14:01:13.671 [10268] DEBUG - Activity: updated activity ecc8d57e-c3fb-4238-8adf-36a915551914 - completed 0.0% - Refreshing Sub
Mar 25, 2022 14:01:13.674 [10268] DEBUG - Subscription: No existing library item show 'guid: plex://show/5fc6ace97c6557002ed8364b ratingKey: plex%3A%2F%2Fshow%2F5fc6ace97c6557002ed8364b thumb: https://metadata-static.plex.tv/1/gracenote/15dc9b57226531d22e64687bfefa1c7c.jpg title: SEAL Team type: 2 year: 2017'
Mar 25, 2022 14:01:13.674 [10268] DEBUG - Subscription: Checking in provider Live TV & DVR
Mar 25, 2022 14:01:13.674 [10268] DEBUG - Downloading document http://127.0.0.1:32400/tv.plex.providers.epg.cloud:8/metadata/plex%3a%2f%2fshow%2f5fc6ace97c6557002ed8364b?includeMarkers=1&includeParentKey=1&includePreferences=1
Mar 25, 2022 14:01:13.685 [10268] DEBUG - There were 0 top-level paths for SEAL Team.
Mar 25, 2022 14:01:13.685 [10268] DEBUG - Subscription: The item at /tv.plex.providers.epg.cloud:8/metadata/plex%3A%2F%2Fshow%2F5fc6ace97c6557002ed8364b is of type 2
Mar 25, 2022 14:01:13.685 [10268] DEBUG - Downloading document http://127.0.0.1:32400/tv.plex.providers.epg.cloud:8/metadata/plex%3a%2f%2fshow%2f5fc6ace97c6557002ed8364b/grandchildren?includeElements=Media,Stream,Tags&includeMarkers=1&includeMarkers=1&includeParentKey=1&includePreferences=1, paging as 0 + 100
Mar 25, 2022 14:01:13.690 [10268] DEBUG - Setting container serialization range to [0, 99] (total=-1)
Mar 25, 2022 14:01:13.791 [16428] DEBUG - [JobRunner] Jobs: Starting child process with pid 10652
--EOF--

mjwsatx_gmail_com · March 25, 2022, 10:37pm

Thanks for the reply. I wasn’t doing anything active on the computer that runs my server when Plex crashed. It might have been DVR recording from my HDHomerun at the time. I wasn’t running anything else.

I do think the regular fluctuations in Plex CPU usage is indicative of a problem. I just don’t know what is causing this fluctuation.

Do you know anyone else who can help?

Thanks. Mike ////////\////////

baconator_admin · April 1, 2022, 4:51am

The frequency of crashes seems to have decreased, which again leads me to believe that a user is triggering it somehow, but it did go down on 3/31 at around 23:50. Logs attached.
Plex Media Server Logs_2022-03-31_23-51-35.zip (25.3 MB)

The logs were collected immediately after restarting the server. It was completely down so I couldn’t generate a log bundle from the web interface before restarting, although, it occurs to me now that I could have just grabbed them directly off disk.

I did finally use this chance to set the LogNumFiles to 10, so, future log bundles will not be so large.

sa2000 · April 11, 2022, 10:15am

Seems to be slow processing of some playback timeline updates and resulting in lots of requests getting queued up behind and taking very long time to complete

The process was not crashed - just processing requests with a backlog of queued requests and the time to complete the request got longer and longer

Logs show PMS process was killed at Mar 31, 2022 23:51:08

Wondering if it is to do with some media items having lots of streams

Could you run with the current beta and get me fresh logs - i am not sure how easy it would be for you to locate a crash dump file if you do force a process dump whilst it is in this state - killing the Plex Media Server with -SEGV parameter - we do copy copy crash dumps to $TMPDIR for the Plex Media Server process - not sure where that would be in the docker environment

Also would like to have a download of your Plex Media Server database to see if the slow requests are to do with media files that have a lot of streams

One Example you can check is Star.Wars.Episode.III.Revenge.Of.The.Sith.1080p.mkv
to see how many audio and subtitle streams there are

system · July 10, 2022, 10:15am

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

Topic		Replies	Views
Server keeps crashing - 1.22.2.4264 Desktops & Laptops server-windows	154	4170	January 4, 2022
Plex Crashing frequently for the past few months Desktops & Laptops server-windows	84	1375	November 22, 2018
What do these logs mean exactly? Trying to debug general instability Desktops & Laptops server-docker	13	4951	February 19, 2019
Plex Server Crashing Randomly Desktops & Laptops server-windows	205	5637	January 17, 2023
Plex crashes after a while Desktops & Laptops server-linux , server-docker	38	1268	February 19, 2019

Constant server deadlocks/crashes recenty

Related topics