On Wed, Jul 31, 2024 at 11:38 AM Frank Dinoff <fdinoff@xxxxxxxxxx> wrote: > > I have a fuse filesystem with writeback cache enabled. We noticed a slow down > when copying files to the fuse filesystem using cp. The slowdown seems to > consistently trigger for the first copy but not later ones. > > Using passthrough_ll from https://github.com/libfuse/libfuse I was able to > reproduce the issue. > > # start the fuse filesystem > $ git clone https://github.com/libfuse/libfuse > $ git checkout fuse-3.16.2 > $ meson build && cd build && ninja > $ mkdir /tmp/passthrough > $ ./example/passthrough_ll -o writeback -o debug -f /tmp/passthrough > > In another terminal > $ dd if=/dev/urandom of=/tmp/foo bs=1M count=4 > # run this multiple times > $ time cp /tmp/foo /tmp/passthrough/tmp/foo2 > > On my machine the first cp call takes between 0.4s and 1s. Repeated cp calls > take 0.05s. If you wait long enough between attempts cp becomes slow again > Hi Frank, I don't think this is an issue on the most up to date versions of the kernel and libfuse. I'm on top of the fuse tree and libfuse, and I don't see this slowdown for the first cp. Here's what I'm seeing: [vmuser@myvm ~]$ dd if=/dev/urandom of=/tmp/foo bs=1M count=4 4+0 records in 4+0 records out 4194304 bytes (4.2 MB, 4.0 MiB) copied, 0.0169003 s, 248 MB/s [vmuser@myvm ~]$ time sudo cp /tmp/foo /tmp/passthrough/tmp/foo2 real 0m0.035s user 0m0.006s sys 0m0.008s [vmuser@myvm ~]$ time sudo cp /tmp/foo /tmp/passthrough/tmp/foo2 real 0m0.026s user 0m0.004s sys 0m0.009s ANd these are the corresponding daemon logs I see: [vmuser@myvm build]$ sudo ./example/passthrough_ll -o writeback -o debug -f /tmp/passthrough FUSE library version: 3.17.0 unique: 2, opcode: INIT (26), nodeid: 0, insize: 104, pid: 0 INIT: 7.40 flags=0x73fffffb max_readahead=0x00020000 lo_init: activating writeback INIT: 7.40 flags=0x4041f429 max_readahead=0x00020000 max_write=0x00100000 max_background=0 congestion_threshold=0 time_gran=1 unique: 2, success, outsize: 80 unique: 4, opcode: LOOKUP (1), nodeid: 1, insize: 44, pid: 658 lo_lookup(parent=1, name=tmp) 1/tmp -> 139767698164736 unique: 4, success, outsize: 144 unique: 6, opcode: LOOKUP (1), nodeid: 139767698164736, insize: 45, pid: 658 lo_lookup(parent=139767698164736, name=foo2) unique: 6, error: -2 (No such file or directory), outsize: 16 unique: 8, opcode: LOOKUP (1), nodeid: 139767698164736, insize: 45, pid: 658 lo_lookup(parent=139767698164736, name=foo2) unique: 8, error: -2 (No such file or directory), outsize: 16 unique: 10, opcode: CREATE (35), nodeid: 139767698164736, insize: 61, pid: 658 lo_create(parent=139767698164736, name=foo2) 139767698164736/foo2 -> 139767832383168 unique: 10, success, outsize: 160 unique: 12, opcode: GETXATTR (22), nodeid: 139767832383168, insize: 68, pid: 658 unique: 12, error: -38 (Function not implemented), outsize: 16 unique: 14, opcode: WRITE (16), nodeid: 139767832383168, insize: 131152, pid: 0 lo_write(ino=139767832383168, size=131072, off=0) unique: 14, success, outsize: 24 unique: 16, opcode: WRITE (16), nodeid: 139767832383168, insize: 1048656, pid: 0 lo_write(ino=139767832383168, size=1048576, off=131072) unique: 16, success, outsize: 24 unique: 18, opcode: WRITE (16), nodeid: 139767832383168, insize: 1048656, pid: 0 lo_write(ino=139767832383168, size=1048576, off=1179648) unique: 18, success, outsize: 24 unique: 20, opcode: WRITE (16), nodeid: 139767832383168, insize: 1048656, pid: 0 lo_write(ino=139767832383168, size=1048576, off=2228224) unique: 22, opcode: WRITE (16), nodeid: 139767832383168, insize: 409680, pid: 0 lo_write(ino=139767832383168, size=409600, off=3276800) unique: 24, opcode: SETATTR (4), nodeid: 139767832383168, insize: 128, pid: 57 unique: 24, success, outsize: 120 unique: 22, success, outsize: 24 unique: 20, success, outsize: 24 unique: 26, opcode: WRITE (16), nodeid: 139767832383168, insize: 507984, pid: 0 lo_write(ino=139767832383168, size=507904, off=3686400) unique: 26, success, outsize: 24 unique: 28, opcode: FLUSH (25), nodeid: 139767832383168, insize: 64, pid: 658 unique: 28, success, outsize: 16 unique: 30, opcode: RELEASE (18), nodeid: 139767832383168, insize: 64, pid: 0 unique: 30, success, outsize: 16 unique: 32, opcode: LOOKUP (1), nodeid: 1, insize: 44, pid: 664 lo_lookup(parent=1, name=tmp) 1/tmp -> 139767698164736 unique: 32, success, outsize: 144 unique: 34, opcode: LOOKUP (1), nodeid: 139767698164736, insize: 45, pid: 664 lo_lookup(parent=139767698164736, name=foo2) 139767698164736/foo2 -> 139767832383168 unique: 34, success, outsize: 144 unique: 36, opcode: OPEN (14), nodeid: 139767832383168, insize: 48, pid: 664 lo_open(ino=139767832383168, flags=33281) unique: 36, success, outsize: 32 unique: 38, opcode: GETATTR (3), nodeid: 139767832383168, insize: 56, pid: 664 unique: 38, success, outsize: 120 unique: 40, opcode: WRITE (16), nodeid: 139767832383168, insize: 1048656, pid: 0 lo_write(ino=139767832383168, size=1048576, off=0) unique: 42, opcode: WRITE (16), nodeid: 139767832383168, insize: 1048656, pid: 0 lo_write(ino=139767832383168, size=1048576, off=1048576) unique: 40, success, outsize: 24 unique: 44, opcode: WRITE (16), nodeid: 139767832383168, insize: 1048656, pid: 0 lo_write(ino=139767832383168, size=1048576, off=2097152) unique: 42, success, outsize: 24 unique: 46, opcode: WRITE (16), nodeid: 139767832383168, insize: 487504, pid: 0 lo_write(ino=139767832383168, size=487424, off=3145728) unique: 48, opcode: SETATTR (4), nodeid: 139767832383168, insize: 128, pid: 57 unique: 44, success, outsize: 24 unique: 46, success, outsize: 24 unique: 48, success, outsize: 120 unique: 50, opcode: WRITE (16), nodeid: 139767832383168, insize: 561232, pid: 0 lo_write(ino=139767832383168, size=561152, off=3633152) unique: 50, success, outsize: 24 unique: 52, opcode: FLUSH (25), nodeid: 139767832383168, insize: 64, pid: 664 unique: 52, success, outsize: 16 unique: 54, opcode: RELEASE (18), nodeid: 139767832383168, insize: 64, pid: 0 unique: 54, success, outsize: 16 > The debug logs for the slow runs say that the write size is 32k (or smaller). > The fast runs have write sizes of 1M. strace says cp is doing writes in 128k > blocks. > > I think I'm running a kernel based on 6.6.15. > > Is this a known issue? Is there any fix for this? >
