Database size increasing significantly above the ~100MB Expectation

dirtycajunrice · March 7, 2018, 6:08pm

Its only been 2 weeks since I last spoke with ChuckPA in this post showing that the database shouldn’t exceed 100MB or so for what i have and the DB is already 1.4G And the jump was within 5 days. This verifies it didn’t just crap the bed a while back. What the heck could possibly be going on? Below is the Debug logs during a database optimization, a bundle clean and a trash removal:

du -h com.plexapp.plugins.library.db*
1.4G    com.plexapp.plugins.library.db
153M    com.plexapp.plugins.library.db-2018-02-27
1.4G    com.plexapp.plugins.library.db-2018-03-02
1.4G    com.plexapp.plugins.library.db-2018-03-05
12M     com.plexapp.plugins.library.db-shm
1.5G    com.plexapp.plugins.library.db-wal

Mar 07, 2018 12:15:53.240 [0x7f7732ffe700] DEBUG - Auth: authenticated user 1 as redacted
Mar 07, 2018 12:15:53.241 [0x7f7706bfd700] DEBUG - Request: [10.0.0.3:62858 (WAN)] PUT /library/optimize?async=1 (19 live) TLS GZIP Signed-in Token (redacted)
Mar 07, 2018 12:15:53.244 [0x7f7706bfd700] DEBUG - Activity: registered new activity bbdf4ccb-67a9-4a9f-8330-3ebca6d19123 - Optimizing database
Mar 07, 2018 12:15:53.245 [0x7f76f3bfb700] DEBUG - Database optimization: Optimizing database. Starting by capturing all sessions.
Mar 07, 2018 12:15:53.245 [0x7f76f3bfb700] DEBUG - Activity: updated activity bbdf4ccb-67a9-4a9f-8330-3ebca6d19123 - completed 0% - Optimizing database
Mar 07, 2018 12:15:53.246 [0x7f7732ffe700] DEBUG - Completed: [10.0.0.3:62858] 200 PUT /library/optimize?async=1 (19 live) TLS GZIP 5ms 268 bytes (pipelined: 1)
Mar 07, 2018 12:15:53.246 [0x7f76f3bfb700] DEBUG - Activity: updated activity bbdf4ccb-67a9-4a9f-8330-3ebca6d19123 - completed 10% - Optimizing database
Mar 07, 2018 12:15:53.247 [0x7f76f3bfb700] DEBUG - Running database fix-ups.
Mar 07, 2018 12:15:53.829 [0x7f77337ff700] DEBUG - Auth: authenticated user 1 as redacted
Mar 07, 2018 12:15:53.830 [0x7f76ecbfe700] DEBUG - Request: [10.0.10.105:37996 (Subnet)] GET /status/sessions (20 live) Signed-in Token (redacted)
Mar 07, 2018 12:15:53.957 [0x7f76f3bfb700] WARN - Held transaction for too long (../Library/DatabaseFixups.cpp:191): 1.440000 seconds
Mar 07, 2018 12:15:53.965 [0x7f76f3bfb700] DEBUG - Running database fix-ups completed in 1.5 seconds.
Mar 07, 2018 12:15:53.965 [0x7f76f3bfb700] DEBUG - Captured session 0.
(repeat 1-18)
Mar 07, 2018 12:15:56.215 [0x7f772b3fe700] DEBUG - HubCache: Computed '1/home.ondeck/hubs/12/en' in 23662 ms.
Mar 07, 2018 12:15:56.216 [0x7f772b3fe700] DEBUG - HubCache: Retrieving '1/home.movies.recent/hubs/12/en' from the cache.
Mar 07, 2018 12:15:56.217 [0x7f772b3fe700] DEBUG - HubCache: Adding '1/home.television.recent/hubs/12/en' to the cache (1/home.television.recent/hubs/12/en).
Mar 07, 2018 12:15:56.219 [0x7f772b3fe700] ERROR - QueryParser: Invalid field 'onlyTransient' found, ignoring.
Mar 07, 2018 12:15:56.239 [0x7f772b3fe700] DEBUG - It took 10.000000 ms to retrieve 200 items.
Mar 07, 2018 12:15:56.314 [0x7f772b3fe700] DEBUG - It took 70.000000 ms to retrieve 50 items.
Mar 07, 2018 12:15:56.368 [0x7f772b3fe700] DEBUG - HubCache: Computed '1/home.television.recent/hubs/12/en' in 150 ms.
Mar 07, 2018 12:15:56.369 [0x7f772b3fe700] DEBUG - HubCache: Retrieving '1/home.videos.recent/hubs/12/en' from the cache.
Mar 07, 2018 12:15:56.369 [0x7f772b3fe700] DEBUG - HubCache: Retrieving '1/home.photos.recent/hubs/12/en' from the cache.
Mar 07, 2018 12:15:56.370 [0x7f772b3fe700] DEBUG - HubCache: Retrieving '1/home.music.recent/hubs/12/en' from the cache.
Mar 07, 2018 12:15:56.370 [0x7f76f3bfb700] DEBUG - Captured session 19.
Mar 07, 2018 12:15:56.370 [0x7f76f3bfb700] DEBUG - Database optimization: Rebuilding full text search tables.
Mar 07, 2018 12:15:56.371 [0x7f76f3bfb700] DEBUG - Activity: updated activity bbdf4ccb-67a9-4a9f-8330-3ebca6d19123 - completed 40% - Optimizing database
Mar 07, 2018 12:15:57.248 [0x7f76f3bfb700] WARN - Held transaction for too long (../Library/FullTextSearch.cpp:17): 0.880000 seconds
Mar 07, 2018 12:15:57.863 [0x7f76f3bfb700] WARN - Held transaction for too long (../Library/FullTextSearch.cpp:27): 0.590000 seconds
Mar 07, 2018 12:15:58.566 [0x7f77337ff700] DEBUG - Auth: authenticated user redacted as redacted
Mar 07, 2018 12:16:01.105 [0x7f771cbff700] DEBUG - NetworkServiceBrowser: SSDP departed after not being seen for 20.262875 seconds: 10.0.10.57
Mar 07, 2018 12:16:01.309 [0x7f76f3bfb700] WARN - Held transaction for too long (../Library/FullTextSearch.cpp:38): 3.510000 seconds
Mar 07, 2018 12:16:01.958 [0x7f7732ffe700] DEBUG - Auth: authenticated user 1 as redacted
Mar 07, 2018 12:16:01.958 [0x7f7706bfd700] DEBUG - Request: [10.0.10.105:38000 (Subnet)] GET /status/sessions (22 live) Signed-in Token (redacted)
Mar 07, 2018 12:16:02.592 [0x7f76f3bfb700] WARN - Held transaction for too long (../Library/FullTextSearch.cpp:48): 1.230000 seconds
Mar 07, 2018 12:16:02.612 [0x7f76f3bfb700] DEBUG - Database optimization: starting.
Mar 07, 2018 12:16:02.612 [0x7f76f3bfb700] DEBUG - Activity: updated activity bbdf4ccb-67a9-4a9f-8330-3ebca6d19123 - completed 60% - Optimizing database
Mar 07, 2018 12:16:08.558 [0x7f7732ffe700] DEBUG - Auth: authenticated user redacted as redacted
Mar 07, 2018 12:16:51.805 [0x7f771cbff700] DEBUG - NetworkServiceBrowser: SSDP arrived: 10.0.10.57 (http://10.0.10.57:8008/ssdp/device-desc.xml)
Mar 07, 2018 12:17:41.105 [0x7f771cbff700] DEBUG - NetworkServiceBrowser: SSDP departed after not being seen for 21.889071 seconds: 10.0.10.57
Mar 07, 2018 12:17:56.760 [0x7f76f3bfb700] DEBUG - Database optimization: complete.
Mar 07, 2018 12:17:56.777 [0x7f76f3bfb700] INFO - SQLITE3:0x10, 17, statement aborts at 57: [select * from metadata_items limit 1] database schema has changed
(repeat x18)

Not much for helpful info in the logs from what i see other than the HubCache taking 23662 ms. (The hub is always broken on initial load and a retry works instantly) i chalk that up to the DB being too large… (correct me if im wrong on that)

ChuckPa · March 7, 2018, 6:45pm

Please do a manual capture (go in at the shell level) with PMS off.

Create a ZIP of both databases in one ZIP

Let’s find a way for me to get that to engineering.

Either PMS is eating your lunch (literally) or we’ve got a problem Houston
I need their eyes to find out what

Also, please spin me a full ZIP set of logs while downloading the DB

dirtycajunrice · March 7, 2018, 7:12pm

Here is a link to all 6 db files as listed above as well as the entire log directory, tarred, feathered, and gzipped XD.

Lemme know if you need anything else.

dirtycajunrice · March 7, 2018, 7:29pm

Looks like a sqldiff gives:

sqldiff --summary com.plexapp.plugins.library.db-2018-02-27 com.plexapp.plugins.library.db-2018-03-02
accounts: 4 changes, 6 inserts, 0 deletes, 31 unchanged
blobs: 0 changes, 0 inserts, 0 deletes, 0 unchanged
cloudsync_files: 0 changes, 0 inserts, 0 deletes, 0 unchanged
devices: 0 changes, 39 inserts, 0 deletes, 50 unchanged
directories: 42 changes, 89 inserts, 0 deletes, 3685 unchanged
fts4_metadata_titles_docsize: 14 changes, 140 inserts, 2 deletes, 21283 unchanged
fts4_metadata_titles_segdir: 1 changes, 41 inserts, 31 deletes, 0 unchanged
fts4_metadata_titles_segments: 0 changes, 627 inserts, 593 deletes, 0 unchanged
fts4_metadata_titles_stat: 1 changes, 0 inserts, 0 deletes, 0 unchanged
fts4_tag_titles_docsize: 0 changes, 856 inserts, 57 deletes, 40562 unchanged
fts4_tag_titles_segdir: 14 changes, 0 inserts, 5 deletes, 0 unchanged
fts4_tag_titles_segments: 0 changes, 560 inserts, 547 deletes, 0 unchanged
fts4_tag_titles_stat: 1 changes, 0 inserts, 0 deletes, 0 unchanged
library_section_permissions: 0 changes, 0 inserts, 0 deletes, 0 unchanged
library_sections: 3 changes, 0 inserts, 0 deletes, 0 unchanged
library_timeline_entries: 0 changes, 0 inserts, 0 deletes, 0 unchanged
locatables: 0 changes, 0 inserts, 0 deletes, 0 unchanged
location_places: 0 changes, 0 inserts, 0 deletes, 0 unchanged
locations_node: 0 changes, 0 inserts, 0 deletes, 1 unchanged
locations_parent: 0 changes, 0 inserts, 0 deletes, 0 unchanged
locations_rowid: 0 changes, 0 inserts, 0 deletes, 0 unchanged
media_grabs: 0 changes, 0 inserts, 0 deletes, 0 unchanged
media_item_settings: 0 changes, 0 inserts, 0 deletes, 0 unchanged
media_items: 132 changes, 143 inserts, 24 deletes, 19421 unchanged
media_metadata_mappings: 0 changes, 0 inserts, 0 deletes, 0 unchanged
media_part_settings: 0 changes, 4 inserts, 0 deletes, 0 unchanged
media_parts: 2283 changes, 143 inserts, 24 deletes, 17273 unchanged
media_provider_resources: 0 changes, 0 inserts, 0 deletes, 0 unchanged
media_streams: 11841 changes, 718 inserts, 55 deletes, 51214 unchanged
media_subscriptions: 0 changes, 0 inserts, 0 deletes, 0 unchanged
metadata_item_accounts: 0 changes, 0 inserts, 0 deletes, 1 unchanged
metadata_item_clusterings: 0 changes, 0 inserts, 0 deletes, 0 unchanged
metadata_item_clusters: 0 changes, 0 inserts, 0 deletes, 0 unchanged
metadata_item_settings: 4232 changes, 209 inserts, 12 deletes, 20955 unchanged
metadata_item_views: 12 changes, 2632111 inserts, 0 deletes, 121859 unchanged
metadata_items: 3135 changes, 140 inserts, 2 deletes, 18162 unchanged
metadata_relations: 0 changes, 0 inserts, 0 deletes, 0 unchanged
play_queue_generators: 0 changes, 37 inserts, 12 deletes, 7 unchanged
play_queue_items: 0 changes, 664 inserts, 288 deletes, 146 unchanged
play_queues: 2 changes, 37 inserts, 12 deletes, 6 unchanged
plugin_permissions: 0 changes, 0 inserts, 0 deletes, 0 unchanged
plugin_prefixes: 0 changes, 2 inserts, 2 deletes, 0 unchanged
plugins: 14 changes, 0 inserts, 0 deletes, 0 unchanged
preferences: 1 changes, 0 inserts, 0 deletes, 1 unchanged
schema_migrations: 0 changes, 4 inserts, 0 deletes, 107 unchanged
section_locations: 3 changes, 0 inserts, 0 deletes, 0 unchanged
spellfix_metadata_titles_vocab: 12493 changes, 45 inserts, 0 deletes, 600 unchanged
spellfix_tag_titles_vocab: 27572 changes, 387 inserts, 0 deletes, 2 unchanged
sqlite_sequence: 17 changes, 1 inserts, 0 deletes, 7 unchanged
sqlite_stat1: 86 changes, 3 inserts, 0 deletes, 11 unchanged
statistics_bandwidth: 136 changes, 1382 inserts, 0 deletes, 312 unchanged
statistics_media: 48 changes, 497 inserts, 0 deletes, 97 unchanged
stream_types: 0 changes, 0 inserts, 0 deletes, 3 unchanged
sync_schema_versions: 0 changes, 0 inserts, 0 deletes, 1 unchanged
synced_ancestor_items: 0 changes, 0 inserts, 0 deletes, 0 unchanged
synced_library_sections: 0 changes, 0 inserts, 0 deletes, 0 unchanged
synced_metadata_items: 0 changes, 0 inserts, 0 deletes, 0 unchanged
synced_play_queue_generators: 0 changes, 0 inserts, 0 deletes, 0 unchanged
synchronization_files: 0 changes, 0 inserts, 0 deletes, 0 unchanged
taggings: 0 changes, 6327 inserts, 1242 deletes, 177482 unchanged
tags: 291 changes, 1403 inserts, 15 deletes, 57114 unchanged
versioned_metadata_items: 0 changes, 0 inserts, 0 deletes, 0 unchanged
view_settings: 0 changes, 0 inserts, 0 deletes, 0 unchanged

the biggest inserts i see (as changes shouldn’t increase size exponentially) are:

metadata_item_views: 12 changes, 2632111 inserts, 0 deletes, 121859 unchanged
taggings: 0 changes, 6327 inserts, 1242 deletes, 177482 unchanged

And the biggest changes i see are:

spellfix_tag_titles_vocab: 27572 changes, 387 inserts, 0 deletes, 2 unchanged
spellfix_metadata_titles_vocab: 12493 changes, 45 inserts, 0 deletes, 600 unchanged
media_streams: 11841 changes, 718 inserts, 55 deletes, 51214 unchanged

with 3 more being 4K,3K, and 2K respectively.

Hopefully that helps engineering out a bit.

ChuckPa · March 7, 2018, 7:47pm

Thank you!

I’ve reached out to one of our database wizards to take a look inside

ChuckPa · March 7, 2018, 8:54pm

Hey @dirtycajunrice ,

It’s one of those days here. I had an idea (your cue to duck)

Do you use DLNA to access PMS?

I ask because I used DLNA to access my PMS, It started firing off Play events (which is what’s in your database) for every item in the database as PMS looked at the poster. (DLNA bug) It was so bad I had fired off a few thousand WebHook events before finding the source is DLNA.

Possible?

dirtycajunrice · March 7, 2018, 9:40pm

I do not, and explicitly have Enable the DLNA server unchecked. The in-home devices are an Nvidia Shield for the 4K TV, and an Apple TV 4 for the bedroom TV. With the computers using the web client, and 2 iPhones with their client.

For the webhooks, i do have an entire automation system in place. The systems that actually make calls to Plex itself are Ombi (requests), and Tautulli (Monitoring). I have a few python scripts using the PlexAPI pip module that run every ~hour or so as a cronjob for a few tidying tasks but nothing excessive.

dirtycajunrice · March 7, 2018, 9:41pm

I do not, and explicitly have Enable the DLNA server unchecked. The in-home devices are an Nvidia Shield for the 4K TV, and an Apple TV 4 for the bedroom TV. With the computers using the web client, and 2 iPhones for the wife and I with the swift client.

For the webhooks, i do have an entire automation system in place. The systems that actually make calls to Plex itself are Ombi (requests), and Tautulli (Monitoring). I have a few python scripts using the PlexAPI pip module that run every ~hour or so as a cronjob for a few tidying tasks but nothing excessive.

ChuckPa · March 7, 2018, 9:52pm

Thank you. This is good to know.

Can you tell me what endpoints those scripts hit for your automation? We’re seeing a pattern and trying to figure out which device / thing is hitting it

dirtycajunrice · March 7, 2018, 9:58pm

Roger. All of the scripts are pointed to an http://fqdn:32400 as the server with the pip module. As the module is just a glorified wrapper for the web api endpoints using the requests module im going to assume its only hitting the /session endpoint as thats all they are watching. that being said, i have NO idea what Ombi/Tautulli are hitting but with the verbosity of the information recorded i assume it is a vast majority of the parent endpoints.

Edit:
Just from simple deducing i would assume Ombi hits at least /status/sessions, /library/sections, /servers, and /photo
and Tautulli hits all the above and /identity, /library/onDeck, /search (possibly more)

dirtycajunrice · March 7, 2018, 10:32pm

Also… If you are inferring that all of this extra space has been used from the database saving metadata view requests in the metadata_item_views table, it poses a few thoughts.

Shouldnt database optimization clean any views older than foo days? If not implicitly then an advanced setting to allow it?
Assuming the above is true, is there any adverse affects to clearing that table (And any other statistics based tables) manually on a schedule until a fix is imposed?

ChuckPa · March 7, 2018, 10:57pm

Over X days old — yes. You’ve been at it how long? (Since Feb 28) and look at the size.

dirtycajunrice · March 7, 2018, 10:58pm

I tested… for the sake of testing… and oh my god thats all of it. used a COPY of a BACKED UP db just to be completely safe.

cp com.plexapp.plugins.library.db-2018-03-02 com.plexapp.plugins.library.db-2018-03-02-test
sqlite3 com.plexapp.plugins.library.db-2018-03-02-test 
DELETE FROM `metadata_item_views`
    WHERE id <= (
    SELECT id
    FROM (
        SELECT id
        FROM `metadata_item_views`
        ORDER BY id DESC
        LIMIT 1 OFFSET 10
    ) foo
);
(wait 3 or so minutes)
vacuum;
.quit
du -h com.plexapp.plugins.library.db-2018-03-02-test
95M     com.plexapp.plugins.library.db-2018-03-02-test

Hallelujah. Now i just need to know if #2 above is ok

dirtycajunrice · March 7, 2018, 11:01pm

Basically… anyone using a monitoring system could be having this issue. I would really like the ability to control the “X” in number of days. Until then if #2 is ok and it doesnt bork anything ill just do that.

ChuckPa · March 7, 2018, 11:03pm

Tautulli doesn’t have it. It’s the old “PlexPy” and if there was an issue caused by it, 3/4 of Engineering would have seen it long ago

dirtycajunrice · March 7, 2018, 11:05pm

I was already on Tautulli before the database clear we did 2 weeks ago So that concerns me. Does the logs tell you where the majority of the requests are coming from? as an IP address? That will tell me for SURE what it is.

ChuckPa · March 7, 2018, 11:22pm

We’re pulling that all apart now. This is a very manual process as we’re reconstructing activity from history.

You mentioned other endpoints / scripts you run. Care to enlighten me? I ask because one issue we know of (DLNA) will cause this. If you found another, we need FIX IT

dirtycajunrice · March 7, 2018, 11:27pm

All of my personally written scripts that are recurring revolve around sessions and sessions alone. e.g. Person X has paused for > 10 min (Probably fell asleep) kill the stream. Person is transcoding 4k (Probably cant handle it on their device) kill the stream etc etc.
I have one offs that get all usernames & emails, and get version vs new version then pull from the site and update, but none of those touch metadata.

Since DNLA is off, it makes me worry its another thing that hasn’t been found. I hope you come back and say its coming from 10.0.10.105 or 10.0.10.108 (Tautulli / Ombi respectively). Less work for you and less direct conversations with the respective content creators for me haha.

ChuckPa · March 7, 2018, 11:45pm

You would need to start running Trakt to see the IP logging. PMS doesn’t to that (too invasive from the Plex perspective)

ChuckPa · March 8, 2018, 4:38am

Discussing this issue with other staff, We have another diagnostic step.

Temporarily remove any plug-ins
Restore the DB to normal (your script)
Observe for 72 hours to see if condition still replicated.

If issue not observed, use process of elimination to find problematic plug-in

Topic		Replies	Views
Calling all users with MASSIVE libraries Plex Media Server server-linux	24	455	May 12, 2022
Optimize Database time General Discussions	16	1780	January 8, 2020
DB locks and wait times Desktops & Laptops server-linux , server-docker	56	990	March 13, 2022
Enormous size of database file NAS & Devices server-linux	27	1046	October 14, 2020
Trying to find the cause, why PMS is corrupting its own database after a while NAS & Devices server-synology	30	340	April 6, 2020

Database size increasing significantly above the ~100MB Expectation

Related topics