Plex partial scanning is extremely slow to start on large libraries

I hate to break into this with a ‘me too’ post, but I might have some useful information to add. A friend of mine is having the same problem. Suspecting a sqlite issue, I ran a (rather tedious and manual) sqlite diagnostic trace.
His database is 1 GB in size, which seems to be in the same weightclass as Johnsen’s.
His system is a windows server 2019 with direct attached storage. But the following measurements were done on a copy of the database using a Windows 10 desktop (without the relevant disks attached).

database com.plexapp.plugins.library.db
table directories: 27488 rows
table library_sections: 9 rows
table section_locations: 64 rows
table media_items: 303486 rows
table media_parts: 303588 rows

Command: --scan --refresh --section 1 --directory “O:\TV Shows\My Show\Season 1”

Total time spent: 235.6 seconds
Time spent inside sqlite3_step: 222.9 seconds
Number of sqlite3_step invocations: 276607
(sqlite3_step is the main sqlite function used for executing sqlite queries)

The most frequent queries:

264684x  (4227 unique)   select ... from directories where parent_directory_id=?
  7980x                  sqlite internal master table queries
   957x  (1 unique)      select distinct(metadata_items.id) from metadata_items where metadata_items.library_section_id=1 and metadata_items.metadata_type in (2) order by metadata_items.title_sort
   956x  (956 unique)    select ... from metadata_items where id=?
   956x  (956 unique)    select ... from metadata_items join metadata_items as parents on parents.id=metadata_items.parent_id join metadata_items as grandparents on grandparents.id=parents.parent_id where grandparents.id=150932 and metadata_items.refreshed_at is null order by parents.`index`,parents.year,metadata_items.`index`,metadata_items.originally_available_at 
   954x  (954 unique)    select ... from metadata_items join metadata_items as parents on parents.id=metadata_items.parent_id join metadata_items as grandparents on grandparents.id=parents.parent_id where grandparents.id=150932 and (metadata_items.guid like 'local://%' or metadata_items.guid='') order by parents.`index`,parents.year,metadata_items.`index`,metadata_items.originally_available_at 

Other relevant queries:

    29x  (1 unique)      select ... from section_locations where library_section_id=1 order by created_at
     3x  (2 unique)      select ... from directories where library_section_id=1 and path='MY SHOW/Season 1' and parent_directory_id=34251 order by path

Concerning here is of course the huge number of queries to the directories table, there’s also a significant amount of duplicate queries using the same parameter values.
The majority of these queries take place before any disk access is attempted on the target path, so the kind of disk mount or storage system is unlikely to be a factor.

PS: Johnsen, I did this on windows with some ugly custom tooling and cannot be easily duplicated. Well, it depends on your level of expertise with debugging tools.

1 Like

Great information.

That is very similar to my database.

I just have a few more directories and section_locations:

table directories: 45164 rows
table library_sections: 10 rows
table section_locations: 280 rows
table media_items: 297933 rows
table media_parts: 297936 rows

Looking at these, for me their relationships looks off:

library_sections (Libraries):
ok

section_locations (Library root folders):
Related to library_sections
ok

directories (Sub folders):
Related to library_sections
Why is this linked to library_sections? Shouldn’t it be section_locations instead? It has only one top folder for each entry. Therefore, there is basically no way to know which root folder these directories belong to.

media_items (Item):
Related to library_sections and section_locations
Okish. There is duplicate information since you can derive library_sections from section_locations.

media_parts (Itempart)
Related to media_items and directories
Okish. File contains duplicate information since it contains the full path. Only filename should be needed since you should be able to derive the full path from directories > section_locations

From a database optimize perspective their relationships should have been a straight:

library_sections < section_locations < directories < media_items < media_parts

1 Like

Managed to partial workaround this by symlinking the movies folder together so plex only sees them as one directory.

However, this still leaves my TV folder, which are split by first characters due to space contains. The Plex TV agent does not accept subfolders and will then try to match A,B,C etc to a series name. By symlinking the folders into this structure “C:\Media\TV\A\Series Name” and then only adding “C:\Media\TV” as a folder to the library.

I wonder why you have so many separate volumes.
How many NAS units are there?

Only one Synology ds3612xs with 36 disks. With each volume set up as a 4 disks RAID 5. I did larger ones before. However, when my movies filled up a whole enclosure (12 disks) I decided to split them all up in small part for easier management.

Looks like automatic partial scan does not pick up changes in symlinked folders. So its back to square one. Looks like I just need to wait for this bug to be fixed…

I just currently disabled the partial scan when changes are detected… Hoping this gets fixed soon…

I have referred this to the development team

As I understand it, the number of folder paths (locations) defined for the library is a factor here

Quick summary of the problem:

When running av partial scan for example:
“C:\Program Files (x86)\Plex\Plex Media Server\Plex Media Scanner.exe” --scan --refresh --section 3 --directory “\NAS\MOVIES-M\The Matrix (1999) [tt0133093]”

There is a delay with lots of database operations before the actual scanning starts. This delays looks to be exponentially longer based on how many root folders/paths you have added to the library/section and also how many directories are under these root folders.

Thanks for all the troubleshooting

The development team have made progress in identifying the excessive database requests

1 Like

That’s awesome news. I’m really glad the additional details helped to illuminate the underlying issue.

I have just sent you alpha build 1.16.2.1238-20d45f627 which is expected to solve this issue

Please let me know the results

Thanks

2 Likes

Same command from the first post:

“C:\Program Files (x86)\Plex\Plex Media Server\Plex Media Scanner.exe” --scan --refresh --section 3 --directory “\NAS\MOVIES-M\The Matrix (1999) [tt0133093]”

Library with 28 root folders and 23000 sub folders.

Previously took 90 minutes.

Now 27 seconds!

Jun 19, 2019 19:44:41.266 [5276] INFO - Plex Media Scanner v1.16.2.1238-20d45f627 - Microsoft PC x64 - build: windows-x86 - GMT 02:00
Jun 19, 2019 19:44:41.268 [5276] INFO - Windows version: 6.2 (Build 9200), language en-US
Jun 19, 2019 19:44:41.268 [5276] INFO - 8 3696 MHz processor(s): Architecture=0, Level=6, Revision=40458 Processor Identifier=Intel64 Family 6 Model 158 Stepping 10, GenuineIntel
Jun 19, 2019 19:44:41.268 [5276] DEBUG - "C:\Program Files (x86)\Plex\Plex Media Server\Plex Media Scanner.exe"   --scan --refresh --section 3 --directory "\\NAS\MOVIES-M\The Matrix (1999) [tt0133093]"
Jun 19, 2019 19:44:41.270 [5708] DEBUG - Opening 20 database sessions to library (com.plexapp.plugins.library), SQLite 3.26.0, threadsafe=1
Jun 19, 2019 19:44:41.441 [5708] DEBUG - It took 93.750000 ms to retrieve 23575 items.
Jun 19, 2019 19:44:42.413 [5708] DEBUG - It took 93.750000 ms to retrieve 23575 items.
Jun 19, 2019 19:44:43.410 [5708] DEBUG - It took 93.750000 ms to retrieve 23575 items.
Jun 19, 2019 19:44:44.394 [5708] DEBUG - It took 93.750000 ms to retrieve 23575 items.
Jun 19, 2019 19:44:45.373 [5708] DEBUG - It took 109.375000 ms to retrieve 23575 items.
Jun 19, 2019 19:44:46.393 [5708] DEBUG - It took 109.375000 ms to retrieve 23575 items.
Jun 19, 2019 19:44:47.383 [5708] DEBUG - It took 109.375000 ms to retrieve 23575 items.
Jun 19, 2019 19:44:48.428 [5708] DEBUG - It took 93.750000 ms to retrieve 23575 items.
Jun 19, 2019 19:44:49.413 [5708] DEBUG - It took 109.375000 ms to retrieve 23575 items.
Jun 19, 2019 19:44:50.410 [5708] DEBUG - It took 125.000000 ms to retrieve 23575 items.
Jun 19, 2019 19:44:51.441 [5708] DEBUG - It took 93.750000 ms to retrieve 23575 items.
Jun 19, 2019 19:44:52.441 [5708] DEBUG - It took 109.375000 ms to retrieve 23575 items.
Jun 19, 2019 19:44:53.456 [5708] DEBUG - It took 109.375000 ms to retrieve 23575 items.
Jun 19, 2019 19:44:54.477 [5708] DEBUG - It took 109.375000 ms to retrieve 23575 items.
Jun 19, 2019 19:44:55.521 [5708] DEBUG - It took 93.750000 ms to retrieve 23575 items.
Jun 19, 2019 19:44:56.496 [5708] DEBUG - It took 93.750000 ms to retrieve 23575 items.
Jun 19, 2019 19:44:57.480 [5708] DEBUG - It took 109.375000 ms to retrieve 23575 items.
Jun 19, 2019 19:44:58.499 [5708] DEBUG - It took 93.750000 ms to retrieve 23575 items.
Jun 19, 2019 19:44:59.469 [5708] DEBUG - It took 93.750000 ms to retrieve 23575 items.
Jun 19, 2019 19:45:00.469 [5708] DEBUG - It took 93.750000 ms to retrieve 23575 items.
Jun 19, 2019 19:45:01.492 [5708] DEBUG - It took 93.750000 ms to retrieve 23575 items.
Jun 19, 2019 19:45:02.480 [5708] DEBUG - It took 93.750000 ms to retrieve 23575 items.
Jun 19, 2019 19:45:03.439 [5708] DEBUG - It took 93.750000 ms to retrieve 23575 items.
Jun 19, 2019 19:45:04.433 [5708] DEBUG - It took 109.375000 ms to retrieve 23575 items.
Jun 19, 2019 19:45:05.428 [5708] DEBUG - It took 93.750000 ms to retrieve 23575 items.
Jun 19, 2019 19:45:06.409 [5708] DEBUG - It took 93.750000 ms to retrieve 23575 items.
Jun 19, 2019 19:45:07.384 [5708] DEBUG - It took 109.375000 ms to retrieve 23575 items.
Jun 19, 2019 19:45:08.303 [5708] DEBUG - Scanning Movies using en(Plex Movie Scanner) with 1 current media items and 1 section locations in the database...
Jun 19, 2019 19:45:08.303 [6344] DEBUG - HTTP requesting GET http://127.0.0.1:32400/:/metadata/notify/cullTimeline?librarySectionID=3&sinceTime=1560965108
Jun 19, 2019 19:45:08.304 [6344] DEBUG - HTTP 200 response from GET http://127.0.0.1:32400/:/metadata/notify/cullTimeline?librarySectionID=3&sinceTime=1560965108
Jun 19, 2019 19:45:08.353 [5708] DEBUG - Performing a scan with 'Plex Movie Scanner' (language: en virtual: 0).
Jun 19, 2019 19:45:08.353 [5708] DEBUG -   * Scanning \\NAS\MOVIES-M\The Matrix (1999) [tt0133093]
Jun 19, 2019 19:45:08.364 [5708] DEBUG -     * Scanning directory \\NAS\MOVIES-M\The Matrix (1999) [tt0133093] (parent: yes)
Jun 19, 2019 19:45:08.365 [5708] DEBUG - Adding file for scanner: "\\NAS\MOVIES-M\The Matrix (1999) [tt0133093]\The.Matrix.1999.REMASTERED.1080p.Bluray.Proper.x264.AAC.5.1-RARBG.mp4"
Jun 19, 2019 19:45:08.751 [5708] DEBUG - Skipping over directory 'The Matrix (1999) [tt0133093]', as nothing has changed; removing 1 media items from map.
Jun 19, 2019 19:45:08.755 [6344] DEBUG - HTTP requesting GET http://127.0.0.1:32400/:/metadata/updateProgressMessage?message=Scanning%20The%20Matrix%20(1999)%20[tt0133093]
Jun 19, 2019 19:45:08.756 [6344] DEBUG - HTTP 200 response from GET http://127.0.0.1:32400/:/metadata/updateProgressMessage?message=Scanning%20The%20Matrix%20(1999)%20[tt0133093]
Jun 19, 2019 19:45:08.759 [5708] DEBUG - Removing 0 media items that were left.
Jun 19, 2019 19:45:08.759 [5708] DEBUG - Removing 0 directories that were left.
Jun 19, 2019 19:45:08.805 [5708] DEBUG - Refreshing section 3 of type: 1
Jun 19, 2019 19:45:08.854 [6304] DEBUG - Refreshing 0 IDs.
1 Like

Impressive

Thanks for confirming

when will this be fix be pushed out?

1.16.2 should be out on beta very soon - may be tomorrow. Not definite

1 Like

Plex Media Server 1.16.2.1297 beta is now out. It has the fix for this

See release notice Plex Media Server

  • Greatly speed up partial scan operation (#10171)

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