Thanks, but seems like my conclusion was too hasty.
A more thorough test shows that both webdav and mount will read the executable to extract the icon. This will happen with or without "Show thumbnails instead of icons".
Apparently Windows has some kind of (timed) icon cache that blurred my tests unless each action was performed with minimum 10 minutes delay.
Good question, it made me discover the above and investigate why Explorer behaves so badly when using rclone mount.
This is what Windows requests from rclone each time you hover, select or right-click on an executable like rclone.exe:
That is 4K from the start and 17K near the end of the file (probably the icon resource). This amount of data would typically be transferred quicker than the human reaction/detection time.
rclone however has a default --buffer-size of 16Mi, so it reads 16MB from the start of the file and another 16 MB from the end. That will roughly take the above mentioned 30 seconds to complete on my simulated 10 mbps connection. That is an effective transfer speed of 5,600 bit per second seen from Windows. This speed is comparable to some of the very first phone modems I used 30+ years ago, so I guess this would cripple any modern (Linux or Windows) program performing small random reads.
With this knowledge I tried setting --buffer-size=0 which effectively reduced the buffer to 32KB (on my machine). This made Explorer nicely responsive, even with thumbnails enabled. I was even able to do reasonable pleasant Explorer navigation on a simulated 1 mbps connection (starting with empty cache):
rclone mount --network-mode --cache-mode=full --buffer-size=0 --bwlimit=100K myOneDrive:testfolder/ Z:
I also tried a few other things (downloading rclone.exe and browsing a folder with photos). It was slow as expected, but I didn't see any negative consequences of the much lower --buffer-size. Performance also seem fine when using the mount with --buffer-size=0 on my full 600mbps bandwidth.
I guess this explains the much better performance seen with the default installation/usage of RaiDrive. RaiDrive probably doesn't try to read (as much) ahead as rclone does with default settings, and it also seems to enable a small read cache by default.
So these are the rclone settings that seems to match the RaiDrive default settings:
rclone mount --network-mode --cache-mode=full --buffer-size=0 ...
@wslrj Does these settings improve/solve your issue?
A closing remark for the technically interested: I also briefly tried the same trick with rclone serve webdav, and that wasn't a success. Seems like the whole file is being downloaded irrespective of --buffer-size, I didn't investigate why or any details. That will be a challenge for somebody else.
both webdav and mount will read the executable to extract the icon. This will happen with or without "Show thumbnails instead of icons".
Hmm didn't know that.
For me a 100MB exe responds instantly to both right-clicking and displaying file properties. But perhaps, as you've mentioned, the data is being cached too fast for me to notice. A 700MB exe on the other hand takes about ~1s to respond to a right click, then ~8s to display properties.
Handling that 700MB exe is the first time I've felt any lag while using these mount flags: --vfs-cache-mode full --use-server-modtime --network-mode
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 am a bit puzzled by the 4 seconds to display file properties, is it a publicly available executable that I can test?
Not that I am aware of.
A typical pc can easily move data with the responsiveness needed to efficiently utilize networked storage, so I see no need for the additional rclone buffering on mounts.
Please let me know if you experience anything different.
I'm puzzled too. Wish I had other large executables to test.
The exe I used was an old version of ZBrush 4R4 — probably difficult to find now. Below is a GIF of me interacting with it via my Wasabi mount using these flags:
--vfs-cache-mode full --use-server-modtime --network-mode --buffer-size=0
Here's the log from one Right Click > Properties attempt.
For what it's worth I also tested this exe on a local HDD (WD Black 1TB). It responded instantly to a right click and instantly displayed file properties.
The delay on the mounted drive isn't a big problem for me personally, since I don't often interact with executables. But I'd be interested to learn why it happens.
You can see all the different file handles corresponding to the different opens by the OS.
The OS seems to read bits out of the first 32k 8 times! This isn't a problem it should be cached after the first read. It reads another 32k 3 times also.
As the reads are relatively close together you can see rclone just streams the first 900k of the file.
This means that the file bits are in cache very quickly - see the present = true here. Everything is in cache at 02:48:08 (when the read above finished) so <1 second after starting but the OS wasn't done with the file until 02:48:16 so there are 8 seconds of overhead.
2022/11/10 02:48:08 DEBUG : vfs cache: looking for range={Pos:0 Size:4096} in [] - present false
2022/11/10 02:48:08 DEBUG : vfs cache: looking for range={Pos:840192 Size:16384} in [{Pos:0 Size:32768}] - present false
2022/11/10 02:48:08 DEBUG : vfs cache: looking for range={Pos:872960 Size:15360} in [{Pos:0 Size:884736}] - present false
2022/11/10 02:48:12 DEBUG : vfs cache: looking for range={Pos:0 Size:4096} in [{Pos:0 Size:950272}] - present true
2022/11/10 02:48:12 DEBUG : vfs cache: looking for range={Pos:0 Size:32768} in [{Pos:0 Size:950272}] - present true
2022/11/10 02:48:12 DEBUG : vfs cache: looking for range={Pos:839680 Size:32768} in [{Pos:0 Size:950272}] - present true
2022/11/10 02:48:12 DEBUG : vfs cache: looking for range={Pos:880640 Size:32768} in [{Pos:0 Size:950272}] - present true
2022/11/10 02:48:13 DEBUG : vfs cache: looking for range={Pos:0 Size:32768} in [{Pos:0 Size:950272}] - present true
2022/11/10 02:48:14 DEBUG : vfs cache: looking for range={Pos:0 Size:32768} in [{Pos:0 Size:950272}] - present true
2022/11/10 02:48:15 DEBUG : vfs cache: looking for range={Pos:0 Size:32768} in [{Pos:0 Size:950272}] - present true
2022/11/10 02:48:15 DEBUG : vfs cache: looking for range={Pos:0 Size:4096} in [{Pos:0 Size:950272}] - present true
2022/11/10 02:48:15 DEBUG : vfs cache: looking for range={Pos:840192 Size:16384} in [{Pos:0 Size:950272}] - present true
2022/11/10 02:48:15 DEBUG : vfs cache: looking for range={Pos:872960 Size:15360} in [{Pos:0 Size:950272}] - present true
2022/11/10 02:48:16 DEBUG : vfs cache: looking for range={Pos:0 Size:4096} in [{Pos:0 Size:950272}] - present true
2022/11/10 02:48:16 DEBUG : vfs cache: looking for range={Pos:840192 Size:16384} in [{Pos:0 Size:950272}] - present true
2022/11/10 02:48:16 DEBUG : vfs cache: looking for range={Pos:872960 Size:15360} in [{Pos:0 Size:950272}] - present true
Could you do this test again with more accurate timing? You can enable that with --log-format time,microseconds - then I can check which part of the open is causing the problem. I suspect it is the checking remote fingerprint and a more accurate timing will show that.
If it is, I don't think it would be unreasonable to cache these fingerprints. Exactly for how long I don't know but somewhere around --dir-cache-time maybe. Or maybe with its own parameter.
Perhaps @ncw can give a quick rundown of the drawbacks/risks.
Agree, Windows reads the same app. 35K several times. And the 35K comes from different parts of the file so 2-3 reads of the minimum buffer size (32768) from the remote is to be expected.
It does however puzzle me why rclone decides to stream the first 900k of the file, can you briefly give me a hint?
You see two actions in the log: The file is selected at 02:48:08 and Windows checks something (icon) behind the scenes. The right-click is happening at 02:48:12 and may be a combined select and right-click, driving the number of requests up. It takes 4 seconds with all content loaded from cache, so really only checking the fingerprint 13 times - 300ms per fingerprint.
Might be a very good idea to better support applications with high appetite on rapidly sniffing small parts of (executable) files.
However, not sure I understand the fingerprinting method and usage in relation to mounts well enough to comment on the best approach. Do we have a description of rclone's finger printing and especially the method used by --vfs-fast-fingerprint? something between the above link and the code (docs, forum posts, ...)
For mount sftp,why right click on exe file is so slow until it freezes - Help and Support - rclone forum.Right clicking on REMOVEDURL .exe files* or folders causes file explorer to freeze , on desktop as well as in the start menu and in a File Explorer window. If an app's added shell extension isn't working properly , it can cause a context menu to be extremely slow or freeze when you right click to ... file which is responsible for the context menu is actually still loaded, enabled and causing the right click to be very slow!
The other flags were kept the same: --vfs-cache-mode full --use-server-modtime --network-mode --buffer-size=0
I didn't notice that fast fingerprint was recommended for S3 (Wasabi), thanks for pointing that out! There's not much difference for me with it enabled, and I wonder if it's because I'm already using --use-server-modtime. They seem to do similar things, so maybe their effects don't stack very well
Thanks for the logs @prizi - it doesn't look like fast fingerprint helps much here - it will help the first time the fingerprint is checked, but the time will be cached in the object after that. It looks like the OS already read the time so we had it cached.
(If you are using s3 based backend then using --use-server-modtime will make your mount a lot snappier at the expense of only seeing the times the objects were uploaded rather then their actual modtimes).
There is an 800ms gap here which is almost certainly networking. What was rclone doing since rclone already has the file cached here? It shouldn't need to make any network transactions.
There are 8 of these sequences in the log. For some reason 2 of them don't have any delay. The other 6 seem to have about 800ms delay. In total that is 4.8s which seems like it would go a long way to explaining this problem.
To get an idea of what is happening can you run your test with with --dump headers as well as --vfs-cache-mode full --use-server-modtime --network-mode --buffer-size=0 please?
This will make an even more bulky log, but it will have the HTTP transaction of what rclone was doing which will hopefully give a clue.
Using --fast-fingerprint is probably better than using a cache. With fast fingerprint there should be no need to make any transactions to the remote.
The difference it makes with S3 is that we need the modtime without it which is stored as metadata on the object. This takes an extra HEAD request to retrieve. However we only fetch it once and cache it in the object, so effectively we already have a fast fingerprint cache (at least for s3 though the other backends all cache stuff if it is expensive to calculate).
That is 210ms without network communication on a very fast laptop, so there may be an issue here. I am using v1.60 on a fully up-to-date Windows 11 with OneDrive as backend.
I will see if I can make it more pronounced by slowing CPU or similar, and then try reproducing with a debugger, if I can figure out how to link/debug with cmount (using Windows).
I am interested if this is something you already have, otherwise it may be quicker to find in my debugger.
Its immediately clear from the log that my attempt to not truncate the file didn't work
I just tested it locally on Linux and it does appear to work....
So either it is something to do with your system (eg Windows) or could you have run the wrong binary? Your log doesn't have the very start where rclone prints its version so I can't check.
I've been attempting to replicate this locally. I've written a python program which simulates what windows does to the exe (based on the above).
Can either of you try this on the exe file in the mount and report back its output.
"""
Read parts out of the executable like windows does
"""
import sys
import time
if len(sys.argv) < 2:
print(f"Syntax {sys.argv} <file>")
raise SystemExit(1)
file_name = sys.argv[1]
t0 = time.time()
def dt():
return time.time() - t0
def readAt(f, size, off):
"""
Read size bytes from offset
"""
f.seek(off)
bs = f.read(size)
assert len(bs) == size
print(f"{dt():.6f} {file_name}: read {size:6} bytes at {off:6}")
f = open(file_name, "rb")
readAt(f, 4096, 0)
readAt(f, 16384, 840192)
readAt(f, 15360, 872960)
f.close()
f = open(file_name, "rb")
readAt(f, 4096, 0)
f.close()
f = open(file_name, "rb")
readAt(f, 32768, 0)
readAt(f, 32768, 839680)
readAt(f, 32768, 880640)
readAt(f, 32768, 0)
f.close()
f = open(file_name, "rb")
readAt(f, 32768, 0)
f.close()
f = open(file_name, "rb")
readAt(f, 32768, 0)
f.close()
f = open(file_name, "rb")
readAt(f, 4096, 0)
readAt(f, 16384, 840192)
readAt(f, 15360, 872960)
readAt(f, 4096, 0)
readAt(f, 16384, 840192)
readAt(f, 15360, 872960)
f.close()
Run it like this
$ python3 test_bin.py /mnt/tmp/bin.exe
0.001172 /mnt/tmp/bin.exe: read 4096 bytes at 0
0.001438 /mnt/tmp/bin.exe: read 16384 bytes at 840192
0.001769 /mnt/tmp/bin.exe: read 15360 bytes at 872960
0.002156 /mnt/tmp/bin.exe: read 4096 bytes at 0
0.002891 /mnt/tmp/bin.exe: read 32768 bytes at 0
0.003285 /mnt/tmp/bin.exe: read 32768 bytes at 839680
0.003428 /mnt/tmp/bin.exe: read 32768 bytes at 880640
0.003438 /mnt/tmp/bin.exe: read 32768 bytes at 0
0.003915 /mnt/tmp/bin.exe: read 32768 bytes at 0
0.004429 /mnt/tmp/bin.exe: read 32768 bytes at 0
0.004951 /mnt/tmp/bin.exe: read 4096 bytes at 0
0.005035 /mnt/tmp/bin.exe: read 16384 bytes at 840192
0.005164 /mnt/tmp/bin.exe: read 15360 bytes at 872960
0.005169 /mnt/tmp/bin.exe: read 4096 bytes at 0
0.005175 /mnt/tmp/bin.exe: read 16384 bytes at 840192
0.005181 /mnt/tmp/bin.exe: read 15360 bytes at 872960
And give it the path to the file.
The timestamps are how long the program has been running so we should see delays in there.
This has extra debugging in it to show how long the truncated bits and pieces take. There are two operations, setting the file sparse and truncating it and with microsecond log we should see what is going on.
11:30:56.253333 DEBUG : 20M: _truncateToCurrentSize: need truncate - current size -1 new size 0
11:30:56.253335 DEBUG : 20M: _truncate: starting
11:30:56.253368 DEBUG : 20M: _truncate: start SetSparse
11:30:56.253371 DEBUG : 20M: _truncate: end SetSparse
11:30:56.253372 DEBUG : 20M: vfs cache: truncate to size=0
11:30:56.253374 DEBUG : 20M: _truncate: start Truncate
11:30:56.253388 DEBUG : 20M: _truncate: end Truncate
You can drop the --dump headers now - I think we've eliminated that.