PMS causes 100% RAM usage when any episode added to one specific series

Plex Media Server Desktops & Laptops
1

Server Version#: 1.31.1.6733
Player Version#: N/A

Got a weird one. Have PMS running in a TrueNAS 13.0-U4 jail (manual install, not plugin), and have come across something that reliably cripples my NAS. If I add anything new to just my South Park series in my TV library and do a library scan, PMS instantly sucks up all of my RAM (32GB + a bunch of Swap) and causes the box to be almost completely unresponsive (having PMS service crash would be a good thing in this case, because otherwise it gets to the point where it starts taking out TrueNAS services to the point where I can’t even access the web GUI).

Yesterday I had added the latest episodes of South Park and Poker Face and noticed that scanning never seemed to actually end, the Activity dialog said it was scanning the Poker Face episode for what seemed like forever and my NAS was acting funny. Came back this morning to troubleshoot in earnest. First I disabled Intro + Credit scanning, no change. Then I moved the PF file out of the library, no change. Then I took the SP file out, server is happy again. Put PF back, picked up normally (TrueNAS showed a brief spike in RAM and CPU usage, but none of those got pegged), everything’s happy. Put SP back, bad things started happening again. And then things got weird.

It has nothing to do with the file itself, as I’ve tried remuxing/stream fixing to no avail. Then I copied another episode in the library (which plays back just fine) and renamed it to the new one, still failed, proving it’s nothing to do with the actual file. Then I did the same thing, but naming it to a Special I didn’t have in the library, fail. So nothing to do with the metadata. Did an Optimize Database for kicks, nada. About the only thing I haven’t done is roll back to a previous version, would prefer to hold off doing that just in case it needs to stay where it is for further debugging.

Attached are the log zips from after my last failed scan after doing the Optimize Database.
Plex Media Server Logs_2023-03-03_11-40-45.zip (962.0 KB)

2

This is an interesting one… Sounds like you tried the right things. I can’t help but I am here to see the resolution!

3

It’s a memory leak in the code of PMS. This software eats RAM and swap space like it’s nothing over time. For over a year now all PMS does is fill up RAM and swap and I have the LibreNMS graphs to prove it.

This is also a contributing factor on why this software is nowhere near secure.

4

Quick update: added a show to another series without incident, so it’s not like I came across some arbitrary entry limit for the entire library, and it’s certainly not a limit of entries in a series because said series I added to was the Simpsons, which has more than double the number of files than my South Park directory.

As a sanity check afterwards I tried adding the SP episode back and scanning, got the runaway RAM usage problem once again (and this time I was too slow to stop the PMS service/jail and had to completely restart my NAS).

Still holding off on downgrading for the time being.

5

Upgraded to 1.31.1.6782, still failed. Finally downgraded to 1.31.0.6654, problem went away. Something definitely broke between 1.31.0.6654 and 1.31.1.6733.

6

Still broken in 1.31.2.6810

7

I too have South Park on my PMS and a good number of episodes. 26 seasons and 323 episodes currently. I have not noticed an issue like this. Has this problem always existed for SP for you or has the issue just started happening recently? What is your current media scanner set to, the legacy scanner or the new Plex TV Shows? Have you tried changing scanners to see if that makes a difference? (NOTE: If you choose to revert to using the legacy scanner, it is possible that you may not be able to go back without deleting the library and adding it back. I read that you are supposed to get an option to convert library to use the Plex TV Shows scanner but this option never appeared for me, so I ultimately ended up having to deleting the TV Shows library and adding it back) Another thing to try would be to move the entire SP series to a folder that is not monitored by Plex. Scan the library and let it remove the show. Then move SP back to the monitored folder and scan then scan again. If that works it would eliminate the need to mess with the rest of the shows in the library.

8

Issue only cropped up when I upgraded to 1.31.1.6733
Every other series I’ve added media to since this issue first appeared has not been affected
Re-upgraded to 1.31.2.6810, moved the entire folder out of the library directory, scanned, put it back in, re-scanned, still failed.
Using the Plex TV Series scanner and agent, the edit dialog box says I haven’t touched those settings in a year. Switching back to the old Plex Series Scanner/TheTVDB agent does work, at least as far as not nuking my system goes, as it added all the entries just fine but didn’t display any metadata (probably because of a mix of new/old scanner setups). Switching back to the TV Series agent and re-scanning insta-fails again, so it has to be something regarding the scanner.

Gonna stick with 1.31.0.6654 for the time being.

9

There are at least two other recent threads regarding weirdness with the plex scanner. Certainly feels like a regression but so far I’ve been unable to pinpoint a cause or get it working as it did a few weeks back :weary:

10

I updated yesterday and it’s been crashing multiple times a day now. This must be the issue.

11

For any issues with memory usage by the Plex Media Server process, please run with the setting to log memory usage - see this support article Advanced, Hidden Server Settings | Plex Support

The setting to be added is LogMemoryUse with a value of 1

When the issue arises, please capture the server logs

We did resolve an issue causing excessive memory use during Intro Detection - the fix was released sometime ago - so this must be a different problem

If there is a specific episode file that gives rise to this - then would also need to get a copy - zipped and uploaded to dropbox/google drive etc and private message with a link sent to me and referencing the post with the logs with the LogMemoryUse setting

Please use the latest beta or public release when providing the diagnostics

At this time - that is
Public 1.31.2.6810-a607d384f
Beta 1.31.3.6819-2ef591a4c

12

With this option enabled, the library scan seems to stop at my podcast library with m4a files, causing the entire server to lock up. The memory does not go above 550 or so megabytes.

Edit: It seems like after a few minutes it continues, now with 200mb more memory used. It has never been this slow scanning m4a files before.

Edit 2: Now it crashed, rising rapidly.

Mar 20, 2023 17:06:03.939 [0x8097c4000] DEBUG - Skipping over directory '[REDACTED]', as nothing has changed; removing 3 media items from map.
Mar 20, 2023 17:06:03.940 [0x8097c4000] DEBUG - Activity: updated activity 770b83a7-dd59-4354-83e2-b04ef416f098 - completed 95.2% - Scanning Svensk TV (Memory Usage: 868.0 MB/16037.0 MB)
Mar 20, 2023 17:06:03.940 [0x8097c4000] DEBUG - Scanner: Processing directory [REDACTED] (parent: yes)
Mar 20, 2023 17:06:03.979 [0x8097c4000] DEBUG - Directory had 11 files, database had 10 files, can't skip.
Mar 20, 2023 17:06:04.497 [0x807788000] DEBUG - Auth: authenticated user [REDACTED] as [REDACTED]
Mar 20, 2023 17:06:04.497 [0x811487500] DEBUG - Request: [[REDACTED] (WAN)] GET /:/websockets/notifications (30 live) #abf63 TLS GZIP Signed-in Token ([REDACTED]) (Memory Usage: 1553.0 MB/16726.0 MB)
Mar 20, 2023 17:06:04.497 [0x811487500] DEBUG - WebSocket: Performing handshake from origin
Mar 20, 2023 17:06:04.497 [0x811487500] DEBUG - Beginning read from WebSocket
Mar 20, 2023 17:06:05.552 [0x8076d9b00] DEBUG - Auth: authenticated user [REDACTED] as [REDACTED]
Mar 20, 2023 17:06:05.552 [0x811487500] DEBUG - Request: [127.0.0.1:18615 (WAN)] GET /video/:/transcode/universal/ping?session=xj1eyluqwesmwwh7cwibeed0 (30 live) #ab4f9 TLS GZIP Signed-in Token ([REDACTED]) (Memory Usage: 2966.0 MB/18151.0 MB)
Mar 20, 2023 17:06:05.552 [0x811487500] WARN - [Req#ab4f9/Transcode] Got a transcode session ping without a valid session ID.
Mar 20, 2023 17:06:05.552 [0x8076d9b00] DEBUG - Completed: [127.0.0.1:18615] 404 GET /video/:/transcode/universal/ping?session=xj1eyluqwesmwwh7cwibeed0 (30 live) #ab4f9 TLS GZIP 0ms 504 bytes (pipelined: 83) (Memory Usage: 2966.0 MB/18151.0 MB)
Mar 20, 2023 17:06:05.633 [0x807788000] DEBUG - Auth: authenticated user [REDACTED] as [REDACTED]
Mar 20, 2023 17:06:05.634 [0x8124f8900] DEBUG - Request: [127.0.0.1:18615 (WAN)] GET /:/timeline?key=%2Flibrary%2Fmetadata%2F286428&ratingKey=286428&state=paused&time=2060332&duration=4538560&playbackTime=2247758&playQueueItemID=1027710&context=source%3Ahub.tv.recentlyaired&row=0&col=13 (30 live) #b247c TLS GZIP Signed-in Token ([REDACTED]) (Memory Usage: 3076.0 MB/18259.0 MB)
Mar 20, 2023 17:06:05.634 [0x8124f8900] DEBUG - [Req#b247c] Client [4xfellyf9dvwc37pc661ol6u] reporting timeline state paused, progress of 2060332/4538560ms for guid=, playbackTime=2247758ms ratingKey=286428 url=, key=/library/metadata/286428, containerKey=, metadataId=286428, source=
Mar 20, 2023 17:06:05.637 [0x8124f8900] DEBUG - [Req#b247c] [Now] User is [REDACTED] (ID: [REDACTED])
Mar 20, 2023 17:06:05.637 [0x8124f8900] DEBUG - [Req#b247c] [Now] Device is PlayStation (PS4-021).
Mar 20, 2023 17:06:05.638 [0x8124f8900] ERROR - [Req#b247c] Unable to find client profile for device; platform=PlayStation, platformVersion=v2.9.1-0-g0c0e2d4b SDK: (0x09008001u), Built: Feb  4 2022 12:53:47, device=PlayStation 4, model=PlayStation 4 Pro
Mar 20, 2023 17:06:05.638 [0x8124f8900] DEBUG - [Req#b247c] [Now] Updated play state for /library/metadata/286428.
Mar 20, 2023 17:06:05.638 [0x8124f8900] DEBUG - [Req#b247c] Statistics: (4xfellyf9dvwc37pc661ol6u) Reporting active playback in state 1 of type 4 (scrobble: 0) for account [REDACTED]
Mar 20, 2023 17:06:05.639 [0x8076d9b00] DEBUG - Completed: [127.0.0.1:18615] 200 GET /:/timeline?key=%2Flibrary%2Fmetadata%2F286428&ratingKey=286428&state=paused&time=2060332&duration=4538560&playbackTime=2247758&playQueueItemID=1027710&context=source%3Ahub.tv.recentlyaired&row=0&col=13 (30 live) #b247c TLS GZIP 5ms 583 bytes (pipelined: 84) (Memory Usage: 3084.0 MB/18266.0 MB)
Mar 20, 2023 17:06:05.644 [0x811487f00] DEBUG - Request: [10.0.0.11:9106 (Allowed Network (Subnet))] GET /status/sessions (30 live) #adc76 TLS GZIP Signed-in Token ([REDACTED]) (Firefox) (Memory Usage: 3090.0 MB/18272.0 MB)
Mar 20, 2023 17:06:05.644 [0x811487f00] DEBUG - [Req#adc76] [Now] Adding 1 sessions.
Mar 20, 2023 17:06:05.644 [0x807788000] DEBUG - Completed: [10.0.0.11:9106] 200 GET /status/sessions (30 live) #adc76 TLS GZIP 0ms 475 bytes (pipelined: 36) (Memory Usage: 3090.0 MB/18273.0 MB)
Mar 20, 2023 17:06:05.657 [0x810066500] DEBUG - Request: [10.0.0.46:62946 (Allowed Network (Subnet))] GET /status/sessions (31 live) #b247b TLS GZIP Signed-in Token ([REDACTED]) (tautulli) (Memory Usage: 3108.0 MB/18291.0 MB)
Mar 20, 2023 17:06:05.657 [0x810066500] DEBUG - [Req#b247b] [Now] Adding 1 sessions.
Mar 20, 2023 17:06:05.657 [0x807788000] DEBUG - Completed: [10.0.0.46:62946] 200 GET /status/sessions (31 live) #b247b TLS GZIP 0ms 397 bytes (pipelined: 1) (Memory Usage: 3108.0 MB/18291.0 MB)
Mar 20, 2023 17:06:06.030 [0x80b5c5e00] DEBUG - Request: [10.0.0.46:16718 (Allowed Network (Subnet))] GET /status/sessions (31 live) #b248b TLS GZIP Signed-in Token ([REDACTED]) (tautulli) (Memory Usage: 3613.0 MB/18799.0 MB)
Mar 20, 2023 17:06:06.030 [0x80b5c5e00] DEBUG - [Req#b248b] [Now] Adding 1 sessions.
Mar 20, 2023 17:06:06.031 [0x807788000] DEBUG - Completed: [10.0.0.46:16718] 200 GET /status/sessions (31 live) #b248b TLS GZIP 0ms 397 bytes (pipelined: 1) (Memory Usage: 3614.0 MB/18799.0 MB)
Mar 20, 2023 17:06:16.325 [0x8124f7500] DEBUG - Request: [10.0.0.46:23731 (Allowed Network (Subnet))] GET /status/sessions (28 live) #b248e TLS GZIP Signed-in Token ([REDACTED]) (tautulli) (Memory Usage: 17091.0 MB/30903.0 MB)
Mar 20, 2023 17:06:16.325 [0x8124f7500] DEBUG - [Req#b248e] [Now] Adding 1 sessions.
Mar 20, 2023 17:06:16.325 [0x807788000] DEBUG - Completed: [10.0.0.46:23731] 200 GET /status/sessions (28 live) #b248e TLS GZIP 0ms 397 bytes (pipelined: 1) (Memory Usage: 17092.0 MB/30904.0 MB)
Mar 20, 2023 17:06:20.698 [0x807788000] DEBUG - Auth: authenticated user [REDACTED] as [REDACTED]
Mar 20, 2023 17:06:20.703 [0x8124f7500] DEBUG - Request: [127.0.0.1:18615 (WAN)] GET /:/timeline?key=%2Flibrary%2Fmetadata%2F286428&ratingKey=286428&state=paused&time=2060332&duration=4538560&playbackTime=2247758&playQueueItemID=1027710&context=source%3Ahub.tv.recentlyaired&row=0&col=13 (21 live) #b2489 TLS GZIP Signed-in Token ([REDACTED]) (Memory Usage: 17692.0 MB/30993.0 MB)
Mar 20, 2023 17:06:20.704 [0x8124f7500] DEBUG - [Req#b2489] Client [4xfellyf9dvwc37pc661ol6u] reporting timeline state paused, progress of 2060332/4538560ms for guid=, playbackTime=2247758ms ratingKey=286428 url=, key=/library/metadata/286428, containerKey=, metadataId=286428, source=
13

Chiming in to add that this exact ramp-up was happening to me, but on install. 1.21. So it definitely exists.

However I was unsuccessful for different reasons. I attempted an update, but the updater failed when trying to uninstall what it claims to see an existing 32-bit version.
I’ll open a new thread on this, because I cannot do a manual uninstall, cannot find a comprehensive list of installed files, and no longer have a functioning server.

14

I found the issue (for me at least), it’s an FLV file that’s causing this. When I remove it, all is well.

15

As I stated, it’s not a specific file that’s causing my issue, it’s anything new gets added to just this specific series that causes PMS to choke.

I’ve attached a log after upgrading to v1.31.2.6810-a607d384f and turning on the LogMemoryUse preference, but the log doesn’t show anything abnormal. The last entry before I had to kill the service listed the memory usage as 715MB out of >16GB, but the TrueNAS reports page showed that basically all 32GB was being eaten up (after rolling back the PMS install and starting the service it says I have 27.3GB free sitting idle). The only other log file that got updated during this test was the Tuner Service one, and all it says is “I started up” and “I’m shutting down”.

Plex Media Server.log (561.7 KB)

16

Were these log lines filtered out or do they follow each other

Mar 20, 2023 17:06:06.031 [0x807788000] DEBUG - Completed: [10.0.0.46:16718] 200 GET /status/sessions (31 live) #b248b TLS GZIP 0ms 397 bytes (pipelined: 1) (Memory Usage: 3614.0 MB/18799.0 MB)
Mar 20, 2023 17:06:16.325 [0x8124f7500] DEBUG - Request: [10.0.0.46:23731 (Allowed Network (Subnet))] GET /status/sessions (28 live) #b248e TLS GZIP Signed-in Token ([REDACTED]) (tautulli) (Memory Usage: 17091.0 MB/30903.0 MB)

usage by PMS process jumped from 3614 Mb to 17091 Mb

would like to see full logs and have the flv file if possible - zipped and sent by private message

17

I did not remove any lines, only edited out sensitive information.

I will see what I can do, it’s a gigabyte big.

18

Thanks for the log. You are running on FreeBSD which has issue with our memory usage logging.

image
image1247Ă—315 25 KB

The log shows a scan starting for the TV Shows library but did not seem to go beyond the last log line for the scan

Mar 20, 2023 14:19:34.063 [0x80b42d100] DEBUG - Activity: updated activity 18e509c6-ef32-4701-a4ac-53be0217a5ca - completed 0.0% - Scanning TV Shows (Memory Usage: 132.0 MB/17797.0 MB)
Mar 20, 2023 14:19:34.074 [0x80b42d100] DEBUG - Asked to cull library timeline before time 1679335174, we're starting with 0 items.
Mar 20, 2023 14:19:34.074 [0x80b42d100] DEBUG - Library timeline cull complete with 0 items left.
Mar 20, 2023 14:19:34.075 [0x80b42d100] DEBUG - Scanning TV Shows using en-US(Plex TV Series) with 9651 current media items and 2 section locations in the database.
Mar 20, 2023 14:19:34.075 [0x80b42d100] DEBUG - Performing a scan with 'Plex TV Series' (language: en-US virtual: 0).
Mar 20, 2023 14:19:34.075 [0x80b42d100] DEBUG -   * Scanning /media/Shows
Mar 20, 2023 14:19:34.075 [0x80b42d100] DEBUG - Scanner: Processing directory /media/Shows (parent: no)
Mar 20, 2023 14:19:34.079 [0x80b42d100] DEBUG - Skipping over directory '', as nothing has changed; removing 0 media items from map.
Mar 20, 2023 14:19:34.082 [0x80b42d100] DEBUG - Scanner: Processing directory /media/Shows/South Park (parent: yes)
Mar 20, 2023 14:19:34.091 [0x80b42d100] DEBUG - Directory had 334 files, database had 333 files, can't skip.

Is the issue arising whenever the TV Shows library is scanned ?

and is it only showing on specific versions of Plex Media Server ? Which versions are ok and which show the problem?

Will need more examples (logs) of the issue and also logs from version where it is ok
Can you get memory usage figures from the TrueNAS report to show the time and memory used - to correlate to what the logs show ?

19

Was the flv file within this directory or library?

Mar 20, 2023 17:06:03.939 [0x8097c4000] DEBUG - Skipping over directory '[REDACTED]', as nothing has changed; removing 3 media items from map.
Mar 20, 2023 17:06:03.940 [0x8097c4000] DEBUG - Activity: updated activity 770b83a7-dd59-4354-83e2-b04ef416f098 - completed 95.2% - Scanning Svensk TV (Memory Usage: 868.0 MB/16037.0 MB)
Mar 20, 2023 17:06:03.940 [0x8097c4000] DEBUG - Scanner: Processing directory [REDACTED] (parent: yes)
Mar 20, 2023 17:06:03.979 [0x8097c4000] DEBUG - Directory had 11 files, database had 10 files, can't skip.

You can send me the full server logs zip by Private Message - need to see the start of the scan and if the flv is mentioned at all - verbose logging may add some more info

Hopefully can repro with the actual file

20

It was, yes. I will get back to it when I have access to the file.