VFS keeps checking same files

Joost1991 · July 28, 2022, 9:09am

What is the problem you are having with rclone?

With vfs-cache-mode full it keeps checking the same files over and over again to see if they can be removed. This is causing downloads to be very slow, 40KB/s tops.

These files are currently uploading to Dropbox.

Run the command 'rclone version' and share the full output of the command.

I was running 1.59.0, also tried 1.60.0 beta.

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

Dropbox

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

rclone mount crypt:/ --allow-other --vfs-cache-mode full --vfs-cache-max-size 80G --vfs-read-chunk-size 16M --vfs-read-chunk-size-limit 128M --bwlimit 60M --dir-cache-time 9999h --tpslimit 10 --tpslimit-burst 10 --disable-http2 -vv --log-file=rclone.log --cache-dir cache Media

The rclone config contents with secrets removed.

[dropbox]
type = dropbox
client_id = <redacted>
client_secret = <redacted>
impersonate = <redacted>
token = {"access_token":"<redacted>","token_type":"bearer","refresh_token":"<redacted>","expiry":"2022-07-28T14:23:00.338181+02:00"}

[crypt]
type = crypt
remote = dropbox:encrypted
password = <redacted>
password2 = <redacted>

A log from the command with the `-vv` flag

2022/07/28 10:57:23 INFO  : Starting bandwidth limiter at 60Mi Byte/s
2022/07/28 10:57:23 INFO  : Starting transaction limiter: max 10 transactions/s with burst 10
2022/07/28 10:57:23 DEBUG : rclone: Version "v1.60.0-beta.6375.72227a015" starting with parameters ["rclone" "mount" "crypt:/" "--allow-other" "--vfs-cache-mode" "full" "--vfs-cache-max-size" "80G" "--vfs-read-chunk-size" "16M" "--vfs-read-chunk-size-limit" "128M" "--bwlimit" "60M" "--dir-cache-time" "9999h" "--tpslimit" "10" "--tpslimit-burst" "10" "--disable-http2" "-vv" "--log-file=rclone.log" "--cache-dir" "cache" "Media"]
2022/07/28 10:57:23 DEBUG : Creating backend with remote "crypt:/"
2022/07/28 10:57:23 DEBUG : Using config file from "/Users/j/.config/rclone/rclone.conf"
2022/07/28 10:57:23 DEBUG : Creating backend with remote "dropbox:encrypted"
2022/07/28 10:57:24 DEBUG : vfs cache: root is "/Users/j/cache"
2022/07/28 10:57:24 DEBUG : vfs cache: data root is "/Users/j/cache/vfs/crypt"
2022/07/28 10:57:24 DEBUG : vfs cache: metadata root is "/Users/j/cache/vfsMeta/crypt"
2022/07/28 10:57:24 DEBUG : Creating backend with remote "/Users/j/cache/vfs/crypt//"
2022/07/28 10:57:24 DEBUG : Creating backend with remote "/Users/j/cache/vfsMeta/crypt//"
2022/07/28 10:57:27 DEBUG : TV Shows/Catfish - The TV Show/Season 8/Catfish - The TV Show - S08E05 - Joseph & Sabrina - HDTV-1080p.mkv: vfs cache: truncate to size=1843997843
2022/07/28 10:57:27 DEBUG : TV Shows/Catfish - The TV Show/Season 8/Catfish - The TV Show - S08E05 - Joseph & Sabrina - HDTV-1080p.mkv: vfs cache: setting modification time to 2020-02-06 00:53:54 +0100 CET
2022/07/28 10:57:27 INFO  : TV Shows/Catfish - The TV Show/Season 8/Catfish - The TV Show - S08E05 - Joseph & Sabrina - HDTV-1080p.mkv: vfs cache: queuing for upload in 5s
2022/07/28 10:57:32 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item TV Shows/Catfish - The TV Show/Season 8/Catfish - The TV Show - S08E05 - Joseph & Sabrina - HDTV-1080p.mkv not removed, freed 0 bytes
2022/07/28 10:57:32 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item TV Shows/Catfish - The TV Show/Season 8/Catfish - The TV Show - S08E05 - Joseph & Sabrina - HDTV-1080p.mkv not removed, freed 0 bytes
2022/07/28 10:57:32 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item TV Shows/Catfish - The TV Show/Season 8/Catfish - The TV Show - S08E05 - Joseph & Sabrina - HDTV-1080p.mkv not removed, freed 0 bytes
2022/07/28 10:57:32 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item TV Shows/Catfish - The TV Show/Season 8/Catfish - The TV Show - S08E05 - Joseph & Sabrina - HDTV-1080p.mkv not removed, freed 0 bytes
2022/07/28 10:57:32 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item TV Shows/Catfish - The TV Show/Season 8/Catfish - The TV Show - S08E05 - Joseph & Sabrina - HDTV-1080p.mkv not removed, freed 0 bytes
2022/07/28 10:57:32 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item TV Shows/Catfish - The TV Show/Season 8/Catfish - The TV Show - S08E05 - Joseph & Sabrina - HDTV-1080p.mkv not removed, freed 0 bytes
2022/07/28 10:57:32 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item TV Shows/Catfish - The TV Show/Season 8/Catfish - The TV Show - S08E05 - Joseph & Sabrina - HDTV-1080p.mkv not removed, freed 0

It just keeps going like that. It seems like it's not respecting the --vfs-cache-poll-interval flag, which defaults to 1m.

Animosity022 · July 28, 2022, 11:00am

You can follow the issue:

Dropbox --poll-interval not respected · Issue #6205 · rclone/rclone (github.com)

ncw · July 28, 2022, 11:19am

I don't understand what is going on here!

@Animosity022 how is this related to dropbox polling? I don't think a dropbox poll should be doing anything to the VFS cache.

@Joost1991 did your storage get full or is it nearly full? That could explain the problem. Or is it at quota?

What did you set this to? This should control the interval of the "vfs cache RemoveNotInUse" checks.

--vfs-cache-poll-interval duration   Interval to poll the cache for stale objects (default 1m0s)

Animosity022 · July 28, 2022, 11:24am

It's not set so it should default to 1 minute:

--vfs-cache-poll-interval duration   Interval to poll the cache for stale objects (default 1m0s)

But the OP is seeing it happen not at 1 minute intervals.

That initial log looks like the startup cache check, but since we only have 10 seconds of a log, it's tough to see what's going on other than a file is queued for upload and it repeats a few times.

Seems like a startup issue rather than a polling issue.

Joost1991 · July 28, 2022, 11:32am

It's nearly full, 10G was left but it was already 40G over quota.

Disk is 120G, vfs-cache-max-size=80G.

The --vfs-cache-poll-interval duration was indeed not set, so it defaults to 1m0s.

What I expect to happen is that it checks the files to be removed every minute. Not all the time without stopping making the whole system basically unusable.

Just for the record, I'm running on arm64 OSX.

ncw · July 28, 2022, 11:48am

That's my expectation too!

Can you try setting --poll-interval 0 to disable the dropbox polling and we can test @Animosity022 's theory that it is something to do with that.

I have a feeling that it being over quota might be causing the problem but I'm not sure about that either!

Animosity022 · July 28, 2022, 12:04pm

It's a bug related to the startup and max size.

I can easily reproduce it.

rclone mount DB: /home/felix/test --vfs-cache-mode full --vfs-cache-max-size 20M -vvv

I copied one file in there over the quota, stopped the mount before the upload finished and start up the mount again, and you basically have a broken mount as that just spams over and over.

2022/07/28 08:03:47 DEBUG : rclone: Version "v1.59.0" starting with parameters ["rclone" "mount" "DB:" "/home/felix/test" "--vfs-cache-mode" "full" "--vfs-cache-max-size" "20M" "-vvv" "--log-file" "blah.log"]
2022/07/28 08:03:47 DEBUG : Creating backend with remote "DB:"
2022/07/28 08:03:47 DEBUG : Using config file from "/opt/rclone/rclone.conf"
2022/07/28 08:03:48 DEBUG : vfs cache: root is "/home/felix/.cache/rclone"
2022/07/28 08:03:48 DEBUG : vfs cache: data root is "/home/felix/.cache/rclone/vfs/DB"
2022/07/28 08:03:48 DEBUG : vfs cache: metadata root is "/home/felix/.cache/rclone/vfsMeta/DB"
2022/07/28 08:03:48 DEBUG : Creating backend with remote "/home/felix/.cache/rclone/vfs/DB/"
2022/07/28 08:03:48 DEBUG : Creating backend with remote "/home/felix/.cache/rclone/vfsMeta/DB/"
2022/07/28 08:03:48 DEBUG : blah.mkv: vfs cache: truncate to size=1504953150
2022/07/28 08:03:48 DEBUG : blah.mkv: vfs cache: setting modification time to 2022-07-28 08:02:20.140479899 -0400 EDT
2022/07/28 08:03:48 INFO  : blah.mkv: vfs cache: queuing for upload in 5s
2022/07/28 08:03:48 DEBUG : : Added virtual directory entry vAddFile: "blah.mkv"
2022/07/28 08:03:48 DEBUG : Dropbox root '': Mounting on "/home/felix/test"
2022/07/28 08:03:48 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item blah.mkv not removed, freed 0 bytes
2022/07/28 08:03:48 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item blah.mkv not removed, freed 0 bytes
2022/07/28 08:03:48 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item blah.mkv not removed, freed 0 bytes
2022/07/28 08:03:48 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item blah.mkv not removed, freed 0 bytes
2022/07/28 08:03:48 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item blah.mkv not removed, freed 0 bytes
2022/07/28 08:03:48 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item blah.mkv not removed, freed 0 bytes
2022/07/28 08:03:48 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item blah.mkv not removed, freed 0 bytes
2022/07/28 08:03:48 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item blah.mkv not removed, freed 0 bytes
2022/07/28 08:03:48 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item blah.mkv not removed, freed 0 bytes
2022/07/28 08:03:48 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item blah.mkv not removed, freed 0 bytes
2022/07/28 08:03:48 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item blah.mkv not removed, freed 0 bytes
2022/07/28 08:03:48 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item blah.mkv not removed, freed 0 bytes
2022/07/28 08:03:48 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item blah.mkv not removed, freed 0 bytes
2022/07/28 08:03:48 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item blah.mkv not removed, freed 0 bytes
2022/07/28 08:03:48 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item blah.mkv not removed, freed 0 bytes
2022/07/28 08:03:48 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item blah.mkv not removed, freed 0 bytes
2022/07/28 08:03:48 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item blah.mkv not removed, freed 0 bytes
2022/07/28 08:03:48 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item blah.mkv not removed, freed 0 bytes
2022/07/28 08:03:48 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item blah.mkv not removed, freed 0 bytes
2022/07/28 08:03:48 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item blah.mkv not removed, freed 0 bytes
2022/07/28 08:03:48 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item blah.mkv not removed, freed 0 bytes
2022/07/28 08:03:48 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item blah.mkv not removed, freed 0 bytes
2022/07/28 08:03:48 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item blah.mkv not removed, freed 0 bytes
2022/07/28 08:03:48 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item blah.mkv not removed, freed 0 bytes
2022/07/28 08:03:48 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item blah.mkv not removed, freed 0 bytes
2022/07/28 08:03:48 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item blah.mkv not removed, freed 0 bytes
2022/07/28 08:03:48 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item blah.mkv not removed, freed 0 bytes
2022/07/28 08:03:48 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item blah.mkv not removed, freed 0 bytes
2022/07/28 08:03:48 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item blah.mkv not removed, freed 0 bytes
2022/07/28 08:03:48 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item blah.mkv not removed, freed 0 bytes
2022/07/28 08:03:48 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item blah.mkv not removed, freed 0 bytes
2022/07/28 08:03:48 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item blah.mkv not removed, freed 0 bytes

Joost1991 · July 28, 2022, 12:10pm

Yeah indeed, I am able to reproduce exactly the same.

Maybe this is not related to my initial problem, the download speed being incredible slow at some point. When that happened, I tried to restart the mount and this problem pops up.

Not sure if they are related.

ncw · July 28, 2022, 12:15pm

Great - thank you

I'll have a go at fixing it in a moment (after lunch!)

ncw · July 28, 2022, 5:19pm

That looks like quite a bad bug! Whenever rclone was unavoidably over quota in the cache it would just chew CPU.

I've fixed it here.

I've also put some memory optimizations into the VFS to make it use (a small amount) less memory.

v1.60.0-beta.6378.c9619d16d.fix-vfs-startup on branch fix-vfs-startup (uploaded in 15-30 mins)

Animosity022 · July 28, 2022, 6:04pm

That looks good to me in my test case as it was still broken on the stable 1.59 and using the downloaded version, it properly starts up:

./rclone mount DB: /home/felix/test --vfs-cache-mode full --vfs-cache-max-size 20M -vvv
2022/07/28 14:03:59 DEBUG : Setting --config "/opt/rclone/rclone.conf" from environment variable RCLONE_CONFIG="/opt/rclone/rclone.conf"
2022/07/28 14:03:59 DEBUG : rclone: Version "v1.60.0-beta.6378.c9619d16d.fix-vfs-startup" starting with parameters ["./rclone" "mount" "DB:" "/home/felix/test" "--vfs-cache-mode" "full" "--vfs-cache-max-size" "20M" "-vvv"]
2022/07/28 14:03:59 DEBUG : Creating backend with remote "DB:"
2022/07/28 14:03:59 DEBUG : Using config file from "/opt/rclone/rclone.conf"
2022/07/28 14:03:59 DEBUG : vfs cache: root is "/home/felix/.cache/rclone"
2022/07/28 14:03:59 DEBUG : vfs cache: data root is "/home/felix/.cache/rclone/vfs/DB"
2022/07/28 14:03:59 DEBUG : vfs cache: metadata root is "/home/felix/.cache/rclone/vfsMeta/DB"
2022/07/28 14:03:59 DEBUG : Creating backend with remote "/home/felix/.cache/rclone/vfs/DB/"
2022/07/28 14:03:59 DEBUG : Creating backend with remote "/home/felix/.cache/rclone/vfsMeta/DB/"
2022/07/28 14:03:59 DEBUG : blah.mkv: vfs cache: truncate to size=1504953150
2022/07/28 14:03:59 DEBUG : blah.mkv: vfs cache: setting modification time to 2022-07-28 08:02:20.140479899 -0400 EDT
2022/07/28 14:03:59 INFO  : blah.mkv: vfs cache: queuing for upload in 5s
2022/07/28 14:03:59 DEBUG : : Added virtual directory entry vAddFile: "blah.mkv"
2022/07/28 14:03:59 DEBUG : Dropbox root '': Mounting on "/home/felix/test"
2022/07/28 14:03:59 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item blah.mkv not removed, freed 0 bytes
2022/07/28 14:03:59 INFO  : vfs cache: cleaned: objects 1 (was 1) in use 1, to upload 1, uploading 0, total size 1.402Gi (was 1.402Gi)
2022/07/28 14:03:59 DEBUG : : Root:
2022/07/28 14:03:59 DEBUG : : >Root: node=/, err=<nil>
2022/07/28 14:04:04 DEBUG : blah.mkv: vfs cache: starting upload
2022/07/28 14:04:05 DEBUG : blah.mkv: Uploading chunk 1/23
2022/07/28 14:04:07 DEBUG : blah.mkv: Uploading chunk 2/23
2022/07/28 14:04:10 DEBUG : blah.mkv: Uploading chunk 3/23
^C2022/07/28 14:04:10 INFO  : Signal received: interrupt
2022/07/28 14:04:10 INFO  : Dropbox root '': Commiting uploads - please wait...
2022/07/28 14:04:10 DEBUG : vfs cache: cleaner exiting
2022/07/28 14:04:10 ERROR : /home/felix/test: Unmounted rclone mount
2022/07/28 14:04:10 INFO  : Exiting...

Joost1991 · August 2, 2022, 7:22am

Seems like the bug has been fixed with this release.

Will now check if my original reported bug is fixed as well.

ncw · August 4, 2022, 9:22am

I've merged this to master now which means it will be in the latest beta in 15-30 minutes and released in v1.60 - thanks for testing

system · September 3, 2022, 9:22am

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