Poor read performance with network backend

[j-vizcaino]

Use case

• /tmp/encrypted is an Amazon Cloud Drive folder, mounted read-only using rclone
• /tmp/clear is the gocryptfs deciphered version of the above.

Copying a 300MB file (ciphered) from /tmp/encrypted, I get around 5-6MBps, which is OK, considering my bandwidth is 10MBps.
Copying the same file from /tmp/clear yields extremely poor speeds (from 100KBps to 1MBps).
Speed is not limited by the CPU.
Tracing read requests in rclone shows read sizes from 4KB to 128KB occuring at low frequency (thus low througput)

Any advice would be greatly appreciated.

Environment

• Debian Stretch, x86_64
• gocryptfs 1.2.1
• Ciphered volume has the following features:
  • version: 2
  • flags: GCMIV128, DirIV, EMENames, LongNames, AESSIV
• rclone 1.35, mount max-read-ahead set to 16MB

[j-vizcaino]

After some extra tests it seems that setting the max-read-ahead for rclone has not effect since reads are 128KB max.
Swapped rclone mount with acd_cli and performance is almost the same:

• reading directly from acd_cli mount gives around 10 MBps
• reading from deciphered gocryptfs mount gives bursts at 2 MBps with stalls of more than 3 seconds :(

How does gocryptfs handles fadvise? Does it propagates these flags to the underlying FS when opening the crypted file?

[rfjakob]

Looks like gocryptfs is doing something that's pretty slow on Amazon Cloud Drive. I don't really known how ACD works, but can you give me access to an ACD folder filled with garbage to examine this?

[rfjakob]

PS: fadvise: no, fadvise is completely ignored.

[j-vizcaino]

@rfjakob I cannot delegate part of an ACD folder sadly has mount is all-or-nothing. IIRC, ACD has a free plan though and it's super easy to set it up.
Regarding fadvise, please discard my comment as, digging deeper I found out that the syscall is handled by the page cache of the kernel (so no FS interaction or support is needed)

[j-vizcaino]

@rfjakob I think I found what causes the problem: reads issued by gocryptfs are not sequential. When running rclone mount with debug information, I see a lot of seek calls. It seems gocryptfs is "jumping around" in the file, therefore the read-ahead cannot work properly and throughput is badly affected by the read latency.

EDIT: rclone code is causing the excessive calls to seek. Maybe this is related to this part of the code where reads must fulfill a page cache.
Considering that gocryptfs adds 32 bytes every 4 KB (size of page), the read is misaligned.
@ncw Could you shed some light in this?

[rfjakob]

Can you attach the log?

[j-vizcaino]

2017/03/16 11:18:24 aaa/gocryptfs.diriv: File.Open
2017/03/16 11:18:24 aaa/gocryptfs.diriv: ReadFileHandle.Read size 4096 offset 0
2017/03/16 11:18:24 aaa/gocryptfs.diriv: ReadFileHandle.Read OK
2017/03/16 11:18:25 aaa/bbb/ccc: ReadFileHandle.Read OK
2017/03/16 11:18:25 aaa/bbb/ccc: ReadFileHandle.Read size 4096 offset 8192
2017/03/16 11:18:25 aaa/bbb/ccc: ReadFileHandle.seek from 135168 to 8192
2017/03/16 11:18:25 aaa/bbb/ccc: ReadFileHandle.Read OK
2017/03/16 11:18:25 aaa/bbb/ccc: ReadFileHandle.Read size 4096 offset 135168
2017/03/16 11:18:25 aaa/bbb/ccc: ReadFileHandle.seek from 12288 to 135168
2017/03/16 11:18:25 aaa/bbb/ccc: ReadFileHandle.Read OK
2017/03/16 11:18:25 aaa/bbb/ccc: ReadFileHandle.Read size 4096 offset 12288
2017/03/16 11:18:25 aaa/bbb/ccc: ReadFileHandle.seek from 139264 to 12288
2017/03/16 11:18:26 aaa/bbb/ccc: ReadFileHandle.Read OK
2017/03/16 11:18:26 aaa/bbb/ccc: ReadFileHandle.Read size 4096 offset 139264
2017/03/16 11:18:26 aaa/bbb/ccc: ReadFileHandle.seek from 16384 to 139264
2017/03/16 11:18:26 aaa/bbb/ccc: ReadFileHandle.Read OK
2017/03/16 11:18:26 aaa/bbb/ccc: ReadFileHandle.Read size 4096 offset 16384
2017/03/16 11:18:26 aaa/bbb/ccc: ReadFileHandle.seek from 143360 to 16384
2017/03/16 11:18:27 aaa/bbb/ccc: ReadFileHandle.Read OK

[rfjakob]

It looks like there are two processes reading sequentially at the same time

[j-vizcaino]

I simply run a cat or cp command for the test. I don't think those two are threaded in any way.

…

On Thu, Mar 16, 2017, 11:37 rfjakob ***@***.***> wrote: It look like there are two processes reading sequentially at the same time — You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub <#92 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AEfKlcQy16cW25h5yBvVo1u6GIaKBAd4ks5rmRDygaJpZM4MegP2> .

[rfjakob]

The other process may be the kernel performing readahead on it's own. Can you try mounting gocryptfs with

-ko max_readahead=0

[j-vizcaino]

No luck there :'(

Adding -ko mount options: [max_readahead=0]
/bin/fusermount: mount failed: Invalid argument
Mount failed: fusermount exited with code 256

[rfjakob]

Ok. I probably have time to look at this today in the evening.

[ncw]

I know what this problem is...

It is almost certainly this issue: hanwen/go-fuse#140 (reported by me!)

I was unable to fix this with go-fuse, but https://github.com/bazil/fuse doesn't seem to have this problem so I never switched over to go-fuse in rclone.

I tried to fix go-fuse but I didn't succeed and I couldn't convince the author that it was anything other than expected behaviour.

[j-vizcaino]

@ncw Thank you for your expertise! It seems most likely related to go-fuse delivering read requests out-of-order.

@rfjakob What do you think about moving from go-fuse → bazil.org/fuse? If it is not an advanced task (I'm a Go noob), I can give it a try.