Plex Database optimization runs at wrong time

Plex Media Server Metadata & Adding Files
1

Server Version#: v.1.40.1.8227-c0dd5a73e

Within the plex server GUI settings I have maintenance time set to between 5:00 and 6:00.
I figure that means 5am and 6am.

For some reason Plex every day for the past month or so has been doing database optimization around 1:58 PM.

Mar 27, 2024 13:52:48.749 [140412921776952] ERROR - [Req#1be615f] Unable to find client profile for device; platform=windows, platformVersion=10.0.22621, device=, model=Gecko
Mar 27, 2024 13:52:50.375 [140412919667512] INFO - Request: [10.23.122.245:56598 (WAN)] PUT /library/sections/1/emptyTrash (20 live) #1be61a8 TLS GZIP Signed-in Token (gravee) (plex)
Mar 27, 2024 13:52:50.400 [140414874037048] INFO - Completed: [10.23.122.245:56598] 200 PUT /library/sections/1/emptyTrash (20 live) #1be61a8 TLS GZIP 25ms 195 bytes (pipelined: 1)
Mar 27, 2024 13:52:50.411 [140413163436856] INFO - Request: [10.23.122.245:56608 (WAN)] PUT /library/sections/2/emptyTrash (19 live) #1be61ac TLS GZIP Signed-in Token (gravee) (plex)
Mar 27, 2024 13:52:50.499 [140414874037048] INFO - Completed: [10.23.122.245:56608] 200 PUT /library/sections/2/emptyTrash (19 live) #1be61ac TLS GZIP 87ms 195 bytes (pipelined: 1)
Mar 27, 2024 13:52:50.510 [140412888410936] INFO - Request: [10.23.122.245:56614 (WAN)] PUT /library/sections/4/emptyTrash (19 live) #1be61b2 TLS GZIP Signed-in Token (gravee) (plex)
Mar 27, 2024 13:52:50.522 [140414871927608] INFO - Completed: [10.23.122.245:56614] 200 PUT /library/sections/4/emptyTrash (19 live) #1be61b2 TLS GZIP 11ms 195 bytes (pipelined: 1)
Mar 27, 2024 13:52:50.533 [140412921776952] INFO - Request: [10.23.122.245:56618 (WAN)] PUT /library/sections/5/emptyTrash (19 live) #1be61b6 TLS GZIP Signed-in Token (gravee) (plex)
Mar 27, 2024 13:52:50.537 [140414871927608] INFO - Completed: [10.23.122.245:56618] 200 PUT /library/sections/5/emptyTrash (19 live) #1be61b6 TLS GZIP 3ms 195 bytes (pipelined: 1)
Mar 27, 2024 13:52:50.547 [140412930214712] INFO - Request: [10.23.122.245:56624 (WAN)] PUT /library/sections/3/emptyTrash (19 live) #1be61b9 TLS GZIP Signed-in Token (gravee) (plex)
Mar 27, 2024 13:52:50.551 [140414874037048] INFO - Completed: [10.23.122.245:56624] 200 PUT /library/sections/3/emptyTrash (19 live) #1be61b9 TLS GZIP 3ms 195 bytes (pipelined: 1)
Mar 27, 2024 13:52:53.414 [140412934433592] WARN - [Req#1be61bf/Database optimization/com.plexapp.plugins.library.db/DatabaseFixups] Held transaction for too long (/home/runner/actions-runner/_work/plex-media-server/plex-media-server/Library/DatabaseFixups.cpp:222): 4.070000 seconds
Mar 27, 2024 13:52:54.336 [140412934433592] WARN - [Req#1be61bf/Database optimization/com.plexapp.plugins.library.db/DatabaseFixups] Held transaction for too long (/home/runner/actions-runner/_work/plex-media-server/plex-media-server/Library/DatabaseFixups.cpp:357): 1.740000 seconds
Mar 27, 2024 13:52:54.939 [140412934433592] WARN - [Req#1be61bf/Database optimization/com.plexapp.plugins.library.db/DatabaseFixups] Held transaction for too long (/home/runner/actions-runner/_work/plex-media-server/plex-media-server/Library/DatabaseFixups.cpp:390): 1.220000 seconds
Mar 27, 2024 13:53:13.301 [140412934433592] WARN - [Req#1be61bf/Database optimization/com.plexapp.plugins.library.db] Held transaction for too long (/home/runner/actions-runner/_work/plex-media-server/plex-media-server/Library/FullTextSearch.cpp:58): 14.070000 seconds
Mar 27, 2024 13:53:17.987 [140412934433592] WARN - [Req#1be61bf/Database optimization/com.plexapp.plugins.library.db] Held transaction for too long (/home/runner/actions-runner/_work/plex-media-server/plex-media-server/Library/FullTextSearch.cpp:71): 4.030000 seconds
Mar 27, 2024 13:53:46.463 [140412934433592] WARN - [Req#1be61bf/Database optimization/com.plexapp.plugins.library.db] Held transaction for too long (/home/runner/actions-runner/_work/plex-media-server/plex-media-server/Library/FullTextSearch.cpp:81): 28.350000 seconds
Mar 27, 2024 13:54:02.732 [140412934433592] WARN - [Req#1be61bf/Database optimization/com.plexapp.plugins.library.db] Held transaction for too long (/home/runner/actions-runner/_work/plex-media-server/plex-media-server/Library/FullTextSearch.cpp:94): 15.930000 seconds
Mar 27, 2024 13:55:10.188 [140412934433592] INFO - [Req#1be61bf/Database optimization/com.plexapp.plugins.library.db] SQLITE3:0x80000001, 17, statement aborts at 59: [select * from metadata_items limit 1] database schema has changed
Mar 27, 2024 13:55:10.191 [140412934433592] INFO - [Req#1be61bf/Database optimization/com.plexapp.plugins.library.db] SQLITE3:0x80000001, 17, statement aborts at 59: [select * from metadata_items limit 1] database schema has changed
Mar 27, 2024 13:55:10.193 [140412934433592] INFO - [Req#1be61bf/Database optimization/com.plexapp.plugins.library.db] SQLITE3:0x80000001, 17, statement aborts at 59: [select * from metadata_items limit 1] database schema has changed
Mar 27, 2024 13:55:10.196 [140412934433592] INFO - [Req#1be61bf/Database optimization/com.plexapp.plugins.library.db] SQLITE3:0x80000001, 17, statement aborts at 59: [select * from metadata_items limit 1] database schema has changed
Mar 27, 2024 13:55:10.198 [140412934433592] INFO - [Req#1be61bf/Database optimization/com.plexapp.plugins.library.db] SQLITE3:0x80000001, 17, statement aborts at 59: [select * from metadata_items limit 1] database schema has changed
Mar 27, 2024 13:55:10.201 [140412934433592] INFO - [Req#1be61bf/Database optimization/com.plexapp.plugins.library.db] SQLITE3:0x80000001, 17, statement aborts at 59: [select * from metadata_items limit 1] database schema has changed
Mar 27, 2024 13:55:10.203 [140412934433592] INFO - [Req#1be61bf/Database optimization/com.plexapp.plugins.library.db] SQLITE3:0x80000001, 17, statement aborts at 59: [select * from metadata_items limit 1] database schema has changed
Mar 27, 2024 13:55:10.206 [140412934433592] INFO - [Req#1be61bf/Database optimization/com.plexapp.plugins.library.db] SQLITE3:0x80000001, 17, statement aborts at 59: [select * from metadata_items limit 1] database schema has changed
Mar 27, 2024 13:55:10.208 [140412934433592] INFO - [Req#1be61bf/Database optimization/com.plexapp.plugins.library.db] SQLITE3:0x80000001, 17, statement aborts at 59: [select * from metadata_items limit 1] database schema has changed
Mar 27, 2024 13:55:10.211 [140412934433592] INFO - [Req#1be61bf/Database optimization/com.plexapp.plugins.library.db] SQLITE3:0x80000001, 17, statement aborts at 59: [select * from metadata_items limit 1] database schema has changed
Mar 27, 2024 13:55:10.213 [140412934433592] INFO - [Req#1be61bf/Database optimization/com.plexapp.plugins.library.db] SQLITE3:0x80000001, 17, statement aborts at 59: [select * from metadata_items limit 1] database schema has changed
Mar 27, 2024 13:55:10.216 [140412934433592] INFO - [Req#1be61bf/Database optimization/com.plexapp.plugins.library.db] SQLITE3:0x80000001, 17, statement aborts at 59: [select * from metadata_items limit 1] database schema has changed
Mar 27, 2024 13:55:10.218 [140412934433592] INFO - [Req#1be61bf/Database optimization/com.plexapp.plugins.library.db] SQLITE3:0x80000001, 17, statement aborts at 59: [select * from metadata_items limit 1] database schema has changed

I’m using the official Plex docker image, with the docker compose below

#version: "3"
services:
  plex:
    image: plexinc/pms-docker:latest
    container_name: plex
    network_mode: host
    environment:
      - PUID=1000
      - PGID=1000
      - TZ=America/New_York
      - NVIDIA_VISIBLE_DEVICES=all
      - NVIDIA_DRIVER_CAPABILITIES=all
    volumes:
      - /etc/localtime:/etc/localtime:ro
      - /opt/plex/plexmediaserver:/config
      - /opt/plex/PlexDBRepair:/opt/PlexDBRepair
      - /mnt/tv:/mnt/tv
      - /mnt/movies:/mnt/movies
      - /mnt/music:/mnt/music
      - /mnt/homevideos:/mnt/homevideos
      - /mnt/demos:/mnt/demos
      - /mnt/transcode:/mnt/transcode
    restart: unless-stopped
    deploy:
      resources:
        reservations:
          devices:
            - driver: nvidia
              count: 1
              capabilities: [gpu]

All of the logs show correct times, and running ‘date’ on the host VM, and within the docker container gives me the correct date and time.

Why is plex randomly deciding to run these operations in the middle of the day?

2

Just as weird (weirder in my opinion) is that it’s occurring every day; it should only happen once a week as part of scheduled maintenance, not every day:

Screen Shot 2024-03-27 at 3.32.35 PM

Given both of these anomalies, I’d suspect some external trigger occurring. Perhaps a script that runs every day around this time? Via a cron job perhaps, intended to perform some other function but which also optimizes the database via an API call?

You may need to enable debug logging and provide a full server logs as that will show whether or not the optimization is indeed being triggered by the Butler.

1 Like
3

Sometimes writing problems out helps me realize other factors, and exactly what you said came up. I had gone through and validated the configs and timings on scripts like Plex Meta Manager, but the issue was still happening.

After writing this post, I turned everything external off. I’m going to let it run for 24 hours and see if it happens again. Hopefully no and then I can focus in on which specific external tool is the problem.

I will post debug logs if it happens again tomorrow, thank you!

4

You can look in Plex Media Server.log to Plex Media Server.5.log for Butler tasks. That will show you when the maintenance tasks start and stop.

If the tasks do not complete, you might try opening the window further to let Plex clear out the backlog.

Not sure if it will help with the database optimization at undesired times. However, it won’t hurt and it will clear out any backlogged tasks. Also, if your logs do not wrap for several days, you might see the db optimization running in the maintenance window.

I checked the logs on my server. Unfortunately, they wrapped within 24 hours and did not have any database optimization entries.


Example: Maintenance Window is 0300 to 1500.

Start of maintenance window:

Mar 27, 2024 03:01:04.279 [0x746982881b38] DEBUG - Butler: we're in the window, starting.
Mar 27, 2024 03:01:04.279 [0x746982881b38] DEBUG - Butler: Waking up!

Last task finished at 1418:

Mar 27, 2024 14:18:42.140 [0x746982361b38] DEBUG - Butler: Periodic metadata refresh complete (movies: 100, seasons: 1, artists: 0)
Mar 27, 2024 14:18:42.148 [0x746982361b38] DEBUG - Butler: Done doing work.

Window closes at 1500:
Mar 27, 2024 15:01:04.373 [0x74697362bb38] DEBUG - Butler: we're outside the window, stopping.

5

If it is kicked off by the Butler, it should look something like this (from my logs):

Mar 21, 2024 16:01:12.347 [134839212174136] DEBUG - Activity: registered new activity 698b8474-9ee5-4d90-bee7-59d0cc8b79db - "Optimizing database"
Mar 21, 2024 16:01:12.347 [134839212174136] DEBUG - [Database optimization/com.plexapp.plugins.library.db] Optimizing database. Starting by capturing all sessions.
Mar 21, 2024 16:01:12.347 [134839212174136] DEBUG - [Database optimization/com.plexapp.plugins.library.db] Activity: updated activity 698b8474-9ee5-4d90-bee7-59d0cc8b79db - completed 0.0% - Optimizing database
Mar 21, 2024 16:01:12.348 [134839212174136] DEBUG - [Database optimization/com.plexapp.plugins.library.db] Activity: updated activity 698b8474-9ee5-4d90-bee7-59d0cc8b79db - completed 10.0% - Optimizing database
...
Mar 21, 2024 16:01:18.601 [134839212174136] DEBUG - Butler: optimized your database

The ellipsis represents a bunch of optimization messages for all three databases (main, blobs, and EPG in my case).

2 Likes
6

The server performs a shorter variety of database optimization after extensive database changes as well. Like after refreshing metadata of a whole library or adding or removing of a library.

If you use external tools which regularly touch a lot of records in the DB in a short time, you can expect an automatic optimization to happen shortly afterwards.

7

Thanks everyone for the help! It was Plex Meta Manager, I haven’t fully checked up on its config over the months and I guess at some point it started taking nearly 10 hours to complete what ever its doing.

8

Glad you got it figured out!

9

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