Vfs/refresh not quite working correctly

Help and Support
1

What is the problem you are having with rclone?

vfs/refresh with recursive=true only seems to be recursing 1-2 layers deep.

What is your rclone version (output from rclone version)

rclone v1.54.0-beta.5063.80e63af47

  • os/arch: windows/amd64
  • go version: go1.15.6

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

Windows 10, 64 bit

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)

rclone rc vfs/refresh -vv recursive=true --rc-addr localhost:5572 --rc-user test --rc-pass test --timeout 30m
OR
rclone rc vfs/refresh fs=GDriveStuff:/ recursive=true --rc-user test --rc-pass test -vvv --fast-list --timeout 30m

The rclone config contents with secrets removed.

[GDrive]
type = drive
client_id = CLIENTID
client_secret = CLIENTSECRET
scope = drive
token = TOKEN STUFF

[GDriveStuff]
type = crypt
remote = GDrive:Stuff
filename_encryption = standard
directory_name_encryption = true
password = PASSWORD
password2 =  SALT

the rclone rc start command is run first

start rclone rcd ^
--rc-web-gui ^
--rc-addr localhost:5572 ^
--rc-user test ^
--rc-pass test ^
--cache-dir "O:\!---rclone_VFS_Cache"

Then the drive is mounted using an rc command

start rclone rc mount/mount fs=GDriveStuff:/ mountPoint=X: mountType=cmount vfsOpt="{\"CacheMode\": 3, \"PollInterval\": 15000000000, \"CachePollInterval\": 1200000000000, \"CacheMaxAge\": 31536000000000000}" mountOpt="{\"AllowOther\": true, \"AttrTimeout\": 31320000000000000, \"VolumeName\": \"GDriveStuff\"}" --rc-user test --rc-pass test

Then the refresh command is called. I can see rclone's memory usage increasing while the refresh command is running, going from < 20 MB to ~110MB by completion. Higher level folders will notice a speedup in access times (<1s, as if it was a physical disk), but by the 3rd level, the mount behaves as if the files have never been cached before and has to query Gdrive.
However, when looking at the cache-dir folder ("O:!---rclone_VFS_Cache"), nothing gets populated, it will only populate by manually going through the folders in the mounted disk.

I can see network utilization in the RC panel when manually getting the files to refresh (going into the folders and waiting), but there is no network utilization when calling vfs/refresh.

A log from the command with the -vv flag

c:\rclone>rclone rc vfs/refresh -vv recursive=true --rc-addr localhost:5572 --rc-user test --rc-pass test --timeout 30m
2021/01/17 19:04:49 DEBUG : rclone: Version "v1.54.0-beta.5063.80e63af47" starting with parameters ["rclone" "rc" "vfs/refresh" "-vv" "recursive=true" "--rc-addr" "localhost:5572" "--rc-user" "test" "--rc-pass" "test" "--timeout" "30m"]
{
        "result": {
                "": "OK"
        }
}
2021/01/17 19:05:40 DEBUG : 4 go routines active
2

Refresh only gets a directory listing and file listing and doesn’t download anything.

The cache-dir is for using vfs-cache-mode.

3

So then why am I still waiting for file listings inside folders to populate after running it? Or am I misunderstanding what you mean?

So I shouldn't be seeing anything in the cache-dir until actually reading or writing, correct?

4

You would have to supply a debug log file and that would show you what’s going on.

I use refresh quite a lot and it works quite well.

Correct, cache dir does not do much until you read or write but that depends on what cache mode you have. Again, the debug log here would answer any questions.

5

Thanks for the quick replies!
I suspect that this is either a simple case of user error or a misunderstanding of the purpose of precaching / refresh.
I'm more than willing to supply a debug log, I'm just not sure how to get one out of rclone when using RC. The typical '--log-file=XXXX', '--log-level DEBUG' doesn't seem to write anything useful, only stuff like this.

2021/01/17 20:11:10 DEBUG : rclone: Version "v1.54.0-beta.5063.80e63af47" starting with parameters ["rclone" "rc" "vfs/refresh" "fs=GDriveStuff:/" "recursive=true" "--rc-addr" "localhost:5572" "--rc-user" "test" "--rc-pass" "test" "--timeout" "30m" "--log-file=C:\\rclone\\automountLogs\\RCDRefresh.txt" "--log-level" "DEBUG"]
2021/01/17 20:11:58 DEBUG : 4 go routines active

If I'm being stupid and not getting the log file in the right way, just let me know.
I'm not sure if calling vfs/refresh with -vv enabled is supposed to produce anything other than an error if it goes wrong.

A more specific description of problem I'm having is that I'm mounting GDriveStuff (the remote) and refreshing it, accessing directory A (full of individual files and folders, immediately inside the remote), and then when accessing some of the folders in directory A (which only contain files), windows explorer will either respond immediately with the filenames, or it'll seize up and have to go fetch them from the cloud (I'm assuming that's what it's doing because I can see the network utilization in RC, taskmanager, and netlimiter).
I can't seem to figure out why some of the folders will cause explorer to seize and others don't.

EDIT: I realized that I made a mistake in getting the logs, I've got them now. Going to clean them up and post them here.

6

Got a logfile of the full rclone rcd command, had to change out some sensitive filenames, but no lines have been added or removed.

Before running this I cleared the cache-dir and went opening up folders until I got one that had to go query rclone and the cloud.

7

What was it called? There are 100,000 lines in the log so a little clue would help :slight_smile:

How do you know it had to query the cloud? A delay when opening? Or something else?

8

I can't quite tell what you are trying to do.

Cleaning the cache-dir has nothing to do with the vfs refresh.

Here is your mount command:

2021/01/17 21:12:11 DEBUG : rc: "mount/mount": with parameters map[fs:GDriveStuff:/ mountOpt:{"AllowOther": true, "AttrTimeout": 31320000000000000, "VolumeName": "GDriveStuff"} mountPoint:V: mountType:cmount vfsOpt:{"CacheMode": 3, "PollInterval": 15000000000, "CachePollInterval": 1200000000000, "CacheMaxAge": 31536000000000000}]

You've supplied no dir-cache-time so it uses the default of 5 minutes.

You kick off a refresh:

2021/01/17 21:12:12 DEBUG : rc: "vfs/refresh": with parameters map[fs:GDriveStuff:/ recursive:true]
2021/01/17 21:12:12 DEBUG : : Reading directory tree

It finishes:

2021/01/17 21:13:10 DEBUG : rc: "vfs/refresh": reply map[result:map[:OK]]: <nil>

If you check the log, there a bunch of directory checks that all come from the cache, you can see "OpenFiles" and at 21:14, you change from listing things to reading files, which doesn't come from dir-cache.

RCD makes it a bit tougher, but you can do a very simple test with a mount.

No refresh/prime:

felix@gemini:~$ rclone mount gcrypt: /home/felix/test --rc --rc-addr :5573
2021/01/18 06:55:42 NOTICE: Serving remote control on http://0.0.0.0:5573/

and it takes over 20+ minutes for me to get a listing done:

felix@gemini:~/test$ time ls -alR | wc -l
^C

real    21m3.083s
user    0m0.700s
sys     0m1.204s

and if I do a refresh:

felix@gemini:~$ rclone mount gcrypt: /home/felix/test --rc --rc-addr :5573 --rc-user felix --rc-pass felix
2021/01/18 07:19:03 NOTICE: Serving remote control on http://0.0.0.0:5573/

and

felix@gemini:~$  /usr/bin/rclone rc vfs/refresh recursive=true --rc-addr 127.0.0.1:5573 --rc-user felix --rc-pass felix
{
        "result": {
                "": "OK"
        }
}
felix@gemini:~$ cd test
felix@gemini:~/test$ time ls -alR | wc -l
70259

real    0m1.576s
user    0m0.176s
sys     0m0.288s

To replicate, just test with a mount and a directory listing as that's all dir-cache and refresh are doing. It is separate from --cache-dir and what is happening with vfs-cache-mode.

They compliment each other as the directory and file listing making things faster if they aren't changing.

9

I'm pretty sure the folder was /DL/11-27 it should be near the very end of the logfile.

Windows explorer became totally unresponsive for around 5-10 seconds, and both netlimiter and task manager were reporting network downstream utilization by rclone.

I just did that, and I'm getting the exact same results as you.
Before refresh:

Minutes           : 9
Seconds           : 33
Milliseconds      : 18
Ticks             : 5730188426

After a remount and refresh:

Minutes           : 0
Seconds           : 4
Milliseconds      : 154
Ticks             : 41547343

Using the Measure-Command { ls -Recurse } in powershell.

So it seems like refresh is working fine, and I'm just mis-interpreting windows explorer's behavior with a lack of refresh working.

I guess my follow up question then is, why is windows explorer going unresponsive on some folders? My original reason behind precaching was to mitigate this issue and speed up cloud drive responsiveness.
An interesting discovery I made while trying to diagnose this, I when calling the refresh command, rclone is still doing something, because memory utilization is increasing. It increases to around 100MB after the first run, hitting around 170MB after the second, and all the way past 220MB after the third. This doesn't solve explorer's lack of responsiveness in some folders, in fact the first one I tried caused it to lock up for a few seconds.

A quick aside, I'm trying out this RCD system (been like 2 days of usage) after previously just using a bunch of scripts to call individual mounts without RC, and letting them run their course. And I'm running into the error of my GDrive token expiring after an hour and not refreshing. I'll start a new thread on the forum, but I thought there could be some possibility of the token expiring and this issue relating.

10

I wouldn't have a clue as I don't use Windows and everything I've read here, folks tend to avoid Windows explorer.

If you see it in the log file, you can beat it's reading the file, which is an open and a close and if it does that a lot, that would make the window appear unresponsive as depending on how many files you have, opening 20-100+ files would take some time.

All in all, just install Linux :slight_smile:

11

Been there, done that. I still run Linux through WSL for all my development work. However, I need some Windows or Mac only programs (read: Adobe) which just don't exist on Linux and I'm not interested enough in spending the time to get them to work in WINE.
I hate windows just as much as the next guy, believe me. I guess I'll go hunting for some other fixes.
Anyway, thanks for the help, and unless ncw has any other suggestions or whatnot, I'll mark this thread as closed or solved or whatever the equivalent is on this forum.

12

The usual suspect is reading thumbnails for images and videos

That shouldn't happen... I will see the new thread!

13

I just realized I haven't followed up on this.

I tracked down a post from @thestigma who advised to optimize all the mounted drives for documents, which has helped a lot with responsiveness by preventing constant fetching for thumbnails.

And instead of writing up another forum post about using mounts through RC, I just elected to spin up the mounts individually and give each of them their own RC port on localhost. Less efficient, I know, but I have enough CPU, memory, and internet to handle it, so I'm happy.

p.s. @thestigma, thank you so much for all the windows mounting posts you've made throughout the years, it's saved me so much time and headache!

1 Like
14

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