sendfile regression detected in ZFS 2.0 (tip) with 5.10-rc2 (and not 5.9)

[ColinIanKing]

Type	Version/Name
Distribution Name	Ubuntu
Distribution Version	Hirsute (development)
Linux Kernel	5.10-rc2
Architecture	x86-64
ZFS Version	ZFS 2.0 (tip, on commit 71ae6a9)
SPL Version	as above

Running xfs test 249 I'm seeing a regression just on the 5.10-rc2 kernel (and not on the 5.9 stable kernel) with ZFS. The failure is in sendfile returning -EINVAL with the 5.10-rc2 kernel where as in 5.9 it works fine.

Just a side note, I back-ported the ZFS 5.10/5.9 compat changes to an earlier 0.8.4 ZFS and I see the same issue, so I'm not sure if this a 5.10-rc2 issue or a ZFS compat issue or a combo of both.

Describe how to reproduce the problem

Reproducer:

#!/bin/bash

VDEV_PATH=${PWD}
POOL=testpool
TESTDIR=test


vdev0=${VDEV_PATH}/block-dev-0
truncate -s 1G ${vdev0}

zpool destroy $POOL &> /dev/null || true
zpool create $POOL $vdev0 -f
zfs create $POOL/$TESTDIR
#zfs set acltype=posixacl $POOL/$TESTDIR
#zfs set compression=on $POOL/$TESTDIR

xfs_io -f -c "pwrite -S 0xa5a55a5a 0 32768k" -c fsync /$POOL/$TESTDIR/249.src
strace -f xfs_io -f -c "sendfile -i /$POOL/$TESTDIR/249.src 0 32768k" -c fsync /$POOL/$TESTDIR/249.dst

zpool destroy $POOL
rm -rf $vdev0

With ZFS 2.0 + 5.10-rc2 we see the sendfile return an unexpected -EINVAL as follows:

wrote 33554432/33554432 bytes at offset 0
32 MiB, 8192 ops; 0.1738 sec (184.106 MiB/sec and 47131.1122 ops/sec)
execve("/usr/sbin/xfs_io", ["xfs_io", "-f", "-c", "sendfile -i /testpool/test/249.s"..., "-c", "fsync", "/testpool/test/249.dst"], 0x7ffea4835c68 /* 16 vars */) = 0
brk(NULL)                               = 0x560b3693c000
arch_prctl(0x3001 /* ARCH_??? */, 0x7ffc701a7880) = -1 EINVAL (Invalid argument)
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=43079, ...}) = 0
mmap(NULL, 43079, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f9549b1d000
close(3)                                = 0
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libpthread.so.0", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0000\201\0\0\0\0\0\0"..., 832) = 832
pread64(3, "\4\0\0\0\24\0\0\0\3\0\0\0GNU\0{\324M\31\306%'\265\343\356k%\214\217\2035"..., 68, 824) = 68
fstat(3, {st_mode=S_IFREG|0755, st_size=151232, ...}) = 0
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f9549b1b000
mmap(NULL, 136272, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f9549af9000
mmap(0x7f9549b00000, 65536, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x7000) = 0x7f9549b00000
mmap(0x7f9549b10000, 20480, PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x17000) = 0x7f9549b10000
mmap(0x7f9549b15000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1b000) = 0x7f9549b15000
mmap(0x7f9549b17000, 13392, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f9549b17000
close(3)                                = 0
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libreadline.so.5", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\0\34\1\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0644, st_size=253456, ...}) = 0
mmap(NULL, 260536, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f9549ab9000
mmap(0x7f9549aca000, 122880, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x11000) = 0x7f9549aca000
mmap(0x7f9549ae8000, 32768, PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x2f000) = 0x7f9549ae8000
mmap(0x7f9549af0000, 32768, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x36000) = 0x7f9549af0000
mmap(0x7f9549af8000, 2488, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f9549af8000
close(3)                                = 0
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libdevmapper.so.1.02.1", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0@\255\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0644, st_size=431472, ...}) = 0
mmap(NULL, 437648, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f9549a4e000
mmap(0x7f9549a58000, 294912, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0xa000) = 0x7f9549a58000
mmap(0x7f9549aa0000, 81920, PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x52000) = 0x7f9549aa0000
mmap(0x7f9549ab4000, 16384, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x65000) = 0x7f9549ab4000
mmap(0x7f9549ab8000, 3472, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f9549ab8000
close(3)                                = 0
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\360\215\2\0\0\0\0\0"..., 832) = 832
pread64(3, "\6\0\0\0\4\0\0\0@\0\0\0\0\0\0\0@\0\0\0\0\0\0\0@\0\0\0\0\0\0\0"..., 784, 64) = 784
pread64(3, "\4\0\0\0\20\0\0\0\5\0\0\0GNU\0\2\0\0\300\4\0\0\0\3\0\0\0\0\0\0\0", 32, 848) = 32
pread64(3, "\4\0\0\0\24\0\0\0\3\0\0\0GNU\0~\303\347M\250B\312<j\233\242\v!0<\341"..., 68, 880) = 68
fstat(3, {st_mode=S_IFREG|0755, st_size=1995896, ...}) = 0
pread64(3, "\6\0\0\0\4\0\0\0@\0\0\0\0\0\0\0@\0\0\0\0\0\0\0@\0\0\0\0\0\0\0"..., 784, 64) = 784
mmap(NULL, 2004064, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f9549864000
mprotect(0x7f954988a000, 1810432, PROT_NONE) = 0
mmap(0x7f954988a000, 1495040, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x26000) = 0x7f954988a000
mmap(0x7f95499f7000, 311296, PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x193000) = 0x7f95499f7000
mmap(0x7f9549a44000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1df000) = 0x7f9549a44000
mmap(0x7f9549a4a000, 13408, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f9549a4a000
close(3)                                = 0
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libtinfo.so.6", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\240\346\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0644, st_size=192032, ...}) = 0
mmap(NULL, 194944, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f9549834000
mmap(0x7f9549842000, 61440, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0xe000) = 0x7f9549842000
mmap(0x7f9549851000, 57344, PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1d000) = 0x7f9549851000
mmap(0x7f954985f000, 20480, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x2a000) = 0x7f954985f000
close(3)                                = 0
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libselinux.so.1", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0 p\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0644, st_size=163256, ...}) = 0
mmap(NULL, 174568, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f9549809000
mmap(0x7f954980f000, 102400, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x6000) = 0x7f954980f000
mmap(0x7f9549828000, 32768, PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1f000) = 0x7f9549828000
mmap(0x7f9549830000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x26000) = 0x7f9549830000
mmap(0x7f9549832000, 6632, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f9549832000
close(3)                                = 0
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libudev.so.1", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0000N\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0644, st_size=158056, ...}) = 0
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f9549807000
mmap(NULL, 162080, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f95497df000
mmap(0x7f95497e3000, 102400, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x4000) = 0x7f95497e3000
mmap(0x7f95497fc000, 36864, PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1d000) = 0x7f95497fc000
mmap(0x7f9549805000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x25000) = 0x7f9549805000
close(3)                                = 0
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libm.so.6", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\300\363\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0644, st_size=1369352, ...}) = 0
mmap(NULL, 1368336, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f9549690000
mmap(0x7f954969f000, 684032, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0xf000) = 0x7f954969f000
mmap(0x7f9549746000, 618496, PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0xb6000) = 0x7f9549746000
mmap(0x7f95497dd000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x14c000) = 0x7f95497dd000
close(3)                                = 0
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libpcre2-8.so.0", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\340\"\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0644, st_size=584392, ...}) = 0
mmap(NULL, 586536, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f9549600000
mmap(0x7f9549602000, 409600, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x2000) = 0x7f9549602000
mmap(0x7f9549666000, 163840, PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x66000) = 0x7f9549666000
mmap(0x7f954968e000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x8d000) = 0x7f954968e000
close(3)                                = 0
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libdl.so.2", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0 \22\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0644, st_size=18816, ...}) = 0
mmap(NULL, 20752, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f95495fa000
mmap(0x7f95495fb000, 8192, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1000) = 0x7f95495fb000
mmap(0x7f95495fd000, 4096, PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x3000) = 0x7f95495fd000
mmap(0x7f95495fe000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x3000) = 0x7f95495fe000
close(3)                                = 0
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f95495f8000
mmap(NULL, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f95495f5000
arch_prctl(ARCH_SET_FS, 0x7f95495f5800) = 0
mprotect(0x7f9549a44000, 12288, PROT_READ) = 0
mprotect(0x7f95495fe000, 4096, PROT_READ) = 0
mprotect(0x7f9549b15000, 4096, PROT_READ) = 0
mprotect(0x7f954968e000, 4096, PROT_READ) = 0
mprotect(0x7f95497dd000, 4096, PROT_READ) = 0
mprotect(0x7f9549805000, 4096, PROT_READ) = 0
mprotect(0x7f9549830000, 4096, PROT_READ) = 0
mprotect(0x7f954985f000, 16384, PROT_READ) = 0
mprotect(0x7f9549ab4000, 4096, PROT_READ) = 0
mprotect(0x7f9549af0000, 8192, PROT_READ) = 0
mprotect(0x560b354c6000, 4096, PROT_READ) = 0
mprotect(0x7f9549b56000, 4096, PROT_READ) = 0
munmap(0x7f9549b1d000, 43079)           = 0
set_tid_address(0x7f95495f5ad0)         = 3265
set_robust_list(0x7f95495f5ae0, 24)     = 0
rt_sigaction(SIGRTMIN, {sa_handler=0x7f9549b00b90, sa_mask=[], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x7f9549b0dbb0}, NULL, 8) = 0
rt_sigaction(SIGRT_1, {sa_handler=0x7f9549b00c30, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART|SA_SIGINFO, sa_restorer=0x7f9549b0dbb0}, NULL, 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [RTMIN RT_1], NULL, 8) = 0
prlimit64(0, RLIMIT_STACK, NULL, {rlim_cur=8192*1024, rlim_max=RLIM64_INFINITY}) = 0
statfs("/sys/fs/selinux", 0x7ffc701a77d0) = -1 ENOENT (No such file or directory)
statfs("/selinux", 0x7ffc701a77d0)      = -1 ENOENT (No such file or directory)
brk(NULL)                               = 0x560b3693c000
brk(0x560b3695d000)                     = 0x560b3695d000
openat(AT_FDCWD, "/proc/filesystems", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0444, st_size=0, ...}) = 0
read(3, "nodev\tsysfs\nnodev\ttmpfs\nnodev\tbd"..., 1024) = 420
read(3, "", 1024)                       = 0
close(3)                                = 0
access("/etc/selinux/config", F_OK)     = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/lib/locale/locale-archive", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=3041504, ...}) = 0
mmap(NULL, 3041504, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f954930e000
close(3)                                = 0
access("/proc/self/mounts", R_OK)       = 0
openat(AT_FDCWD, "/proc/self/mounts", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0444, st_size=0, ...}) = 0
read(3, "sysfs /sys sysfs rw,nosuid,nodev"..., 1024) = 1024
lstat("/sys", {st_mode=S_IFDIR|0555, st_size=0, ...}) = 0
getcwd("/home/cking", 4096)             = 12
lstat("/home/cking/sysfs", 0x7ffc701a4390) = -1 ENOENT (No such file or directory)
lstat("/proc", {st_mode=S_IFDIR|0555, st_size=0, ...}) = 0
getcwd("/home/cking", 4096)             = 12
lstat("/home/cking/proc", 0x7ffc701a4390) = -1 ENOENT (No such file or directory)
lstat("/dev", {st_mode=S_IFDIR|0755, st_size=4060, ...}) = 0
getcwd("/home/cking", 4096)             = 12
lstat("/home/cking/udev", 0x7ffc701a4390) = -1 ENOENT (No such file or directory)
lstat("/dev", {st_mode=S_IFDIR|0755, st_size=4060, ...}) = 0
lstat("/dev/pts", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
getcwd("/home/cking", 4096)             = 12
lstat("/home/cking/devpts", 0x7ffc701a4390) = -1 ENOENT (No such file or directory)
lstat("/run", {st_mode=S_IFDIR|0755, st_size=920, ...}) = 0
getcwd("/home/cking", 4096)             = 12
lstat("/home/cking/tmpfs", 0x7ffc701a4390) = -1 ENOENT (No such file or directory)
lstat("/dev", {st_mode=S_IFDIR|0755, st_size=4060, ...}) = 0
lstat("/dev/vda2", {st_mode=S_IFBLK|0660, st_rdev=makedev(0xfc, 0x2), ...}) = 0
stat("/", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
statfs("/", {f_type=EXT2_SUPER_MAGIC, f_bsize=4096, f_blocks=7578609, f_bfree=3819671, f_bavail=3428939, f_files=1933312, f_ffree=1686992, f_fsid={val=[3617647594, 2305891747]}, f_namelen=255, f_frsize=4096, f_flags=ST_VALID|ST_RELATIME}) = 0
stat("/", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
lstat("/sys", {st_mode=S_IFDIR|0555, st_size=0, ...}) = 0
lstat("/sys/kernel", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
lstat("/sys/kernel/security", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
getcwd("/home/cking", 4096)             = 12
lstat("/home/cking/securityfs", 0x7ffc701a4390) = -1 ENOENT (No such file or directory)
lstat("/dev", {st_mode=S_IFDIR|0755, st_size=4060, ...}) = 0
lstat("/dev/shm", {st_mode=S_IFDIR|S_ISVTX|0777, st_size=40, ...}) = 0
getcwd("/home/cking", 4096)             = 12
lstat("/home/cking/tmpfs", 0x7ffc701a4390) = -1 ENOENT (No such file or directory)
lstat("/run", {st_mode=S_IFDIR|0755, st_size=920, ...}) = 0
lstat("/run/lock", {st_mode=S_IFDIR|S_ISVTX|0777, st_size=80, ...}) = 0
getcwd("/home/cking", 4096)             = 12
lstat("/home/cking/tmpfs", 0x7ffc701a4390) = -1 ENOENT (No such file or directory)
lstat("/sys", {st_mode=S_IFDIR|0555, st_size=0, ...}) = 0
lstat("/sys/fs", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
lstat("/sys/fs/cgroup", {st_mode=S_IFDIR|0755, st_size=380, ...}) = 0
getcwd("/home/cking", 4096)             = 12
lstat("/home/cking/tmpfs", 0x7ffc701a4390) = -1 ENOENT (No such file or directory)
lstat("/sys", {st_mode=S_IFDIR|0555, st_size=0, ...}) = 0
lstat("/sys/fs", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
lstat("/sys/fs/cgroup", {st_mode=S_IFDIR|0755, st_size=380, ...}) = 0
lstat("/sys/fs/cgroup/unified", {st_mode=S_IFDIR|0555, st_size=0, ...}) = 0
getcwd("/home/cking", 4096)             = 12
lstat("/home/cking/cgroup2", 0x7ffc701a4390) = -1 ENOENT (No such file or directory)
lstat("/sys", {st_mode=S_IFDIR|0555, st_size=0, ...}) = 0
lstat("/sys/fs", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
lstat("/sys/fs/cgroup", {st_mode=S_IFDIR|0755, st_size=380, ...}) = 0
lstat("/sys/fs/cgroup/systemd", {st_mode=S_IFDIR|0555, st_size=0, ...}) = 0
getcwd("/home/cking", 4096)             = 12
lstat("/home/cking/cgroup", 0x7ffc701a4390) = -1 ENOENT (No such file or directory)
lstat("/sys", {st_mode=S_IFDIR|0555, st_size=0, ...}) = 0
lstat("/sys/fs", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
lstat("/sys/fs/pstore", {st_mode=S_IFDIR|0750, st_size=0, ...}) = 0
getcwd("/home/cking", 4096)             = 12
lstat("/home/cking/pstore", 0x7ffc701a4390) = -1 ENOENT (No such file or directory)
lstat("/sys", {st_mode=S_IFDIR|0555, st_size=0, ...}) = 0
lstat("/sys/firmware", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
lstat("/sys/firmware/efi", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
lstat("/sys/firmware/efi/efivars", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
getcwd("/home/cking", 4096)             = 12
lstat("/home/cking/efivarfs", 0x7ffc701a4390) = -1 ENOENT (No such file or directory)
read(3, "xec,relatime,mode=700 0 0\ncgroup"..., 1024) = 1024
lstat("/sys", {st_mode=S_IFDIR|0555, st_size=0, ...}) = 0
lstat("/sys/fs", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
lstat("/sys/fs/bpf", {st_mode=S_IFDIR|S_ISVTX|0700, st_size=0, ...}) = 0
getcwd("/home/cking", 4096)             = 12
lstat("/home/cking/none", 0x7ffc701a4390) = -1 ENOENT (No such file or directory)
lstat("/sys", {st_mode=S_IFDIR|0555, st_size=0, ...}) = 0
lstat("/sys/fs", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
lstat("/sys/fs/cgroup", {st_mode=S_IFDIR|0755, st_size=380, ...}) = 0
lstat("/sys/fs/cgroup/cpu,cpuacct", {st_mode=S_IFDIR|0555, st_size=0, ...}) = 0
getcwd("/home/cking", 4096)             = 12
lstat("/home/cking/cgroup", 0x7ffc701a4390) = -1 ENOENT (No such file or directory)
lstat("/sys", {st_mode=S_IFDIR|0555, st_size=0, ...}) = 0
lstat("/sys/fs", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
lstat("/sys/fs/cgroup", {st_mode=S_IFDIR|0755, st_size=380, ...}) = 0
lstat("/sys/fs/cgroup/net_cls,net_prio", {st_mode=S_IFDIR|0555, st_size=0, ...}) = 0
getcwd("/home/cking", 4096)             = 12
lstat("/home/cking/cgroup", 0x7ffc701a4390) = -1 ENOENT (No such file or directory)
lstat("/sys", {st_mode=S_IFDIR|0555, st_size=0, ...}) = 0
lstat("/sys/fs", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
lstat("/sys/fs/cgroup", {st_mode=S_IFDIR|0755, st_size=380, ...}) = 0
lstat("/sys/fs/cgroup/rdma", {st_mode=S_IFDIR|0555, st_size=0, ...}) = 0
getcwd("/home/cking", 4096)             = 12
lstat("/home/cking/cgroup", 0x7ffc701a4390) = -1 ENOENT (No such file or directory)
lstat("/sys", {st_mode=S_IFDIR|0555, st_size=0, ...}) = 0
lstat("/sys/fs", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
lstat("/sys/fs/cgroup", {st_mode=S_IFDIR|0755, st_size=380, ...}) = 0
lstat("/sys/fs/cgroup/devices", {st_mode=S_IFDIR|0555, st_size=0, ...}) = 0
getcwd("/home/cking", 4096)             = 12
lstat("/home/cking/cgroup", 0x7ffc701a4390) = -1 ENOENT (No such file or directory)
lstat("/sys", {st_mode=S_IFDIR|0555, st_size=0, ...}) = 0
lstat("/sys/fs", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
lstat("/sys/fs/cgroup", {st_mode=S_IFDIR|0755, st_size=380, ...}) = 0
lstat("/sys/fs/cgroup/perf_event", {st_mode=S_IFDIR|0555, st_size=0, ...}) = 0
getcwd("/home/cking", 4096)             = 12
lstat("/home/cking/cgroup", 0x7ffc701a4390) = -1 ENOENT (No such file or directory)
lstat("/sys", {st_mode=S_IFDIR|0555, st_size=0, ...}) = 0
lstat("/sys/fs", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
lstat("/sys/fs/cgroup", {st_mode=S_IFDIR|0755, st_size=380, ...}) = 0
lstat("/sys/fs/cgroup/freezer", {st_mode=S_IFDIR|0555, st_size=0, ...}) = 0
getcwd("/home/cking", 4096)             = 12
lstat("/home/cking/cgroup", 0x7ffc701a4390) = -1 ENOENT (No such file or directory)
lstat("/sys", {st_mode=S_IFDIR|0555, st_size=0, ...}) = 0
lstat("/sys/fs", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
lstat("/sys/fs/cgroup", {st_mode=S_IFDIR|0755, st_size=380, ...}) = 0
lstat("/sys/fs/cgroup/memory", {st_mode=S_IFDIR|0555, st_size=0, ...}) = 0
getcwd("/home/cking", 4096)             = 12
lstat("/home/cking/cgroup", 0x7ffc701a4390) = -1 ENOENT (No such file or directory)
lstat("/sys", {st_mode=S_IFDIR|0555, st_size=0, ...}) = 0
lstat("/sys/fs", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
lstat("/sys/fs/cgroup", {st_mode=S_IFDIR|0755, st_size=380, ...}) = 0
lstat("/sys/fs/cgroup/pids", {st_mode=S_IFDIR|0555, st_size=0, ...}) = 0
getcwd("/home/cking", 4096)             = 12
lstat("/home/cking/cgroup", 0x7ffc701a4390) = -1 ENOENT (No such file or directory)
lstat("/sys", {st_mode=S_IFDIR|0555, st_size=0, ...}) = 0
lstat("/sys/fs", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
lstat("/sys/fs/cgroup", {st_mode=S_IFDIR|0755, st_size=380, ...}) = 0
lstat("/sys/fs/cgroup/cpuset", {st_mode=S_IFDIR|0555, st_size=0, ...}) = 0
getcwd("/home/cking", 4096)             = 12
lstat("/home/cking/cgroup", 0x7ffc701a4390) = -1 ENOENT (No such file or directory)
lstat("/sys", {st_mode=S_IFDIR|0555, st_size=0, ...}) = 0
lstat("/sys/fs", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
lstat("/sys/fs/cgroup", {st_mode=S_IFDIR|0755, st_size=380, ...}) = 0
lstat("/sys/fs/cgroup/hugetlb", {st_mode=S_IFDIR|0555, st_size=0, ...}) = 0
getcwd("/home/cking", 4096)             = 12
lstat("/home/cking/cgroup", 0x7ffc701a4390) = -1 ENOENT (No such file or directory)
lstat("/sys", {st_mode=S_IFDIR|0555, st_size=0, ...}) = 0
lstat("/sys/fs", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
lstat("/sys/fs/cgroup", {st_mode=S_IFDIR|0755, st_size=380, ...}) = 0
lstat("/sys/fs/cgroup/blkio", {st_mode=S_IFDIR|0555, st_size=0, ...}) = 0
getcwd("/home/cking", 4096)             = 12
lstat("/home/cking/cgroup", 0x7ffc701a4390) = -1 ENOENT (No such file or directory)
read(3, "o=5,direct,pipe_ino=18625 0 0\nhu"..., 1024) = 1024
lstat("/proc", {st_mode=S_IFDIR|0555, st_size=0, ...}) = 0
lstat("/proc/sys", {st_mode=S_IFDIR|0555, st_size=0, ...}) = 0
lstat("/proc/sys/fs", {st_mode=S_IFDIR|0555, st_size=0, ...}) = 0
lstat("/proc/sys/fs/binfmt_misc", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
getcwd("/home/cking", 4096)             = 12
lstat("/home/cking/systemd-1", 0x7ffc701a4390) = -1 ENOENT (No such file or directory)
lstat("/dev", {st_mode=S_IFDIR|0755, st_size=4060, ...}) = 0
lstat("/dev/hugepages", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
getcwd("/home/cking", 4096)             = 12
lstat("/home/cking/hugetlbfs", 0x7ffc701a4390) = -1 ENOENT (No such file or directory)
lstat("/dev", {st_mode=S_IFDIR|0755, st_size=4060, ...}) = 0
lstat("/dev/mqueue", {st_mode=S_IFDIR|S_ISVTX|0777, st_size=40, ...}) = 0
getcwd("/home/cking", 4096)             = 12
lstat("/home/cking/mqueue", 0x7ffc701a4390) = -1 ENOENT (No such file or directory)
lstat("/sys", {st_mode=S_IFDIR|0555, st_size=0, ...}) = 0
lstat("/sys/kernel", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
lstat("/sys/kernel/debug", {st_mode=S_IFDIR|0700, st_size=0, ...}) = 0
getcwd("/home/cking", 4096)             = 12
lstat("/home/cking/debugfs", 0x7ffc701a4390) = -1 ENOENT (No such file or directory)
lstat("/sys", {st_mode=S_IFDIR|0555, st_size=0, ...}) = 0
lstat("/sys/kernel", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
lstat("/sys/kernel/tracing", {st_mode=S_IFDIR|0700, st_size=0, ...}) = 0
getcwd("/home/cking", 4096)             = 12
lstat("/home/cking/tracefs", 0x7ffc701a4390) = -1 ENOENT (No such file or directory)
lstat("/run", {st_mode=S_IFDIR|0755, st_size=920, ...}) = 0
lstat("/run/rpc_pipefs", {st_mode=S_IFDIR|0555, st_size=0, ...}) = 0
getcwd("/home/cking", 4096)             = 12
lstat("/home/cking/sunrpc", 0x7ffc701a4390) = -1 ENOENT (No such file or directory)
lstat("/proc", {st_mode=S_IFDIR|0555, st_size=0, ...}) = 0
lstat("/proc/fs", {st_mode=S_IFDIR|0555, st_size=0, ...}) = 0
lstat("/proc/fs/nfsd", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
getcwd("/home/cking", 4096)             = 12
lstat("/home/cking/nfsd", 0x7ffc701a4390) = -1 ENOENT (No such file or directory)
lstat("/sys", {st_mode=S_IFDIR|0555, st_size=0, ...}) = 0
lstat("/sys/fs", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
lstat("/sys/fs/fuse", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
lstat("/sys/fs/fuse/connections", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
getcwd("/home/cking", 4096)             = 12
lstat("/home/cking/fusectl", 0x7ffc701a4390) = -1 ENOENT (No such file or directory)
lstat("/sys", {st_mode=S_IFDIR|0555, st_size=0, ...}) = 0
lstat("/sys/kernel", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
lstat("/sys/kernel/config", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
getcwd("/home/cking", 4096)             = 12
lstat("/home/cking/configfs", 0x7ffc701a4390) = -1 ENOENT (No such file or directory)
lstat("/boot", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
lstat("/boot/efi", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
lstat("/dev", {st_mode=S_IFDIR|0755, st_size=4060, ...}) = 0
lstat("/dev/vda1", {st_mode=S_IFBLK|0660, st_rdev=makedev(0xfc, 0x1), ...}) = 0
stat("/boot/efi", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
statfs("/boot/efi", {f_type=MSDOS_SUPER_MAGIC, f_bsize=4096, f_blocks=130812, f_bfree=128816, f_bavail=128816, f_files=0, f_ffree=0, f_fsid={val=[64513, 0]}, f_namelen=1530, f_frsize=4096, f_flags=ST_VALID|ST_RELATIME}) = 0
stat("/boot/efi", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
lstat("/snap", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
lstat("/snap/core18", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
lstat("/snap/core18/1932", {st_mode=S_IFDIR|0755, st_size=348, ...}) = 0
lstat("/dev", {st_mode=S_IFDIR|0755, st_size=4060, ...}) = 0
lstat("/dev/loop1", {st_mode=S_IFBLK|0660, st_rdev=makedev(0x7, 0x1), ...}) = 0
stat("/snap/core18/1932", {st_mode=S_IFDIR|0755, st_size=348, ...}) = 0
statfs("/snap/core18/1932", {f_type=SQUASHFS_MAGIC, f_bsize=131072, f_blocks=443, f_bfree=0, f_bavail=0, f_files=10779, f_ffree=0, f_fsid={val=[1793, 0]}, f_namelen=256, f_frsize=131072, f_flags=ST_VALID|ST_RDONLY|ST_NODEV|ST_RELATIME}) = 0
stat("/snap/core18/1932", {st_mode=S_IFDIR|0755, st_size=348, ...}) = 0
lstat("/snap", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
lstat("/snap/core18", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
lstat("/snap/core18/1885", {st_mode=S_IFDIR|0755, st_size=334, ...}) = 0
lstat("/dev", {st_mode=S_IFDIR|0755, st_size=4060, ...}) = 0
lstat("/dev/loop0", {st_mode=S_IFBLK|0660, st_rdev=makedev(0x7, 0), ...}) = 0
stat("/snap/core18/1885", {st_mode=S_IFDIR|0755, st_size=334, ...}) = 0
statfs("/snap/core18/1885", {f_type=SQUASHFS_MAGIC, f_bsize=131072, f_blocks=443, f_bfree=0, f_bavail=0, f_files=10775, f_ffree=0, f_fsid={val=[1792, 0]}, f_namelen=256, f_frsize=131072, f_flags=ST_VALID|ST_RDONLY|ST_NODEV|ST_RELATIME}) = 0
stat("/snap/core18/1885", {st_mode=S_IFDIR|0755, st_size=334, ...}) = 0
lstat("/snap", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
lstat("/snap/lxd", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
lstat("/snap/lxd/17936", {st_mode=S_IFDIR|0755, st_size=246, ...}) = 0
lstat("/dev", {st_mode=S_IFDIR|0755, st_size=4060, ...}) = 0
lstat("/dev/loop2", {st_mode=S_IFBLK|0660, st_rdev=makedev(0x7, 0x2), ...}) = 0
stat("/snap/lxd/17936", {st_mode=S_IFDIR|0755, st_size=246, ...}) = 0
statfs("/snap/lxd/17936", {f_type=SQUASHFS_MAGIC, f_bsize=131072, f_blocks=554, f_bfree=0, f_bavail=0, f_files=1559, f_ffree=0, f_fsid={val=[1794, 0]}, f_namelen=256, f_frsize=131072, f_flags=ST_VALID|ST_RDONLY|ST_NODEV|ST_RELATIME}) = 0
stat("/snap/lxd/17936", {st_mode=S_IFDIR|0755, st_size=246, ...}) = 0
lstat("/snap", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
lstat("/snap/lxd", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
lstat("/snap/lxd/18137", {st_mode=S_IFDIR|0755, st_size=246, ...}) = 0
lstat("/dev", {st_mode=S_IFDIR|0755, st_size=4060, ...}) = 0
lstat("/dev/loop3", {st_mode=S_IFBLK|0660, st_rdev=makedev(0x7, 0x3), ...}) = 0
stat("/snap/lxd/18137", {st_mode=S_IFDIR|0755, st_size=246, ...}) = 0
statfs("/snap/lxd/18137", {f_type=SQUASHFS_MAGIC, f_bsize=131072, f_blocks=554, f_bfree=0, f_bavail=0, f_files=1559, f_ffree=0, f_fsid={val=[1795, 0]}, f_namelen=256, f_frsize=131072, f_flags=ST_VALID|ST_RDONLY|ST_NODEV|ST_RELATIME}) = 0
stat("/snap/lxd/18137", {st_mode=S_IFDIR|0755, st_size=246, ...}) = 0
lstat("/snap", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
lstat("/snap/snapd", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
lstat("/snap/snapd/9721", {st_mode=S_IFDIR|0755, st_size=119, ...}) = 0
lstat("/dev", {st_mode=S_IFDIR|0755, st_size=4060, ...}) = 0
lstat("/dev/loop4", {st_mode=S_IFBLK|0660, st_rdev=makedev(0x7, 0x4), ...}) = 0
stat("/snap/snapd/9721", {st_mode=S_IFDIR|0755, st_size=119, ...}) = 0
statfs("/snap/snapd/9721", {f_type=SQUASHFS_MAGIC, f_bsize=131072, f_blocks=248, f_bfree=0, f_bavail=0, f_files=472, f_ffree=0, f_fsid={val=[1796, 0]}, f_namelen=256, f_frsize=131072, f_flags=ST_VALID|ST_RDONLY|ST_NODEV|ST_RELATIME}) = 0
stat("/snap/snapd/9721", {st_mode=S_IFDIR|0755, st_size=119, ...}) = 0
read(3, "=401880k,mode=755 0 0\nnsfs /run/"..., 1024) = 268
lstat("/run", {st_mode=S_IFDIR|0755, st_size=920, ...}) = 0
lstat("/run/snapd", {st_mode=S_IFDIR|0755, st_size=80, ...}) = 0
lstat("/run/snapd/ns", {st_mode=S_IFDIR|0755, st_size=100, ...}) = 0
getcwd("/home/cking", 4096)             = 12
lstat("/home/cking/tmpfs", 0x7ffc701a4390) = -1 ENOENT (No such file or directory)
lstat("/run", {st_mode=S_IFDIR|0755, st_size=920, ...}) = 0
lstat("/run/snapd", {st_mode=S_IFDIR|0755, st_size=80, ...}) = 0
lstat("/run/snapd/ns", {st_mode=S_IFDIR|0755, st_size=100, ...}) = 0
lstat("/run/snapd/ns/lxd.mnt", {st_mode=S_IFREG|0444, st_size=0, ...}) = 0
getcwd("/home/cking", 4096)             = 12
lstat("/home/cking/nsfs", 0x7ffc701a4390) = -1 ENOENT (No such file or directory)
lstat("/run", {st_mode=S_IFDIR|0755, st_size=920, ...}) = 0
lstat("/run/user", {st_mode=S_IFDIR|0755, st_size=60, ...}) = 0
lstat("/run/user/1000", {st_mode=S_IFDIR|0700, st_size=140, ...}) = 0
getcwd("/home/cking", 4096)             = 12
lstat("/home/cking/tmpfs", 0x7ffc701a4390) = -1 ENOENT (No such file or directory)
lstat("/testpool", {st_mode=S_IFDIR|0755, st_size=3, ...}) = 0
getcwd("/home/cking", 4096)             = 12
lstat("/home/cking/testpool", 0x7ffc701a4390) = -1 ENOENT (No such file or directory)
lstat("/testpool", {st_mode=S_IFDIR|0755, st_size=3, ...}) = 0
lstat("/testpool/test", {st_mode=S_IFDIR|0755, st_size=3, ...}) = 0
getcwd("/home/cking", 4096)             = 12
lstat("/home/cking/testpool", 0x7ffc701a4390) = -1 ENOENT (No such file or directory)
read(3, "", 1024)                       = 0
close(3)                                = 0
openat(AT_FDCWD, "/etc/projects", O_RDONLY) = -1 ENOENT (No such file or directory)
stat("/testpool/test/249.dst", 0x7ffc701a73f0) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/testpool/test/249.dst", O_RDWR|O_CREAT, 0600) = 3
fstatfs(3, {f_type=ZFS_SUPER_MAGIC, f_bsize=131072, f_blocks=6655, f_bfree=6398, f_bavail=6398, f_files=1638096, f_ffree=1638089, f_fsid={val=[1239261780, 15049724]}, f_namelen=255, f_frsize=131072, f_flags=ST_VALID}) = 0
fstat(3, {st_mode=S_IFREG|0600, st_size=0, ...}) = 0
fstatfs(3, {f_type=ZFS_SUPER_MAGIC, f_bsize=131072, f_blocks=6655, f_bfree=6398, f_bavail=6398, f_files=1638096, f_ffree=1638089, f_fsid={val=[1239261780, 15049724]}, f_namelen=255, f_frsize=131072, f_flags=ST_VALID}) = 0
fstat(3, {st_mode=S_IFREG|0600, st_size=0, ...}) = 0
openat(AT_FDCWD, "/usr/share/locale/locale.alias", O_RDONLY|O_CLOEXEC) = 4
fstat(4, {st_mode=S_IFREG|0644, st_size=2996, ...}) = 0
read(4, "# Locale name alias data base.\n#"..., 4096) = 2996
read(4, "", 4096)                       = 0
close(4)                                = 0
openat(AT_FDCWD, "/usr/share/locale/en_GB.UTF-8/LC_MESSAGES/xfsprogs.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/share/locale/en_GB.utf8/LC_MESSAGES/xfsprogs.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/share/locale/en_GB/LC_MESSAGES/xfsprogs.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/share/locale/en.UTF-8/LC_MESSAGES/xfsprogs.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/share/locale/en.utf8/LC_MESSAGES/xfsprogs.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/share/locale/en/LC_MESSAGES/xfsprogs.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/share/locale-langpack/en_GB.UTF-8/LC_MESSAGES/xfsprogs.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/share/locale-langpack/en_GB.utf8/LC_MESSAGES/xfsprogs.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/share/locale-langpack/en_GB/LC_MESSAGES/xfsprogs.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/share/locale-langpack/en.UTF-8/LC_MESSAGES/xfsprogs.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/share/locale-langpack/en.utf8/LC_MESSAGES/xfsprogs.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/share/locale-langpack/en/LC_MESSAGES/xfsprogs.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
sysinfo({uptime=626, loads=[4256, 1472, 224], totalram=4115226624, freeram=3357290496, sharedram=1187840, bufferram=43425792, totalswap=4116705280, freeswap=4116705280, procs=278, totalhigh=0, freehigh=0, mem_unit=1}) = 0
stat("/testpool/test/249.src", {st_mode=S_IFREG|0600, st_size=33554432, ...}) = 0
openat(AT_FDCWD, "/testpool/test/249.src", O_RDONLY) = 4
sendfile(3, 4, [0], 33554432)           = -1 EINVAL (Invalid argument)
dup(2)                                  = 5
fcntl(5, F_GETFL)                       = 0x2 (flags O_RDWR)
openat(AT_FDCWD, "/usr/share/locale/en_GB.UTF-8/LC_MESSAGES/libc.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/share/locale/en_GB.utf8/LC_MESSAGES/libc.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/share/locale/en_GB/LC_MESSAGES/libc.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/share/locale/en.UTF-8/LC_MESSAGES/libc.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/share/locale/en.utf8/LC_MESSAGES/libc.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/share/locale/en/LC_MESSAGES/libc.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/share/locale-langpack/en_GB.UTF-8/LC_MESSAGES/libc.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/share/locale-langpack/en_GB.utf8/LC_MESSAGES/libc.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/share/locale-langpack/en_GB/LC_MESSAGES/libc.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/share/locale-langpack/en.UTF-8/LC_MESSAGES/libc.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/share/locale-langpack/en.utf8/LC_MESSAGES/libc.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/share/locale-langpack/en/LC_MESSAGES/libc.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
fstat(5, {st_mode=S_IFCHR|0620, st_rdev=makedev(0x88, 0), ...}) = 0
write(5, "sendfile: Invalid argument\n", 27sendfile: Invalid argument
) = 27
close(5)                                = 0
close(4)                                = 0
fsync(3)                                = 0
exit_group(1)                           = ?
+++ exited with 1 +++

This works fine on 5.9 with ZFS 2.0.

[snajpa]

This looks to be because of the removal of the set_fs mechanism, one particular commit that speaks for the work that went to 5.10: torvalds/linux@36e2c74; related LWN article

[snajpa]

Proper fix will probably require extending UIO with pipes; if I remember correctly, that proper support would need at least some bits from the direct IO PR (#10018).

[behlendorf]

Proper fix will probably require extending UIO with pipes;

Right, registering the generic splice_read / splice_write helpers would get us most of the way there. However it looks like we'll also need to update the dmu_read_uio_dnode()->uiomove() call path to be able to handle pipes. Otherwise uiomove() returns EFAULT which gets converted to EAGAIN by generic_file_splice_read(). torvalds/linux@36e2c74 is the relevant upstream kernel change.

diff --git a/module/os/linux/zfs/zpl_file.c b/module/os/linux/zfs/zpl_file.c
index 90d9737f0..d8ea78aaf 100644
--- a/module/os/linux/zfs/zpl_file.c
+++ b/module/os/linux/zfs/zpl_file.c
@@ -1035,6 +1036,8 @@ const struct file_operations zpl_file_operations = {
 #endif
        .read_iter      = zpl_iter_read,
        .write_iter     = zpl_iter_write,
+       .splice_read    = generic_file_splice_read,
+       .splice_write   = iter_file_splice_write,
 #else
        .read           = do_sync_read,
        .write          = do_sync_write,

[snajpa]

For now, I have this patch to work around the lack of support for pipes down the stack - it seems to work, but I probably wouldn't want to merge this 😄 it's based on the generic helpers (which might be an issue for merging I guess, even some comments stayed the same 🙂...).

diff --git a/module/os/linux/zfs/zpl_file.c b/module/os/linux/zfs/zpl_file.c
index 90d9737f0..e3d82f330 100644
--- a/module/os/linux/zfs/zpl_file.c
+++ b/module/os/linux/zfs/zpl_file.c
@@ -27,6 +27,7 @@
 #ifdef CONFIG_COMPAT
 #include <linux/compat.h>
 #endif
+#include <linux/splice.h>
 #include <sys/file.h>
 #include <sys/dmu_objset.h>
 #include <sys/zfs_znode.h>
@@ -1016,6 +1017,101 @@ zpl_compat_ioctl(struct file *filp, unsigned int cmd, unsigned long arg)
 #endif /* CONFIG_COMPAT */
 
 
+static ssize_t zpl_file_splice_read(struct file *in, loff_t *ppos,
+                                struct pipe_inode_info *pipe, size_t len,
+                                unsigned int flags)
+{
+       cred_t *cr = CRED();
+       struct inode *ip = in->f_mapping->host;
+       struct iov_iter to;
+       struct page **pages;
+       unsigned int nr_pages;
+       unsigned int mask;
+       size_t offset, base, copied = 0;
+       ssize_t res;
+       int i;
+
+       if (pipe_full(pipe->head, pipe->tail, pipe->max_usage))
+               return -EAGAIN;
+
+       /*
+        * Try to keep page boundaries matching to source pagecache ones -
+        * it probably won't be much help, but...
+        */
+       offset = *ppos & ~PAGE_MASK;
+
+       iov_iter_pipe(&to, READ, pipe, len + offset);
+
+       res = iov_iter_get_pages_alloc(&to, &pages, len + offset, &base);
+       if (res <= 0)
+               return -ENOMEM;
+
+       nr_pages = DIV_ROUND_UP(res + base, PAGE_SIZE);
+
+       mask = pipe->ring_size - 1;
+       pipe->bufs[to.head & mask].offset = offset;
+       pipe->bufs[to.head & mask].len -= offset;
+
+       for (i = 0; i < nr_pages; i++) {
+               struct iovec vec;
+               size_t this_len = min_t(size_t, len, PAGE_SIZE - offset);
+               vec.iov_base = page_address(pages[i]) + offset;
+               vec.iov_len = this_len;
+               len -= this_len;
+               res = zpl_read_common_iovec(ip, &vec, this_len, 1, ppos,
+                   UIO_SYSSPACE, flags, cr, offset);
+               if (res < 0)
+                       goto out;
+               else
+                       copied += res;
+               offset = 0;
+       }
+
+       return copied;
+out:
+       for (i = 0; i < nr_pages; i++)
+               put_page(pages[i]);
+       kvfree(pages);
+       iov_iter_advance(&to, copied);  /* truncates and discards */
+       return res;
+}
+
+static int zpl_write_pipe_buf(struct pipe_inode_info *pipe, struct pipe_buffer *buf,
+                         struct splice_desc *sd)
+{
+       int ret;
+       void *data;
+       loff_t tmp = sd->pos;
+
+       data = kmap(buf->page);
+       ret = __kernel_write(sd->u.file, data + buf->offset, sd->len, &tmp);
+       kunmap(buf->page);
+
+       return ret;
+}
+
+static ssize_t zpl_file_splice_write(struct pipe_inode_info *pipe,
+                                        struct file *out, loff_t *ppos,
+                                        size_t len, unsigned int flags)
+{
+       ssize_t ret;
+
+       struct splice_desc sd = {
+               .total_len = len,
+               .flags = flags,
+               .pos = *ppos,
+               .u.file = out,
+       };
+
+       pipe_lock(pipe);
+       ret = __splice_from_pipe(pipe, &sd, zpl_write_pipe_buf);
+       pipe_unlock(pipe);
+       if (ret > 0)
+               *ppos += ret;
+
+       return ret;
+}
+
 const struct address_space_operations zpl_address_space_operations = {
        .readpages      = zpl_readpages,
        .readpage       = zpl_readpage,
@@ -1051,6 +1147,8 @@ const struct file_operations zpl_file_operations = {
 #ifdef CONFIG_COMPAT
        .compat_ioctl   = zpl_compat_ioctl,
 #endif
+       .splice_write   = zpl_file_splice_write,
+       .splice_read    = zpl_file_splice_read,
 };
 
 const struct file_operations zpl_dir_file_operations = {

[behlendorf]

@snajpa there are only so many ways to copy from A to B, some version of what you're suggesting should be fine if we need a quick fix. That said, it's really pretty sub-optimal because we're calling zfs_read() effectively a page at a time which is going to add a substantial bit of overhead. Not that it would be any worse than what happens today since that's what the kernel has been doing on ZFS's behalf in the fallback code which was removed. This is actually a good opportunity to revisit the uio_t handling. Now that the code has been refactored for FreeBSD and Linux it's easier to see how one might cleanly pass the iov_iter along with the uio_t so it's available in a platform specific uiomove() function.

[ColinIanKing]

The suggested workaround does have some issues of it's own:

[ 116.832238] run fstests generic/013 at 2020-11-25 19:41:25
[ 117.142206] BUG: unable to handle page fault for address: 000000000000b9ca
[ 117.142228] #PF: supervisor write access in kernel mode
[ 117.142247] #PF: error_code(0x0002) - not-present page
[ 117.142258] PGD 0 P4D 0
[ 117.142268] Oops: 0002 [#1] SMP PTI
[ 117.142279] CPU: 1 PID: 18875 Comm: fsstress Tainted: P OE 5.10.0-4-generic #5
[ 117.142296] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 1.14.0-1 04/01/2014
[ 117.142324] RIP: 0010:__memmove+0x24/0x1a0
[ 117.142333] Code: 6f ff ff ff cc cc 48 89 f8 48 39 fe 7d 0f 49 89 f0 49 01 d0 49 39 f8 0f 8f a9 00 00 00 48 83 fa 20 0f 82 f5 00 00 00 48 89 d1 a4 c3 48 81 fa a8 02 00 00 72 05 40 38 fe 74 3b 48 83 ea 20 48
[ 117.142367] RSP: 0018:ffffa97d43b87ab8 EFLAGS: 00010202
[ 117.142378] RAX: 000000000000b9ca RBX: 0000000000000549 RCX: 0000000000000549
[ 117.142392] RDX: 0000000000000549 RSI: ffffa97d493b6ab7 RDI: 000000000000b9ca
[ 117.142406] RBP: ffffa97d43b87b08 R08: ffffa97d493b7000 R09: ffff9aaac37ddc80
[ 117.142420] R10: 0000000000000000 R11: 0000000000000001 R12: ffffa97d43b87c38
[ 117.142434] R13: 0000000000000000 R14: 0000000000000549 R15: ffffa97d43b87d18
[ 117.142448] FS: 00007f88fa2a8740(0000) GS:ffff9aab3bd00000(0000) knlGS:0000000000000000
[ 117.142464] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 117.142475] CR2: 000000000000b9ca CR3: 000000010b09c006 CR4: 0000000000370ee0
[ 117.142491] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 117.142505] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[ 117.142518] Call Trace:
[ 117.142533] ? uiomove_iov+0xc7/0x270 [zcommon]
[ 117.142546] uiomove+0x14/0x20 [zcommon]
[ 117.142586] dmu_read_uio_dnode+0xb2/0x140 [zfs]
[ 117.142617] dmu_read_uio_dbuf+0x47/0x60 [zfs]
[ 117.142654] zfs_read+0x28f/0x480 [zfs]
[ 117.142690] zpl_read_common_iovec+0x98/0xe0 [zfs]
[ 117.142728] zpl_file_splice_read+0x197/0x270 [zfs]
[ 117.142746] do_splice_to+0x6e/0xa0
[ 117.142754] splice_direct_to_actor+0xc9/0x230
[ 117.142764] ? generic_file_splice_read+0x1b0/0x1b0
[ 117.142775] do_splice_direct+0x89/0xd0
[ 117.142789] vfs_copy_file_range+0x140/0x370
[ 117.142799] __do_sys_copy_file_range+0xc0/0x1f0
[ 117.142810] __x64_sys_copy_file_range+0x29/0x30
[ 117.142827] do_syscall_64+0x38/0x90
[ 117.142838] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 117.142849] RIP: 0033:0x7f88fa3be67d
[ 117.142857] Code: 00 c3 66 2e 0f 1f 84 00 00 00 00 00 90 f3 0f 1e fa 48 89 f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d bb f7 0c 00 f7 d8 64 89 01 48
[ 117.142892] RSP: 002b:00007ffc7c7012b8 EFLAGS: 00000246 ORIG_RAX: 0000000000000146
[ 117.142907] RAX: ffffffffffffffda RBX: 000000000000b481 RCX: 00007f88fa3be67d
[ 117.142921] RDX: 0000000000000012 RSI: 00007ffc7c701300 RDI: 0000000000000008
[ 117.142934] RBP: 0000000000000008 R08: 000000000000b481 R09: 0000000000000000
[ 117.143350] R10: 00007ffc7c701308 R11: 0000000000000246 R12: 00007ffc7c701308
[ 117.143778] R13: 000000000008f549 R14: 00007ffc7c701300 R15: 0000000000000012
[ 117.144186] Modules linked in: zfs(POE) zunicode(POE) zavl(POE) icp(POE) zcommon(POE) znvpair(POE) spl(OE) dm_multipath zlua(POE) scsi_dh_rdac scsi_dh_emc scsi_dh_alua snd_hda_codec_generic ledtrig_audio snd_hda_intel snd_intel_dspcfg soundwire_intel soundwire_generic_allocation soundwire_cadence snd_hda_codec snd_hda_core snd_hwdep soundwire_bus intel_rapl_msr intel_rapl_common kvm_intel snd_soc_core snd_compress kvm ac97_bus snd_pcm_dmaengine rapl joydev snd_pcm snd_timer snd input_leds soundcore serio_raw mac_hid qemu_fw_cfg sch_fq_codel nfsd auth_rpcgss nfs_acl lockd grace sunrpc nfs_ssc virtio_rng ip_tables x_tables autofs4 btrfs blake2b_generic raid10 raid456 async_raid6_recov async_memcpy async_pq async_xor async_tx xor raid6_pq libcrc32c raid1 raid0 multipath linear hid_generic usbhid hid crct10dif_pclmul crc32_pclmul ghash_clmulni_intel aesni_intel crypto_simd cryptd glue_helper psmouse qxl ahci i2c_i801 libahci i2c_smbus drm_ttm_helper ttm lpc_ich drm_kms_helper syscopyarea
[ 117.144226] sysfillrect sysimgblt virtio_blk fb_sys_fops cec rc_core drm virtio_net net_failover failover
[ 117.148326] CR2: 000000000000b9ca
[ 117.148793] ---[ end trace 8c2fe58ea4e1aec6 ]---

[ColinIanKing]

Given that 5.10 will be complete in a few weeks, is there a planned fix for this regression for 5.10+

[behlendorf]

Not yet. I was planning to look in to putting together a fix for this next week.

[ColinIanKing]

Thanks for the update - much appreciated!