Slowdown copy files into gocrypt directory

[krim404]

New Ticket based on #160.

rsync will extremly slow down the whole machine.
NFS (host EXT4) <-> GCFS. Starts with 80mb/s, ends with 2mb/s. slowing down pretty fast (after 15sec).
Has nothing to do with the NFS, also slows down when running directly on the internal SSD (EXT4, too). Already tried to mount with noprealloc, same issue.

Using encfs in the same setup has no problem, so i doubt it has something to do with fuse or the os.
Running gocryptfs based on the debian package in testing (gocryptfs 1.6.1; go-fuse 0.0~git20181027.c029b69; 2019-01-25 go1.11.5)

iostat -x 1 -d:
sda gets to 100% utilisation, which is the SWAP device. Machine has 16gb memory (most of it free), maybe this has something to do with poor memory utilization?

[rfjakob]

Hi! Thanks for the report! I'm trying to reproduce this here.

First experiment: I write 10 files directly to ext4, 1GB each. This on a Samsung SSD 840 EVO 250GB:

$ for i in 0 1 2 3 4 5 6 7 8 9 ; do dd if=/dev/zero of=1gb.$i bs=1M count=1024 ; done
1073741824 bytes (1.1 GB, 1.0 GiB) copied, 3.82566 s, 281 MB/s
1073741824 bytes (1.1 GB, 1.0 GiB) copied, 6.93688 s, 155 MB/s
1073741824 bytes (1.1 GB, 1.0 GiB) copied, 3.46698 s, 310 MB/s
1073741824 bytes (1.1 GB, 1.0 GiB) copied, 17.4238 s, 61.6 MB/s
1073741824 bytes (1.1 GB, 1.0 GiB) copied, 25.9596 s, 41.4 MB/s
1073741824 bytes (1.1 GB, 1.0 GiB) copied, 21.5438 s, 49.8 MB/s
1073741824 bytes (1.1 GB, 1.0 GiB) copied, 18.0861 s, 59.4 MB/s
1073741824 bytes (1.1 GB, 1.0 GiB) copied, 28.977 s, 37.1 MB/s
1073741824 bytes (1.1 GB, 1.0 GiB) copied, 24.8763 s, 43.2 MB/s
1073741824 bytes (1.1 GB, 1.0 GiB) copied, 28.723 s, 37.4 MB/s

[krim404]

OK i can confirm: it just fills up the ram, then utilizing the swap. This is when the slowdown occurs.
Has nothing to do directly with gocryptfs, as this behaviour even appears when copying large files to a NFS share.

[rfjakob]

rsync the files to a normal directory:

$ time rsync -P 1gb.* normal-dir

1gb.0
  1,073,741,824 100%   57.55MB/s    0:00:17 (xfr#1, to-chk=9/10)
1gb.1
  1,073,741,824 100%   52.27MB/s    0:00:19 (xfr#2, to-chk=8/10)
1gb.2
  1,073,741,824 100%   36.16MB/s    0:00:28 (xfr#3, to-chk=7/10)
1gb.3
  1,073,741,824 100%   24.98MB/s    0:00:41 (xfr#4, to-chk=6/10)
1gb.4
  1,073,741,824 100%   22.25MB/s    0:00:46 (xfr#5, to-chk=5/10)
1gb.5
  1,073,741,824 100%   21.37MB/s    0:00:47 (xfr#6, to-chk=4/10)
1gb.6
  1,073,741,824 100%   22.85MB/s    0:00:44 (xfr#7, to-chk=3/10)
1gb.7
  1,073,741,824 100%   27.99MB/s    0:00:36 (xfr#8, to-chk=2/10)
1gb.8
  1,073,741,824 100%   22.16MB/s    0:00:46 (xfr#9, to-chk=1/10)
1gb.9
  1,073,741,824 100%   22.04MB/s    0:00:46 (xfr#10, to-chk=0/10)

real	6m10.829s
user	0m54.323s
sys	0m21.500s

Transfer slows down to 22MB/s, also the whole systems becomes sluggish sometimes. iostat shows 100%.

rsync to gocryptfs mount:

$ time rsync -P 1gb.* gocryptfs-mnt
1gb.0
  1,073,741,824 100%   41.31MB/s    0:00:24 (xfr#1, to-chk=9/10)
1gb.1
  1,073,741,824 100%   29.80MB/s    0:00:34 (xfr#2, to-chk=8/10)
1gb.2
  1,073,741,824 100%   19.29MB/s    0:00:53 (xfr#3, to-chk=7/10)
1gb.3
  1,073,741,824 100%   22.97MB/s    0:00:44 (xfr#4, to-chk=6/10)
1gb.4
  1,073,741,824 100%   30.38MB/s    0:00:33 (xfr#5, to-chk=5/10)
1gb.5
  1,073,741,824 100%   28.01MB/s    0:00:36 (xfr#6, to-chk=4/10)
1gb.6
  1,073,741,824 100%   29.70MB/s    0:00:34 (xfr#7, to-chk=3/10)
1gb.7
  1,073,741,824 100%   28.92MB/s    0:00:35 (xfr#8, to-chk=2/10)
1gb.8
  1,073,741,824 100%   25.62MB/s    0:00:39 (xfr#9, to-chk=1/10)
1gb.9
  1,073,741,824 100%   20.36MB/s    0:00:50 (xfr#10, to-chk=0/10)

real	6m23.280s
user	0m54.593s
sys	0m21.307s

Transfer speed varies, iostat shows 100%, but also 20% every now and then. System becomes sluggish.

[rfjakob]

Hmm, but what fills up RAM and swap? gocryptfs?

[krim404]

i edited the post above.
just realized this after trying big files.

the problem with gocryptfs is, that it even happens with small files with rsync, while directly rsync on a NFS / encfs seems to flush the memory more frequently to the storage. So - not a bug, just a strange behaviour.

[rfjakob]

Interesting to watch while rsync is running:

watch -n 0.1 grep dirty /proc/vmstat

Here, nr_dirty is the number pages that have not yet been written to disk, and are buffered in RAM. Looks like Linux flushes everything every few seconds (nr_dirty goes to zero), and this is when rsync slows down.