What is the problem you are having with rclone?
I have a Google Shared Drive mounted to a Windows machine. rclone is sometimes slow to open files, even if the files are small, the Internet connection is fast, and I would expect the files to be cached locally in the VFS.
I can fabricate a scenario where this happens by reading a file which is not in the VFS. Watching the debug log in real-time, it looks like "Re-reading directory" is the slow part, and the actual downloading of the file is relatively quick.
I have seen similar slow loading with files which have been opened within the last week (and therefore should be in the VFS), but have not been able to capture logs from this situation yet.
I've tried --fast-list
to see if that can speed up (or even remove) the "re-reading directory" step, but it's not supported by the mount command.
Run the command 'rclone version' and share the full output of the command.
rclone v1.69.0
- os/version: Microsoft Windows 11 Pro 24H2 24H2 (64 bit)
- os/kernel: 10.0.26100.2605 (x86_64)
- os/type: windows
- os/arch: amd64
- go/version: go1.23.4
- go/linking: static
- go/tags: cmount
Which cloud storage system are you using? (eg Google Drive)
Google Drive, shared drive.
The command you were trying to run (eg rclone copy /tmp remote:tmp
)
rclone mount music: M: --volname "Music" --network-mode --temp-dir D:\ --cache-dir D:\ --vfs-cache-mode full --vfs-cache-max-age 2y --vfs-read-ahead 1Gi --vfs-cache-min-free-space 10Gi --config "C:\config\rclone.conf" --log-file D:\music.log --log-level DEBUG
The cache max-age is intentionally very large, ideally most-if-not-all of the drive is cached locally so file reads are as fast as possible - the mount is primarily for sync between systems. I've also tried without a vfs-read-ahead
.
Please run 'rclone config redacted' and share the full output. If you get command not found, please make sure to update rclone.
[music]
type = drive
client_id = XXX
client_secret = XXX
scope = drive
service_account_file = C:/config/service-account.json
team_drive = XXX
root_folder_id =
A log from the command that you were trying to run with the -vv
flag
Log was taken from a file with the debug level, because this mount runs as a Windows service. I also had the web GUI running at the time to see if that showed anything helpful, so please ignore log lines related to that.
Mount setup
2025/01/28 11:36:30 DEBUG : rclone: Version "v1.69.0" starting with parameters ["C:\\bin\\rclone" "mount" "music:" "M:" "--volname" "Music" "--network-mode" "--fast-list" "--temp-dir" "D:\\" "--cache-dir" "D:\\" "--vfs-cache-mode" "full" "--vfs-cache-max-age" "2y" "--vfs-read-ahead" "1Gi" "--vfs-cache-min-free-space" "10Gi" "--config" "C:\\config\\rclone.conf" "--rc" "--rc-web-gui" "--rc-user" "admin" "--rc-pass" "admin" "--rc-web-gui-update" "--log-file" "D:\\music.log" "--log-level" "DEBUG"]
2025/01/28 11:36:30 DEBUG : Current tag: v2.0.5, Release tag: v2.0.5
2025/01/28 11:36:30 NOTICE: No update to Web GUI available.
2025/01/28 11:36:30 NOTICE: Serving Web GUI
2025/01/28 11:36:30 INFO : Using --user admin --pass XXXX as authenticated user
2025/01/28 11:36:30 NOTICE: Serving remote control on http://127.0.0.1:5572/
2025/01/28 11:36:30 DEBUG : login_token "YWRtaW46YWRtaW4="
2025/01/28 11:36:30 NOTICE: --fast-list does nothing on a mount
2025/01/28 11:36:30 DEBUG : Creating backend with remote "music:"
2025/01/28 11:36:30 DEBUG : Using config file from "C:\\config\\rclone.conf"
2025/01/28 11:36:31 DEBUG : Google drive root '': vfs cache: root is "D:\\"
2025/01/28 11:36:31 DEBUG : Google drive root '': vfs cache: data root is "\\\\?\\D:\\vfs\\music"
2025/01/28 11:36:31 DEBUG : Google drive root '': vfs cache: metadata root is "\\\\?\\D:\\vfsMeta\\music"
2025/01/28 11:36:31 DEBUG : Creating backend with remote ":local,encoding='Slash,LtGt,DoubleQuote,Colon,Question,Asterisk,Pipe,BackSlash,Ctl,RightSpace,RightPeriod,InvalidUtf8,Dot':D://vfs/music/"
2025/01/28 11:36:31 DEBUG : :local: detected overridden config - adding "{fbZPM}" suffix to name
2025/01/28 11:36:31 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,LtGt,DoubleQuote,Colon,Question,Asterisk,Pipe,BackSlash,Ctl,RightSpace,RightPeriod,InvalidUtf8,Dot':D://vfs/music/" to be canonical ":local{fbZPM}://?/D:/vfs/music"
2025/01/28 11:36:31 DEBUG : Creating backend with remote ":local,encoding='Slash,LtGt,DoubleQuote,Colon,Question,Asterisk,Pipe,BackSlash,Ctl,RightSpace,RightPeriod,InvalidUtf8,Dot':D://vfsMeta/music/"
2025/01/28 11:36:31 DEBUG : :local: detected overridden config - adding "{fbZPM}" suffix to name
2025/01/28 11:36:31 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,LtGt,DoubleQuote,Colon,Question,Asterisk,Pipe,BackSlash,Ctl,RightSpace,RightPeriod,InvalidUtf8,Dot':D://vfsMeta/music/" to be canonical ":local{fbZPM}://?/D:/vfsMeta/music"
2025/01/28 11:36:31 DEBUG : Network mode mounting is enabled
2025/01/28 11:36:31 DEBUG : Mounting on "M:" ("\\server\\Music")
2025/01/28 11:36:31 DEBUG : Google drive root '': Mounting with options: ["-o" "attr_timeout=1" "-o" "uid=-1" "-o" "gid=-1" "--FileSystemName=rclone" "--VolumePrefix=\\server\\Music"]
File loading
To get this, I manually deleted a file from the VFS cache and then tried to read it. I do sometimes have slow loading of files which should be in the VFS cache (as they were opened on this machine in the last week), but haven't been able to get a log file of that yet - I will update if I do.
2025/01/28 11:45:31 INFO : Google drive root '': vfs cache: cleaned: objects 2946 (was 2946) in use 0, to upload 0, uploading 0, total size 20.148Gi (was 20.148Gi)
2025/01/28 11:45:34 DEBUG : /Track.m4a: Getattr: fh=0xFFFFFFFFFFFFFFFF
2025/01/28 11:45:34 DEBUG : : Re-reading directory (9m2.0743435s old)
2025/01/28 11:45:35 DEBUG : rc: "core/stats": with parameters map[]
2025/01/28 11:45:35 DEBUG : rc: "core/stats": reply map[bytes:0 checks:0 deletedDirs:0 deletes:0 elapsedTime:539.9796377 errors:0 eta:<nil> fatalError:false renames:0 retryError:false serverSideCopies:0 serverSideCopyBytes:0 serverSideMoveBytes:0 serverSideMoves:0 speed:0 totalBytes:0 totalChecks:0 totalTransfers:0 transferTime:0 transfers:0]: <nil>
2025/01/28 11:45:35 DEBUG : rc: "core/stats": with parameters map[]
2025/01/28 11:45:35 DEBUG : rc: "core/stats": reply map[bytes:0 checks:0 deletedDirs:0 deletes:0 elapsedTime:539.9800398 errors:0 eta:<nil> fatalError:false renames:0 retryError:false serverSideCopies:0 serverSideCopyBytes:0 serverSideMoveBytes:0 serverSideMoves:0 speed:0 totalBytes:0 totalChecks:0 totalTransfers:0 transferTime:0 transfers:0]: <nil>
2025/01/28 11:45:52 DEBUG : : Removed virtual directory entry vAddFile: "Track2.m4a"
2025/01/28 11:45:52 DEBUG : : Removed virtual directory entry vAddFile: "Track3.m4a"
There's then a debug line for every file in the shared drive of its file name followed by : Reset virtual modtime
, before:
2025/01/28 11:45:52 DEBUG : /Track.m4a: >Getattr: errc=0
2025/01/28 11:45:52 DEBUG : /Track.m4a: Getattr: fh=0xFFFFFFFFFFFFFFFF
2025/01/28 11:45:52 DEBUG : /Track.m4a: >Getattr: errc=0
2025/01/28 11:45:52 DEBUG : /Track.m4a: OpenEx: flags=0x0
2025/01/28 11:45:52 DEBUG : /Track.m4a: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2025/01/28 11:45:52 DEBUG : Track.m4a: Open: flags=O_RDONLY
2025/01/28 11:45:52 DEBUG : Track.m4a: newRWFileHandle:
2025/01/28 11:45:52 DEBUG : Track.m4a: >newRWFileHandle: err=<nil>
2025/01/28 11:45:52 DEBUG : Track.m4a: >Open: fd=Track.m4a (rw), err=<nil>
2025/01/28 11:45:52 DEBUG : /Track.m4a: >OpenFile: fd=Track.m4a (rw), err=<nil>
2025/01/28 11:45:52 DEBUG : /Track.m4a: >OpenEx: errc=0, fh=0x0
2025/01/28 11:45:52 DEBUG : /Track.m4a: Read: ofst=0, fh=0x0
2025/01/28 11:45:52 DEBUG : Track.m4a(0xc0002d6780): _readAt: size=4096, off=0
2025/01/28 11:45:52 DEBUG : Track.m4a(0xc0002d6780): openPending:
2025/01/28 11:45:52 DEBUG : Track.m4a: vfs cache: checking remote fingerprint "11713844,2023-02-04 11:42:17 +0000 UTC,b9dfa34958ad5028f9924a0f3e7af78b" against cached fingerprint "11713844,2023-02-04 11:42:17 +0000 UTC,b9dfa34958ad5028f9924a0f3e7af78b"
2025/01/28 11:45:52 ERROR : Track.m4a: vfs cache: detected external removal of cache file
2025/01/28 11:45:52 DEBUG : Track.m4a: vfs cache: removed metadata from cache as cache file externally deleted
2025/01/28 11:45:52 DEBUG : Track.m4a: vfs cache: truncate to size=11713844
2025/01/28 11:45:52 DEBUG : : Added virtual directory entry vAddFile: "Track.m4a"
2025/01/28 11:45:52 DEBUG : Track.m4a(0xc0002d6780): >openPending: err=<nil>
2025/01/28 11:45:52 DEBUG : vfs cache: looking for range={Pos:0 Size:4096} in [] - present false
2025/01/28 11:45:52 DEBUG : Track.m4a: ChunkedReader.RangeSeek from -1 to 0 length -1
2025/01/28 11:45:52 DEBUG : Track.m4a: ChunkedReader.Read at -1 length 4096 chunkOffset 0 chunkSize 134217728
2025/01/28 11:45:52 DEBUG : Track.m4a: ChunkedReader.openRange at 0 length 134217728
2025/01/28 11:45:57 DEBUG : Track.m4a: ChunkedReader.Read at 4096 length 8192 chunkOffset 0 chunkSize 134217728
2025/01/28 11:45:57 DEBUG : Track.m4a(0xc0002d6780): >_readAt: n=4096, err=<nil>
2025/01/28 11:45:57 DEBUG : /Track.m4a: >Read: n=4096
2025/01/28 11:45:57 DEBUG : Track.m4a: ChunkedReader.Read at 12288 length 16384 chunkOffset 0 chunkSize 134217728
2025/01/28 11:45:57 DEBUG : /Track.m4a: Read: ofst=89963, fh=0x0
2025/01/28 11:45:57 DEBUG : Track.m4a(0xc0002d6780): _readAt: size=4096, off=89963
2025/01/28 11:45:57 DEBUG : vfs cache: looking for range={Pos:89963 Size:4096} in [{Pos:0 Size:12288}] - present false
2025/01/28 11:45:57 DEBUG : Track.m4a: ChunkedReader.Read at 28672 length 32768 chunkOffset 0 chunkSize 134217728
2025/01/28 11:45:57 DEBUG : Track.m4a: ChunkedReader.Read at 61440 length 65536 chunkOffset 0 chunkSize 134217728
2025/01/28 11:45:57 DEBUG : Track.m4a: ChunkedReader.Read at 126976 length 131072 chunkOffset 0 chunkSize 134217728
2025/01/28 11:45:57 DEBUG : Track.m4a(0xc0002d6780): >_readAt: n=4096, err=<nil>
2025/01/28 11:45:57 DEBUG : /Track.m4a: >Read: n=4096
2025/01/28 11:45:57 DEBUG : /Track.m4a: Read: ofst=11713701, fh=0x0
2025/01/28 11:45:57 DEBUG : Track.m4a(0xc0002d6780): _readAt: size=4096, off=11713701
2025/01/28 11:45:57 DEBUG : vfs cache: looking for range={Pos:11713701 Size:143} in [{Pos:0 Size:126976}] - present false
2025/01/28 11:45:57 DEBUG : Track.m4a: ChunkedReader.Read at 258048 length 262144 chunkOffset 0 chunkSize 134217728
2025/01/28 11:45:57 DEBUG : Track.m4a: ChunkedReader.Read at 520192 length 524288 chunkOffset 0 chunkSize 134217728
2025/01/28 11:45:57 DEBUG : Track.m4a: ChunkedReader.Read at 1044480 length 1048576 chunkOffset 0 chunkSize 134217728
2025/01/28 11:45:57 DEBUG : Track.m4a: ChunkedReader.Read at 2093056 length 1048576 chunkOffset 0 chunkSize 134217728
2025/01/28 11:45:57 DEBUG : Track.m4a: ChunkedReader.Read at 3141632 length 1048576 chunkOffset 0 chunkSize 134217728
2025/01/28 11:45:58 DEBUG : Track.m4a: ChunkedReader.Read at 4190208 length 1048576 chunkOffset 0 chunkSize 134217728
2025/01/28 11:45:58 DEBUG : Track.m4a: ChunkedReader.Read at 5238784 length 1048576 chunkOffset 0 chunkSize 134217728
2025/01/28 11:45:58 DEBUG : Track.m4a: ChunkedReader.Read at 6287360 length 1048576 chunkOffset 0 chunkSize 134217728
2025/01/28 11:45:58 DEBUG : Track.m4a: ChunkedReader.Read at 7335936 length 1048576 chunkOffset 0 chunkSize 134217728
2025/01/28 11:45:58 DEBUG : Track.m4a: ChunkedReader.Read at 8384512 length 1048576 chunkOffset 0 chunkSize 134217728
2025/01/28 11:45:58 DEBUG : Track.m4a: ChunkedReader.Read at 9433088 length 1048576 chunkOffset 0 chunkSize 134217728
2025/01/28 11:45:58 DEBUG : Track.m4a: ChunkedReader.Read at 10481664 length 1048576 chunkOffset 0 chunkSize 134217728
2025/01/28 11:45:58 DEBUG : Track.m4a: ChunkedReader.Read at 11530240 length 1048576 chunkOffset 0 chunkSize 134217728
2025/01/28 11:45:58 DEBUG : Track.m4a(0xc0002d6780): >_readAt: n=143, err=EOF
2025/01/28 11:45:58 DEBUG : /Track.m4a: >Read: n=143
2025/01/28 11:45:58 DEBUG : /Track.m4a: Read: ofst=0, fh=0x0
2025/01/28 11:45:58 DEBUG : Track.m4a(0xc0002d6780): _readAt: size=4096, off=0
2025/01/28 11:45:58 DEBUG : vfs cache: looking for range={Pos:0 Size:4096} in [{Pos:0 Size:11713844}] - present true
2025/01/28 11:45:58 DEBUG : Track.m4a(0xc0002d6780): >_readAt: n=4096, err=<nil>
2025/01/28 11:45:58 DEBUG : /Track.m4a: >Read: n=4096
2025/01/28 11:45:58 DEBUG : /Track.m4a: Read: ofst=33276, fh=0x0
2025/01/28 11:45:58 DEBUG : Track.m4a(0xc0002d6780): _readAt: size=4096, off=33276
2025/01/28 11:45:58 DEBUG : vfs cache: looking for range={Pos:33276 Size:4096} in [{Pos:0 Size:11713844}] - present true