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

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:

DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc0005921c0): _readAt: size=4096, off=0
DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc0005921c0): _readAt: size=16384, off=47643648
DEBUG : rclone-v1.60.0-windows-amd64/rclone.exe(0xc0005921c0): _readAt: size=1536, off=47668224

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.

More info on --buffer-size here:
https://rclone.org/docs/#buffer-size-size
https://rclone.org/commands/rclone_mount/#vfs-file-buffering
https://rclone.org/commands/rclone_mount/#vfs-cache-mode-full

3 Likes

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.

Are there any downsides to reducing the buffer?

Thanks, appreciate the test and confirmation!

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.

Very useful log - thank you.

Looking at your log, probably the main slowdown is the fact the OS opens and closes the file 8 times!

Each time the OS opens the file rclone checks it is the same on the remote end - this takes an HTTP roundtrip. This could potentially be optimised.

The OS reads these chunks out of the file

File Handle  Operation Size Read   Offset in file
0xc00070e8c0: _readAt: size=4096, off=0
0xc00070e8c0: _readAt: size=16384, off=840192
0xc00070e8c0: _readAt: size=15360, off=872960
0xc000b323c0: _readAt: size=4096, off=0
0xc0004101c0: _readAt: size=32768, off=0
0xc0004101c0: _readAt: size=32768, off=839680
0xc0004101c0: _readAt: size=32768, off=880640
0xc000410280: _readAt: size=32768, off=0
0xc000a4a0c0: _readAt: size=32768, off=0
0xc00070e100: _readAt: size=32768, off=0
0xc000b320c0: _readAt: size=4096, off=0
0xc000b320c0: _readAt: size=16384, off=840192
0xc000b320c0: _readAt: size=15360, off=872960
0xc000b32200: _readAt: size=4096, off=0
0xc000b32200: _readAt: size=16384, off=840192
0xc000b32200: _readAt: size=15360, off=872960

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.

2022/11/10 02:48:08 DEBUG : wasabi/media/apps/3d/zbrush/install/ZBrush_4R4_Installer_WIN.exe: ChunkedReader.RangeSeek from -1 to 0 length -1
2022/11/10 02:48:08 DEBUG : wasabi/media/apps/3d/zbrush/install/ZBrush_4R4_Installer_WIN.exe: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728
2022/11/10 02:48:08 DEBUG : wasabi/media/apps/3d/zbrush/install/ZBrush_4R4_Installer_WIN.exe: ChunkedReader.openRange at 0 length 134217728
2022/11/10 02:48:08 DEBUG : wasabi/media/apps/3d/zbrush/install/ZBrush_4R4_Installer_WIN.exe: ChunkedReader.Read at 32768 length 32768 chunkOffset 0 chunkSize 134217728
2022/11/10 02:48:08 DEBUG : wasabi/media/apps/3d/zbrush/install/ZBrush_4R4_Installer_WIN.exe: ChunkedReader.Read at 65536 length 32768 chunkOffset 0 chunkSize 134217728
2022/11/10 02:48:08 DEBUG : wasabi/media/apps/3d/zbrush/install/ZBrush_4R4_Installer_WIN.exe: ChunkedReader.Read at 98304 length 32768 chunkOffset 0 chunkSize 134217728
2022/11/10 02:48:08 DEBUG : wasabi/media/apps/3d/zbrush/install/ZBrush_4R4_Installer_WIN.exe: ChunkedReader.Read at 131072 length 32768 chunkOffset 0 chunkSize 134217728
2022/11/10 02:48:08 DEBUG : wasabi/media/apps/3d/zbrush/install/ZBrush_4R4_Installer_WIN.exe: ChunkedReader.Read at 163840 length 32768 chunkOffset 0 chunkSize 134217728
2022/11/10 02:48:08 DEBUG : wasabi/media/apps/3d/zbrush/install/ZBrush_4R4_Installer_WIN.exe: ChunkedReader.Read at 196608 length 32768 chunkOffset 0 chunkSize 134217728
2022/11/10 02:48:08 DEBUG : wasabi/media/apps/3d/zbrush/install/ZBrush_4R4_Installer_WIN.exe: ChunkedReader.Read at 229376 length 32768 chunkOffset 0 chunkSize 134217728
2022/11/10 02:48:08 DEBUG : wasabi/media/apps/3d/zbrush/install/ZBrush_4R4_Installer_WIN.exe: ChunkedReader.Read at 262144 length 32768 chunkOffset 0 chunkSize 134217728
2022/11/10 02:48:08 DEBUG : wasabi/media/apps/3d/zbrush/install/ZBrush_4R4_Installer_WIN.exe: ChunkedReader.Read at 294912 length 32768 chunkOffset 0 chunkSize 134217728
2022/11/10 02:48:08 DEBUG : wasabi/media/apps/3d/zbrush/install/ZBrush_4R4_Installer_WIN.exe: ChunkedReader.Read at 327680 length 32768 chunkOffset 0 chunkSize 134217728
2022/11/10 02:48:08 DEBUG : wasabi/media/apps/3d/zbrush/install/ZBrush_4R4_Installer_WIN.exe: ChunkedReader.Read at 360448 length 32768 chunkOffset 0 chunkSize 134217728
2022/11/10 02:48:08 DEBUG : wasabi/media/apps/3d/zbrush/install/ZBrush_4R4_Installer_WIN.exe: ChunkedReader.Read at 393216 length 32768 chunkOffset 0 chunkSize 134217728
2022/11/10 02:48:08 DEBUG : wasabi/media/apps/3d/zbrush/install/ZBrush_4R4_Installer_WIN.exe: ChunkedReader.Read at 425984 length 32768 chunkOffset 0 chunkSize 134217728
2022/11/10 02:48:08 DEBUG : wasabi/media/apps/3d/zbrush/install/ZBrush_4R4_Installer_WIN.exe: ChunkedReader.Read at 458752 length 32768 chunkOffset 0 chunkSize 134217728
2022/11/10 02:48:08 DEBUG : wasabi/media/apps/3d/zbrush/install/ZBrush_4R4_Installer_WIN.exe: ChunkedReader.Read at 491520 length 32768 chunkOffset 0 chunkSize 134217728
2022/11/10 02:48:08 DEBUG : wasabi/media/apps/3d/zbrush/install/ZBrush_4R4_Installer_WIN.exe: ChunkedReader.Read at 524288 length 32768 chunkOffset 0 chunkSize 134217728
2022/11/10 02:48:08 DEBUG : wasabi/media/apps/3d/zbrush/install/ZBrush_4R4_Installer_WIN.exe: ChunkedReader.Read at 557056 length 32768 chunkOffset 0 chunkSize 134217728
2022/11/10 02:48:08 DEBUG : wasabi/media/apps/3d/zbrush/install/ZBrush_4R4_Installer_WIN.exe: ChunkedReader.Read at 589824 length 32768 chunkOffset 0 chunkSize 134217728
2022/11/10 02:48:08 DEBUG : wasabi/media/apps/3d/zbrush/install/ZBrush_4R4_Installer_WIN.exe: ChunkedReader.Read at 622592 length 32768 chunkOffset 0 chunkSize 134217728
2022/11/10 02:48:08 DEBUG : wasabi/media/apps/3d/zbrush/install/ZBrush_4R4_Installer_WIN.exe: ChunkedReader.Read at 655360 length 32768 chunkOffset 0 chunkSize 134217728
2022/11/10 02:48:08 DEBUG : wasabi/media/apps/3d/zbrush/install/ZBrush_4R4_Installer_WIN.exe: ChunkedReader.Read at 688128 length 32768 chunkOffset 0 chunkSize 134217728
2022/11/10 02:48:08 DEBUG : wasabi/media/apps/3d/zbrush/install/ZBrush_4R4_Installer_WIN.exe: ChunkedReader.Read at 720896 length 32768 chunkOffset 0 chunkSize 134217728
2022/11/10 02:48:08 DEBUG : wasabi/media/apps/3d/zbrush/install/ZBrush_4R4_Installer_WIN.exe: ChunkedReader.Read at 753664 length 32768 chunkOffset 0 chunkSize 134217728
2022/11/10 02:48:08 DEBUG : wasabi/media/apps/3d/zbrush/install/ZBrush_4R4_Installer_WIN.exe: ChunkedReader.Read at 786432 length 32768 chunkOffset 0 chunkSize 134217728
2022/11/10 02:48:08 DEBUG : wasabi/media/apps/3d/zbrush/install/ZBrush_4R4_Installer_WIN.exe: ChunkedReader.Read at 819200 length 32768 chunkOffset 0 chunkSize 134217728
2022/11/10 02:48:08 DEBUG : wasabi/media/apps/3d/zbrush/install/ZBrush_4R4_Installer_WIN.exe: ChunkedReader.Read at 851968 length 32768 chunkOffset 0 chunkSize 134217728
2022/11/10 02:48:08 DEBUG : wasabi/media/apps/3d/zbrush/install/ZBrush_4R4_Installer_WIN.exe: ChunkedReader.Read at 884736 length 32768 chunkOffset 0 chunkSize 134217728
2022/11/10 02:48:08 DEBUG : wasabi/media/apps/3d/zbrush/install/ZBrush_4R4_Installer_WIN.exe: ChunkedReader.Read at 917504 length 32768 chunkOffset 0 chunkSize 134217728

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.

1 Like

Great example, illustration and debug log! :slightly_smiling_face:

I have made the same observations as Nick, who probably thinks you are using SFTP (from the thread heading).

I do however know that you are using S3 (Wasabi), so I feel pretty sure you will see much better responsiveness by adding --vfs-fast-fingerprint:

If you are running a vfs cache over local , s3 or swift backends then using this flag is recommended.

Source: https://rclone.org/commands/rclone_mount/#fingerprinting

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, ...)

1 Like

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!

Nice breakdown of the log!

Sure. Performed the same test (right click > properties) a couple more times:

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 :thinking:

1 Like

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).

The problem seems to be in here

12:37:18.585687 DEBUG : wasabi/media/apps/3d/zbrush/install/ZBrush_4R4_Installer_WIN.exe(0xc0004da3c0): openPending:
12:37:18.589093 DEBUG : wasabi/media/apps/3d/zbrush/install/ZBrush_4R4_Installer_WIN.exe: vfs cache: checking remote fingerprint "701579568,2022-11-01 17:59:46 +0000 UTC,debebb104c00cbfb3b123c2f75299367" against cached fingerprint "701579568,2022-11-01 17:59:46 +0000 UTC,debebb104c00cbfb3b123c2f75299367"
12:37:18.589633 DEBUG : wasabi/media/apps/3d/zbrush/install/ZBrush_4R4_Installer_WIN.exe: vfs cache: truncate to size=701579568
12:37:19.417656 DEBUG : wasabi/media/apps/3d/zbrush/install: Added virtual directory entry vAddFile: "ZBrush_4R4_Installer_WIN.exe"
12:37:19.418188 DEBUG : wasabi/media/apps/3d/zbrush/install/ZBrush_4R4_Installer_WIN.exe(0xc0004da3c0): >openPending: err=<nil>

or

12:37:23.151494 DEBUG : wasabi/media/apps/3d/zbrush/install/ZBrush_4R4_Installer_WIN.exe(0xc000061100): openPending:
12:37:23.151494 DEBUG : wasabi/media/apps/3d/zbrush/install/ZBrush_4R4_Installer_WIN.exe: vfs cache: checking remote fingerprint "701579568,2022-11-01 17:59:46 +0000 UTC,debebb104c00cbfb3b123c2f75299367" against cached fingerprint "701579568,2022-11-01 17:59:46 +0000 UTC,debebb104c00cbfb3b123c2f75299367"
12:37:23.151494 DEBUG : wasabi/media/apps/3d/zbrush/install/ZBrush_4R4_Installer_WIN.exe: vfs cache: truncate to size=701579568
12:37:23.974167 DEBUG : wasabi/media/apps/3d/zbrush/install: Added virtual directory entry vAddFile: "ZBrush_4R4_Installer_WIN.exe"
12:37:23.974715 DEBUG : wasabi/media/apps/3d/zbrush/install/ZBrush_4R4_Installer_WIN.exe(0xc000061100): >openPending: err=<nil>

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).

No prob. Here's a new log.

The full mount command was:

rclone mount wasabi: Z:
-vv
--dump headers
--log-format time,microseconds
--vfs-cache-mode full
--cache-dir "%cd%\cache"
--use-server-modtime
--buffer-size=0
--network-mode

Happy to provide further logs if needed.

1 Like

Well colour me surprised, but there are no http transactions in that 800ms gap.

16:39:02.017488 DEBUG : wasabi/media/apps/3d/zbrush/install/ZBrush_4R4_Installer_WIN.exe: vfs cache: checking remote fingerprint "701579568,2022-11-01 17:59:46 +0000 UTC,debebb104c00cbfb3b123c2f75299367" against cached fingerprint "701579568,2022-11-01 17:59:46 +0000 UTC,debebb104c00cbfb3b123c2f75299367"
16:39:02.018031 DEBUG : wasabi/media/apps/3d/zbrush/install/ZBrush_4R4_Installer_WIN.exe: vfs cache: truncate to size=701579568
16:39:02.826896 DEBUG : wasabi/media/apps/3d/zbrush/install: Added virtual directory entry vAddFile: "ZBrush_4R4_Installer_WIN.exe"

I wonder - could it take Windows 800ms to truncate a file to the size it is already at?

Here is a binary which doesn't do the truncate if it doesn't need to.

v1.61.0-beta.6555.857ec7001.fix-vfs-pause on branch fix-vfs-pause (uploaded in 15-30 mins)

If that isn't any faster then I'll have to send you a binary with lots of extra debug to pin down what is happening.

That would be quintessential Windows behaviour in my opinion lol.

Using v1.61.0-beta.6555.857ec7001.fix-vfs-pause I generated this log based on this mount command:

rclone mount wasabi: Z:
-vv
--log-format time,microseconds
--vfs-cache-mode full
--cache-dir "%cd%\cache"
--use-server-modtime
--buffer-size=0
--network-mode

Thanks a lot, just tried right-clicking on a 1.8GB exe and the response was almost instant, BUT then I checked the log and found this:

11:14:52.901862 DEBUG : Some/Path/Sequel_3_Trial_Windows.exe: vfs cache: truncate to size=1834024472
11:14:53.115853 DEBUG : Some/Path/Sequel 3: Added virtual directory entry vAddFile: "Sequel_3_Trial_Windows.exe"

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.

You're welcome. That's a huge executable! How long does it take to show file properties?

Less than a second, my immediate reaction was "unable to reproduce" until I checked the log.

Now I have reduced CPU to 25% and can see it clearly, the above sequence now takes 800ms so something CPU bound is going on.

Using VSCode? If so, some real quick pointers based on my setup, if it helps...

In launch.json (for debug):

"name": "Launch",
"type": "go",
"request": "launch",
"mode": "debug",
"program": "${workspaceFolder}",
"buildFlags": "-tags cmount",
"env": {
	"CGO_ENABLED": "0"
},

In settings.json (for intellisense etc)

{
    "go.buildTags": "cmount"
}

In tasks.json (for build):

"label": "Go build task",
"type": "shell",
"options": {
	"env": {
		"CGO_ENABLED": "0"
	}
},
"command": "go build -x -tags cmount",
"group": "build",

1 Like

Its immediately clear from the log that my attempt to not truncate the file didn't work :frowning:

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.

I haven't managed to reproduce this on Linux yet.

I made a new binary to try

v1.61.0-beta.6556.7eefa3428.fix-vfs-pause on branch fix-vfs-pause (uploaded in 15-30 mins)

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.

Could it be disk bound? Any way of checking that?

1 Like

Sorry Nick, that'll be my fault! :man_facepalming: My previous comment should now lead you to the correct log.

You were right, not truncating is indeed faster. Using that version of rclone I was able to show file properties in <1s (reduced from ~4s).

Thanks @prizi

That certainly is an improvement - maybe that is the problem fixed? I don't know!

There still is one 800ms delay now don't know why.

11:53:15.564783 DEBUG : wasabi/media/apps/3d/zbrush/install/ZBrush_4R4_Installer_WIN.exe: vfs cache: checking remote fingerprint "701579568,2022-11-01 17:59:46 +0000 UTC,debebb104c00cbfb3b123c2f75299367" against cached fingerprint "701579568,2022-11-01 17:59:46 +0000 UTC,debebb104c00cbfb3b123c2f75299367"
11:53:16.413351 DEBUG : wasabi/media/apps/3d/zbrush/install: Added virtual directory entry vAddFile: "ZBrush_4R4_Installer_WIN.exe"

This binary has more timing on the truncate and sparse calls - it would be very interesting to see the timings on those

Yes, big improvement! Fixed from my point of view, but my usage probably differs from @wslrj.

Using v1.61.0-beta.6556.7eefa3428.fix-vfs-pause I generated this log. The first line shows version and params, the rest is just output from a right click > properties action.