For mount sftp,why right click on exe file is so slow until it freezes

[prizi]

Hi Nick, see below the result of running your Go program in Windows 10.

In case it's important, the way I've been triggering a cache of my exe is by doing a right click > properties action on it. Let me know if that's an insufficient way to put it into the cache for the purpose of this test.

# Running test_bin.exe on sparse-cache version of my exe (the one in --cache-dir).
0.000525 D:\sparse-cache\ZBrush_4R4_Installer_WIN.exe: read   4096 at      0
0.000525 D:\sparse-cache\ZBrush_4R4_Installer_WIN.exe: read  16384 at 840192
0.000525 D:\sparse-cache\ZBrush_4R4_Installer_WIN.exe: read  15360 at 872960
0.001079 D:\sparse-cache\ZBrush_4R4_Installer_WIN.exe: read   4096 at      0
0.001587 D:\sparse-cache\ZBrush_4R4_Installer_WIN.exe: read  32768 at      0
0.001670 D:\sparse-cache\ZBrush_4R4_Installer_WIN.exe: read  32768 at 839680
0.001670 D:\sparse-cache\ZBrush_4R4_Installer_WIN.exe: read  32768 at 880640
0.001670 D:\sparse-cache\ZBrush_4R4_Installer_WIN.exe: read  32768 at      0
0.002315 D:\sparse-cache\ZBrush_4R4_Installer_WIN.exe: read  32768 at      0
0.002315 D:\sparse-cache\ZBrush_4R4_Installer_WIN.exe: read  32768 at      0
0.002855 D:\sparse-cache\ZBrush_4R4_Installer_WIN.exe: read   4096 at      0
0.002855 D:\sparse-cache\ZBrush_4R4_Installer_WIN.exe: read  16384 at 840192
0.002855 D:\sparse-cache\ZBrush_4R4_Installer_WIN.exe: read  15360 at 872960
0.003360 D:\sparse-cache\ZBrush_4R4_Installer_WIN.exe: read   4096 at      0
0.003380 D:\sparse-cache\ZBrush_4R4_Installer_WIN.exe: read  16384 at 840192
0.003380 D:\sparse-cache\ZBrush_4R4_Installer_WIN.exe: read  15360 at 872960

[Ole (Ole Frost)]

I have performed some additional test and debugging and now have a much clearer picture of the remaining delay seen in our experiments/tests.

When all of the below conditions are true, then it takes considerable longer time to open a file in a Windows mount:

• Windows (Defender) real-time protection is ON
• The file being selected/right-clicked is an executable (e.g. rclone.exe)
• The underlying cache file is partially cached, that is a file where some/certain parts of the content are binary zeros.

So there seems to be no good way to avoid it, if we like the Windows security and rclone to download only requested parts of files.

Things I have tried/investigated:

• The time it takes to scan a sparse file with 50K real size on disk seems independent from logical file size and hard disk speed. The time increases proportionally with a decrease in CPU speed.
• Increasing --buffer-size doesn't help until it it about the same size as the executable being selected, that is 50M for rclone.exe.
• Disabling file.SetSparse() in the code has no effect except making the the files take up much more disk space.
• Renaming executable files when storing in the cache doesn't help either. Tried hacking (Cache)toOSPath(name) to substitute file ending with ".exe" to be stored in the cache as ".not-an-exe". Didn't make a difference. Seems like defender somehow/luckily see through any attempt to hide what is really going on.

Things I cannot (yet) explain:

• Why the Python ang Go programs made by @ncw doesn't trigger the same scanning when executed directly on the cache file. Seems like Windows Security/Defender somehow knows the difference between a clean open and an open triggered by using winFSP/rclone - and (somewhat rightfully) increases security in the last situation.

[ncw (Nick Craig-Wood)]

@prizi

Hi Nick, see below the result of running your Go program in Windows 10.

Thanks. So that doesn't show the problem

I'm going to do some more investigation now!

@prizi

In case it's important, the way I've been triggering a cache of my exe is by doing a right click > properties action on it. Let me know if that's an insufficient way to put it into the cache for the purpose of this test.

That's perfect.

If you want you can look at the vfsMeta version of the same file. This is actually a JSON file and will show which parts of the file are present and which aren't.

---

I've managed to replicate the problem now using only Go.

The problem is caused by truncating the file to its current size - this causes the **next ** Open call to take 600ms.

This only happens on sparse files.

I've updated test_bin.zip - if you run it on a sparse file, you'll get something like this

Z:\go\src\github.com\rclone\rclone>test_bin.exe C:\cache\vfs\s3\rclone\rclone.exe
OpenFile took 0s
Close took 0s
OpenFile took 0s
Truncate took 0s
Close took 0s
OpenFile took 467.4613ms
Close took 0s
OpenFile took 0s
Truncate took 0s
Close took 0s
OpenFile took 455.3718ms
Close took 0s

So if we never truncate a file where it is the correct size then we'll get the performance back...

Here is my proposed fix (which is very similar to the first fix, but a bit more aggressive in trying not to run truncate)

v1.61.0-beta.6555.91e14b802.fix-vfs-pause-windows on branch fix-vfs-pause-windows (uploaded in 15-30 mins)

Can you give that a test please? Hopefully it should run nice and fast now. If it looks OK I'll merge it. It is small enough to go in v1.60.1

One 600ms delay is inevitable - we need to truncate the file once when we create it - this is how you create a sparse file - unless there is a different quicker way?

[ncw (Nick Craig-Wood)]

Sorry my reply crossed in the post!

@Ole

I have performed some additional test and debugging and now have a much clearer picture of the remaining delay seen in our experiments/tests.

When all of the below conditions are true, then it takes considerable longer time to open a file in a Windows mount:

• Windows (Defender) real-time protection is ON
• The file being selected/right-clicked is an executable (e.g. rclone.exe)
• The underlying cache file is partially cached, that is a file where some/certain parts of the content are binary zeros.

I agree that the sparse file is the important bit. Avoiding truncate seems to have fixed the problem.

If you disable Windows Defender does it fix it also?

Is there a way to disable Windows Defender on the VFS cache directory only? If so that would be a useful speedup for the docs.

I didn't check that it was only a problem for an executable, but I just did and you are correct.

@Ole

Things I cannot (yet) explain:

• Why the Python ang Go programs made by @ncw doesn't trigger the same scanning when executed directly on the cache file. Seems like Windows Security/Defender somehow knows the difference between a clean open and an open triggered by using winFSP/rclone - and (somewhat rightfully) increases security in the last situation.

I think this is because they didn't write to the file. The new program has a truncate call and that is enough to trigger the behaviour.

[prizi]

Using v1.61.0-beta.6555.91e14b802.fix-vfs-pause-windows I generated this log.

Nice and fast for me now Nick! Big exe shows properties within 1s, and smaller exe's are lightning fast. Nice work

[Ole (Ole Frost)]

@ncw

Avoiding truncate seems to have fixed the problem.

Confirmed now only delay on the second open

The negative effect can often be reduced by also adding something like: --vfs-cache-max-age=7d --vfs-cache-max-size=10G

Perhaps we should add little mount quick start in the beginning of the mount doc to share a good all-round setups for Windows, Mac and Other (Linux). This is my current suggestion for a simple all-round Windows mount with 10GB free for caching:

rclone mount --network-mode --buffer-size=0 --vfs-cache-mode=full --vfs-cache-max-age=7d --vfs-cache-max-size=10G

@ncw

If you disable Windows Defender does it fix it also?

Yes, but not recommended.

@ncw

Is there a way to disable Windows Defender on the VFS cache directory only? If so that would be a useful speedup for the docs.

That is possible, but again not recommended. Most wouldn't understand the risks/consequences nor how to mitigate them. It would therefore easily make the rclone cache a great place to hide malware and thereby increase the risk of rclone being considered malware too.

@ncw

I think this is because they didn't write to the file. The new program has a truncate call and that is enough to trigger the behaviour.

Well spotted!

Perhaps we can improve responsiveness by doing an open/close immediately after the first close - or something along these lines. Then it will often not be noticeable. That may well be easier said that done.

I naively tried a RDWR open/close immediately after the truncate and that was instant, but it didn't have the desired effect - perhaps Defender is sniffing the file header to see it is an executable.

[ncw (Nick Craig-Wood)]

Thanks for testing.

I've revised the commit and comments to take into account @Ole's findings and I'll merge this now

I've merged this to master now which means it will be in the latest beta in 15-30 minutes and released in v1.61. I think since it only speeds up executables I won't put it in v1.60.1.

[ncw (Nick Craig-Wood)]

@Ole

Perhaps we should add little mount quick start in the beginning of the mount doc to share a good all-round setups for Windows, Mac and Other (Linux). This is my current suggestion for a simple all-round Windows mount with 10GB free for caching:

rclone mount --net-work-mode --buffer-size=0 --vfs-cache-mode=full --vfs-cache-max-age=7d --vfs-cache-max-size=10G

That is probably a good idea. I wouldn't particularly recommend --buffer-size=0 though - the VFS readahead mechanisms rely on it. Why do you have that?

your notes about windows defender

@Ole

Perhaps we can improve responsiveness by doing an open/close immediately after the first close - or something along these lines. Then it will often not be noticeable. That may well be easier said that done.

I naively tried a RDWR open/close immediately after the truncate and that was instant, but it didn't have the desired effect - perhaps Defender is sniffing the file header to see it is an executable.

I don't know quite what defender will be making of a sparse file where most of the executable reads as NULLs!

[Ole (Ole Frost)]

@ncw

That is probably a good idea. I wouldn't particularly recommend --buffer-size=0 though - the VFS readahead mechanisms rely on it. Why do you have that?

From the last half of this very liked post:
https://forum.rclone.org/t/for-mount-sftp-why-right-click-on-exe-file-is-so-slow-until-it-freezes/33830/13

It vastly improves responsiveness, except on very fast connections and backends where it "only" improves by a factor 2:

@prizi

After clearing the cache and adding an additional flag of --buffer-size=0 the 700MB exe responds instantly to a right-click (reduced from ~1s), and takes ~4s to display file properties (reduced from ~8s). That's a really good improvement.

I see no negative effects, do you?

[ncw (Nick Craig-Wood)]

@Ole

From the last half of this very liked post:
For mount sftp,why right click on exe file is so slow until it freezes - #13 by Ole

It vastly improves responsiveness, except on very fast connections and backends where it "only" improves by a factor 2:

How about throughput? Does setting --buffer-size 0 affect throughput?

Setting --buffer-size shouldn't really affect responsiveness except in the presence of limited network speed which I guess is your point.

I guess --buffer-size 16M the default is optimized for large files, video streaming.

I wonder whether rclone should not use the buffer for small files. (We already don't use it for files < buffer_size).

Maybe the VFS read ahead by the buffer size is a mistake...

[prizi]

@Ole

Perhaps we should add little mount quick start in the beginning of the mount doc to share a good all-round setups for Windows, Mac and Other (Linux).

Highlighting the optimal recommended parameters for different use-cases could be very helpful. Nice idea Ole

@Ole

I see no negative effects, do you?

--buffer-size=0 definitely sped up the right click > properties action on executables, but I have not been able to notice any other significant effects (positive or negative) with my limited usage. If I find anything I will let you know

[Ole (Ole Frost)]

@ncw

How about throughput? Does setting --buffer-size 0 affect throughput?

It didn't in my tests - also tried sync/copy to/from local.

@ncw

Setting --buffer-size shouldn't really affect responsiveness except in the presence of limited network speed which I guess is your point.

Incorrect, it always makes a difference whether you need to download 64KB or 32MB (to display a simple icon). 32MB still takes 300ms on a 1Gbps fiber (best case), that is enough to be noticeable when put on top of overhead and latencies.

@ncw

I guess --buffer-size 16M the default is optimized for large files, video streaming.

My test showed no negative effect of --buffer-size=0 on downloads easily surpassing the need for 8K Cinematic UHD. I also guess it may improve responsiveness on video streaming by making the first data earlier available. I may also help a lot when scanning and creating thumbnails, which are probably random reads. I will leave the testing so somebody with a working cinema setup.

My guess is the 16M buffer size was optimized for copy and sync between remotes, where it still makes a lot of sense. Seems like --buffer-size=0 is better suited for mounts on todays pcs (with GUI, gigabit, multicore, SSD etc).

@ncw

I wonder whether rclone should not use the buffer for small files. (We already don't use it for files < buffer_size).

It also has a great effect on large files, when you are doing random reads - apparently without any negative effect on sequential reads. Size really doesn't matter when doing random reads.

@ncw

Maybe the VFS read ahead by the buffer size is a mistake...

I cannot see the need for VFS read ahead on a a typical pc. It can easily move data with the responsiveness needed to efficiently utilize networked storage up to the available bandwidth.

What are the use cases where VFS read ahead makes a difference?

[ncw (Nick Craig-Wood)]

This all indicates to me that the VFS readahead isn't working as designed.

@Ole

Incorrect, it always makes a difference whether you need to download 64KB or 32MB (to display a simple icon). 32MB still takes 300ms on a 1Gbps fiber (best case), that is enough to be noticeable when put on top of overhead and latencies.

The idea is that it will download the buffer size (16M) but it will return to the OS as soon as the 64K for the icon has been returned and continue downloading up to the buffer size in the background so this really shouldn't affect latency.

@Ole

My guess is the 16M buffer size was optimized for copy and sync between remotes, where it still makes a lot of sense. Seems like --buffer-size=0 is better suited for mounts on todays pcs (with GUI, gigabit, multicore, SSD etc).

The 16M buffer was indeed optimised for copy/sync. It has 3 important uses

1. it decouples the reading from the writing which increases efficiency
2. it adds a buffer which is useful to keep throughput up if there are pauses
3. it increases the read-ahead for --vfs-cache-mode full

I'm beginning to suspect that option 3 is incorrectly implemented.

Give this a try without --buffer-size=0 and see what you think. It disables option 3

v1.61.0-beta.6566.b7cba2835.fix-vfs-latency on branch fix-vfs-latency (uploaded in 15-30 mins)

[Ole (Ole Frost)]

@ncw

continue downloading up to the buffer size in the background so this really shouldn't affect latency.

I think any extra data downloaded may affect responsiveness/experience negatively in several ways:

1. The extra data fetched will affect the burst mode and throttling of the internet connection and remote, and thereby potentially slow any immediately following request. Most connections (cable/fibre) and remotes (OneDrive, Google Drive) are throttled based on the amount of data transferred in the past second(s).
2. The rclone cache will be filled with (potentially) unneeded data and then push out older but more needed data (--vfs-cache-max-size)
3. Other concurrent (non-rclone) activities will have less available resources (CPU, network).
4. Thermal capacity (especially laptops) may be affected, so the next CPU burst is reduced.

I therefore don't like rclone mount to do any read ahead unless explicitly told to do so and therefore prefer--buffer-size=0, until I see a test/scenario proving me wrong.

@ncw

Give this a try without --buffer-size=0 and see what you think. It disables option 3

v1.61.0-beta.6566.b7cba2835.fix-vfs-latency on branch fix-vfs-latency (uploaded in 15-30 mins)

Sure, will try to find the time later today.

[ncw (Nick Craig-Wood)]

@Ole

I think any extra data downloaded may affect responsiveness/experience negatively in several ways:

1. The extra data fetched will affect the burst mode and throttling of the internet connection and remote, and thereby potentially slow any immediately following request. Most connections (cable/fibre) and remotes (OneDrive, Google Drive) are throttled based on the amount of data transferred in the past second(s).
2. The rclone cache will be filled with (potentially) unneeded data and then push out older but more needed data (--vfs-cache-max-size)
3. Other concurrent (non-rclone) activities will have less available resources (CPU, network).
4. Thermal capacity (especially laptops) may be affected, so the next CPU burst is reduced.

I therefore don't like rclone mount to do any read ahead unless explicitly told to do so and therefore prefer--buffer-size=0, until I see a test/scenario proving me wrong.

All good points.

@Ole

Sure, will try to find the time later today.

[Ole (Ole Frost)]

@ncw

The 16M buffer was indeed optimised for copy/sync. It has 3 important uses

1. it decouples the reading from the writing which increases efficiency
2. it adds a buffer which is useful to keep throughput up if there are pauses
3. it increases the read-ahead for --vfs-cache-mode full

I'm beginning to suspect that option 3 is incorrectly implemented.

Give this a try without --buffer-size=0 and see what you think. It disables option 3

v1.61.0-beta.6566.b7cba2835.fix-vfs-latency on branch fix-vfs-latency (uploaded in 15-30 mins)

Thanks Nick!

I have performed the test very much like my initial test. I click the first file in the folder and then press and hold the arrow key to rapidly select the files in the folder one by one - rclone.exe is in the middle.

The tests show a significant improvement, but is still far from the improvement when using --buffer-size=0.

The results are:

Baseline before fix with default buffer size: response time 14 sec, 16.072Mi downloaded
fix-vfs-latency with default buffer size: response time 5.2 sec, 6.021Mi downloaded
fix-vfs-latency with --buffer-size=0: response time 1.9 sec, 0.089Mi downloaded

Note that more than half of the 1.9 sec is fixed time waiting for OneDrive to open cursors, other remotes may well be significantly faster.

Important rclone parameters used in the tests:

 --network-mode --vfs-cache-mode=full --bwlimit=1M --dump=headers --log-format=time,microseconds

Logs are in the following posts and have been reduced with this regex:

" OpenEx:|>Release:|readAt:|ChunkedReader.|HTTP RE| vfs cache:"

[Ole (Ole Frost)]

Baseline: master branch with default --buffer-size (16M)

Explorer response time: 14 sec (time from first "OpenEx:" to last ">_readAt:")
Data downloaded and stored in cache: 16.072Mi

14:32:14.009617 DEBUG : /rclone-v1.60.0-windows-amd64/rclone.exe: OpenEx: flags=0x0
14:32:14.010122 DEBUG : /rclone-v1.60.0-windows-amd64/rclone.exe: >Release: errc=0
14:32:14.010122 DEBUG : /rclone-v1.60.0-windows-amd64/rclone.exe: OpenEx: flags=0x0
14:32:14.011371 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc000064480): _readAt: size=4096, off=0
14:32:14.011371 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: vfs cache: checking remote fingerprint "47669760,2022-11-02 16:24:07 +0000 UTC,9bca9c8b180733a5f921a5e276598cf0b50e0e79" against cached fingerprint ""
14:32:14.011876 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: vfs cache: truncate to size=47669760
14:32:14.012423 DEBUG : vfs cache: looking for range={Pos:0 Size:4096} in [] - present false
14:32:14.012423 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.RangeSeek from -1 to 0 length -1
14:32:14.012939 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.Read at -1 length 4096 chunkOffset 0 chunkSize 134217728
14:32:14.012939 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.openRange at 0 length 134217728
14:32:14.013464 DEBUG : HTTP REQUEST (req 0xc000af2100)
14:32:14.448096 DEBUG : HTTP RESPONSE (req 0xc000af2100)
14:32:14.448833 DEBUG : HTTP REQUEST (req 0xc000af2600)
14:32:15.126271 DEBUG : HTTP RESPONSE (req 0xc000af2600)
14:32:15.126468 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.Read at 4096 length 8192 chunkOffset 0 chunkSize 134217728
14:32:15.126662 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.Read at 12288 length 16384 chunkOffset 0 chunkSize 134217728
14:32:15.126662 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc000064480): >_readAt: n=4096, err=<nil>
14:32:15.127560 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc000064480): _readAt: size=16384, off=47643648
14:32:15.127560 DEBUG : vfs cache: looking for range={Pos:47643648 Size:16384} in [{Pos:0 Size:4096}] - present false
14:32:15.127560 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.RangeSeek from -1 to 47643648 length -1
14:32:15.128309 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.Read at -1 length 4096 chunkOffset 47643648 chunkSize 134217728
14:32:15.128309 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.openRange at 47643648 length 134217728
14:32:15.128677 DEBUG : HTTP REQUEST (req 0xc000a10400)
14:32:15.131553 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.Read at 28672 length 32768 chunkOffset 0 chunkSize 134217728
14:32:15.131553 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.Read at 61440 length 65536 chunkOffset 0 chunkSize 134217728
14:32:15.145988 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.Read at 126976 length 131072 chunkOffset 0 chunkSize 134217728
14:32:15.152164 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.Read at 258048 length 262144 chunkOffset 0 chunkSize 134217728
14:32:15.165542 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.Read at 520192 length 524288 chunkOffset 0 chunkSize 134217728
14:32:15.274828 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.Read at 1044480 length 1048576 chunkOffset 0 chunkSize 134217728
14:32:15.307908 DEBUG : HTTP RESPONSE (req 0xc000a10400)
14:32:15.308550 DEBUG : HTTP REQUEST (req 0xc0006dc200)
14:32:15.326388 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.Read at 2093056 length 1048576 chunkOffset 0 chunkSize 134217728
14:32:15.384045 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.Read at 3141632 length 1048576 chunkOffset 0 chunkSize 134217728
14:32:15.449394 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.Read at 4190208 length 1048576 chunkOffset 0 chunkSize 134217728
14:32:16.175412 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.Read at 5238784 length 1048576 chunkOffset 0 chunkSize 134217728
14:32:17.170092 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.Read at 6287360 length 1048576 chunkOffset 0 chunkSize 134217728
14:32:17.295297 DEBUG : HTTP RESPONSE (req 0xc0006dc200)
14:32:17.296164 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.Read at 47647744 length 8192 chunkOffset 47643648 chunkSize 134217728
14:32:17.296164 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.Read at 47655936 length 16384 chunkOffset 47643648 chunkSize 134217728
14:32:17.296164 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc000064480): >_readAt: n=16384, err=<nil>
14:32:17.297232 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc000064480): _readAt: size=1536, off=47668224
14:32:17.297232 DEBUG : vfs cache: looking for range={Pos:47668224 Size:1536} in [{Pos:0 Size:4096} {Pos:47643648 Size:26112}] - present true
14:32:17.297232 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc000064480): >_readAt: n=1536, err=<nil>
14:32:17.298173 DEBUG : /rclone-v1.60.0-windows-amd64/rclone.exe: OpenEx: flags=0x0
14:32:17.299944 DEBUG : /rclone-v1.60.0-windows-amd64/rclone.exe: OpenEx: flags=0x0
14:32:17.312770 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc000486200): _readAt: size=4096, off=0
14:32:21.183444 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: vfs cache: setting modification time to 2022-11-02 16:24:07 +0000 UTC
14:32:21.197577 DEBUG : /rclone-v1.60.0-windows-amd64/rclone.exe: >Release: errc=0
14:32:21.197577 DEBUG : /rclone-v1.60.0-windows-amd64/rclone.exe: >Release: errc=0
14:32:21.198201 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: vfs cache: checking remote fingerprint "47669760,2022-11-02 16:24:07 +0000 UTC,9bca9c8b180733a5f921a5e276598cf0b50e0e79" against cached fingerprint "47669760,2022-11-02 16:24:07 +0000 UTC,9bca9c8b180733a5f921a5e276598cf0b50e0e79"
14:32:21.198811 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: vfs cache: truncate to size=47669760 (not needed as size correct)
14:32:21.224861 DEBUG : vfs cache: looking for range={Pos:0 Size:4096} in [{Pos:0 Size:7335936} {Pos:47643648 Size:26112}] - present true
14:32:21.224861 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.RangeSeek from -1 to 7335936 length -1
14:32:21.224861 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc000486200): >_readAt: n=4096, err=<nil>
14:32:21.224861 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.Read at -1 length 4096 chunkOffset 7335936 chunkSize 134217728
14:32:21.224861 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.openRange at 7335936 length 134217728
14:32:21.224861 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc000486200): _readAt: size=16384, off=47643648
14:32:21.224861 DEBUG : vfs cache: looking for range={Pos:47643648 Size:16384} in [{Pos:0 Size:7335936} {Pos:47643648 Size:26112}] - present true
14:32:21.225378 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc000486200): >_readAt: n=16384, err=<nil>
14:32:21.225378 DEBUG : HTTP REQUEST (req 0xc0006dc200)
14:32:21.225465 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc000486200): _readAt: size=1536, off=47668224
14:32:21.225465 DEBUG : vfs cache: looking for range={Pos:47668224 Size:1536} in [{Pos:0 Size:7335936} {Pos:47643648 Size:26112}] - present true
14:32:21.225465 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc000486200): >_readAt: n=1536, err=<nil>
14:32:21.225465 DEBUG : /rclone-v1.60.0-windows-amd64/rclone.exe: OpenEx: flags=0x0
14:32:21.226522 DEBUG : /rclone-v1.60.0-windows-amd64/rclone.exe: OpenEx: flags=0x0
14:32:21.227105 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc000064680): _readAt: size=4096, off=0
14:32:21.352775 DEBUG : HTTP RESPONSE (req 0xc0006dc200)
14:32:21.353405 DEBUG : HTTP REQUEST (req 0xc000830800)
14:32:22.235332 DEBUG : HTTP RESPONSE (req 0xc000830800)
14:32:22.247708 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: vfs cache: setting modification time to 2022-11-02 16:24:07 +0000 UTC
14:32:22.248254 DEBUG : /rclone-v1.60.0-windows-amd64/rclone.exe: >Release: errc=0
14:32:22.248254 DEBUG : /rclone-v1.60.0-windows-amd64/rclone.exe: >Release: errc=0
14:32:22.248254 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: vfs cache: checking remote fingerprint "47669760,2022-11-02 16:24:07 +0000 UTC,9bca9c8b180733a5f921a5e276598cf0b50e0e79" against cached fingerprint "47669760,2022-11-02 16:24:07 +0000 UTC,9bca9c8b180733a5f921a5e276598cf0b50e0e79"
14:32:22.248812 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: vfs cache: truncate to size=47669760 (not needed as size correct)
14:32:22.276093 DEBUG : vfs cache: looking for range={Pos:0 Size:4096} in [{Pos:0 Size:7340032} {Pos:47643648 Size:26112}] - present true
14:32:22.276093 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.RangeSeek from -1 to 7340032 length -1
14:32:22.276093 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc000064680): >_readAt: n=4096, err=<nil>
14:32:22.276240 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.Read at -1 length 4096 chunkOffset 7340032 chunkSize 134217728
14:32:22.276338 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.openRange at 7340032 length 134217728
14:32:22.276338 DEBUG : HTTP REQUEST (req 0xc0004c0b00)
14:32:22.276338 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc000064680): _readAt: size=16384, off=47643648
14:32:22.276893 DEBUG : vfs cache: looking for range={Pos:47643648 Size:16384} in [{Pos:0 Size:7340032} {Pos:47643648 Size:26112}] - present true
14:32:22.276893 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc000064680): >_readAt: n=16384, err=<nil>
14:32:22.277101 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc000064680): _readAt: size=1536, off=47668224
14:32:22.277101 DEBUG : vfs cache: looking for range={Pos:47668224 Size:1536} in [{Pos:0 Size:7340032} {Pos:47643648 Size:26112}] - present true
14:32:22.277101 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc000064680): >_readAt: n=1536, err=<nil>
14:32:22.277265 DEBUG : /rclone-v1.60.0-windows-amd64/rclone.exe: OpenEx: flags=0x0
14:32:22.278092 DEBUG : /rclone-v1.60.0-windows-amd64/rclone.exe: OpenEx: flags=0x0
14:32:22.278902 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc00002a200): _readAt: size=4096, off=0
14:32:22.484274 DEBUG : HTTP RESPONSE (req 0xc0004c0b00)
14:32:22.485294 DEBUG : HTTP REQUEST (req 0xc0006dc800)
14:32:23.555141 DEBUG : HTTP RESPONSE (req 0xc0006dc800)
14:32:23.587845 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: vfs cache: setting modification time to 2022-11-02 16:24:07 +0000 UTC
14:32:23.588054 DEBUG : /rclone-v1.60.0-windows-amd64/rclone.exe: >Release: errc=0
14:32:23.588054 DEBUG : /rclone-v1.60.0-windows-amd64/rclone.exe: >Release: errc=0
14:32:23.588736 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: vfs cache: checking remote fingerprint "47669760,2022-11-02 16:24:07 +0000 UTC,9bca9c8b180733a5f921a5e276598cf0b50e0e79" against cached fingerprint "47669760,2022-11-02 16:24:07 +0000 UTC,9bca9c8b180733a5f921a5e276598cf0b50e0e79"
14:32:23.600745 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: vfs cache: truncate to size=47669760 (not needed as size correct)
14:32:23.636025 DEBUG : vfs cache: looking for range={Pos:0 Size:4096} in [{Pos:0 Size:7344128} {Pos:47643648 Size:26112}] - present true
14:32:23.636025 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.RangeSeek from -1 to 7344128 length -1
14:32:23.636025 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc00002a200): >_readAt: n=4096, err=<nil>
14:32:23.636025 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.Read at -1 length 4096 chunkOffset 7344128 chunkSize 134217728
14:32:23.636025 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.openRange at 7344128 length 134217728
14:32:23.636611 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc00002a200): _readAt: size=16384, off=47643648
14:32:23.636611 DEBUG : HTTP REQUEST (req 0xc000a10500)
14:32:23.636611 DEBUG : vfs cache: looking for range={Pos:47643648 Size:16384} in [{Pos:0 Size:7344128} {Pos:47643648 Size:26112}] - present true
14:32:23.637170 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc00002a200): >_readAt: n=16384, err=<nil>
14:32:23.637170 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc00002a200): _readAt: size=1536, off=47668224
14:32:23.637170 DEBUG : vfs cache: looking for range={Pos:47668224 Size:1536} in [{Pos:0 Size:7344128} {Pos:47643648 Size:26112}] - present true
14:32:23.637170 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc00002a200): >_readAt: n=1536, err=<nil>
14:32:23.660042 DEBUG : /rclone-v1.60.0-windows-amd64/rclone.exe: OpenEx: flags=0x0
14:32:23.660550 DEBUG : /rclone-v1.60.0-windows-amd64/rclone.exe: OpenEx: flags=0x0
14:32:23.661589 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc000064980): _readAt: size=4096, off=0
14:32:23.867220 DEBUG : HTTP RESPONSE (req 0xc000a10500)
14:32:23.867851 DEBUG : HTTP REQUEST (req 0xc0006dcb00)
14:32:25.043951 DEBUG : HTTP RESPONSE (req 0xc0006dcb00)
14:32:25.046561 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: vfs cache: setting modification time to 2022-11-02 16:24:07 +0000 UTC
14:32:25.046561 DEBUG : /rclone-v1.60.0-windows-amd64/rclone.exe: >Release: errc=0
14:32:25.047173 DEBUG : /rclone-v1.60.0-windows-amd64/rclone.exe: >Release: errc=0
14:32:25.047173 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: vfs cache: checking remote fingerprint "47669760,2022-11-02 16:24:07 +0000 UTC,9bca9c8b180733a5f921a5e276598cf0b50e0e79" against cached fingerprint "47669760,2022-11-02 16:24:07 +0000 UTC,9bca9c8b180733a5f921a5e276598cf0b50e0e79"
14:32:25.048814 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: vfs cache: truncate to size=47669760 (not needed as size correct)
14:32:25.079872 DEBUG : vfs cache: looking for range={Pos:0 Size:4096} in [{Pos:0 Size:7348224} {Pos:47643648 Size:26112}] - present true
14:32:25.079872 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.RangeSeek from -1 to 7348224 length -1
14:32:25.079872 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc000064980): >_readAt: n=4096, err=<nil>
14:32:25.079872 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.Read at -1 length 4096 chunkOffset 7348224 chunkSize 134217728
14:32:25.079872 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.openRange at 7348224 length 134217728
14:32:25.080441 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc000064980): _readAt: size=16384, off=47643648
14:32:25.080441 DEBUG : vfs cache: looking for range={Pos:47643648 Size:16384} in [{Pos:0 Size:7348224} {Pos:47643648 Size:26112}] - present true
14:32:25.080441 DEBUG : HTTP REQUEST (req 0xc0004c1d00)
14:32:25.080441 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc000064980): >_readAt: n=16384, err=<nil>
14:32:25.080972 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc000064980): _readAt: size=1536, off=47668224
14:32:25.080972 DEBUG : vfs cache: looking for range={Pos:47668224 Size:1536} in [{Pos:0 Size:7348224} {Pos:47643648 Size:26112}] - present true
14:32:25.080972 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc000064980): >_readAt: n=1536, err=<nil>
14:32:25.080972 DEBUG : /rclone-v1.60.0-windows-amd64/rclone.exe: OpenEx: flags=0x0
14:32:25.082303 DEBUG : /rclone-v1.60.0-windows-amd64/rclone.exe: >Release: errc=0
14:32:25.082812 DEBUG : /rclone-v1.60.0-windows-amd64/rclone.exe: OpenEx: flags=0x0
14:32:25.083999 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc0006e2640): _readAt: size=4096, off=0
14:32:25.207933 DEBUG : HTTP RESPONSE (req 0xc0004c1d00)
14:32:25.208539 DEBUG : HTTP REQUEST (req 0xc0006ed500)
14:32:26.062024 DEBUG : HTTP RESPONSE (req 0xc0006ed500)
14:32:26.064159 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: vfs cache: setting modification time to 2022-11-02 16:24:07 +0000 UTC
14:32:26.066924 DEBUG : /rclone-v1.60.0-windows-amd64/rclone.exe: >Release: errc=0
14:32:26.067058 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: vfs cache: checking remote fingerprint "47669760,2022-11-02 16:24:07 +0000 UTC,9bca9c8b180733a5f921a5e276598cf0b50e0e79" against cached fingerprint "47669760,2022-11-02 16:24:07 +0000 UTC,9bca9c8b180733a5f921a5e276598cf0b50e0e79"
14:32:26.068235 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: vfs cache: truncate to size=47669760 (not needed as size correct)
14:32:26.090254 DEBUG : vfs cache: looking for range={Pos:0 Size:4096} in [{Pos:0 Size:7352320} {Pos:47643648 Size:26112}] - present true
14:32:26.090254 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.RangeSeek from -1 to 7352320 length -1
14:32:26.090758 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.Read at -1 length 4096 chunkOffset 7352320 chunkSize 134217728
14:32:26.090758 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.openRange at 7352320 length 134217728
14:32:26.090758 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc0006e2640): >_readAt: n=4096, err=<nil>
14:32:26.090758 DEBUG : HTTP REQUEST (req 0xc000af2500)
14:32:26.090758 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc0006e2640): _readAt: size=16384, off=47643648
14:32:26.090758 DEBUG : vfs cache: looking for range={Pos:47643648 Size:16384} in [{Pos:0 Size:7352320} {Pos:47643648 Size:26112}] - present true
14:32:26.090758 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc0006e2640): >_readAt: n=16384, err=<nil>
14:32:26.091344 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc0006e2640): _readAt: size=1536, off=47668224
14:32:26.091344 DEBUG : vfs cache: looking for range={Pos:47668224 Size:1536} in [{Pos:0 Size:7352320} {Pos:47643648 Size:26112}] - present true
14:32:26.091344 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc0006e2640): >_readAt: n=1536, err=<nil>
14:32:26.091344 DEBUG : /rclone-v1.60.0-windows-amd64/rclone.exe: OpenEx: flags=0x0
14:32:26.092406 DEBUG : /rclone-v1.60.0-windows-amd64/rclone.exe: OpenEx: flags=0x0
14:32:26.092942 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc000064b80): _readAt: size=4096, off=0
14:32:26.245981 DEBUG : HTTP RESPONSE (req 0xc000af2500)
14:32:26.247080 DEBUG : HTTP REQUEST (req 0xc000830b00)
14:32:27.317603 DEBUG : HTTP RESPONSE (req 0xc000830b00)
14:32:27.318058 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.Read at 7356416 length 8192 chunkOffset 7352320 chunkSize 134217728
14:32:27.318327 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.Read at 7364608 length 16384 chunkOffset 7352320 chunkSize 134217728
14:32:27.332407 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: vfs cache: setting modification time to 2022-11-02 16:24:07 +0000 UTC
14:32:27.332920 DEBUG : /rclone-v1.60.0-windows-amd64/rclone.exe: >Release: errc=0
14:32:27.332995 DEBUG : /rclone-v1.60.0-windows-amd64/rclone.exe: >Release: errc=0
14:32:27.332995 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: vfs cache: checking remote fingerprint "47669760,2022-11-02 16:24:07 +0000 UTC,9bca9c8b180733a5f921a5e276598cf0b50e0e79" against cached fingerprint "47669760,2022-11-02 16:24:07 +0000 UTC,9bca9c8b180733a5f921a5e276598cf0b50e0e79"
14:32:27.333599 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: vfs cache: truncate to size=47669760 (not needed as size correct)
14:32:27.356695 DEBUG : vfs cache: looking for range={Pos:0 Size:4096} in [{Pos:0 Size:7380992} {Pos:47643648 Size:26112}] - present true
14:32:27.356695 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.RangeSeek from -1 to 7380992 length -1
14:32:27.356695 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc000064b80): >_readAt: n=4096, err=<nil>
14:32:27.356695 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.Read at -1 length 4096 chunkOffset 7380992 chunkSize 134217728
14:32:27.356695 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.openRange at 7380992 length 134217728
14:32:27.357230 DEBUG : HTTP REQUEST (req 0xc000a10b00)
14:32:27.357230 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc000064b80): _readAt: size=16384, off=47643648
14:32:27.357770 DEBUG : vfs cache: looking for range={Pos:47643648 Size:16384} in [{Pos:0 Size:7380992} {Pos:47643648 Size:26112}] - present true
14:32:27.357770 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc000064b80): >_readAt: n=16384, err=<nil>
14:32:27.357770 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc000064b80): _readAt: size=1536, off=47668224
14:32:27.357770 DEBUG : vfs cache: looking for range={Pos:47668224 Size:1536} in [{Pos:0 Size:7380992} {Pos:47643648 Size:26112}] - present true
14:32:27.357770 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc000064b80): >_readAt: n=1536, err=<nil>
14:32:27.358427 DEBUG : /rclone-v1.60.0-windows-amd64/rclone.exe: OpenEx: flags=0x0
14:32:27.359507 DEBUG : /rclone-v1.60.0-windows-amd64/rclone.exe: OpenEx: flags=0x0
14:32:27.360962 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc00002ac00): _readAt: size=4096, off=0
14:32:27.486899 DEBUG : HTTP RESPONSE (req 0xc000a10b00)
14:32:27.488258 DEBUG : HTTP REQUEST (req 0xc000af2b00)
14:32:28.155915 DEBUG : HTTP RESPONSE (req 0xc000af2b00)
14:32:28.155915 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.Read at 7385088 length 8192 chunkOffset 7380992 chunkSize 134217728
14:32:28.158648 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: vfs cache: setting modification time to 2022-11-02 16:24:07 +0000 UTC
14:32:28.158932 DEBUG : /rclone-v1.60.0-windows-amd64/rclone.exe: >Release: errc=0
14:32:28.159124 DEBUG : /rclone-v1.60.0-windows-amd64/rclone.exe: >Release: errc=0
14:32:28.159124 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: vfs cache: checking remote fingerprint "47669760,2022-11-02 16:24:07 +0000 UTC,9bca9c8b180733a5f921a5e276598cf0b50e0e79" against cached fingerprint "47669760,2022-11-02 16:24:07 +0000 UTC,9bca9c8b180733a5f921a5e276598cf0b50e0e79"
14:32:28.170135 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: vfs cache: truncate to size=47669760 (not needed as size correct)
14:32:28.203251 DEBUG : vfs cache: looking for range={Pos:0 Size:4096} in [{Pos:0 Size:7393280} {Pos:47643648 Size:26112}] - present true
14:32:28.203251 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.RangeSeek from -1 to 7393280 length -1
14:32:28.203251 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc00002ac00): >_readAt: n=4096, err=<nil>
14:32:28.203251 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.Read at -1 length 4096 chunkOffset 7393280 chunkSize 134217728
14:32:28.203251 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.openRange at 7393280 length 134217728
14:32:28.203758 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc00002ac00): _readAt: size=16384, off=47643648
14:32:28.203758 DEBUG : vfs cache: looking for range={Pos:47643648 Size:16384} in [{Pos:0 Size:7393280} {Pos:47643648 Size:26112}] - present true
14:32:28.203758 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc00002ac00): >_readAt: n=16384, err=<nil>
14:32:28.203758 DEBUG : HTTP REQUEST (req 0xc000a10f00)
14:32:28.203758 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc00002ac00): _readAt: size=1536, off=47668224
14:32:28.203758 DEBUG : vfs cache: looking for range={Pos:47668224 Size:1536} in [{Pos:0 Size:7393280} {Pos:47643648 Size:26112}] - present true
14:32:28.203758 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc00002ac00): >_readAt: n=1536, err=<nil>
14:32:28.406996 DEBUG : HTTP RESPONSE (req 0xc000a10f00)
14:32:28.408277 DEBUG : HTTP REQUEST (req 0xc000a11200)
14:32:31.550593 DEBUG : HTTP RESPONSE (req 0xc000a11200)
14:32:31.550593 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.Read at 7397376 length 8192 chunkOffset 7393280 chunkSize 134217728
14:32:31.578620 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.Read at 7405568 length 16384 chunkOffset 7393280 chunkSize 134217728
14:32:31.578875 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.Read at 7421952 length 32768 chunkOffset 7393280 chunkSize 134217728
14:32:31.579086 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.Read at 7454720 length 65536 chunkOffset 7393280 chunkSize 134217728
14:32:31.608461 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.Read at 7520256 length 131072 chunkOffset 7393280 chunkSize 134217728
14:32:31.680787 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.Read at 7651328 length 262144 chunkOffset 7393280 chunkSize 134217728
14:32:31.701934 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.Read at 7913472 length 524288 chunkOffset 7393280 chunkSize 134217728
14:32:31.797001 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.Read at 8437760 length 1048576 chunkOffset 7393280 chunkSize 134217728
14:32:31.863335 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.Read at 9486336 length 1048576 chunkOffset 7393280 chunkSize 134217728
14:32:31.921649 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.Read at 10534912 length 1048576 chunkOffset 7393280 chunkSize 134217728
14:32:31.975586 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.Read at 11583488 length 1048576 chunkOffset 7393280 chunkSize 134217728
14:32:32.605663 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.Read at 12632064 length 1048576 chunkOffset 7393280 chunkSize 134217728
14:32:33.615303 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.Read at 13680640 length 1048576 chunkOffset 7393280 chunkSize 134217728
14:32:34.600630 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.Read at 14729216 length 1048576 chunkOffset 7393280 chunkSize 134217728
14:32:35.632201 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.Read at 15777792 length 1048576 chunkOffset 7393280 chunkSize 134217728
14:32:36.552806 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: vfs cache: stopping download thread as it timed out
14:32:58.183240 INFO  : vfs cache: cleaned: objects 1 (was 1) in use 1, to upload 0, uploading 0, total size 16.072Mi (was 16.072Mi)
14:33:58.172773 INFO  : vfs cache: cleaned: objects 1 (was 1) in use 1, to upload 0, uploading 0, total size 16.072Mi (was 16.072Mi)

[Ole (Ole Frost)]

Branch fix-vfs-latency with default --buffer-size (16M)

Explorer response time: 5.2 sec
Data downloaded and stored in cache: 6.021Mi

15:05:47.360441 DEBUG : /rclone-v1.60.0-windows-amd64/rclone.exe: OpenEx: flags=0x0
15:05:47.360441 DEBUG : /rclone-v1.60.0-windows-amd64/rclone.exe: >Release: errc=0
15:05:47.360954 DEBUG : /rclone-v1.60.0-windows-amd64/rclone.exe: OpenEx: flags=0x0
15:05:47.361469 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc000612f80): _readAt: size=4096, off=0
15:05:47.361469 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: vfs cache: checking remote fingerprint "47669760,2022-11-02 16:24:07 +0000 UTC,9bca9c8b180733a5f921a5e276598cf0b50e0e79" against cached fingerprint ""
15:05:47.362016 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: vfs cache: truncate to size=47669760
15:05:47.362527 DEBUG : vfs cache: looking for range={Pos:0 Size:4096} in [] - present false
15:05:47.362527 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.RangeSeek from -1 to 0 length -1
15:05:47.362527 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.Read at -1 length 4096 chunkOffset 0 chunkSize 134217728
15:05:47.362527 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.openRange at 0 length 134217728
15:05:47.363037 DEBUG : HTTP REQUEST (req 0xc000552800)
15:05:47.628440 DEBUG : HTTP RESPONSE (req 0xc000552800)
15:05:47.628440 DEBUG : HTTP REQUEST (req 0xc000770700)
15:05:48.497557 DEBUG : HTTP RESPONSE (req 0xc000770700)
15:05:48.497557 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.Read at 4096 length 8192 chunkOffset 0 chunkSize 134217728
15:05:48.497557 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.Read at 12288 length 16384 chunkOffset 0 chunkSize 134217728
15:05:48.497557 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc000612f80): >_readAt: n=4096, err=<nil>
15:05:48.498063 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc000612f80): _readAt: size=16384, off=47643648
15:05:48.498063 DEBUG : vfs cache: looking for range={Pos:47643648 Size:16384} in [{Pos:0 Size:4096}] - present false
15:05:48.498063 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.RangeSeek from -1 to 47643648 length -1
15:05:48.498063 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.Read at -1 length 4096 chunkOffset 47643648 chunkSize 134217728
15:05:48.498063 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.openRange at 47643648 length 134217728
15:05:48.498063 DEBUG : HTTP REQUEST (req 0xc000900b00)
15:05:48.502653 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.Read at 28672 length 32768 chunkOffset 0 chunkSize 134217728
15:05:48.503410 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.Read at 61440 length 65536 chunkOffset 0 chunkSize 134217728
15:05:48.509255 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.Read at 126976 length 131072 chunkOffset 0 chunkSize 134217728
15:05:48.516783 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.Read at 258048 length 262144 chunkOffset 0 chunkSize 134217728
15:05:48.543650 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.Read at 520192 length 524288 chunkOffset 0 chunkSize 134217728
15:05:48.603857 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.Read at 1044480 length 1048576 chunkOffset 0 chunkSize 134217728
15:05:48.623783 DEBUG : HTTP RESPONSE (req 0xc000900b00)
15:05:48.623783 DEBUG : HTTP REQUEST (req 0xc000900d00)
15:05:48.648434 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.Read at 2093056 length 1048576 chunkOffset 0 chunkSize 134217728
15:05:48.690988 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.Read at 3141632 length 1048576 chunkOffset 0 chunkSize 134217728
15:05:48.734567 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.Read at 4190208 length 1048576 chunkOffset 0 chunkSize 134217728
15:05:49.528212 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.Read at 5238784 length 1048576 chunkOffset 0 chunkSize 134217728
15:05:50.434402 DEBUG : HTTP RESPONSE (req 0xc000900d00)
15:05:50.434402 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.Read at 47647744 length 8192 chunkOffset 47643648 chunkSize 134217728
15:05:50.434402 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.Read at 47655936 length 16384 chunkOffset 47643648 chunkSize 134217728
15:05:50.434402 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc000612f80): >_readAt: n=16384, err=<nil>
15:05:50.441073 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc000612f80): _readAt: size=1536, off=47668224
15:05:50.441073 DEBUG : vfs cache: looking for range={Pos:47668224 Size:1536} in [{Pos:0 Size:4096} {Pos:47643648 Size:26112}] - present true
15:05:50.441073 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc000612f80): >_readAt: n=1536, err=<nil>
15:05:50.441073 DEBUG : /rclone-v1.60.0-windows-amd64/rclone.exe: OpenEx: flags=0x0
15:05:50.441073 DEBUG : /rclone-v1.60.0-windows-amd64/rclone.exe: OpenEx: flags=0x0
15:05:50.444908 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc0000643c0): _readAt: size=4096, off=0
15:05:52.549473 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: vfs cache: setting modification time to 2022-11-02 16:24:07 +0000 UTC
15:05:52.549473 DEBUG : /rclone-v1.60.0-windows-amd64/rclone.exe: >Release: errc=0
15:05:52.549473 DEBUG : /rclone-v1.60.0-windows-amd64/rclone.exe: >Release: errc=0
15:05:52.554578 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: vfs cache: checking remote fingerprint "47669760,2022-11-02 16:24:07 +0000 UTC,9bca9c8b180733a5f921a5e276598cf0b50e0e79" against cached fingerprint "47669760,2022-11-02 16:24:07 +0000 UTC,9bca9c8b180733a5f921a5e276598cf0b50e0e79"
15:05:52.554578 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: vfs cache: truncate to size=47669760 (not needed as size correct)
15:05:52.589081 DEBUG : vfs cache: looking for range={Pos:0 Size:4096} in [{Pos:0 Size:6287360} {Pos:47643648 Size:26112}] - present true
15:05:52.589081 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc0000643c0): >_readAt: n=4096, err=<nil>
15:05:52.589081 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc0000643c0): _readAt: size=16384, off=47643648
15:05:52.589585 DEBUG : vfs cache: looking for range={Pos:47643648 Size:16384} in [{Pos:0 Size:6287360} {Pos:47643648 Size:26112}] - present true
15:05:52.589585 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc0000643c0): >_readAt: n=16384, err=<nil>
15:05:52.589669 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc0000643c0): _readAt: size=1536, off=47668224
15:05:52.589669 DEBUG : vfs cache: looking for range={Pos:47668224 Size:1536} in [{Pos:0 Size:6287360} {Pos:47643648 Size:26112}] - present true
15:05:52.589669 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc0000643c0): >_readAt: n=1536, err=<nil>
15:05:52.589669 DEBUG : /rclone-v1.60.0-windows-amd64/rclone.exe: OpenEx: flags=0x0
15:05:52.590264 DEBUG : /rclone-v1.60.0-windows-amd64/rclone.exe: >Release: errc=0
15:05:52.593923 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: vfs cache: setting modification time to 2022-11-02 16:24:07 +0000 UTC
15:05:52.593923 DEBUG : /rclone-v1.60.0-windows-amd64/rclone.exe: >Release: errc=0
15:05:52.593923 DEBUG : /rclone-v1.60.0-windows-amd64/rclone.exe: OpenEx: flags=0x0
15:05:52.594444 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc000486280): _readAt: size=4096, off=0
15:05:52.595076 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: vfs cache: checking remote fingerprint "47669760,2022-11-02 16:24:07 +0000 UTC,9bca9c8b180733a5f921a5e276598cf0b50e0e79" against cached fingerprint "47669760,2022-11-02 16:24:07 +0000 UTC,9bca9c8b180733a5f921a5e276598cf0b50e0e79"
15:05:52.595076 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: vfs cache: truncate to size=47669760 (not needed as size correct)
15:05:52.597657 DEBUG : vfs cache: looking for range={Pos:0 Size:4096} in [{Pos:0 Size:6287360} {Pos:47643648 Size:26112}] - present true
15:05:52.597657 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc000486280): >_readAt: n=4096, err=<nil>
15:05:52.597769 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc000486280): _readAt: size=16384, off=47643648
15:05:52.597769 DEBUG : vfs cache: looking for range={Pos:47643648 Size:16384} in [{Pos:0 Size:6287360} {Pos:47643648 Size:26112}] - present true
15:05:52.597769 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc000486280): >_readAt: n=16384, err=<nil>
15:05:52.597769 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc000486280): _readAt: size=1536, off=47668224
15:05:52.597769 DEBUG : vfs cache: looking for range={Pos:47668224 Size:1536} in [{Pos:0 Size:6287360} {Pos:47643648 Size:26112}] - present true
15:05:52.597769 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc000486280): >_readAt: n=1536, err=<nil>
15:05:52.598276 DEBUG : /rclone-v1.60.0-windows-amd64/rclone.exe: OpenEx: flags=0x0
15:05:52.598276 DEBUG : /rclone-v1.60.0-windows-amd64/rclone.exe: >Release: errc=0
15:05:52.598893 DEBUG : /rclone-v1.60.0-windows-amd64/rclone.exe: OpenEx: flags=0x0
15:05:52.599472 DEBUG : /rclone-v1.60.0-windows-amd64/rclone.exe: >Release: errc=0
15:06:32.007091 INFO  : vfs cache: cleaned: objects 1 (was 1) in use 1, to upload 0, uploading 0, total size 6.021Mi (was 6.021Mi)

Branch fix-vfs-latency with --buffer-size=0

Explorer response time: 1.9 sec
Data downloaded and stored in cache: 89.500Ki

15:17:25.286262 DEBUG : /rclone-v1.60.0-windows-amd64/rclone.exe: OpenEx: flags=0x0
15:17:25.286777 DEBUG : /rclone-v1.60.0-windows-amd64/rclone.exe: >Release: errc=0
15:17:25.286777 DEBUG : /rclone-v1.60.0-windows-amd64/rclone.exe: OpenEx: flags=0x0
15:17:25.287289 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc0003b9b00): _readAt: size=4096, off=0
15:17:25.287802 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: vfs cache: checking remote fingerprint "47669760,2022-11-02 16:24:07 +0000 UTC,9bca9c8b180733a5f921a5e276598cf0b50e0e79" against cached fingerprint ""
15:17:25.287802 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: vfs cache: truncate to size=47669760
15:17:25.288321 DEBUG : vfs cache: looking for range={Pos:0 Size:4096} in [] - present false
15:17:25.288321 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.RangeSeek from -1 to 0 length -1
15:17:25.288321 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728
15:17:25.288321 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.openRange at 0 length 134217728
15:17:25.288839 DEBUG : HTTP REQUEST (req 0xc00023b500)
15:17:25.509898 DEBUG : HTTP RESPONSE (req 0xc00023b500)
15:17:25.511343 DEBUG : HTTP REQUEST (req 0xc00023b900)
15:17:26.324383 DEBUG : HTTP RESPONSE (req 0xc00023b900)
15:17:26.340025 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.Read at 32768 length 32768 chunkOffset 0 chunkSize 134217728
15:17:26.340025 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc0003b9b00): >_readAt: n=4096, err=<nil>
15:17:26.341240 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc0003b9b00): _readAt: size=16384, off=47643648
15:17:26.341376 DEBUG : vfs cache: looking for range={Pos:47643648 Size:16384} in [{Pos:0 Size:32768}] - present false
15:17:26.341376 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.RangeSeek from -1 to 47643648 length -1
15:17:26.341516 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.Read at -1 length 32768 chunkOffset 47643648 chunkSize 134217728
15:17:26.341516 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: ChunkedReader.openRange at 47643648 length 134217728
15:17:26.342272 DEBUG : HTTP REQUEST (req 0xc000429700)
15:17:26.621735 DEBUG : HTTP RESPONSE (req 0xc000429700)
15:17:26.622358 DEBUG : HTTP REQUEST (req 0xc0000cba00)
15:17:26.971903 DEBUG : HTTP RESPONSE (req 0xc0000cba00)
15:17:26.972786 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc0003b9b00): >_readAt: n=16384, err=<nil>
15:17:26.972786 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc0003b9b00): _readAt: size=1536, off=47668224
15:17:26.973351 DEBUG : vfs cache: looking for range={Pos:47668224 Size:1536} in [{Pos:0 Size:32768} {Pos:47643648 Size:26112}] - present true
15:17:26.973351 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc0003b9b00): >_readAt: n=1536, err=<nil>
15:17:26.974265 DEBUG : /rclone-v1.60.0-windows-amd64/rclone.exe: OpenEx: flags=0x0
15:17:26.977258 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: vfs cache: setting modification time to 2022-11-02 16:24:07 +0000 UTC
15:17:26.980443 DEBUG : /rclone-v1.60.0-windows-amd64/rclone.exe: >Release: errc=0
15:17:26.980615 DEBUG : /rclone-v1.60.0-windows-amd64/rclone.exe: >Release: errc=0
15:17:26.980615 DEBUG : /rclone-v1.60.0-windows-amd64/rclone.exe: OpenEx: flags=0x0
15:17:26.983024 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc00041e0c0): _readAt: size=4096, off=0
15:17:26.984142 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: vfs cache: checking remote fingerprint "47669760,2022-11-02 16:24:07 +0000 UTC,9bca9c8b180733a5f921a5e276598cf0b50e0e79" against cached fingerprint "47669760,2022-11-02 16:24:07 +0000 UTC,9bca9c8b180733a5f921a5e276598cf0b50e0e79"
15:17:26.984268 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe: vfs cache: truncate to size=47669760 (not needed as size correct)
15:17:27.188913 DEBUG : vfs cache: looking for range={Pos:0 Size:4096} in [{Pos:0 Size:65536} {Pos:47643648 Size:26112}] - present true
15:17:27.188913 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc00041e0c0): >_readAt: n=4096, err=<nil>
15:17:27.189086 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc00041e0c0): _readAt: size=16384, off=47643648
15:17:27.189086 DEBUG : vfs cache: looking for range={Pos:47643648 Size:16384} in [{Pos:0 Size:65536} {Pos:47643648 Size:26112}] - present true
15:17:27.189086 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc00041e0c0): >_readAt: n=16384, err=<nil>
15:17:27.189086 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc00041e0c0): _readAt: size=1536, off=47668224
15:17:27.189086 DEBUG : vfs cache: looking for range={Pos:47668224 Size:1536} in [{Pos:0 Size:65536} {Pos:47643648 Size:26112}] - present true
15:17:27.189086 DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc00041e0c0): >_readAt: n=1536, err=<nil>
15:17:27.189593 DEBUG : /rclone-v1.60.0-windows-amd64/rclone.exe: OpenEx: flags=0x0
15:17:27.189593 DEBUG : /rclone-v1.60.0-windows-amd64/rclone.exe: >Release: errc=0
15:17:27.190114 DEBUG : /rclone-v1.60.0-windows-amd64/rclone.exe: OpenEx: flags=0x0
15:17:27.191246 DEBUG : /rclone-v1.60.0-windows-amd64/rclone.exe: >Release: errc=0
15:17:27.191246 DEBUG : /rclone-v1.60.0-windows-amd64/rclone.exe: OpenEx: flags=0x0
15:17:27.191246 DEBUG : /rclone-v1.60.0-windows-amd64/rclone.exe: >Release: errc=0
15:17:27.191921 DEBUG : /rclone-v1.60.0-windows-amd64/rclone.exe: OpenEx: flags=0x0
15:17:27.192626 DEBUG : /rclone-v1.60.0-windows-amd64/rclone.exe: >Release: errc=0
15:18:12.636002 INFO  : vfs cache: cleaned: objects 1 (was 1) in use 1, to upload 0, uploading 0, total size 89.500Ki (was 89.500Ki)

[ncw (Nick Craig-Wood)]

That is very interesting, thank you @Ole.

Looks like there is some work to do here as things definitely aren't working as designed.

What I'd like to do is write a program which simulates your test to make it 100% repeatable, then I can try things to see what improves.

Looking at your logs, it seems the only thing that had to be queried from Onedrive was rclone.exe - this indicates my previous test_bin.py program might well be a good enough test?

Can you try test_bin.py or the Go version of it with the 3 different types of mount on rclone.exe?

I guess what I should do is try to measure the throughput too and work out what network speed (if any) the buffer is useful.

If you raise --bwlimit and/or mount a local disk instead do you see a similar result?

The buffer was originally introduced to speed up disk transfers on Windows. It allows the reading of the disk to happen in bigger buffers and continuously in the background which really helps with Windows. Maybe it isn't needed or desirable for network transfers or maybe it becomes useful at a certain speed.

PS I could make --vfs-cache-mode full default to --buffer-size 0 unless you explicitly set the buffer.

[Ole (Ole Frost)]

I am busy travelling the rest of the month, so my time end options are very limited. Here is the best I can do right now.

@ncw

What I'd like to do is write a program which simulates your test to make it 100% repeatable, then I can try things to see what improves.

It should be easy to first replicate on your Windows VM and then simulate using Python or Go.

My test intentionally doesn't rely mouse clicks except opening the folder and placing selection on the first file in the folder without hovering over rclone.exe. Then it is just pressing and holding arrow down until the selection reaches the bottom of the list. I den wait 10 seconds or so and then press and hold arrow up until the selection reaches the top of the list. The last part test the functioning of the cache and Defender etc. I am using a plain OneDrive Personal as backend and accessing a folder 3 levels down.

@ncw

If you raise --bwlimit and/or mount a local disk instead do you see a similar result?

If I raise --bwlimit, then the pattern is almost unchanged. Times are (naturally) lower, but the downloads seems similar.

@ncw

The buffer was originally introduced to speed up disk transfers on Windows. It allows the reading of the disk to happen in bigger buffers and continuously in the background which really helps with Windows. Maybe it isn't needed or desirable for network transfers or maybe it becomes useful at a certain speed.

If so, then I guess the buffer was introduced to handle large diameter spinning hard disks with slow arm movements (cylinder seek). I doubt anybody would use such a disk for caching, anybody caring the slightest about speed would use an SSD for caching nowadays.

@ncw

PS I could make --vfs-cache-mode full default to --buffer-size 0 unless you explicitly set the buffer.

I would consider making the rclone mount command default to --buffer-size 0, not just --vfs-cache-mode full - and on all platforms.

I think that would be the best setting for most users and use cases. I can see some special use cases in data centers, but assume they also have the time and skills to read the docs and then add/tune a read ahead buffer if needed.

Perhaps I am missing something, but I still cannot see any (typical) mount use case benefitting from read ahead.