Out of Memory (>4GB) during "Butler" tasks

Plex Media Server
1

Server Version#: 1.26.0.5715
Player Version#: Web (but bug not related to playback

I’m noticing a problem with my Plex server crashing with an OOM every 5 minutes at certain times. With some investigation I found it’s always during the 02:00 to 05:00 window of scheduled tasks.

I don’t see any errors in the Plex logs themselves, but with debug level on, I always see it’s at the same point:

First I see:

Apr 26, 2022 04:37:55.598 [0x7fcaf8f4cb38] DEBUG - Butler: we're in the window, starting.
Apr 26, 2022 04:37:55.598 [0x7fcaf8f4cb38] DEBUG - Butler: Waking up!
Apr 26, 2022 04:37:55.598 [0x7fcaf8f4cb38] DEBUG - Butler: Scheduling randomized task 'RefreshEpgGuides' in 48 minutes.
Apr 26, 2022 04:37:55.598 [0x7fcaf8f4cb38] DEBUG - Butler: Scheduling randomized task 'RefreshPeriodicMetadata' in 6 minutes.
Apr 26, 2022 04:37:55.598 [0x7fcaf8f4cb38] DEBUG - Butler: Scheduling randomized task 'ReverseGeocode' in 60 minutes.
Apr 26, 2022 04:37:55.598 [0x7fcaf989bb38] DEBUG - Activity: registered new activity f9fbe672-6f96-44f0-84f3-658d5b6fe9e1 - "Butler tasks"

Then a bunch of stuff, but it always ends with “Running intro detection” for the same show (full snippet below). This pattern happens every 5 minutes, until the scheduled task window is over. It always gets to exactly 98.3%. I don’t know if the code just doesn’t log a final “100%”, or if it just happens to always be causing memory to balloon at 98.3%.

What I’m not clear on is if it’s one particular task that’s causing this, or just all of them building up and not releasing memory. I’m guessing the former, and it’s some combination of the ‘intro detection’ task and this particular media file.

The VM it’s in has 4GB, and usually Plex is only consuming 300MB.

Apr 26, 2022 04:32:15.702 [0x7f834e5eab38] DEBUG - Butler: Scheduling intro marker creation for: 2526
Apr 26, 2022 04:32:15.703 [0x7f834e5eab38] DEBUG - IntroDetector: Running intro detection for [2526] [TV Show redacted] [2]
Apr 26, 2022 04:32:15.703 [0x7f834e5eab38] DEBUG - IntroDetector: Initializing for "" (2527)
Apr 26, 2022 04:32:15.707 [0x7f834e5eab38] DEBUG - Activity: updated activity abdd7a70-f0f9-4771-9941-c4d0879c83dc - completed 90.0% - Butler tasks
Apr 26, 2022 04:32:15.707 [0x7f834e5eab38] DEBUG - IntroDetector: Initializing for "" (2529)
Apr 26, 2022 04:32:15.712 [0x7f834e5eab38] DEBUG - Activity: updated activity abdd7a70-f0f9-4771-9941-c4d0879c83dc - completed 91.1% - Butler tasks
Apr 26, 2022 04:32:15.712 [0x7f834e5eab38] DEBUG - IntroDetector: Initializing for "" (2528)
Apr 26, 2022 04:32:15.717 [0x7f834e5eab38] DEBUG - Activity: updated activity abdd7a70-f0f9-4771-9941-c4d0879c83dc - completed 92.3% - Butler tasks
Apr 26, 2022 04:32:15.717 [0x7f834e5eab38] DEBUG - IntroDetector: Initializing for "" (2530)
Apr 26, 2022 04:32:15.722 [0x7f834e5eab38] DEBUG - Activity: updated activity abdd7a70-f0f9-4771-9941-c4d0879c83dc - completed 93.5% - Butler tasks
Apr 26, 2022 04:32:15.722 [0x7f834e5eab38] DEBUG - IntroDetector: Initializing for "" (2539)
Apr 26, 2022 04:32:15.726 [0x7f834e5eab38] DEBUG - Activity: updated activity abdd7a70-f0f9-4771-9941-c4d0879c83dc - completed 94.7% - Butler tasks
Apr 26, 2022 04:32:15.726 [0x7f834e5eab38] DEBUG - IntroDetector: Initializing for "" (2540)
Apr 26, 2022 04:32:15.731 [0x7f834e5eab38] DEBUG - Activity: updated activity abdd7a70-f0f9-4771-9941-c4d0879c83dc - completed 95.9% - Butler tasks
Apr 26, 2022 04:32:15.731 [0x7f834e5eab38] DEBUG - IntroDetector: Initializing for "" (2545)
Apr 26, 2022 04:32:15.736 [0x7f834e5eab38] DEBUG - Activity: updated activity abdd7a70-f0f9-4771-9941-c4d0879c83dc - completed 97.0% - Butler tasks
Apr 26, 2022 04:32:15.736 [0x7f834e5eab38] DEBUG - IntroDetector: Initializing for "" (2570)
Apr 26, 2022 04:32:15.742 [0x7f834e5eab38] DEBUG - Activity: updated activity abdd7a70-f0f9-4771-9941-c4d0879c83dc - completed 98.2% - Butler tasks
Apr 26, 2022 04:32:15.742 [0x7f834e5eab38] DEBUG - Activity: updated activity abdd7a70-f0f9-4771-9941-c4d0879c83dc - completed 98.3% - Butler tasks
Apr 26, 2022 04:32:19.912 [0x7f834dd19b38] DEBUG - Request: [127.0.0.1:40022 (Loopback)] GET /identity (2 live) Signed-in
Apr 26, 2022 04:32:19.912 [0x7f834e83cb38] DEBUG - Completed: [127.0.0.1:40022] 200 GET /identity (2 live) 0ms 398 bytes (pipelined: 1)
Apr 26, 2022 04:32:25.011 [0x7f834dd19b38] DEBUG - Request: [127.0.0.1:40024 (Loopback)] GET /identity (2 live) Signed-in
Apr 26, 2022 04:32:25.012 [0x7f834e83cb38] DEBUG - Completed: [127.0.0.1:40024] 200 GET /identity (2 live) 0ms 398 bytes (pipelined: 1)
Apr 26, 2022 04:32:30.115 [0x7f834dd19b38] DEBUG - Request: [127.0.0.1:40026 (Loopback)] GET /identity (2 live) Signed-in
Apr 26, 2022 04:32:30.115 [0x7f834e83cb38] DEBUG - Completed: [127.0.0.1:40026] 200 GET /identity (2 live) 0ms 398 bytes (pipelined: 1)
Apr 26, 2022 04:32:35.231 [0x7f834dd19b38] DEBUG - Request: [127.0.0.1:40028 (Loopback)] GET /identity (2 live) Signed-in
Apr 26, 2022 04:32:35.231 [0x7f834e819b38] DEBUG - Completed: [127.0.0.1:40028] 200 GET /identity (2 live) 0ms 398 bytes (pipelined: 1)
Apr 26, 2022 04:32:40.343 [0x7f834dd19b38] DEBUG - Request: [127.0.0.1:40030 (Loopback)] GET /identity (2 live) Signed-in
Apr 26, 2022 04:32:40.344 [0x7f834e819b38] DEBUG - Completed: [127.0.0.1:40030] 200 GET /identity (2 live) 0ms 398 bytes (pipelined: 1)
Apr 26, 2022 04:32:45.459 [0x7f834dd19b38] DEBUG - Request: [127.0.0.1:40032 (Loopback)] GET /identity (2 live) Signed-in
Apr 26, 2022 04:32:45.459 [0x7f834e819b38] DEBUG - Completed: [127.0.0.1:40032] 200 GET /identity (2 live) 0ms 398 bytes (pipelined: 1)
2

I have an open issue on this at the moment

May need to replicate the issue in a debug environment
How many files are involved for the show / episodes having the intro detection leading to the memory usage spikes?
Wondered if there is a way for you to repro the problem with the least number of episodes - to make it feasible to give me the files to reproduce the problem - perhaps copying episodes to a new test library and then waiting for intro detection

Does the problem also arise when media is added - if you have the option to add intro markers when media is added ?

1 Like
4

Thanks for your response @sa2000

I think the first thing to do is narrow down which ‘Butler’ task is causing this.

Am I correct in thinking it must be one of these three?

Apr 26, 2022 04:37:55.598 [0x7fcaf8f4cb38] DEBUG - Butler: Scheduling randomized task 'RefreshEpgGuides' in 48 minutes.
Apr 26, 2022 04:37:55.598 [0x7fcaf8f4cb38] DEBUG - Butler: Scheduling randomized task 'RefreshPeriodicMetadata' in 6 minutes.
Apr 26, 2022 04:37:55.598 [0x7fcaf8f4cb38] DEBUG - Butler: Scheduling randomized task 'ReverseGeocode' in 60 minutes.

If so - can I kick those off individually from the command line?

EDIT

Also - is there a reason I’m not see a 100% log like:

 Activity: updated activity abdd7a70-f0f9-4771-9941-c4d0879c83dc - completed 98.3%

Or does it just not bother logging the final 100% status?

6

No. It is a sub task that gets run when the library setting has the preference

image

The sub task would query the database and result in log lines - like these

DEBUG - Butler: Upgrading intro detection for xxx items
DEBUG - Butler: Performing new intro detection for xxx items

DEBUG - Butler: Scheduling intro marker creation for: xxxxx
DEBUG - IntroDetector: Running intro detection for [xxxx] [xxxxxxxxxxx] [x]
7

Thanks @sa2000

Is there a way to manually kick-off intro detection, perhaps from the command line?

EDIT - I realised I could just go to the show and click “Analyse”.

Sure enough, it fails the same way. This is the full log:

May 13, 2022 15:31:35.390 [0x7f6a307e5b38] DEBUG - [JobRunner] Job running: FFMPEG_EXTERNAL_LIBS='/config/Library/Application\ Support/Plex\ Media\ Server/Codecs/994f4ee-4285-linux-x86_64/' X_PLEX_TOKEN=xxxxxxxxxxxxxxxxxxxx "/usr/lib/plexmediaserver/Plex Media Scanner" --analyze --manual --server-action intro --item 2526 --log-file-suffix " Analysis"
May 13, 2022 15:31:35.390 [0x7f6a307e5b38] DEBUG - [JobRunner] Jobs: Starting child process with pid 1017
May 13, 2022 15:31:40.819 [0x7f6a31aaab38] DEBUG - Created thumbnail of size 360x203, has pixels: 1
May 13, 2022 15:31:40.822 [0x7f6a30da9b38] DEBUG - Completed: [192.168.1.236:53079] 200 GET /photo/:/transcode?width=360&height=202&minSize=1&upscale=1&url=%2Flibrary%2Fmetadata%2F2528%2Fthumb%2F1652452296%3FX-Plex-Token%3Dxxxxxxxxxxxxxxxxxxxx (8 live) GZIP 129ms 12562 bytes (pipelined: 1)
May 13, 2022 15:31:40.830 [0x7f6a30b57b38] DEBUG - Calculated media file path for path [metadata://posters/tv.plex.agents.series_93eb2bcec27ffe91cf997e898c0f89b069c99175]: ["/config/Library/Application Support/Plex Media Server/Metadata/TV Shows/7/ece11dcb33ef37f8226c4aae3a5ac229023b339.bundle/Contents/_combined/posters/tv.plex.agents.series_93eb2bcec27ffe91cf997e898c0f89b069c99175"]
May 13, 2022 15:31:40.830 [0x7f6a30b57b38] DEBUG - Calling back into ourselves for photo to transcode, optimizing the process (status: -1)
May 13, 2022 15:31:40.831 [0x7f6a30b57b38] DEBUG - Photo cache obtained 648641 bytes from /library/metadata/2570/thumb/1652452298?X-Plex-Token=xxxxxxxxxxxxxxxxxxxx
May 13, 2022 15:31:40.831 [0x7f6a30b57b38] DEBUG - Saving original media file to /config/Library/Application Support/Plex Media Server/Cache/PhotoTranscoder/28/2838184c122cb1d03d51adc51ad04658cdc53abe.jpg
May 13, 2022 15:31:40.843 [0x7f6a31a47b38] DEBUG - Created thumbnail of size 360x203, has pixels: 1
May 13, 2022 15:31:40.847 [0x7f6a30da9b38] DEBUG - Completed: [192.168.1.236:53080] 200 GET /photo/:/transcode?width=360&height=202&minSize=1&upscale=1&url=%2Flibrary%2Fmetadata%2F2530%2Fthumb%2F1652452297%3FX-Plex-Token%3Dxxxxxxxxxxxxxxxxxxxx (8 live) GZIP 152ms 6357 bytes (pipelined: 1)
May 13, 2022 15:31:40.848 [0x7f6a30aa5b38] DEBUG - Created thumbnail of size 360x203, has pixels: 1
May 13, 2022 15:31:40.859 [0x7f6a30da9b38] DEBUG - Completed: [192.168.1.236:53081] 200 GET /photo/:/transcode?width=360&height=202&minSize=1&upscale=1&url=%2Flibrary%2Fmetadata%2F2540%2Fthumb%2F1652452297%3FX-Plex-Token%3Dxxxxxxxxxxxxxxxxxxxx (8 live) GZIP 164ms 14815 bytes (pipelined: 1)
May 13, 2022 15:31:40.861 [0x7f6a31a24b38] DEBUG - Created thumbnail of size 360x203, has pixels: 1
May 13, 2022 15:31:40.865 [0x7f6a30da9b38] DEBUG - Completed: [192.168.1.236:53082] 200 GET /photo/:/transcode?width=360&height=202&minSize=1&upscale=1&url=%2Flibrary%2Fmetadata%2F2545%2Fthumb%2F1652452297%3FX-Plex-Token%3Dxxxxxxxxxxxxxxxxxxxx (8 live) GZIP 169ms 16439 bytes (pipelined: 1)
May 13, 2022 15:31:40.918 [0x7f6a30b57b38] DEBUG - Created thumbnail of size 360x203, has pixels: 1
May 13, 2022 15:31:40.921 [0x7f6a30da9b38] DEBUG - Completed: [192.168.1.236:53076] 200 GET /photo/:/transcode?width=360&height=202&minSize=1&upscale=1&url=%2Flibrary%2Fmetadata%2F2570%2Fthumb%2F1652452298%3FX-Plex-Token%3Dxxxxxxxxxxxxxxxxxxxx (8 live) GZIP 102ms 14107 bytes (pipelined: 4)
May 13, 2022 15:31:45.299 [0x7f6a307e5b38] DEBUG - Request: [127.0.0.1:49320 (Loopback)] GET /identity (9 live) Signed-in / Accept => */* / Host => localhost:32400 / User-Agent => curl/7.68.0
May 13, 2022 15:31:45.299 [0x7f6a307e5b38] VERBOSE - It took 0.0 sec to serialize a list with 0 elements.
May 13, 2022 15:31:45.299 [0x7f6a30da9b38] DEBUG - Completed: [127.0.0.1:49320] 200 GET /identity (9 live) 0ms 398 bytes (pipelined: 1)
May 13, 2022 15:31:45.299 [0x7f6a30d86b38] VERBOSE - Didn't receive a request from 127.0.0.1:49320: End of file
May 13, 2022 15:31:47.459 [0x7f6a30da9b38] VERBOSE - WebSocket: processed 1 frame(s)
May 13, 2022 15:31:50.411 [0x7f6a31aaab38] DEBUG - Request: [127.0.0.1:49322 (Loopback)] GET /identity (9 live) Signed-in / Accept => */* / Host => localhost:32400 / User-Agent => curl/7.68.0
May 13, 2022 15:31:50.411 [0x7f6a31aaab38] VERBOSE - It took 0.0 sec to serialize a list with 0 elements.
May 13, 2022 15:31:50.411 [0x7f6a30da9b38] DEBUG - Completed: [127.0.0.1:49322] 200 GET /identity (9 live) 0ms 398 bytes (pipelined: 1)
May 13, 2022 15:31:50.411 [0x7f6a30d86b38] VERBOSE - Didn't receive a request from 127.0.0.1:49322: End of file
May 13, 2022 15:32:05.775 [0x7f6a31aaab38] DEBUG - Request: [127.0.0.1:49328 (Loopback)] GET /identity (3 live) Signed-in / Accept => */* / Host => localhost:32400 / User-Agent => curl/7.68.0
May 13, 2022 15:32:05.775 [0x7f6a31aaab38] VERBOSE - It took 0.0 sec to serialize a list with 0 elements.
May 13, 2022 15:32:05.775 [0x7f6a30da9b38] DEBUG - Completed: [127.0.0.1:49328] 200 GET /identity (3 live) 0ms 398 bytes (pipelined: 1)
May 13, 2022 15:32:05.775 [0x7f6a30d86b38] VERBOSE - Didn't receive a request from 127.0.0.1:49328: End of file
May 13, 2022 15:32:07.491 [0x7f6a30d86b38] VERBOSE - WebSocket: processed 1 frame(s)

At which point the container blows up with:

[  406.866566] mosquitto invoked oom-killer: gfp_mask=0x100cca(GFP_HIGHUSER_MOVABLE), order=0, oom_score_adj=0
[  406.866571] CPU: 1 PID: 2414 Comm: mosquitto Tainted: P           O      5.13.19-6-pve #1
...
[  406.866807] oom-kill:constraint=CONSTRAINT_MEMCG,nodemask=(null),cpuset=docker-6df9f61ac045f2df766fdac25d99a95fd2243f2cfe18f5d5701b27974aeb7b97.scope,mems_allowed=0,oom_memcg=/lxc/105,task_memcg=/lxc/105/ns/system.slice/docker-88e9743c1c73dbf4bf8aec47d3da12dcb74035f4096245f6a7b30daf182a7733.scope,task=Plex Media Serv,pid=3685,uid=101000
[  406.866838] Memory cgroup out of memory: Killed process 3685 (Plex Media Serv) total-vm:6400408kB, anon-rss:3645016kB, file-rss:0kB, shmem-rss:4kB, UID:101000 pgtables:8220kB oom_score_adj:0
[  406.961806] oom_reaper: reaped process 3685 (Plex Media Serv), now anon-rss:0kB, file-rss:0kB, shmem-rss:4kB
8

@sa2000 Some more details. I’ve narrowed it down to one show, by hitting ‘analyse’ on that in the UI.

Then I watch the processes, ordered by memory. Sure enough in the course of less than 30 seconds, it fills all 4 gigs, and then my container manager kills it.

Screenshot 2022-05-13 at 15.42.29
Screenshot 2022-05-13 at 15.42.291416×227 42.2 KB

Just out of interest, I doubled the container’s memory to 8GB, and after 2 or 3 minutes, the intro detection completed without killing the container.

I then looked at the show, and noticed two curious things:

  1. The ‘Skip Intro’ button doesn’t appear until 9.5 minutes into the show, and is shown for a whole two minutes. It’s also in the wrong place.

  2. This show has highly irregular intro-placement, both in terms of style and placement in the program.

So perhaps this is just an edge case?

9

Thanks for the investigation - could be edge cases as you say

But what i need is some files to repro the problem with - it needs to be the least number of episodes to highlight the problem when added to a new test library without pre-existing intro detection data in the database and smallest size - so may need to convert the files and repro the problem and then let me have the files

10

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