Plex web slow item loading

[Mitzsch]

Server Version#: 1.32.7.7571
Player Version#: Web 4.108.0

This is essentially a follow-up to this one here => Plex HTPC/Web slow item loading (closed)

I noticed the slow loading of items on my server just recently again. Unfortunately, I have no idea which server version introduced this behavior again… The server hw has not changed.

Items sometimes need over 2s to fully load. => benchmarked with the “show XML info” in plex web gui. The console would then show:
"Completed: [192.168.1.110:64877] 200 GET /library/metadata/11528? checkFiles=1&includeAllConcerts=1&includeBandwidths=1&includeChapters=1&includeChildren=1&includeConcerts=1&includeExtras=1&includeFields=1&includeGeolocation=1&includeLoudnessRamps=1&includeMarkers=1&includeOnDeck=1&includePopularLeaves=1&includePreferences=1&includeRelated=1&includeRelatedCount=1&includeReviews=1&includeStations=1 (11 live) #5467 TLS GZIP 2201ms 15298 bytes (pipelined: 1)"

… 2201ms… well… This number is huge… and also feelable in apps like Plex HTPC, where movie loading takes an eternity (2s…)

The fix for this is to refresh the metadata of the affected item…
Then loading only takes 1/10 the time…

Somehow this behavior is especially noticeable on newly added files… I have already run the PlexDBRepair tool (GitHub - ChuckPa/PlexDBRepair: Database repair utility for Plex Media Server databases) but that had no impact. Absolutely no idea why it is that slow…

What could be the reason for this slowness?

If the server logs are needed, let me know!

[ChuckPa]

@Mitzsch

Yes, Server DEBUG logs are needed to see what’s happening.
The utility script you used puts the DB in pristine sorted defragmented order.

[Mitzsch]

Thanks!

I currently only have the normal logs on hand, but maybe something obvious is already visible there?
Plex Media Server Logs_2023-10-10_16-55-47.zip (2,8 MB)

I will provide the DEBUG logs tomorrow!

@ChuckPa

pristine sorted defragmented order.

Does (should=?) this have an impact on performance?

[Mitzsch]

@ChuckPa

New logs are here:

I just tried benchmarking on two movies (GOG Vol.3 (ID 11619) in 2K and The Exorcist (ID 11640) in 4K…) both also exhibit slow-loading behavior. On The Exorcist I refreshed the metadata and now it’s fast again. (1509ms => 267ms)

Also, the three newly added movies also exhibit that behavior, but somehow only after I changed the artwork. With the preselected one => 360ms, after I selected an artwork => 2180ms, after metadata refresh => 253ms (ID 11655)

The logs are created with the debug option set. (“debug logging”) (The logs above may also be debug logs)

Plex Media Server Logs_2023-10-11_15-53-24.zip (2,3 MB)

Thanks!

[ChuckPa]

@Mitzsch

What kind of environment do you have there ?
The CPU is reporting 2x as many threads as it really has !!!

Oct 11, 2023 15:39:46.855 [140295746341688] INFO - Plex Media Server v1.32.7.7571-13cdc68dc - Ubuntu PC x86_64 - build: linux-x86_64 debian - GMT 02:00
Oct 11, 2023 15:39:46.855 [140295746341688] INFO - Linux version: 22.04.3 LTS (Jammy Jellyfish), language: en-US
Oct 11, 2023 15:39:46.856 [140295746341688] INFO - Processor: 40-core Intel(R) Xeon(R) CPU E5-2640 v4 @ 2.40GHz

https://www.cpubenchmark.net/cpu.php?cpu=Intel+Xeon+E5-2640+v4+%40+2.40GHz&id=2752

The REAL CPU has 10 cores + Hyperthreading == 20 threads.
Your configuration reports 40.

Is this a dual CPU machine?

Compare to an E5-2690v4 with 14 cores / 28 threads

Oct 11, 2023 12:32:42.806 [140092460858168] INFO - Plex Media Server v1.32.7.7571-13cdc68dc - Ubuntu PC x86_64 - build: linux-x86_64 debian - GMT -04:00
Oct 11, 2023 12:32:42.806 [140092460858168] INFO - Linux version: 22.04.3 LTS (Jammy Jellyfish), language: en-US
Oct 11, 2023 12:32:42.806 [140092460858168] INFO - Processor: 28-core Intel(R) Xeon(R) CPU E5-2690 v4 @ 2.60GHz

[Mitzsch]

The system is a dual socket server. (Dell R730XD) It has two of the E5‘s so 40 cores is correct.

[Mitzsch]

@ChuckPa
May I ask if you have found something that could explain the slow loading behavior?

[ChuckPa]

I’ve been trying things with my xeon.

I’m down to two possibilites:

1. Slow I/O in general
2. CPU speed (single thread) versus size of the DB.

What are the sizes of the DB files ? (ls -la will tell us what we need to know)

If you’re willing, would you consider this?
(adjust paths if necessary)

sudo bash
cd  "/var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Plug-in Support/Databases"

for i in *
do
  dd if="$i" of=/dev/null bs=1M
done

When done.

1. Highlight the text in the terminal window
2. Right-click ‘COPY’
3. Open a ‘code’ block (```) in your reply
4. PASTE the console output
5. Close the code block ``` again on a line by itself

It should look something like this:

root@glockner:/vol/plexmediaserver/Plex Media Server/Plug-in Support/Databases# for i in *
> do
> dd if="$i" of=/dev/null bs=1M
> done
1+1 records in
1+1 records out
1060864 bytes (1.1 MB, 1.0 MiB) copied, 0.0185284 s, 57.3 MB/s
1+1 records in
1+1 records out
1060864 bytes (1.1 MB, 1.0 MiB) copied, 0.0148456 s, 71.5 MB/s
1+1 records in
1+1 records out
1060864 bytes (1.1 MB, 1.0 MiB) copied, 0.0185093 s, 57.3 MB/s
1+1 records in
1+1 records out
1060864 bytes (1.1 MB, 1.0 MiB) copied, 0.0181334 s, 58.5 MB/s
1+1 records in
1+1 records out
1060864 bytes (1.1 MB, 1.0 MiB) copied, 0.0146263 s, 72.5 MB/s
0+1 records in
0+1 records out
32768 bytes (33 kB, 32 KiB) copied, 0.000167605 s, 196 MB/s
0+0 records in
0+0 records out
0 bytes copied, 0.000135656 s, 0.0 kB/s
567+1 records in
567+1 records out
594997248 bytes (595 MB, 567 MiB) copied, 0.217891 s, 2.7 GB/s
562+1 records in
562+1 records out
589701120 bytes (590 MB, 562 MiB) copied, 0.453595 s, 1.3 GB/s
562+1 records in
562+1 records out
589701120 bytes (590 MB, 562 MiB) copied, 0.397556 s, 1.5 GB/s
575+1 records in
575+1 records out
603947008 bytes (604 MB, 576 MiB) copied, 0.426771 s, 1.4 GB/s
551+1 records in
551+1 records out
578068480 bytes (578 MB, 551 MiB) copied, 0.415267 s, 1.4 GB/s
0+1 records in
0+1 records out
65536 bytes (66 kB, 64 KiB) copied, 0.000174082 s, 376 MB/s
533+1 records in
533+1 records out
558939832 bytes (559 MB, 533 MiB) copied, 0.336082 s, 1.7 GB/s
0+1 records in
0+1 records out
1621 bytes (1.6 kB, 1.6 KiB) copied, 0.00913015 s, 178 kB/s
root@glockner:/vol/plexmediaserver/Plex Media Server/Plug-in Support/Databases# 

Lastly, we’ll query the DB directly (read-only) with sqlite3

echo 'select count(*) from media_items;' | time sqlite3 com.plexapp.plugins.library.db

Looks like this:

root@glockner:/vol/plexmediaserver/Plex Media Server/Plug-in Support/Databases# echo 'select count(*) from media_items;' | time sqlite3 com.plexapp.plugins.library.db
153757
0.00user 0.00system 0:00.00elapsed 83%CPU (0avgtext+0avgdata 5768maxresident)k
0inputs+0outputs (0major+581minor)pagefaults 0swaps
root@glockner:/vol/plexmediaserver/Plex Media Server/Plug-in Support/Databases#

[Mitzsch]

Sorry for the late reply, the week has been very taxing…

here are the results

root@MediaNAS:/mnt/appdata1/Library/Application Support/Plex Media Server/Plug-in Support/Databases# for i in *
do
  dd if="$i" of=/dev/null bs=1M
done
0+1 records in
0+1 records out
4796 bytes (4.8 kB, 4.7 KiB) copied, 0.0035337 s, 1.4 MB/s
dd: error reading 'Music Analysis 20': Is a directory
0+0 records in
0+0 records out
0 bytes copied, 0.000170513 s, 0.0 kB/s
dd: error reading 'Music Analysis 9': Is a directory
0+0 records in
0+0 records out
0 bytes copied, 0.0001 s, 0 B/s
0+1 records in
0+1 records out
24576 bytes (25 kB, 24 KiB) copied, 0.00057652 s, 42.6 MB/s
0+1 records in
0+1 records out
32768 bytes (33 kB, 32 KiB) copied, 0.00030074 s, 109 MB/s
0+1 records in
0+1 records out
94352 bytes (94 kB, 92 KiB) copied, 0.000425345 s, 222 MB/s
25+1 records in
25+1 records out
27095040 bytes (27 MB, 26 MiB) copied, 0.018937 s, 1.4 GB/s
0+1 records in
0+1 records out
32768 bytes (33 kB, 32 KiB) copied, 0.000110191 s, 297 MB/s
0+0 records in
0+0 records out
0 bytes copied, 6.7047e-05 s, 0.0 kB/s
66+1 records in
66+1 records out
69603328 bytes (70 MB, 66 MiB) copied, 0.0513443 s, 1.4 GB/s
0+1 records in
0+1 records out
32768 bytes (33 kB, 32 KiB) copied, 0.000103244 s, 317 MB/s
0+1 records in
0+1 records out
663352 bytes (663 kB, 648 KiB) copied, 0.000903187 s, 734 MB/s
dd: error reading 'dbtmp': Is a directory
0+0 records in
0+0 records out
0 bytes copied, 9.9066e-05 s, 0.0 kB/s

and

root@MediaNAS:/mnt/appdata1/Library/Application Support/Plex Media Server/Plug-in Support/Databases# echo 'select count(*) from media_items;' | time sqlite3 com.plexapp.plugins.library.db
14999
0.00user 0.00system 0:00.00elapsed 100%CPU (0avgtext+0avgdata 4160maxresident)k
0inputs+0outputs (0major+252minor)pagefaults 0swaps

Thanks!

[acedk047]

I am also noticing the slow loading when changing a poster. Alot of times it ends up erroring rather than eventually loading. However it generated nothing to do with an error in logs. Once I unmatch it and rematch it, it loads fine again. So cannot change posters on any movies at all. I am not seeing the same issue with TV shows. Those seem unaffected. It’s just movies.

[carrousel5301]

@Mitzsch

includeRelated

I believe this may be related to an issue I’m having as well. I’ve narrowed it down to items matched with the default Plex Movie agent

When clicking “View XML”, set includeRelated=1 to 0, the item XML will load instantly.

Here’s my post, I’m curious if you’re seeing the same issue on the /playQueues and /related endpoints?

"Plex Movie" Agent long playback starttimes exceeding 2 minutes

Server Version#: 1.32.6.7557 Player Version#: 4.115.1 This is seemingly irrelevant of PMS version. I’ve tried every version starting from 1.29.2 > latest. The only thing that fixes this issue is running the Legacy Movie Agent. When attempting to play a majority of movies on my server many movies take over 2 minutes to start playback. Inspecting network traffic using dev tools and can see the /playQueues query taking at least 30 seconds for most movies and over 2 minutes for many of them. Th…

I’m running 22.04, 10900k. PMS docker on Optane.

[Mitzsch]

Related Items are indeed something that I suspect to be part of the problem. Sometimes when it loads slowly. The movie overview and the cast loads fast and then after a second or two the related items pop up.

[carrousel5301]

I’ve extracted all of the fields from com.plexapp.plugins.library.db for an affected item. This one only takes 6 seconds for playback to begin.

Default (New) Movie Agent
https://pastebin.com/fAFd0yQP

Legacy Movie Agent

media_items529747 1 1 364897 1920 1080 3885651735 5619008 5532153 mkv h264 -...

I don’t really notice many large differences aside from taggings having more TMDB links compared to the legacy agent.
Changing the match from Plex Movie > Legacy > Plex Movie does not seem to restore these extra tags.

Here is the taggings table for this item AFTER matching it back to the default Movie Agent, running an analyze and metadata refresh.

taggings4172021 364897 4 1 0 410000 1697341390 4172022 364897 4 2 41000 -...

[carrousel5301]

I did some testing on another item that was taking 17 SECONDS for playback to being. I decided to prune some of the extra tags at the bottom that contained TMDB poster links.

Here is the table PRE pruning.

4183112 365260 319 1 0 98098 1697341473 4183113 365260 320 2 98098 346137...

Here is the table afterwards.

4183112 365260 319 1 0 98098 1697341473 4183113 365260 320 2 98098 346137...

This resulted in playback starting in under 2 seconds.

This is still slower than the legacy agent but is acceptable.

[carrousel5301]

@ChuckPa Any idea what the extra fields in the taggings table are being used for? And why deleting the extra entries seems to completely resolve the issue?

[carrousel5301]

I’ve ran the following against my DB and it’s made a massive improvement. Nearly everything has instant playback like it did a year ago.

/opt/plexsql/Plex\ Media\ Server --sqlite com.plexapp.plugins.library.db "DELETE FROM taggings WHERE (tag_id = 100 OR tag_id = 101) AND extra_data NOT LIKE '%local%';"

[ChuckPa]

Just catching up here.

It sounds like you had some residual entries in the database from when there was the IVA bug (tons of extra records were added and slowed thing WAY down).

Just for laughs / final cleanup, did you run my optimize tool?

[carrousel5301]

When was this bug introduced? I’ve tested fresh installs on various PMS versions from 1.29.2, 1.31.2 and the latest 1.32.6. They all exhibit this same issue.

I’ve ran your dbrepair script numerous times and it doesn’t help.

[ChuckPa]

@carrousel5301

If you have a new install of 1.32.6 then you aren’t subject to the issue.
It’s long since resolved.

May I trouble you for a set of Server Debug log files ?

[carrousel5301]

Sure, is there anything in particular you’re looking for?

I restored the backup of the DB with all of the extra entries, did a scan of the library and attempted playback of few items.

Plex Media Server Logs_2023-10-23_14-14-11.zip (799.8 KB)