Adding file to encrypted Google Drive causes Plex to go through entire library

What is the problem you are having with rclone?

Whenever a new file is added to an encrypted google drive mounted using rclone Plex goes through the entire library. This is very slow (an hour or more on a 500/500MBit connection for about 2000 entries).

My setup is that sonarr, radarr etc use the "connection" to Plex to trigger a scan when they add content. Plex is set to partial scan if it finds changes (Run a partial scan when changes are detected). Plex scanning entire library at specific intervals is disabled. They all run in docker containers with the folder mounted from the host and the name of the folder is the same in all containers.

The irritating thing is that I had a previous setup where this worked without any issues. Then I accidently deleted the mount script and had to write it again. So some setting I'm using is most likely causing this behavior.

I have experimented with adding high dir-cache-time etc but doesn't seem to help.

I MIGHT have not used any caching before (now I have caching for writes) if that could be causing this??? Although it seems highly unlikely.

What is your rclone version (output from rclone version)

rclone v1.50.2

  • os/arch: linux/amd64
  • go version: go1.13.6

Which OS you are using and how many bits (eg Windows 7, 64 bit)

Ubuntu 20.04

Which cloud storage system are you using? (eg Google Drive)

Google Drive

The command you were trying to run (eg rclone copy /tmp remote:tmp)

[Unit]
Description=Encrypted GDrive (rclone)
Wants=network-online.target
After=network-online.target
AssertPathIsDirectory=/mnt/gdrive-encrypted

[Service]
Type=notify
Environment=RCLONE_CONFIG=/root/.config/rclone/rclone.conf
KillMode=none
RestartSec=5
Restart=on-failure
ExecStart=/usr/bin/rclone mount gdrive-encrypted: /mnt/gdrive-encrypted \
--allow-other \
--dir-cache-time 1000h \
--attr-timeout 1000h \
--fast-list \
--buffer-size 1G \
--vfs-read-chunk-size 128M \
--vfs-read-chunk-size-limit off \
--drive-skip-gdocs \
--timeout 1h \
--tpslimit 10 \
--tpslimit-burst 10 \
--transfers 24 \
--drive-chunk-size="128M" \
--poll-interval 15s \
--user-agent mygdrive-enc \
--rc \
--rc-addr :5573 \
--rc-no-auth \
--cache-dir=/dev/shm/rclone/cache \
--vfs-cache-mode writes \
--vfs-cache-max-size 10G \
--vfs-cache-max-age 336h

ExecStop=/usr/bin/fusermount -uz /mnt/gdrive-encrypted
ExecStartPost=/usr/bin/rclone rc vfs/refresh recursive=true --rc-addr 127.0.0.1:5573 _async=true
[Install]
WantedBy=default.target

The rclone config contents with secrets removed.

[gdrive]
type = drive
client_id = *REMOVED*
client_secret = *REMOVED*
scope = drive
token = *REMOVED*

[gdrive-encrypted]
type = crypt
remote = gdrive:/encrypted
filename_encryption = standard
directory_name_encryption = true
password = *REMOVED*
password2 = *REMOVED*

A log from the command with the -vv flag

No log added since the transfer etc works so that is not the issue.

Does nothing on a mount and can be removed.

Best to use the defaults here rather than 1G per file.

You may want to use the new vfs-cache-mode full as that provides much better performance for streaming.

You want to set a very large --dir-cache time since you are using Google Drive, which is a polling remote. The default is 5 minutes and I use 1000 hours. Changes are picked up via polling so having a large value only helps things.

That's only for when plex detects a change.

Radarr issues a scan for all movies via the API. Sonarr issues a scan for the TV show rather than all TV shows.

A plex scan on a fully analyzed library usually takes 30-60 seconds on Linux. I have about ~140TB and it takes about 20 seconds for my full library scan to complete.

You want to update your rclone version as well to use the new vfs-cache-mode as your version is very old.

From your reply it sounds like I should not let sonarr, radarr, lidarr etc report to Plex since that (at least for some f them) trigger a complete library rescan?

From what I gathered when testing --vfs-cache-mode full it seemed to try to download the complete file before starting it. Causing Plex to wait for a really long time.

Regarding --buffer-size, that is just how much memory I allow it to pre fill correct?

I updated to the latest version of rclone just now but it still acts the same way. I triggered a "Scan Library Files" which usually is very fast and it goes super slow. It feel like it doesn't understand which folders are actually changed and have to scan all.

If I manually run a command like

find /mnt/gdrive-encrypted/Media/Movies/ -mtime -2

I get a list of all added files during the past two days in a second. Hmmmmmm.

Not at all. I use them all and connect Plex to them.

That's from an old version, the new version doesn't do that and majority of folks use it.

Remove and just use the default with the new version.

If the dir-cache is populated, it's instant. Just like local disk for the most part.

Ahh ok...
Is there and "best practice" mount options list for a setup like this somewhere? Feels like a lot of people are using it :slight_smile:

I changed to full cache mode etc and it behaves way better than full before as you said. But it still does the dumb thing in Plex of scanning the whole library of movies when a single one is added. Looks like it goes into random subfolder also... It's been going for about 30 minutes and as you can see it has barely moved and folders of long ago imported and movies seems to take a minute or something to process.

I think I have narrowed it down. I thought that Plex did some kind of quick listing of the directory to identify new files and perhaps look at modification times to identify changed files and kept track of when it last did this to be able to see what had changed. But Plex seems to use inotify to be informed about changes and added files. This is not supported by fuse which is how rclone mounts. So that is probably part of why I see this behavior. I would guess that for the folder that is the mounted one Plex can't get inotify notifications and instead resorts to do a complete scan in order to find new files.

inotify is only used for this:

in conjunction with this:

The API call used by Radarr scans all movies.
The API call used by Sonarr scans the entire TV show that was added.

Listing out files on a mount when it's all in cache is like local storage and is fast so a Plex scan takes seconds.

felix@gemini:/GD$ time find . -type f | wc -l
51468

real    0m0.921s
user    0m0.086s
sys     0m0.107s

A triggered scan via sonarr, radarr or in Plex still takes a super long time for the mounted folders. Local ones are super fast. Does the new scanner perhaps do a deeper check than the legacy one during scan that requires files to be partially fetched perhaps? (Changed a while back).
The directory structure and files are clearly cached since any kind of lookup similar to you find is almost instant.

foo@bar:/# time find /RemoteMovies -type f | wc -l
13190

real 0m0.525s
user 0m0.042s
sys 0m0.098s

Nope, it does not.

Both just check path, file size and mod time to see if anything changed. If path/size/modtime changes, the file has to be re-analyzed.

If it takes a long time, Plex is analyzing the files because of a change in one of those items above. You can see that specifically in the Plex logs and if you run rclone in debug, you'd see it reading files rather than just getting their meta information.

I enabled verbose and debug logging and then added a single movie to see what would happen.
First thing is that it spams the fact that it found the file (due to how rclone saves and reports the file on the mount?).

Jan 20, 2021 15:25:53.651 [0x7fbb0a7fc700] INFO - Library section 1 (Movies) will be updated because of a change in '"/RemoteMovies"/The Cool Movie (2020)'
Jan 20, 2021 15:25:53.651 [0x7fbb0a7fc700] DEBUG - [Notify] New directory: "/RemoteMovies/The Cool Movie (2020)", adding recursively.
Jan 20, 2021 15:25:53.651 [0x7fbb0a7fc700] DEBUG - [Notify] Now watching "/RemoteMovies/The Cool Movie (2020)"
Jan 20, 2021 15:25:53.954 [0x7fbb0a7fc700] INFO - Library section 1 (Movies) will be updated because of a change in '"/RemoteMovies/The Cool Movie (2020)"/The.Cool.Movie.2020.1080p.WEB.h264-WATCHER.mkv'
Jan 20, 2021 15:25:53.956 [0x7fbb0a7fc700] VERBOSE - Library section 1 (Movies) will be updated because of a change in '"/RemoteMovies/The Cool Movie (2020)"/The.Cool.Movie.2020.1080p.WEB.h264-WATCHER.mkv'
Jan 20, 2021 15:25:53.957 [0x7fbb0a7fc700] VERBOSE - Library section 1 (Movies) will be updated because of a change in '"/RemoteMovies/The Cool Movie (2020)"/The.Cool.Movie.2020.1080p.WEB.h264-WATCHER.mkv'
Jan 20, 2021 15:25:53.959 [0x7fbb0a7fc700] VERBOSE - Library section 1 (Movies) will be updated because of a change in '"/RemoteMovies/The Cool Movie (2020)"/The.Cool.Movie.2020.1080p.WEB.h264-WATCHER.mkv'
Jan 20, 2021 15:25:53.960 [0x7fbb0a7fc700] VERBOSE - Library section 1 (Movies) will be updated because of a change in '"/RemoteMovies/The Cool Movie (2020)"/The.Cool.Movie.2020.1080p.WEB.h264-WATCHER.mkv'
Jan 20, 2021 15:25:53.962 [0x7fbb0a7fc700] VERBOSE - Library section 1 (Movies) will be updated because of a change in '"/RemoteMovies/The Cool Movie (2020)"/The.Cool.Movie.2020.1080p.WEB.h264-WATCHER.mkv'
Jan 20, 2021 15:25:53.963 [0x7fbb0a7fc700] VERBOSE - Library section 1 (Movies) will be updated because of a change in '"/RemoteMovies/The Cool Movie (2020)"/The.Cool.Movie.2020.1080p.WEB.h264-WATCHER.mkv'
Jan 20, 2021 15:25:53.965 [0x7fbb0a7fc700] VERBOSE - Library section 1 (Movies) will be updated because of a change in '"/RemoteMovies/The Cool Movie (2020)"/The.Cool.Movie.2020.1080p.WEB.h264-WATCHER.mkv'
Jan 20, 2021 15:25:53.966 [0x7fbb0a7fc700] VERBOSE - Library section 1 (Movies) will be updated because of a change in '"/RemoteMovies/The Cool Movie (2020)"/The.Cool.Movie.2020.1080p.WEB.h264-WATCHER.mkv'
Jan 20, 2021 15:25:53.967 [0x7fbb0a7fc700] VERBOSE - Library section 1 (Movies) will be updated because of a change in '"/RemoteMovies/The Cool Movie (2020)"/The.Cool.Movie.2020.1080p.WEB.h264-WATCHER.mkv'
Jan 20, 2021 15:25:53.969 [0x7fbb0a7fc700] VERBOSE - Library section 1 (Movies) will be updated because of a change in '"/RemoteMovies/The Cool Movie (2020)"/The.Cool.Movie.2020.1080p.WEB.h264-WATCHER.mkv'
Jan 20, 2021 15:25:53.970 [0x7fbb0a7fc700] VERBOSE - Library section 1 (Movies) will be updated because of a change in '"/RemoteMovies/The Cool Movie (2020)"/The.Cool.Movie.2020.1080p.WEB.h264-WATCHER.mkv'
Jan 20, 2021 15:25:53.970 [0x7fbb0a7fc700] VERBOSE - Library section 1 (Movies) will be updated because of a change in '"/RemoteMovies/The Cool Movie (2020)"/The.Cool.Movie.2020.1080p.WEB.h264-WATCHER.mkv'
Jan 20, 2021 15:25:53.971 [0x7fbb0a7fc700] VERBOSE - Library section 1 (Movies) will be updated because of a change in '"/RemoteMovies/The Cool Movie (2020)"/The.Cool.Movie.2020.1080p.WEB.h264-WATCHER.mkv'
Jan 20, 2021 15:25:53.972 [0x7fbb0a7fc700] VERBOSE - Library section 1 (Movies) will be updated because of a change in '"/RemoteMovies/The Cool Movie (2020)"/The.Cool.Movie.2020.1080p.WEB.h264-WATCHER.mkv'
Jan 20, 2021 15:25:53.973 [0x7fbb0a7fc700] VERBOSE - Library section 1 (Movies) will be updated because of a change in '"/RemoteMovies/The Cool Movie (2020)"/The.Cool.Movie.2020.1080p.WEB.h264-WATCHER.mkv'
Jan 20, 2021 15:25:53.973 [0x7fbb0a7fc700] VERBOSE - Library section 1 (Movies) will be updated because of a change in '"/RemoteMovies/The Cool Movie (2020)"/The.Cool.Movie.2020.1080p.WEB.h264-WATCHER.mkv'
Jan 20, 2021 15:25:53.974 [0x7fbb0a7fc700] VERBOSE - Library section 1 (Movies) will be updated because of a change in '"/RemoteMovies/The Cool Movie (2020)"/The.Cool.Movie.2020.1080p.WEB.h264-WATCHER.mkv'
Jan 20, 2021 15:25:53.975 [0x7fbb0a7fc700] VERBOSE - Library section 1 (Movies) will be updated because of a change in '"/RemoteMovies/The Cool Movie (2020)"/The.Cool.Movie.2020.1080p.WEB.h264-WATCHER.mkv'
Jan 20, 2021 15:25:53.976 [0x7fbb0a7fc700] VERBOSE - Library section 1 (Movies) will be updated because of a change in '"/RemoteMovies/The Cool Movie (2020)"/The.Cool.Movie.2020.1080p.WEB.h264-WATCHER.mkv'
Jan 20, 2021 15:25:53.976 [0x7fbb0a7fc700] VERBOSE - Library section 1 (Movies) will be updated because of a change in '"/RemoteMovies/The Cool Movie (2020)"/The.Cool.Movie.2020.1080p.WEB.h264-WATCHER.mkv'
Jan 20, 2021 15:25:53.977 [0x7fbb0a7fc700] VERBOSE - Library section 1 (Movies) will be updated because of a change in '"/RemoteMovies/The Cool Movie (2020)"/The.Cool.Movie.2020.1080p.WEB.h264-WATCHER.mkv'
Jan 20, 2021 15:25:53.978 [0x7fbb0a7fc700] VERBOSE - Library section 1 (Movies) will be updated because of a change in '"/RemoteMovies/The Cool Movie (2020)"/The.Cool.Movie.2020.1080p.WEB.h264-WATCHER.mkv'
Jan 20, 2021 15:25:53.978 [0x7fbb0a7fc700] VERBOSE - Library section 1 (Movies) will be updated because of a change in '"/RemoteMovies/The Cool Movie (2020)"/The.Cool.Movie.2020.1080p.WEB.h264-WATCHER.mkv'
...

Then, after many, many lines of that I see

Jan 20, 2021 15:26:13.371 [0x7fbb50ff9700] DEBUG - Scanner: Processing directory /RemoteMovies (parent: no)
Jan 20, 2021 15:26:13.372 [0x7fbb50ff9700] VERBOSE - * Noting that '' was updated at 2020-12-07 21:40:12
Jan 20, 2021 15:26:13.372 [0x7fbb50ff9700] VERBOSE - * Taking directory '' (1) out of the map (1865 left)
Jan 20, 2021 15:26:13.375 [0x7fbb50ff9700] VERBOSE - Adding subdirectory for scanner: "/RemoteMovies/Another.Movie.(2009)"
Jan 20, 2021 15:26:13.375 [0x7fbb50ff9700] VERBOSE - Adding subdirectory for scanner: "/RemoteMovies/A.Third.Movie.(1996)"
...

where it lists all the subdirectories in the RemoteMovies folder
After a while I see the actual movie that was just added

Jan 20, 2021 15:26:13.745 [0x7fbb50ff9700] DEBUG - Scanner: Processing directory /RemoteMovies/The Cool Movie (2020) (parent: yes)
Jan 20, 2021 15:26:13.745 [0x7fbb50ff9700] VERBOSE - * Noting that 'The Cool Movie (2020)' was updated at 2021-01-20 15:25:53
Jan 20, 2021 15:26:13.745 [0x7fbb50ff9700] VERBOSE - * Taking directory 'The Cool Movie (2020)' (3132) out of the map (1865 left)
Jan 20, 2021 15:26:14.078 [0x7fbb50ff9700] VERBOSE - Adding file for scanner: "/RemoteMovies/The Cool Movie (2020)/The.Cool.Movie.2020.1080p.WEB.h264-WATCHER.mkv"
Jan 20, 2021 15:26:14.561 [0x7fbbb0851700] VERBOSE - WebSocket: processed 1 frame(s)
Jan 20, 2021 15:26:14.824 [0x7fbb50ff9700] DEBUG - Directory had 1 files, database had 0 files, can't skip.

Then there is a bunch of

Jan 20, 2021 15:26:14.850 [0x7fbb50ff9700] DEBUG - Scanner: Processing directory /RemoteMovies/Already.Existing.Movie (2019) (parent: yes)
Jan 20, 2021 15:26:14.850 [0x7fbb50ff9700] VERBOSE - * Noting that 'Already Existing Movie (2019)' was updated at 2021-01-20 00:06:19
Jan 20, 2021 15:26:14.850 [0x7fbb50ff9700] VERBOSE - * Taking directory 'Already Existing Movie (2019)' (3120) out of the map (1855 left)
Jan 20, 2021 15:26:14.851 [0x7fbb50ff9700] VERBOSE - Adding file for scanner: "/RemoteMovies/Already Existing Movie (2019)/Already.Existing.Movie.BluRay.DTS.x264-iFT.mkv"
Jan 20, 2021 15:26:14.851 [0x7fbb50ff9700] VERBOSE - Adding file for scanner: "/RemoteMovies/Already Existing Movie (2019)/Already.Existing.Movie.BluRay.DTS.x264-iFT.nfo"
Jan 20, 2021 15:26:14.852 [0x7fbb50ff9700] DEBUG - Skipping over directory 'Already Existing Movie (2019)', as nothing has changed; removing 1 media items from map.

It looks like it adds existing movies where it knows it hasn't been recently updated to the scanner?

I also so this quite interesting line in the middle of it all

Jan 20, 2021 15:26:53.921 [0x7fbbabfff700] DEBUG - Queuing up item 75180 for more analysis, looks like the analysis never happened or something changed.

Not sure if it's talking about my local or remote mounted folder thought. But in any case that doesn't sound like it would cause the scan of the entire remote folder... but rather perhaps be a finding of the scan.

If you have an item in Plex and you change the path, it rescans it.

So regardless of rclone or anything else, if you have /start/movie.mkv and you move it to /end/movie.mkv, it analyzes the item as something has changed. This goes for name changes as well as any change in the path or name of the file, it reanalyzes it in Plex.

This gets long if you have a cloud mount and it has to re-analyze items again as it takes a number of seconds per file.

I specifically use mergerfs (or rclone union) to never change paths or names in my setup once something is added to my library.

Yea, I get that a rename or moving path would trigger Plex to look at it. But these are movies in /RemoteMovies in subfolders that have been added a long time ago, been visible and playable in Plex for a long time, never changed, renamed or touched in any way that it still seems like it somehow adds to the scanner just because I add another movie to a new subfolder of /RemoteMovies

The

Jan 20, 2021 15:26:13.372 [0x7fbb50ff9700] VERBOSE - * Noting that '' was updated at 2020-12-07 21:40:12
Jan 20, 2021 15:26:13.372 [0x7fbb50ff9700] VERBOSE - * Taking directory '' (1) out of the map (1865 left)

seems a bit strange. Which folder is that ('') with no name at all. Is that perhaps responsible for triggering the /RemoteMovies root folder to be scanned in it's entirety?

p.s.
Thanks for the effort you put into trying to help :wink:

I wouldn't keep verbose on as that adds a ton of useless info. Debug is usually all you need.

That line is tell you something changed on this file. Name/Date/Time/Size. I can't answer what changed, but something did.

Yea, that exact file was the newly added file. I expect that one to be scanned. :slight_smile:
But where it seems to add all the other folders to the scanner I'm a bit more puzzled. Every single folder under /RemoteMovies is listed like

Jan 20, 2021 15:26:13.375 [0x7fbb50ff9700] VERBOSE - Adding subdirectory for scanner: "/RemoteMovies/Another.Movie.(2009)"
Jan 20, 2021 15:26:13.375 [0x7fbb50ff9700] VERBOSE - Adding subdirectory for scanner: "/RemoteMovies/A.Third.Movie.(1996)"

and then they all go through a similar process, every single folder...

Jan 20, 2021 15:26:19.277 [0x7fbb50ff9700] DEBUG - Scanner: Processing directory /RemoteMovies/Another.Movie.(2009) (parent: yes)
Jan 20, 2021 15:26:19.277 [0x7fbb527fc700] DEBUG - Jobs: Starting child process with pid 1349
Jan 20, 2021 15:26:19.277 [0x7fbb50ff9700] VERBOSE - * Noting that 'Another.Movie.(2009)' was updated at 2020-12-22 13:23:38
Jan 20, 2021 15:26:19.277 [0x7fbb50ff9700] VERBOSE - * Taking directory 'Another.Movie.(2009)' (2976) out of the map (1759 left)
Jan 20, 2021 15:26:19.278 [0x7fbb50ff9700] VERBOSE - Adding file for scanner: "/RemoteMovies/Another.Movie.(2009)/Another.Movie.(2009).mp4"
Jan 20, 2021 15:26:19.278 [0x7fbb517fa700] DEBUG - Scanner [Plex Movie]: found existing media id 24176
Jan 20, 2021 15:26:19.278 [0x7fbb517fa700] DEBUG - Native Scanner: Executed Cloud Match stage in 0.00 sec.
Jan 20, 2021 15:26:19.279 [0x7fbb517fa700] DEBUG - Path matched, we're reusing media item 24176
Jan 20, 2021 15:26:19.280 [0x7fbb517fa700] DEBUG - Native Scanner: Executed Add to Database stage in 0.00 sec.
Jan 20, 2021 15:26:19.280 [0x7fbb517fa700] DEBUG - Native Scanner: Executed Media Analysis stage in 0.00 sec.

That is what is taking time I think. Why add all these other untouched folders/files to the scanner?

Back to the earlier point as that's how the API for Radarr injects a new item. It scans the entire Movie library.

Those entries are finding matches and taking 0 seconds.

Those aren't taking any time for the scan.

Ohh I forgot to mention. I turned off sonarr and radarr notifications while testing. So Plex "found" that a new file had been added by itself.

That the actual check against the DB etc takes 0 seconds is one thing. But it spends about 2 seconds on each folder. That times a few thousands becomes quite some time. Since the rclone cache is filled with files (that has been part of the library and unchanged for months) after Plex has scanned the folder it feels like what is happening is that some part of the file is read before Plex says "I already have this imported... move on".

How does it find it by itself? You have a scan on for something I'd imagine? Those scan everything as well. We can really put that to the side that it really isn't relevant.

A "scan" of whatever you have should not take 2 seconds per folder. If that happens, something changed on the media or it was never analyzed.

I use plex standards for my setup so I have 1 movie directory and that directory it has about 4k directories with my movies. A scan of that folder takes ~7 seconds for me from when I click start till it's done.

If you see this in your alert log, it's analyzed and moves from item to item. If you see anything different, it's analyzing.

I just found in the logs what it seems to be doing with every single existing movie on the remote mount. Running on every movie, every single time a movie is added or a scan initiated.

Job running: EAE_ROOT='/tmp/pms-078ceef8-5717-488f-825b-319de53c6a71/EasyAudioEncoder' FFMPEG_EXTERNAL_LIBS='/config/Library/Application\ Support/Plex\ Media\ Server/Codecs/367b3d4-3654-linux-x86_64/' X_PLEX_TOKEN=xxxxxxxxxxxxxxxxxxxx1' '/usr/lib/plexmediaserver/Plex Media Scanner' '--match' '--type' '1' '--log-file-suffix' ' Matcher' '--files' '/RemoteMovies/A.Movie.(2011)/A.Movie.2011.xvid.DVD-Rip.mp3.Robblowe.avi' '--match-tag-mode=all'

About every three seconds or so a new one shows up in the log for the next movie in the library.

And this happens no matter how many times I let the entire scan finish.

Once it analyzes, it doesn't do it again unless you change name/path/modtime on the file/etc.

Otherwise, your installation is different/broken :slight_smile:

I think I found it... It is an issue in the scanner that Plex team seems to know about. I have two folders in the library. A local folder and a remote mount. Some movies exist in both of them as a backup if the online mount goes down for instance. But Plex seems to have an issue if this is the case and the folder names are the same, which they are in my case. This causes it to have to rescan every time, even if the files has already been added and analyzed etc.

Appending "remote" or something to the folder name would probably fix the issue.