Rclone mount with --vfs-cache-mode writes problem

What is the problem you are having with rclone?

Even using the --vfs-cache-mode writes, after the 4h max age some object are "freed"

here's the nssm configuration:

Path: N:\rclone\rcloneMount.exe
Folder: N:\rclone
Arguments: mount Media: I: --vfs-cache-mode writes --use-mmap --vfs-read-chunk-size-limit 10M  --vfs-read-chunk-size-limit 512M --drive-chunk-size 128M --vfs-cache-max-age 4h --vfs-cache-poll-interval 1h --attr-timeout 5m --verbose --log-file="n:\VFS Cache\rlonemountservice.log" --cache-dir "n:\VFS Cache" --file-perms=0777

and the logs:

I have some application that periodically check the remote folders (emby/sonarr/radarr) but with cache mode writes no files have to be placed in cache folder, right?

thx

What is your rclone version (output from rclone version)

n:\rclone>rclonemount --version
rclone v1.55.1
- os/type: windows
- os/arch: amd64
- go/version: go1.16.3
- go/linking: dynamic
- go/tags: cmount

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

Windows 10 Pro 64bit

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)

[gdrive]
type = drive
scope = drive
root_folder_id = yyyyyyyyyyyyyyyyyyyyyyyyyyy
token = {xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx}
client_id = xxxxxxxxxxxxxxxxxxxxx.apps.googleusercontent.com
client_secret = xxxxxxxxxxxxx

[Media]
type = crypt
remote = gdrive:01
filename_encryption = standard
directory_name_encryption = true
password = xxxxxxxxxxxxxxxxxxxxxxxxxxxxx

The rclone config contents with secrets removed.

see above

A log from the command with the -vv flag

see above

I'm not sure what the problem is as you set the cache time for 4 hours and it does expire.

What do you want to happen?

You have these flags duplicated for some reason.

thx, I fixed this..

about the problem.
using the --vfs-cache-mode writes rclone theoretically cached only the file that's been writed to the remote..
the log I have sended tell that many items are freed from cache, but these are not been writed to the remote..these are old file never touched..

I can't tell much as that's a snippet of a log.

If you can share a full log and an example of that, I'm happy to help out.

this is a 12 hours log with -vv

has you see:

2021/08/03 19:26:26 DEBUG : rclone: Version "v1.55.1" starting with parameters ["N:\\rclone\\rcloneMount.exe" "mount" "Media:" "I:" "--vfs-cache-mode" "writes" "--use-mmap" "--vfs-read-chunk-size-limit" "10M" "--drive-chunk-size" "128M" "--vfs-cache-max-age" "5m" "--vfs-cache-poll-interval" "1h" "--attr-timeout" "5m" "-vv" "--log-file=n:\\VFS Cache\\rlonemountservice.log" "--cache-dir" "n:\\VFS Cache" "--file-perms=0777"]

and this morning at 6:26 many items were freed from cache but this wasn't writen file..

In that log file, there are no file writes that happen.

grep write rlonemountservice.log
2021/08/03 19:26:26 DEBUG : rclone: Version "v1.55.1" starting with parameters ["N:\\rclone\\rcloneMount.exe" "mount" "Media:" "I:" "--vfs-cache-mode" "writes" "--use-mmap" "--vfs-read-chunk-size-limit" "10M" "--drive-chunk-size" "128M" "--vfs-cache-max-age" "5m" "--vfs-cache-poll-interval" "1h" "--attr-timeout" "5m" "-vv" "--log-file=n:\\VFS Cache\\rlonemountservice.log" "--cache-dir" "n:\\VFS Cache" "--file-perms=0777"]
2021/08/04 08:36:05 DEBUG : rclone: Version "v1.55.1" finishing with parameters ["N:\\rclone\\rcloneMount.exe" "mount" "Media:" "I:" "--vfs-cache-mode" "writes" "--use-mmap" "--vfs-read-chunk-size-limit" "10M" "--drive-chunk-size" "128M" "--vfs-cache-max-age" "5m" "--vfs-cache-poll-interval" "1h" "--attr-timeout" "5m" "-vv" "--log-file=n:\\VFS Cache\\rlonemountservice.log" "--cache-dir" "n:\\VFS Cache" "--file-perms=0777"]

In a mount when you write to it, you'll see log lines like:

2021/08/04 08:34:16 DEBUG : jellyfish-400-mbps-4k-uhd-hevc-10bit.mkv(0xc0006fa100): _writeAt: size=131072, off=1504051200
2021/08/04 08:34:16 DEBUG : jellyfish-400-mbps-4k-uhd-hevc-10bit.mkv(0xc0006fa100): >_writeAt: n=131072, err=<nil>
2021/08/04 08:34:16 DEBUG : &{jellyfish-400-mbps-4k-uhd-hevc-10bit.mkv (rw)}: >Write: written=131072, err=<nil>
2021/08/04 08:34:16 DEBUG : &{jellyfish-400-mbps-4k-uhd-hevc-10bit.mkv (rw)}: Write: len=131072, offset=1504182272
2021/08/04 08:34:16 DEBUG : jellyfish-400-mbps-4k-uhd-hevc-10bit.mkv(0xc0006fa100): _writeAt: size=131072, off=1504182272
2021/08/04 08:34:16 DEBUG : jellyfish-400-mbps-4k-uhd-hevc-10bit.mkv(0xc0006fa100): >_writeAt: n=131072, err=<nil>
2021/08/04 08:34:16 DEBUG : &{jellyfish-400-mbps-4k-uhd-hevc-10bit.mkv (rw)}: >Write: written=131072, err=<nil>
2021/08/04 08:34:16 DEBUG : &{jellyfish-400-mbps-4k-uhd-hevc-10bit.mkv (rw)}: Write: len=131072, offset=1504313344
2021/08/04 08:34:16 DEBUG : jellyfish-400-mbps-4k-uhd-hevc-10bit.mkv(0xc0006fa100): _writeAt: size=131072, off=1504313344
2021/08/04 08:34:16 DEBUG : jellyfish-400-mbps-4k-uhd-hevc-10bit.mkv(0xc0006fa100): >_writeAt: n=131072, err=<nil>
2021/08/04 08:34:16 DEBUG : &{jellyfish-400-mbps-4k-uhd-hevc-10bit.mkv (rw)}: >Write: written=131072, err=<nil>
2021/08/04 08:34:16 DEBUG : &{jellyfish-400-mbps-4k-uhd-hevc-10bit.mkv (rw)}: Write: len=131072, offset=1504444416
2021/08/04 08:34:16 DEBUG : jellyfish-400-mbps-4k-uhd-hevc-10bit.mkv(0xc0006fa100): _writeAt: size=131072, off=1504444416
2021/08/04 08:34:16 DEBUG : jellyfish-400-mbps-4k-uhd-hevc-10bit.mkv(0xc0006fa100): >_writeAt: n=131072, err=<nil>
2021/08/04 08:34:16 DEBUG : &{jellyfish-400-mbps-4k-uhd-hevc-10bit.mkv (rw)}: >Write: written=131072, err=<nil>
2021/08/04 08:34:16 DEBUG : &{jellyfish-400-mbps-4k-uhd-hevc-10bit.mkv (rw)}: Write: len=131072, offset=1504575488
2021/08/04 08:34:16 DEBUG : jellyfish-400-mbps-4k-uhd-hevc-10bit.mkv(0xc0006fa100): _writeAt: size=131072, off=1504575488
2021/08/04 08:34:16 DEBUG : jellyfish-400-mbps-4k-uhd-hevc-10bit.mkv(0xc0006fa100): >_writeAt: n=131072, err=<nil>
2021/08/04 08:34:16 DEBUG : &{jellyfish-400-mbps-4k-uhd-hevc-10bit.mkv (rw)}: >Write: written=131072, err=<nil>
2021/08/04 08:34:16 DEBUG : &{jellyfish-400-mbps-4k-uhd-hevc-10bit.mkv (rw)}: Write: len=131072, offset=1504706560
2021/08/04 08:34:16 DEBUG : jellyfish-400-mbps-4k-uhd-hevc-10bit.mkv(0xc0006fa100): _writeAt: size=131072, off=1504706560
2021/08/04 08:34:16 DEBUG : jellyfish-400-mbps-4k-uhd-hevc-10bit.mkv(0xc0006fa100): >_writeAt: n=131072, err=<nil>
2021/08/04 08:34:16 DEBUG : &{jellyfish-400-mbps-4k-uhd-hevc-10bit.mkv (rw)}: >Write: written=131072, err=<nil>
2021/08/04 08:34:16 DEBUG : &{jellyfish-400-mbps-4k-uhd-hevc-10bit.mkv (rw)}: Write: len=115518, offset=1504837632
2021/08/04 08:34:16 DEBUG : jellyfish-400-mbps-4k-uhd-hevc-10bit.mkv(0xc0006fa100): _writeAt: size=115518, off=1504837632
2021/08/04 08:34:16 DEBUG : jellyfish-400-mbps-4k-uhd-hevc-10bit.mkv(0xc0006fa100): >_writeAt: n=115518, err=<nil>
2021/08/04 08:34:16 DEBUG : &{jellyfish-400-mbps-4k-uhd-hevc-10bit.mkv (rw)}: >Write: written=115518, err=<nil>
2021/08/04 08:34:16 DEBUG : &{jellyfish-400-mbps-4k-uhd-hevc-10bit.mkv (rw)}: Flush:
2021/08/04 08:34:16 DEBUG : jellyfish-400-mbps-4k-uhd-hevc-10bit.mkv(0xc0006fa100): RWFileHandle.Flush
2021/08/04 08:34:16 DEBUG : &{jellyfish-400-mbps-4k-uhd-hevc-10bit.mkv (rw)}: >Flush: err=<nil>
2021/08/04 08:34:16 DEBUG : &{jellyfish-400-mbps-4k-uhd-hevc-10bit.mkv (rw)}: Release:
2021/08/04 08:34:16 DEBUG : jellyfish-400-mbps-4k-uhd-hevc-10bit.mkv(0xc0006fa100): RWFileHandle.Release
2021/08/04 08:34:16 DEBUG : jellyfish-400-mbps-4k-uhd-hevc-10bit.mkv(0xc0006fa100): close:
2021/08/04 08:34:16 DEBUG : jellyfish-400-mbps-4k-uhd-hevc-10bit.mkv: vfs cache: setting modification time to 2021-08-04 08:34:16.855375303 -0400 EDT m=+69.990757311
2021/08/04 08:34:16 INFO  : jellyfish-400-mbps-4k-uhd-hevc-10bit.mkv: vfs cache: queuing for upload in 5s
2021/08/04 08:34:16 DEBUG : jellyfish-400-mbps-4k-uhd-hevc-10bit.mkv(0xc0006fa100): >close: err=<nil>
2021/08/04 08:34:16 DEBUG : &{jellyfish-400-mbps-4k-uhd-hevc-10bit.mkv (rw)}: >Release: err=<nil>




2021/08/04 08:34:21 DEBUG : jellyfish-400-mbps-4k-uhd-hevc-10bit.mkv: vfs cache: starting upload
2021/08/04 08:34:23 DEBUG : acc9lv0c13ccdr2i14tm8qu4nisnphfijbtisdo9a9qsfhqk7q87udn8eq28np7gutkk138mchitg: Sending chunk 0 length 1073741824
2021/08/04 08:34:34 DEBUG : acc9lv0c13ccdr2i14tm8qu4nisnphfijbtisdo9a9qsfhqk7q87udn8eq28np7gutkk138mchitg: Sending chunk 1073741824 length 431578782
2021/08/04 08:34:40 DEBUG : jellyfish-400-mbps-4k-uhd-hevc-10bit.mkv: md5 = 097e86c7d92730b5a2e18ca498b8a338 OK
2021/08/04 08:34:40 INFO  : jellyfish-400-mbps-4k-uhd-hevc-10bit.mkv: Copied (new)
2021/08/04 08:34:40 DEBUG : jellyfish-400-mbps-4k-uhd-hevc-10bit.mkv: vfs cache: fingerprint now "1504953150,2021-08-04 12:34:16.855 +0000 UTC"
2021/08/04 08:34:40 DEBUG : jellyfish-400-mbps-4k-uhd-hevc-10bit.mkv: vfs cache: writeback object to VFS layer
2021/08/04 08:34:40 DEBUG : : Added virtual directory entry vAddFile: "jellyfish-400-mbps-4k-uhd-hevc-10bit.mkv"
2021/08/04 08:34:40 INFO  : jellyfish-400-mbps-4k-uhd-hevc-10bit.mkv: vfs cache: upload succeeded try #1
2021/08/04 08:35:07 DEBUG : Google drive root 'crypt': Checking for changes on remote
2021/08/04 08:35:07 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item jellyfish-400-mbps-4k-uhd-hevc-10bit.mkv not removed, freed 0 bytes
2021/08/04 08:35:07 INFO  : vfs cache: cleaned: objects 1 (was 1) in use 0, to upload 0, uploading 0, total size 1.402Gi (was 1.402Gi)
2021/08/04 08:35:07 DEBUG : : changeNotify: relativePath="jellyfish-400-mbps-4k-uhd-hevc-10bit.mkv", type=1
2021/08/04 08:35:07 DEBUG : : invalidating directory cache
2021/08/04 08:35:07 DEBUG : : >changeNotify:

How are you writing files to the mount?

man, you're missing the point.
I'm not asking about writen files.

During the day I have some apps that read the files from the remote.
What I want to understand is why in the log at 6:26 of the morning there are many entries about "freeing cache". why rclone mount are freeing some cache if I didn't write anything to the remote?

check this line:

2021/08/04 06:26:27 INFO  : vfs cache RemoveNotInUse (maxAge=300000000000, emptyOnly=false): item 00 - Online Media/Serie Tv/Il Trono di Spade (2011)/Stagione 07 [720p HEVC] [ITA+ENG]/Il Trono di Spade (2011) - S07E07 - Il drago e il lupo [WEBrip 720p HEVC] [ITA+ENG].mkv was removed, freed 0 bytes

this is a file not writen to the remote. so why is clearing this cache file?

Really not needed.

It's part the changes done with vfs cache mode full as you can see it freed 0 bytes so it's not 'there' per se. What problem are you having because of that line in the log file?

"--vfs-read-chunk-size-limit" "10M"

This line severely limits your speed and makes a ton of extra API calls to read files. Why did you change this?

I really don't undestand you assumption..
about the

"--vfs-read-chunk-size-limit" "10M"

I can change it to a bigger value and that's ok.

about the freed cache..
I used the --vfs-cache-mode full days ago.
I checked yesterday after the mount reboot and the cache folder was empty and as you see in the log the command used is

--vfs-cache-mode writes

why so the mount are freeing these cached files? they shouldn't even been there or I'm missing something?

This limits a range request submitted via the API to 10MB so when you read any file, it only requests 10MB ranges and never changes. So to read a 100MB file, you submit 10 API calls.

It freed 0 bytes so they aren't in the cache. You aren't using any space in the cache:

grep "total size" rlonemountservice.log
2021/08/03 19:26:27 INFO  : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2021/08/03 20:26:27 INFO  : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2021/08/03 21:26:27 INFO  : vfs cache: cleaned: objects 0 (was 58) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2021/08/03 22:26:27 INFO  : vfs cache: cleaned: objects 0 (was 1) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2021/08/03 23:26:27 INFO  : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2021/08/04 00:26:27 INFO  : vfs cache: cleaned: objects 0 (was 74) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2021/08/04 01:26:27 INFO  : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2021/08/04 02:26:28 INFO  : vfs cache: cleaned: objects 0 (was 9320) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2021/08/04 03:26:27 INFO  : vfs cache: cleaned: objects 0 (was 16) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2021/08/04 04:26:27 INFO  : vfs cache: cleaned: objects 356 (was 2842) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2021/08/04 05:26:28 INFO  : vfs cache: cleaned: objects 0 (was 9277) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2021/08/04 06:26:27 INFO  : vfs cache: cleaned: objects 0 (was 2182) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2021/08/04 07:26:27 INFO  : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2021/08/04 08:26:27 INFO  : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)

about this:

"--vfs-read-chunk-size-limit" "10M"

I changed it to 512M

about the main argument, in this line:

2021/08/04 06:26:27 INFO  : vfs cache: cleaned: objects 0 (was 2182) in use 0, to upload 0, uploading 0, total size 0 (was 0)

then the was 2182 what's referring? it's about 2182 file readed from remote and not cached?
it's a relief that if freed 0 bytes is specified is not referring to a cached file, but why needs to be specified? if the file is not cached so a freed 0 bytes is a useless/misleading information..

Why not just leave it at the defaults and remove it? What's the reason to set it to 512M?

You've changed your poll interval to hourly over the one minute so once per hour, it's going to check to clean the cache and the 2182 refers to all the objects that were in there and were removed from the cache. The 0 bytes means nothing was actually freed up as it was just references to files that were being read as the cache functionality is for all modes and in this case, you are only using write nothing was written and nothing was removed.

You are running in debug mode so those lines prints. You can remove -vv and that all goes away as you won't see INFO messages.

for no reason to be sure, I found it in an emby forum, so I just copied it.

Ok, what I want to be sure is that the nightly emby scan were not storing anything in the cache folder.
Before switching to writes, I was using the full mode
Every scan that was some minimal data that were cached on disk and thinking to long terms is not a goog behaviour.

Sure, I disable the -vv options soon.

What that flag does is when you read a file, say 1GB, it starts with the default range request of 128MB so it asks for them in 128M "chunks" from the remote. As it sequentially reads, it increases that up to reduce API hits and give better response. I tend to leave things on defaults unless I have a reason to change it.

I run in full mode all the time. Just easier. Rclone does a great job at managing the cache and it's a layer to help with an internet blip if you have some spare disk space to ensure rclone won't be the reason something 'stutters' (There are many reasons for that but this just removes one factor). I run a small 1TB SSD and just leave my cache there as it gives a nice speed boost.

And what about perfomance between writes and full?
You're leaving the cache there forever?
my gap is the emby library scan. From when I added some remote folders the library scan became longer (a total of 8-10 minutes without significant library change). So I'm searching the correct configuration.

whenever i add new media to my remote and i need to re-scan my emby library, i use the following command first.
rclone rc vfs/refresh recursive=true
rclone will download the folder/file structure and some meta data like mod-time, but not the file contents.
so when emby does the re-scan, it will go much quicker.

My emby setup is with real time folder monitor active so the library is usually up-to-date..
but over night I have the scheduled task to make a full library scan!
Can you explain the command a little?
can be an option to run it every x hours?
for how many minutes/hours the folder-file structure remain downloaded? where are this data placed?
thx

i do not use emby on gdrive, i use a remote that does not support polling.

i delete all emby scheduled tasks, do not generate thumbnails and whatever i can to minimize emby downloading data.

if you want to run a command every x hours, use cron.

as for settings for streaming from gdrive, this is the goto guide
https://github.com/animosity22/homescripts/blob/master/systemd/rclone.service

can be a solution to disable the --vfs-cache-max-age setting it to 0?
doing this the attribute of the files readed by emby scans would never be deleted..but if a file changed the metadata will be refreshed I think..

you can set it to zero and see what happens....

not sure, but if you search around the forum, using a value of zero has been discussed, that items would be moved immediately but you can run try it and see what happens.
or animosity022 would know.

for my rclone mounts, that i use to stream media for my emby server, i do not use -vfs-cache-mode and none of its corresponding flags.