Plex processes hang

Plex Media Server Desktops & Laptops
1

Server Version#: 1.15.2.793 (though I’ve had this problem on the last several versions)
Player Version#: N/A
OS Version: Ubuntu 14.04.5 LTS

Every 1-3 weeks, the server will stop responding (my monitoring system reports a socket timeout). When I check the server, there are no obvious OS-level issues (load, disk space, memory, etc.). Restarting the service normally with service plexmediaserver restart does not work. I have to list all of the Plex processes with ps aux | grep plex and kill them with kill -9 <pid>. Then I can start the server normally with service plexmediaserver start and everything works fine.

I attached the logs to this post, but I looked through them and didn’t see anything obvious around the time of the most recent crash (which was about 2019-03-23 15:06:35 EST).

I also don’t see anything in the Crash Reports folder from today, but that makes sense because it’s not actually crashing.

Anyone know how I can troubleshoot this further?

Plex Media Server Logs_2019-03-23_15-24-19.zip (2.8 MB)

2

As fully expected, you are losing compatbility with PMS

Ubuntu 14.04.5 LTS runtime libraries are on the verge of failure due to age.
Ubuntu / canonical has declared all support ends April 30, 2019

Mar 20, 2019 16:25:30.897 [0x7fed028a5700] INFO - Plex Media Server v1.15.2.793-782228f99 - Ubuntu PC x86_64 - build: linux-x86_64 debian - GMT -04:00
Mar 20, 2019 16:25:30.912 [0x7fed028a5700] INFO - Linux version: 14.04.5 LTS, Trusty Tahr, language: en-US
Mar 20, 2019 16:25:30.913 [0x7fed028a5700] INFO - Processor Intel(R) Xeon(R) CPU           X5650  @ 2.67GHz
Mar 20, 2019 16:25:30.913 [0x7fed028a5700] INFO - ./Plex Media Server
Mar 20, 2019 16:25:30.845 [0x7fecde7fc700] ERROR - [Transcoder] [mpeg4 @ 0xe9fc80] marker does not match f_code
Mar 20, 2019 16:25:30.846 [0x7fec78ff9700] ERROR - [Transcoder] [mpeg4 @ 0xe9fc80] marker does not match f_code
Mar 20, 2019 16:25:30.846 [0x7fecb9ffb700] ERROR - [Transcoder] [mpeg4 @ 0xe9fc80] marker does not match f_code
Mar 20, 2019 16:25:30.847 [0x7fecf89cd700] ERROR - [Transcoder] [mpeg4 @ 0xe9fc80] marker does not match f_code
Mar 20, 2019 16:25:30.848 [0x7fec7bfff700] ERROR - [Transcoder] [mpeg4 @ 0xe9fc80] marker does not match f_code
Mar 20, 2019 16:25:30.849 [0x7fecbaffd700] ERROR - [Transcoder] [mpeg4 @ 0xe9fc80] marker does not match f_code
Mar 20, 2019 16:25:30.850 [0x7fecde7fc700] ERROR - [Transcoder] [mpeg4 @ 0xe9fc80] marker does not match f_code
Mar 20, 2019 16:25:30.851 [0x7fec78ff9700] ERROR - [Transcoder] [mpeg4 @ 0xe9fc80] marker does not match f_code
Mar 20, 2019 16:25:30.852 [0x7fecb9ffb700] ERROR - [Transcoder] [mpeg4 @ 0xe9fc80] marker does not match f_code

File locking / semaphores are no longer working because of glibc incompability.

Mar 20, 2019 16:25:46.733 [0x7fecdffff700] WARN - Held transaction for too long (../Statistics/StatisticsManager.cpp:249): 0.540000 seconds
Mar 20, 2019 16:26:17.348 [0x7fecfa9d1700] WARN - Held transaction for too long (../Statistics/StatisticsManager.cpp:249): 0.560000 seconds
Mar 20, 2019 16:26:48.218 [0x7fec54ff9700] WARN - Held transaction for too long (../Statistics/StatisticsManager.cpp:249): 0.850000 seconds
Mar 20, 2019 16:27:18.878 [0x7fecbb7fe700] WARN - Held transaction for too long (../Statistics/StatisticsManager.cpp:249): 0.510000 seconds
Mar 20, 2019 16:27:49.521 [0x7fecfbfff700] WARN - Held transaction for too long (../Statistics/StatisticsManager.cpp:249): 0.530000 seconds
Mar 20, 2019 16:28:19.930 [0x7fecfa1d0700] WARN - Held transaction for too long (../Statistics/StatisticsManager.cpp:249): 0.320000 seconds
Mar 20, 2019 16:28:50.311 [0x7fecf99cf700] WARN - Held transaction for too long (../Statistics/StatisticsManager.cpp:249): 0.290000 seconds

It is time to upgrade to a newer OS version

3

Interesting, okay. I’ll do that. Thanks.

4

Upgrade finished. Hopefully that will be the end of this issue.

In related news, how I can I know when there’s an incompatibility like this? Obviously Ubuntu 14.04 is pretty old, but its still under support for another month and I’d been keeping the packages up to date. Is this kind of thing in the release notes?

5

This was a surprise to everyone.

The marketing team will be sending out email notifications to those who use the older distros and, in the future, as each distribution’s version is about to become obsoleted.

6

Hi Chuck,

This happened again. I’ve attached another log bundle.

Monitoring noticed a problem around 12:30PM, and I see the following log entries (similar to before):

Mar 30, 2019 12:28:18.247 [0x7f70af7fe700] WARN - Held transaction for too long (../Statistics/StatisticsManager.cpp:249): 0.340000 seconds
Mar 30, 2019 12:28:48.818 [0x7f70457fa700] WARN - Held transaction for too long (../Statistics/StatisticsManager.cpp:249): 0.390000 seconds
Mar 30, 2019 12:29:19.331 [0x7f709dffb700] WARN - Held transaction for too long (../Statistics/StatisticsManager.cpp:249): 0.390000 seconds
Mar 30, 2019 12:29:49.874 [0x7f708bfff700] WARN - Held transaction for too long (../Statistics/StatisticsManager.cpp:249): 0.450000 seconds

I also confirmed that my glibc version is new enough:

root@plex : ~ # ldd --version
ldd (Ubuntu GLIBC 2.23-0ubuntu11) 2.23

Please let me know if you have any more thoughts.

Plex Media Server Logs_2019-03-30_14-41-47.zip (3.0 MB)

7

There is some serious overloading.

1 Database is slow / fragmented. (optimize database ?)

Mar 30, 2019 14:40:18.716 [0x7f72e9ffb700] INFO - AutoUpdate: no updates available
Mar 30, 2019 14:40:26.455 [0x7f7309ffb700] WARN - [CompanionPlayer] We already have a handler, overwriting.
Mar 30, 2019 14:40:42.213 [0x7f73097fa700] WARN - SLOW QUERY: It took 1180.000000 ms to retrieve 6 items.
Mar 30, 2019 14:40:46.470 [0x7f72c7fff700] WARN - [CompanionPlayer] We already have a handler, overwriting.
Mar 30, 2019 14:40:52.908 [0x7f72e97fa700] INFO - AutoUpdate: no updates available
  1. The transcoder is going nuts on this file. whatever it is, it looks VERY bad (I don’t believe 7.1 audio is legal in AAC. Only 5.1 is legal/supported but might be out of date). NAL erros are just a bad encode.
Mar 28, 2019 21:17:49.819 [0x7f708a7fc700] ERROR - [Transcoder] [aac @ 0x2ba2200] Reserved bit set.
Mar 28, 2019 21:17:49.820 [0x7f701bfff700] ERROR - [Transcoder] [aac @ 0x2ba2200] Number of bands (8) exceeds limit (2).
Mar 28, 2019 21:17:49.821 [0x7f70017fa700] ERROR - [Transcoder] Error while decoding stream #0:1: Invalid data found when processing input
Mar 28, 2019 21:17:49.822 [0x7f701affd700] ERROR - [Transcoder] [aac @ 0x2ba2200] Reserved bit set.
Mar 28, 2019 21:17:49.823 [0x7f70457fa700] ERROR - [Transcoder] [aac @ 0x2ba2200] Number of bands (8) exceeds limit (2).
Mar 28, 2019 21:17:49.824 [0x7f70adffb700] ERROR - [Transcoder] Error while decoding stream #0:1: Invalid data found when processing input
Mar 28, 2019 21:17:49.825 [0x7f7002ffd700] ERROR - [Transcoder] [aac @ 0x2ba2200] Reserved bit set.
Mar 28, 2019 21:17:49.826 [0x7f7067fff700] ERROR - [Transcoder] [aac @ 0x2ba2200] Number of bands (8) exceeds limit (2).
Mar 28, 2019 21:17:49.827 [0x7f7066ffd700] ERROR - [Transcoder] Error while decoding stream #0:1: Invalid data found when processing input
Mar 28, 2019 21:17:49.828 [0x7f701bfff700] ERROR - [Transcoder] Error while decoding stream #0:0: Invalid data found when processing input
Mar 28, 2019 21:17:49.829 [0x7f70017fa700] ERROR - [Transcoder] [h264 @ 0x2e5fb80] Invalid NAL unit size (16843009 > 30941).

What is the XML of the file being played?

Can you create that item only? The logs lost the MDE and transcoder start (too many errors reported)

Play for 30 seconds only. stop. download the logs. attach the ZIP again please.

8

My storage is dying. I will get back to you with answers to your questions once I resolve that.

Thanks for the response.

9

I’m seeing the same issue - Ubuntu 18.04 server, nothing at all playing at the moment:

Apr 03, 2019 07:54:32.131 [0x7ff3d5ffb700] WARN - Held transaction for too long (../Statistics/StatisticsManager.cpp:249): 0.130000 seconds
Apr 03, 2019 07:55:02.278 [0x7ff437fff700] WARN - Held transaction for too long (../Statistics/StatisticsManager.cpp:249): 0.130000 seconds
Apr 03, 2019 07:55:32.422 [0x7ff415ffb700] WARN - Held transaction for too long (../Statistics/StatisticsManager.cpp:249): 0.140000 seconds
Apr 03, 2019 07:56:02.567 [0x7ff450f5d700] WARN - Held transaction for too long (../Statistics/StatisticsManager.cpp:249): 0.130000 seconds
Apr 03, 2019 07:56:32.717 [0x7ff3d5ffb700] WARN - Held transaction for too long (../Statistics/StatisticsManager.cpp:249): 0.130000 seconds
Apr 03, 2019 07:57:02.865 [0x7ff4497fa700] WARN - Held transaction for too long (../Statistics/StatisticsManager.cpp:249): 0.140000 seconds
Apr 03, 2019 07:57:33.013 [0x7ff4177fe700] WARN - Held transaction for too long (../Statistics/StatisticsManager.cpp:249): 0.140000 seconds
Apr 03, 2019 07:58:03.160 [0x7ff4167fc700] WARN - Held transaction for too long (../Statistics/StatisticsManager.cpp:249): 0.130000 seconds
Apr 03, 2019 07:58:33.310 [0x7ff435ffb700] WARN - Held transaction for too long (../Statistics/StatisticsManager.cpp:249): 0.130000 seconds
Apr 03, 2019 07:59:03.457 [0x7ff3d5ffb700] WARN - Held transaction for too long (../Statistics/StatisticsManager.cpp:249): 0.130000 seconds
Apr 03, 2019 07:59:33.607 [0x7ff4177fe700] WARN - Held transaction for too long (../Statistics/StatisticsManager.cpp:249): 0.130000 seconds
Apr 03, 2019 08:00:01.859 [0x7ff3ef7fe700] WARN - Held transaction for too long (../Library/DatabaseFixups.cpp:207): 0.180000 seconds
Apr 03, 2019 08:00:02.568 [0x7ff3ef7fe700] WARN - Held transaction for too long (../Library/FullTextSearch.cpp:17): 0.690000 seconds
Apr 03, 2019 08:00:03.152 [0x7ff3ef7fe700] WARN - Held transaction for too long (../Library/FullTextSearch.cpp:27): 0.580000 seconds
Apr 03, 2019 08:00:04.426 [0x7ff3ef7fe700] WARN - Held transaction for too long (../Library/FullTextSearch.cpp:38): 1.270000 seconds
Apr 03, 2019 08:00:05.203 [0x7ff3ef7fe700] WARN - Held transaction for too long (../Library/FullTextSearch.cpp:48): 0.770000 seconds
Apr 03, 2019 08:00:08.479 [0x7ff3ef7fe700] INFO - SQLITE3:(nil), 17, statement aborts at 56: [select * from metadata_items limit 1] database schema has changed
Apr 03, 2019 08:00:08.482 [0x7ff3ef7fe700] INFO - SQLITE3:(nil), 17, statement aborts at 56: [select * from metadata_items limit 1] database schema has changed
Apr 03, 2019 08:00:08.485 [0x7ff3ef7fe700] INFO - SQLITE3:(nil), 17, statement aborts at 56: [select * from metadata_items limit 1] database schema has changed
Apr 03, 2019 08:00:08.489 [0x7ff3ef7fe700] INFO - SQLITE3:(nil), 17, statement aborts at 56: [select * from metadata_items limit 1] database schema has changed
Apr 03, 2019 08:00:08.492 [0x7ff3ef7fe700] INFO - SQLITE3:(nil), 17, statement aborts at 56: [select * from metadata_items limit 1] database schema has changed
Apr 03, 2019 08:00:08.495 [0x7ff3ef7fe700] INFO - SQLITE3:(nil), 17, statement aborts at 56: [select * from metadata_items limit 1] database schema has changed
Apr 03, 2019 08:00:08.497 [0x7ff3ef7fe700] INFO - SQLITE3:(nil), 17, statement aborts at 56: [select * from metadata_items limit 1] database schema has changed
Apr 03, 2019 08:00:08.499 [0x7ff3ef7fe700] INFO - SQLITE3:(nil), 17, statement aborts at 56: [select * from metadata_items limit 1] database schema has changed
Apr 03, 2019 08:00:08.502 [0x7ff3ef7fe700] INFO - SQLITE3:(nil), 17, statement aborts at 56: [select * from metadata_items limit 1] database schema has changed
Apr 03, 2019 08:00:08.504 [0x7ff3ef7fe700] INFO - SQLITE3:(nil), 17, statement aborts at 56: [select * from metadata_items limit 1] database schema has changed
Apr 03, 2019 08:00:08.506 [0x7ff3ef7fe700] INFO - SQLITE3:(nil), 17, statement aborts at 56: [select * from metadata_items limit 1] database schema has changed
Apr 03, 2019 08:00:08.508 [0x7ff3ef7fe700] INFO - SQLITE3:(nil), 17, statement aborts at 56: [select * from metadata_items limit 1] database schema has changed
Apr 03, 2019 08:00:08.510 [0x7ff3ef7fe700] INFO - SQLITE3:(nil), 17, statement aborts at 56: [select * from metadata_items limit 1] database schema has changed
Apr 03, 2019 08:00:08.512 [0x7ff3ef7fe700] INFO - SQLITE3:(nil), 17, statement aborts at 56: [select * from metadata_items limit 1] database schema has changed
Apr 03, 2019 08:00:08.514 [0x7ff3ef7fe700] INFO - SQLITE3:(nil), 17, statement aborts at 56: [select * from metadata_items limit 1] database schema has changed
Apr 03, 2019 08:00:08.517 [0x7ff3ef7fe700] INFO - SQLITE3:(nil), 17, statement aborts at 56: [select * from metadata_items limit 1] database schema has changed
Apr 03, 2019 08:00:08.519 [0x7ff3ef7fe700] INFO - SQLITE3:(nil), 17, statement aborts at 56: [select * from metadata_items limit 1] database schema has changed
Apr 03, 2019 08:00:08.521 [0x7ff3ef7fe700] INFO - SQLITE3:(nil), 17, statement aborts at 56: [select * from metadata_items limit 1] database schema has changed
Apr 03, 2019 08:00:08.523 [0x7ff3ef7fe700] INFO - SQLITE3:(nil), 17, statement aborts at 56: [select * from metadata_items limit 1] database schema has changed
Apr 03, 2019 08:00:08.657 [0x7ff435ffb700] WARN - Held transaction for too long (../Statistics/StatisticsManager.cpp:249): 0.270000 seconds
Apr 03, 2019 08:00:38.796 [0x7ff437fff700] WARN - Held transaction for too long (../Statistics/StatisticsManager.cpp:249): 0.120000 seconds
Apr 03, 2019 08:00:48.900 [0x7ff44a7fc700] INFO - AutoUpdate: no updates available
Apr 03, 2019 08:00:56.647 [0x7ff448ff9700] INFO - AutoUpdate: no updates available
Apr 03, 2019 08:00:56.723 [0x7ff416ffd700] WARN - [CompanionPlayer] We already have a handler, overwriting.
Apr 03, 2019 08:01:03.836 [0x7ff448ff9700] INFO - AutoUpdate: no updates available
Apr 03, 2019 08:01:08.935 [0x7ff3d67fc700] WARN - Held transaction for too long (../Statistics/StatisticsManager.cpp:249): 0.130000 seconds
Apr 03, 2019 08:01:39.078 [0x7ff4377fe700] WARN - Held transaction for too long (../Statistics/StatisticsManager.cpp:249): 0.130000 seconds
Apr 03, 2019 08:02:09.220 [0x7ff437fff700] WARN - Held transaction for too long (../Statistics/StatisticsManager.cpp:249): 0.130000 seconds
Apr 03, 2019 08:02:39.362 [0x7ff414ff9700] WARN - Held transaction for too long (../Statistics/StatisticsManager.cpp:249): 0.130000 seconds
Apr 03, 2019 08:03:09.510 [0x7ff4177fe700] WARN - Held transaction for too long (../Statistics/StatisticsManager.cpp:249): 0.150000 seconds
Apr 03, 2019 08:03:39.655 [0x7ff3d5ffb700] WARN - Held transaction for too long (../Statistics/StatisticsManager.cpp:249): 0.130000 seconds
Apr 03, 2019 08:04:09.788 [0x7ff4367fc700] WARN - Held transaction for too long (../Statistics/StatisticsManager.cpp:249): 0.120000 seconds

I actually ran an optimize at 08:00 sharp, as you can see above, and the issue persists several minutes afterwards. Every ~30s or so i see this error (I assume the statistics update that often?).

My Plex database is on a RAM disk, so I cannot possibly think it has anything to do with I/O or throughput to the database. Let me know what I can do to get rid of these logs - they are 95% of my log files at this point.

10

May I have the rest of the logs please?

If this is the log, please enable DEBUG logging so we can see what Plex is trying to do.
DEBUG logging does not consume more space. It only provides more detail.
Please do not enable VERBOSE. VERBOSE reduces the elapsed time the buffer can hold to about 3 minutes.

11

Logs: https://gist.github.com/SlothCroissant/25dcf5c026f2995806e7d5efb58b24f3

Hopefully it’s enough to get you what you need. Let me know if you’d like it run longer, etc.

Thanks!

12

I wonder if this is related to PMS v1.15 and old clients using some unsupported API or the like, as I’m having the same kind of issues (PMS unresponsive, need server restart) after using my Samsung TV client (3rd party by Orca). Maybe the Tivo client is also using the same approach?
After playing a file, lots of database related errors appear:

Apr 03, 2019 16:33:29.879 [0x6a3f8450] DEBUG - Transcoder segment range: 94 - 136 (136) Apr 03, 2019 16:33:30.047 [0x5b1fa450] WARN - Held transaction for too long (../Statistics/StatisticsMedia.cpp:29): 0.580000 seconds Apr 03, 2019 16:33:30.365 [0x67bf3450] WARN - Waited one whole second for a busy database. Apr 03, 2019 16:33:30.812 [0x625fa450] WARN - Waited one whole second for a busy database. Apr 03, 2019 16:33:31.056 [0x615f8450] WARN - Waited one whole second for a busy database. Apr 03, 2019 16:33:31.140 [0x5b1fa450] WARN - Held transaction for too long (../Statistics/StatisticsMedia.cpp:29): 0.560000 seconds Apr 03, 2019 16:33:32.029 [0x625fa450] ERROR - Soci Exception handled: sqlite3_statement_backend::loadOne: database is locked Apr 03, 2019 16:33:32.031 [0x713ff450] DEBUG - Completed: [192.168.1.100:58722] 500 GET /:/timeline?ratingKey=9232&key=%2Flibrary%2Fmetadata%2F9232&playbackTime=49400&playQueueItemID=8795&state=playing&hasMDE=1&time=526000&duration=2651000 (10 live) GZIP 44890ms 405 bytes (pipelined: 5)

Full log at https://gist.github.com/WolfganP/0417049766412e9135f5abcd08f73f26

Session index (log #line number):
#1 Started server from scratch, went to web player and started playing a TV episode for a couple of minutes, then pause and back (x) to web client home.
#2450 Started Samsung client on my TV, then navigating to the same episode (not appearing On Deck) and then playing for a minute or so. Started from 0 as no Resume option shown.
#3396 Stop playing and back to home, interface doesn’t display any item, just libraries name and can’t navigate.
#3686 had to force exit the TV client. Then back to the PC and resume playing the same episode (no changes on time index, didn’t synced as it was played on another client).
#4447 Stop web player.

Any clue will be appreciated. Thx!

13

My storage is restored. However, it doesn’t look like anyone was playing anything at the time indicated (Mar 28, 2019 21:17). I will update this thread again with more logs if there is another crash. In the meantime I have turned on DEBUG logging so we get more detail.

14

Update: I updated to Version 1.15.3.876 this AM, and the logs are no longer spammed with the errors in my gist. Unsure if it’s a re-install that fixed it (I use the official docker) or the version bump.

EDIT: Nevermind, the issue persists.

15

Unfortunately I have the same issue on my plex server.
After upgrading the plex media server to 1.15.3 on my Qnap I ran optimize for a couple of episodes of a tvshow, now I get this error (only in the season I ran the optimize in) : Apr 17, 2019 16:23:37.702 [0x7f58cef55700] INFO - SQLITE3:(nil), 17, statement aborts at 56: [select * from metadata_items limit 1] database schema has changed

16

Just to re-bump this…

I too have this and do not wish to see the BUG go unnoticed.

May 06, 2019 20:33:24.588 [5432] INFO - SQLITE3:0xa868dada, 17, statement aborts at 56: [select * from metadata_items limit 1] database schema has changed

The error stems from an import of an XMLTV EPG refresh from xteve.

17 
WARN - Held transaction for too long (../Statistics/StatisticsManager.cpp:29)

I had this isue too, In my case the problem was the weight of my DB (100MB) and the number of rows on ‘statistics_media’ table (even being stored on a SSD). +2000 movies, series, and a DB with statistics from 2015.

The solution:

Access through sqlite to your plex library path
%Plex_Library_Path%\Plex Media Server\Plug-in Support\Databases
and open “com.plexapp.plugins.library.db”

delete from ‘statistics_media’;
delete from ‘statistics_bandwidth’;
vacuum; #This will free the space from the DB file. in my case from 100MB to 30MB

Now my Plex goes smooth, before this it didn’t work most of times.

1 Like
18

now how can a lay men do this who has no clue on how to use sq lite

19

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