Great thanks for checking. I'll go figure out how to upgrade the kernel and the version of libfuse we are using. On Wed, Jul 31, 2024 at 5:11 PM Joanne Koong <joannelkoong@xxxxxxxxx> wrote: > > 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? > >
