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)