Rclone - cmount - vfs chunk size not working

/home/felix/go/bin/rclone cmount gcrypt: /gmedia --allow-other --dir-cache-time 48h --vfs-read-chunk-size 32M --vfs-read-chunk-size-limit 2G --cache-dir /data/rclone --vfs-cache-mode writes --buffer-size 512M --syslog --umask 002 --bind 192.168.1.30 -o auto_cache --log-level INFO

I have a pretty basic mount. I noticed that I use cmount, I don’t get any chunksize increases and it stays at the starting level.

If I remove the cmount, I get the increases.

I tested by doing a rsync and I can see in the logs the chunkSize staying consistent and never moving. If I do a regular ‘mount’, it works.

Hmm, I wonder…

Can you see if all the reads are in-order or do you see some reads out of order? Out of order reads will reset the chunk size to 0.

Can you post a few logs?

Yeah, it’s odd as performance on a big copy is really poor compared to a regular mount:

rsync --progress /test/Radarr_Movies/Tomb\ Raider\ \(2018\)/Tomb\ Raider\ \(2018\).mkv .
Tomb Raider (2018).mkv
    105,938,944   0%   10.87MB/s    1:26:21

It flutters from low single digits to mid teens at most.

Whole log: https://pastebin.com/5SNn6V5d

My non cmount really flies.

felix@gemini:/data$ rsync --progress /gmedia/Radarr_Movies/Tomb\ Raider\ \(2018\)/Tomb\ Raider\ \(2018\).mkv .
Tomb Raider (2018).mkv
  1,366,065,152   2%   61.41MB/s    0:14:57  

and at times I can usually get to 90-100MB/s on a rsync.

There is definitely something wrong in the log.
It looks like there are multiple parallel Read s for the same file handle.
For example:

Read: ofst=22806528, fh=0x0
Read: ofst=22675456, fh=0x0
ChunkedReader.Read at 24113152 length 1048576 chunkOffset 0 chunkSize 33554432
ReadFileHandle.seek from 22675456 to 22806528 (fs.RangeSeeker)
ChunkedReader.RangeSeek from 25161728 to 22806528 length -1

In this case the second Read ofst=22806528 happend before the Read ofst=22675456, which causes a seek and resets the chunkSize.

Can you try if the sync_read fuse option fixes this problem?

That did it:

2018/07/12 06:09:21 DEBUG : /Radarr_Movies/Tomb Raider (2018): Getattr: fh=0xFFFFFFFFFFFFFFFF
2018/07/12 06:09:06 DEBUG : rclone: Versiono"v1.42-DEV" starting with parameters ["/home/felix/go/bin/rclone" "cmount" "gcrypt:" "/test" "--allow-other" "--dir-cache-time" "48h" "--vfs-read-chunk-size" "32M" "--vfs-read-chunk-size-limit" "2G" "--cache-dir" "/data/rclone" "--vfs-cache-mode" "writes" "--buffer-size" "512M" "-o" "auto_cache" "-o" "sync_read" "--log-file" "/home/felix/logs/testrsync1.log" "--umask" "002" "--bind" "192.168.1.30" "--log-level" "DEBUG"]

Looks good.

2018/07/12 06:09:24 DEBUG : Radarr_Movies/Tomb Raider (2018)/Tomb Raider (2018).mkv: ChunkedReader.Read at 57667584 length 1048576 chunkOffset 33554432 chunkSize 67108864
2018/07/12 06:09:24 DEBUG : /Radarr_Movies/Tomb Raider (2018)/Tomb Raider (2018).mkv: >Read: n=131072
2018/07/12 06:09:24 DEBUG : /Radarr_Movies/Tomb Raider (2018)/Tomb Raider (2018).mkv: Read: ofst=56623104, fh=0x0
2018/07/12 06:09:24 DEBUG : /Radarr_Movies/Tomb Raider (2018)/Tomb Raider (2018).mkv: >Read: n=131072
2018/07/12 06:09:24 DEBUG : /Radarr_Movies/Tomb Raider (2018)/Tomb Raider (2018).mkv: Read: ofst=56754176, fh=0x0
2018/07/12 06:09:24 DEBUG : /Radarr_Movies/Tomb Raider (2018)/Tomb Raider (2018).mkv: >Read: n=131072
2018/07/12 06:09:24 DEBUG : /Radarr_Movies/Tomb Raider (2018)/Tomb Raider (2018).mkv: Read: ofst=56885248, fh=0x0
2018/07/12 06:09:24 DEBUG : /Radarr_Movies/Tomb Raider (2018)/Tomb Raider (2018).mkv: >Read: n=131072
2018/07/12 06:09:24 DEBUG : /Radarr_Movies/Tomb Raider (2018)/Tomb Raider (2018).mkv: Read: ofst=57016320, fh=0x0
2018/07/12 06:09:24 DEBUG : /Radarr_Movies/Tomb Raider (2018)/Tomb Raider (2018).mkv: >Read: n=131072
2018/07/12 06:09:24 DEBUG : /Radarr_Movies/Tomb Raider (2018)/Tomb Raider (2018).mkv: Read: ofst=57147392, fh=0x0
2018/07/12 06:09:24 DEBUG : /Radarr_Movies/Tomb Raider (2018)/Tomb Raider (2018).mkv: >Read: n=131072
2018/07/12 06:09:24 DEBUG : /Radarr_Movies/Tomb Raider (2018)/Tomb Raider (2018).mkv: Read: ofst=57278464, fh=0x0
2018/07/12 06:09:24 DEBUG : /Radarr_Movies/Tomb Raider (2018)/Tomb Raider (2018).mkv: >Read: n=131072
2018/07/12 06:09:24 DEBUG : /Radarr_Movies/Tomb Raider (2018)/Tomb Raider (2018).mkv: Read: ofst=57409536, fh=0x0
2018/07/12 06:09:24 DEBUG : /Radarr_Movies/Tomb Raider (2018)/Tomb Raider (2018).mkv: >Read: n=131072
2018/07/12 06:09:24 DEBUG : /Radarr_Movies/Tomb Raider (2018)/Tomb Raider (2018).mkv: Read: ofst=57540608, fh=0x0
2018/07/12 06:09:24 DEBUG : Radarr_Movies/Tomb Raider (2018)/Tomb Raider (2018).mkv: ChunkedReader.Read at 58716160 length 1048576 chunkOffset 33554432 chunkSize 67108864
2018/07/12 06:09:24 DEBUG : /Radarr_Movies/Tomb Raider (2018)/Tomb Raider (2018).mkv: >Read: n=131072
2018/07/12 06:09:24 DEBUG : /Radarr_Movies/Tomb Raider (2018)/Tomb Raider (2018).mkv: Read: ofst=57671680, fh=0x0
2018/07/12 06:09:24 DEBUG : /Radarr_Movies/Tomb Raider (2018)/Tomb Raider (2018).mkv: >Read: n=131072
2018/07/12 06:09:24 DEBUG : /Radarr_Movies/Tomb Raider (2018)/Tomb Raider (2018).mkv: Read: ofst=57802752, fh=0x0
2018/07/12 06:09:24 DEBUG : /Radarr_Movies/Tomb Raider (2018)/Tomb Raider (2018).mkv: >Read: n=131072
2018/07/12 06:09:24 DEBUG : /Radarr_Movies/Tomb Raider (2018)/Tomb Raider (2018).mkv: Read: ofst=57933824, fh=0x0
--More--(5%)

Thanks for the tip as I thought I tried that but I guess not.

That is what I was wondering was happening.

I saw this with this alternate fuse library https://github.com/hanwen/go-fuse/issues/140 - I didn’t realise sync_read was the solution though.

Doesn’t sync_read affect performance otherwise?

Doesn’t seem to. I can get a rsync going and max my download without a problem.

felix@gemini:/data$ !428
rsync --progress /gmedia/Radarr_Movies/Tomb\ Raider\ \(2018\)/Tomb\ Raider\ \(2018\).mkv .
Tomb Raider (2018).mkv
  2,090,631,168   3%   92.57MB/s    0:09:47

I just had a look at the source, and for rclone mount we use sync_read by default which I had completely forgotten about.

So using sync_read with cmount is probably a good idea. Perhaps I should make it the default…