Cached Files are still being downloaded from the Cloud

I have the problem that my remote caches files properly but when I close the remote and mount it again it will act like the cache doesn't exist and download every file again even with the file being stored in the cache folder.

When I start the mount with -vv I will get a lot of messages showing me this:
vfs cache RemoveNotInUse (maxAge=360000000000, emptyOnly =false): item **** not removed, freed 0 bytes

I think those are the files that are redownloaded when I access them.

rclone Version:

rclone v1.55.1

  • os/type: windows
  • os/arch: amd64
  • go/version: go1.16.3
  • go/linking: dynamic
  • go/tags: cmount

This is how I mount the Remote:

rclone mount --verbose crypt: S: --buffer-size 32M --use-mmap --dir-cache-time 72h --drive-chunk-size 128M  --timeout 1h  --vfs-cache-mode full --vfs-read-chunk-size 16M --vfs-read-chunk-size-limit 0

The Configuration of the Remotes:

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

[cache]
type = cache
remote = gdrive:/***/***/***
info_age = 5y
chunk_total_size = 400G
chunk_clean_interval = 1y
workers = 10
db_path = F:\cache
chunk_path = F:\cache

[crypt]
type = crypt
remote = cache:/
password = ***

You seem to be mixing both the cache remote (which is buggy / deprecated / should not be used) with the new vfs cache mode full.

You want to not use the cache backend and point your [crypt] remote directly to your gdrive: instead of cache:

Does that mean I could Mount the crypt (that points to gdrive) and use these flags to control the cache?

--vfs-cache-mode full \
--vfs-cache-max-size 100G \
--vfs-cache-max-age 120h \

That is correct.

This doesn't solve my problem. It's still redownloading the Cached files.

This is how I'm mounting it now:

rclone mount --verbose crypt: S: --cache-dir=F:\cache --vfs-read-chunk-size 16M --vfs-read-chunk-size-limit 0 --vfs-cache-max-size 400G  --vfs-cache-max-age 100000h --transfers 10 --buffer-size 32M --use-mmap --dir-cache-time 72h --drive-chunk-size 128M  --timeout 1h  --vfs-cache-mode full 

This is the updated Config:

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

[crypt]
type = crypt
remote = gdrive:/***/***/***
password = ***

Rclone doesn't download anything unless the application requests it so not sure what you mean.

If you have a log file with -vv and share it, you can see what's going on.

When the application requests a file it should be loaded from the cache if possible.
Maybe I misunderstand the concept of the cache.
I want files that are used often to be stored in the cache so they aren't downloaded every time.

That's exactly how the cache works.

It should. But that is exactly my problem. It doesn't

I tested it with a test.png file. The File is already in the cache but it is still loaded from my google drive if I access it.

2021/06/11 21:13:38 DEBUG : Creating backend with remote "crypt:"
2021/06/11 21:13:38 DEBUG : Creating backend with remote "gdrive:/***/***/***"
2021/06/11 21:13:38 DEBUG : gdrive: detected overridden config - adding "{I3nB0}" suffix to name
2021/06/11 21:13:39 DEBUG : fs cache: renaming cache item "gdrive:/***/***/***" to be canonical "gdrive{I3nB0}:***/***/***"
2021/06/11 21:13:40 DEBUG : vfs cache: root is "\\\\?\\F:\\cache\\vfs\\crypt"
2021/06/11 21:13:40 DEBUG : vfs cache: metadata root is "\\\\?\\F:\\cache\\vfs\\crypt"
2021/06/11 21:13:40 DEBUG : Creating backend with remote "\\\\?\\F:\\cache\\vfs\\crypt"
2021/06/11 21:13:40 DEBUG : fs cache: renaming cache item "\\\\?\\F:\\cache\\vfs\\crypt" to be canonical "//?/F:/cache/vfs/crypt"
2021/06/11 21:13:40 DEBUG : fs cache: switching user supplied name "\\\\?\\F:\\cache\\vfs\\crypt" for canonical name "//?/F:/cache/vfs/crypt"
2021/06/11 21:13:40 DEBUG : Network mode mounting is disabled
2021/06/11 21:13:40 DEBUG : Mounting on "S:" ("crypt")
2021/06/11 21:13:40 DEBUG : Encrypted drive 'crypt:': Mounting with options: ["-o" "attr_timeout=1" "-o" "uid=-1" "-o" "gid=-1" "--FileSystemName=rclone" "-o" "volname=crypt"]
2021/06/11 21:13:40 DEBUG : vfs cache RemoveNotInUse (maxAge=360000000000000000, emptyOnly=false): item test.png not removed, freed 0 bytes
2021/06/11 21:13:40 INFO  : vfs cache: cleaned: objects 1 (was 1) in use 0, to upload 0, uploading 0, total size 223.467k (was 223.467k)
.
.
.
.
.
.

2021/06/11 21:13:55 DEBUG : Encrypted drive 'crypt:': Destroy:
2021/06/11 21:13:55 DEBUG : Encrypted drive 'crypt:': >Destroy:
2021/06/11 21:13:55 DEBUG : Not calling host.Unmount as mount already Destroyed
2021/06/11 21:13:55 DEBUG : Unmounted successfully
2021/06/11 21:13:55 DEBUG : vfs cache: cleaner exiting
2021/06/11 21:13:55 DEBUG : rclone: Version "v1.55.1" finishing with parameters ["rclone" "mount" "--verbose" "-vv" "crypt:" "S:" "--cache-dir=F:\\cache" "--vfs-read-chunk-size" "16M" "--vfs-read-chunk-size-limit" "0" "--vfs-cache-max-size" "400G" "--vfs-cache-max-age" "100000h" "--buffer-size" "32M" "--use-mmap" "--dir-cache-time" "72h" "--drive-chunk-size" "128M" "--timeout" "1h" "--vfs-cache-mode" "full"]

Here is the full Log

Log seems to be missing the top portion of it.

That being said, you can see all the 'true' lines in there which means it's reading from the cache.

2021/06/11 21:13:49 DEBUG : test.png(0xc002730080): _readAt: size=32768, off=131072
2021/06/11 21:13:49 DEBUG : vfs cache: looking for range={Pos:131072 Size:32768} in [{Pos:0 Size:228830}] - present true

and

2021/06/11 21:13:50 DEBUG : vfs cache: looking for range={Pos:0 Size:32768} in [{Pos:0 Size:228830}] - present true

and

2021/06/11 21:13:50 DEBUG : vfs cache: looking for range={Pos:0 Size:32768} in [{Pos:0 Size:228830}] - present true
2021/06/11 21:13:50 DEBUG : test.png: >newRWFileHandle: err=<nil>
2021/06/11 21:13:50 DEBUG : test.png: >newRWFileHandle: err=<nil>
2021/06/11 21:13:50 DEBUG : test.png(0xc00063e000): >_readAt: n=32768, err=<nil>
2021/06/11 21:13:50 DEBUG : test.png: >Open: fd=test.png (rw), err=<nil>
2021/06/11 21:13:50 DEBUG : test.png: >Open: fd=test.png (rw), err=<nil>
2021/06/11 21:13:50 DEBUG : /test.png: >Read: n=32768
2021/06/11 21:13:50 DEBUG : /test.png: >OpenFile: fd=test.png (rw), err=<nil>
2021/06/11 21:13:50 DEBUG : /test.png: >OpenFile: fd=test.png (rw), err=<nil>
2021/06/11 21:13:50 DEBUG : /test.png: >OpenEx: errc=0, fh=0x2
2021/06/11 21:13:50 DEBUG : /test.png: >OpenEx: errc=0, fh=0x0
2021/06/11 21:13:50 DEBUG : /test.png: Flush: fh=0x2

So looks to be working perfectly from your log file that you shared.

Maybe reading from the cache is just really slow then.
I'm using a nvme SSD and it it still takes way to much time.

Copying 100 small cached files takes about 24 seconds
When doing it for the 2nd time it only takes 1 second.

After restarting the Remote it's back to 24 seconds.

Also there is network activity while copying it for the first time.

Not really as it reads from whatever the local disk is and if that's SSD, it would be fast.

If you have a log file with the actual issue, that would be great as what you shared looks pretty clean.

Windows is it's own animal so not sure how you are copying/testing.

Here is a pretty basic test of a file read that takes quite bit on the cloud remote but goes back to being fast once cached:

felix@gemini:~/test$ time mediainfo jellyfish-400-mbps-4k-uhd-hevc-10bit.mkv > /dev/null 2>&1

real	0m23.564s
user	0m1.187s
sys	0m0.890s
felix@gemini:~/test$
felix@gemini:~/test$
felix@gemini:~/test$ time mediainfo jellyfish-400-mbps-4k-uhd-hevc-10bit.mkv > /dev/null 2>&1

real	0m1.528s
user	0m0.408s
sys	0m0.350s
felix@gemini:~/test$ time mediainfo jellyfish-400-mbps-4k-uhd-hevc-10bit.mkv > /dev/null 2>&1

real	0m1.643s
user	0m0.318s
sys	0m0.484s

Your right, it seems like the problem is rather windows than rclone.

Also when I copy a folder with 100 files everything is fine.
I Only get the Problem if every file is in it's own folder.
So 100 subfolders with 1 file each is really slow on the first copy.

Thanks for the Help I really appreciate it.