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

[ColinIanKing]

System information

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

Describe the problem you're observing

Running xfs test 075 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 copy_file_range returning -EINVAL with the 5.10-rc2 kernel where as in 5.9 it works fine.

The test exercises "pre-allocate file space, exercising unwritten extents". The same failure occurs also for the generic xfs test 112 that is a variation of test 075 but also uses AIO system calls.

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

Run the current xfs tests on ZFS, test 075. I've distilled this down to a reproducer script:

#!/bin/bash

VDEV_PATH=${PWD}

POOL=testpool
TESTDIR=test
SCRATCHDIR=scratch

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

strace -f ./xfstests-bld/xfstests-dev/ltp/fsx -d -N 10000 -l 10485760 -S 0 -x /$POOL/$TESTDIR

zpool destroy $POOL
rm -rf $vdev0

With 5.10-rc2, the failure is as follows:

Creating zfs pool testpool..
Creating zfs file systems test and scratch in testpool..
VDEVs in /home/cking
execve("./xfstests-bld/xfstests-dev/ltp/fsx", ["./xfstests-bld/xfstests-dev/ltp/"..., "-d", "-N", "10000", "-l", "10485760", "-S", "0", "-x", "/testpool/test"], 0x7ffcb5ab6a30 /* 21 vars */) = 0
brk(NULL)                               = 0x55af65736000
arch_prctl(0x3001 /* ARCH_??? */, 0x7ffe171e9b40) = -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) = 0x7f9a5d23a000
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) = 0x7f9a5d238000
mmap(NULL, 136272, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f9a5d216000
mmap(0x7f9a5d21d000, 65536, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x7000) = 0x7f9a5d21d000
mmap(0x7f9a5d22d000, 20480, PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x17000) = 0x7f9a5d22d000
mmap(0x7f9a5d232000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1b000) = 0x7f9a5d232000
mmap(0x7f9a5d234000, 13392, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f9a5d234000
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) = 0x7f9a5d02c000
mprotect(0x7f9a5d052000, 1810432, PROT_NONE) = 0
mmap(0x7f9a5d052000, 1495040, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x26000) = 0x7f9a5d052000
mmap(0x7f9a5d1bf000, 311296, PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x193000) = 0x7f9a5d1bf000
mmap(0x7f9a5d20c000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1df000) = 0x7f9a5d20c000
mmap(0x7f9a5d212000, 13408, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f9a5d212000
close(3)                                = 0
mmap(NULL, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f9a5d029000
arch_prctl(ARCH_SET_FS, 0x7f9a5d029740) = 0
mprotect(0x7f9a5d20c000, 12288, PROT_READ) = 0
mprotect(0x7f9a5d232000, 4096, PROT_READ) = 0
mprotect(0x55af63f03000, 4096, PROT_READ) = 0
mprotect(0x7f9a5d273000, 4096, PROT_READ) = 0
munmap(0x7f9a5d23a000, 43079)           = 0
set_tid_address(0x7f9a5d029a10)         = 119202
set_robust_list(0x7f9a5d029a20, 24)     = 0
rt_sigaction(SIGRTMIN, {sa_handler=0x7f9a5d21db90, sa_mask=[], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x7f9a5d22abb0}, NULL, 8) = 0
rt_sigaction(SIGRT_1, {sa_handler=0x7f9a5d21dc30, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART|SA_SIGINFO, sa_restorer=0x7f9a5d22abb0}, 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
getpid()                                = 119202
brk(NULL)                               = 0x55af65736000
brk(0x55af65757000)                     = 0x55af65757000
rt_sigaction(SIGHUP, {sa_handler=0x55af63ef89b0, sa_mask=[HUP], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f9a5d06d950}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
rt_sigaction(SIGINT, {sa_handler=0x55af63ef89b0, sa_mask=[INT], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f9a5d06d950}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
rt_sigaction(SIGPIPE, {sa_handler=0x55af63ef89b0, sa_mask=[PIPE], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f9a5d06d950}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
rt_sigaction(SIGALRM, {sa_handler=0x55af63ef89b0, sa_mask=[ALRM], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f9a5d06d950}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
rt_sigaction(SIGTERM, {sa_handler=0x55af63ef89b0, sa_mask=[TERM], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f9a5d06d950}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
rt_sigaction(SIGXCPU, {sa_handler=0x55af63ef89b0, sa_mask=[XCPU], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f9a5d06d950}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
rt_sigaction(SIGXFSZ, {sa_handler=0x55af63ef89b0, sa_mask=[XFSZ], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f9a5d06d950}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
rt_sigaction(SIGVTALRM, {sa_handler=0x55af63ef89b0, sa_mask=[VTALRM], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f9a5d06d950}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
rt_sigaction(SIGUSR1, {sa_handler=0x55af63ef89b0, sa_mask=[USR1], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f9a5d06d950}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
rt_sigaction(SIGUSR2, {sa_handler=0x55af63ef89b0, sa_mask=[USR2], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f9a5d06d950}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
fstat(1, {st_mode=S_IFREG|0664, st_size=5840, ...}) = 0
write(1, "Seed set to 124541\n", 19Seed set to 124541
)    = 19
openat(AT_FDCWD, "/testpool/test", O_RDWR|O_CREAT|O_TRUNC, 0666) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
ioctl(3, _IOC(_IOC_WRITE, 0x58, 0x28, 0x30), 0x7ffe171e8a30) = 0
openat(AT_FDCWD, "/testpool/test.fsxgood", O_RDWR|O_CREAT|O_TRUNC, 0666) = 4
openat(AT_FDCWD, "/testpool/test.fsxlog", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 5
unlink("/testpool/test.fsxops")         = -1 ENOENT (No such file or directory)
mmap(NULL, 10489856, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f9a5c628000
mmap(NULL, 10489856, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f9a5bc27000
ftruncate(3, 0)                         = 0
ftruncate(3, 100000)                    = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=100000, ...}) = 0
ftruncate(3, 0)                         = 0
fallocate(3, 0, 0, 1)                   = 0
ftruncate(3, 0)                         = 0
fallocate(3, FALLOC_FL_KEEP_SIZE, 0, 1) = 0
ftruncate(3, 0)                         = 0
fallocate(3, FALLOC_FL_KEEP_SIZE|FALLOC_FL_PUNCH_HOLE, 0, 1) = 0
ftruncate(3, 0)                         = 0
fallocate(3, FALLOC_FL_ZERO_RANGE, 0, 1) = -1 EOPNOTSUPP (Operation not supported)
write(2, "main: filesystem does not suppor"..., 82main: filesystem does not support fallocate mode FALLOC_FL_ZERO_RANGE, disabling!
) = 82
fallocate(3, FALLOC_FL_COLLAPSE_RANGE, 0, 1) = -1 EOPNOTSUPP (Operation not supported)
write(2, "main: filesystem does not suppor"..., 86main: filesystem does not support fallocate mode FALLOC_FL_COLLAPSE_RANGE, disabling!
) = 86
fallocate(3, FALLOC_FL_INSERT_RANGE, 0, 1) = -1 EOPNOTSUPP (Operation not supported)
write(2, "main: filesystem does not suppor"..., 84main: filesystem does not support fallocate mode FALLOC_FL_INSERT_RANGE, disabling!
) = 84
ioctl(3, BTRFS_IOC_CLONE_RANGE or FICLONERANGE, {src_fd=3, src_offset=0, src_length=0, dest_offset=0}) = -1 EOPNOTSUPP (Operation not supported)
write(2, "main: filesystem does not suppor"..., 58main: filesystem does not support clone range, disabling!
) = 58
ftruncate(3, 262144)                    = 0
ioctl(3, BTRFS_IOC_FILE_EXTENT_SAME or FIDEDUPERANGE, {src_offset=0, src_length=131072, dest_count=1, info=[{dest_fd=3, dest_offset=131072}]}) = -1 EOPNOTSUPP (Operation not supported)
write(2, "main: filesystem does not suppor"..., 59main: filesystem does not support dedupe range, disabling!
) = 59
ftruncate(3, 0)                         = 0
copy_file_range(3, [0], 3, [1], 1, 0)   = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
lseek(3, 0, SEEK_END)                   = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
lseek(3, 0, SEEK_END)                   = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
lseek(3, 0, SEEK_END)                   = 0
write(1, "4 mapwrite\t0x1cdee7 thru\t0x1ce37"..., 484 mapwrite	0x1cdee7 thru	0x1ce375	(0x48f bytes)
) = 48
fstat(5, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
ftruncate(3, 1893238)                   = 0
mmap(NULL, 4982, PROT_READ|PROT_WRITE, MAP_SHARED, 3, 0x1cd000) = 0x7f9a5d243000
msync(0x7f9a5d243000, 4982, MS_SYNC)    = 0
munmap(0x7f9a5d243000, 4982)            = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=1893238, ...}) = 0
lseek(3, 0, SEEK_END)                   = 1893238
fstat(3, {st_mode=S_IFREG|0644, st_size=1893238, ...}) = 0
lseek(3, 0, SEEK_END)                   = 1893238
fstat(3, {st_mode=S_IFREG|0644, st_size=1893238, ...}) = 0
lseek(3, 0, SEEK_END)                   = 1893238
write(1, "7 mapread\t0x9f177 thru\t0xaa531\t("..., 467 mapread	0x9f177 thru	0xaa531	(0xb3bb bytes)
) = 46
mmap(NULL, 46386, PROT_READ, MAP_SHARED, 3, 0x9f000) = 0x7f9a5bc1b000
munmap(0x7f9a5bc1b000, 46386)           = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=1893238, ...}) = 0
lseek(3, 0, SEEK_END)                   = 1893238
write(1, "fallocating to largest ever: 0x4"..., 38fallocating to largest ever: 0x476a84
) = 38
write(1, "8 falloc\tfrom 0x468526 to 0x476a"..., 508 falloc	from 0x468526 to 0x476a84 (0xe55e bytes)
) = 50
fallocate(3, 0, 4621606, 58718)         = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=4680324, ...}) = 0
lseek(3, 0, SEEK_END)                   = 4680324
write(1, "copying to largest ever: 0x82f7b"..., 34copying to largest ever: 0x82f7b9
) = 34
write(1, "9 copy\tfrom 0x1a6cd to 0x1ead9, "..., 599 copy	from 0x1a6cd to 0x1ead9, (0x440c bytes) at 0x82b3ad
) = 59
copy_file_range(3, [108237], 3, [8565677], 17420, 0) = -1 EINVAL (Invalid argument)
write(1, "copy range: 0x1a6cd to 0x1ead9 a"..., 43copy range: 0x1a6cd to 0x1ead9 at 0x82b3ad
) = 43
write(1, "do_copy_range:: Invalid argument"..., 33do_copy_range:: Invalid argument
) = 33
write(1, "LOG DUMP (9 total operations):\n", 31LOG DUMP (9 total operations):
) = 31
openat(AT_FDCWD, "/testpool/test.fsxops", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 6
write(1, "1(  1 mod 256): SKIPPED (no oper"..., 391(  1 mod 256): SKIPPED (no operation)
) = 39
fstat(6, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
write(1, "2(  2 mod 256): SKIPPED (no oper"..., 392(  2 mod 256): SKIPPED (no operation)
) = 39
write(1, "3(  3 mod 256): SKIPPED (no oper"..., 393(  3 mod 256): SKIPPED (no operation)
) = 39
write(1, "4(  4 mod 256): MAPWRITE 0x1cdee"..., 624(  4 mod 256): MAPWRITE 0x1cdee7 thru 0x1ce375	(0x48f bytes)
) = 62
write(1, "5(  5 mod 256): SKIPPED (no oper"..., 395(  5 mod 256): SKIPPED (no operation)
) = 39
write(1, "6(  6 mod 256): SKIPPED (no oper"..., 396(  6 mod 256): SKIPPED (no operation)
) = 39
write(1, "7(  7 mod 256): MAPREAD  0x9f177"..., 617(  7 mod 256): MAPREAD  0x9f177 thru 0xaa531	(0xb3bb bytes)
) = 61
write(1, "8(  8 mod 256): FALLOC   0x46852"..., 738(  8 mod 256): FALLOC   0x468526 thru 0x476a84	(0xe55e bytes) EXTENDING
) = 73
write(1, "9(  9 mod 256): COPY 0x1a6cd thr"..., 839(  9 mod 256): COPY 0x1a6cd thru 0x1ead8	(0x440c bytes) to 0x82b3ad thru 0x82f7b8
) = 83
write(6, "skip dedupe_range 0x0 0x0 0x0 0x"..., 347) = 347
close(6)                                = 0
write(1, "Log of operations saved to \"/tes"..., 77Log of operations saved to "/testpool/test.fsxops"; replay with --replay-ops
) = 77
lseek(4, 0, SEEK_SET)                   = 0
write(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\0\0\0\0\0\0\0\0"..., 4680324) = 4680324
write(1, "Correct content saved for compar"..., 37Correct content saved for comparison
) = 37
write(1, "(maybe hexdump \"/testpool/test\" "..., 61(maybe hexdump "/testpool/test" vs "/testpool/test.fsxgood")
) = 61
close(4)                                = 0
write(5, "4 mapwrite\t0x1cdee7 thru\t0x1ce37"..., 1031) = 1031
exit_group(161)                         = ?
+++ exited with 161 +++
Destroying zfs pool testpool
Removing VDEVs in /home/cking

Where as with 5.9 it runs successfully, there are multiple copy_file_range calls that work fine.

Creating zfs pool testpool..
Creating zfs file systems test and scratch in testpool..
VDEVs in /home/cking
mkdir: cannot create directory ‘/mnt/test’: File exists
mkdir: cannot create directory ‘/mnt/scratch’: File exists
execve("./xfstests-bld/xfstests-dev/ltp/fsx", ["./xfstests-bld/xfstests-dev/ltp/"..., "-d", "-N", "10000", "-l", "10485760", "-S", "0", "-x", "/testpool/test"], 0x7ffe68daab40 /* 21 vars */) = 0
brk(NULL)                               = 0x559870e9d000
arch_prctl(0x3001 /* ARCH_??? */, 0x7fffa1512760) = -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) = 0x7f6c0b333000
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) = 0x7f6c0b331000
mmap(NULL, 136272, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f6c0b30f000
mmap(0x7f6c0b316000, 65536, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x7000) = 0x7f6c0b316000
mmap(0x7f6c0b326000, 20480, PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x17000) = 0x7f6c0b326000
mmap(0x7f6c0b32b000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1b000) = 0x7f6c0b32b000
mmap(0x7f6c0b32d000, 13392, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f6c0b32d000
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) = 0x7f6c0b125000
mprotect(0x7f6c0b14b000, 1810432, PROT_NONE) = 0
mmap(0x7f6c0b14b000, 1495040, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x26000) = 0x7f6c0b14b000
mmap(0x7f6c0b2b8000, 311296, PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x193000) = 0x7f6c0b2b8000
mmap(0x7f6c0b305000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1df000) = 0x7f6c0b305000
mmap(0x7f6c0b30b000, 13408, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f6c0b30b000
close(3)                                = 0
mmap(NULL, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f6c0b122000
arch_prctl(ARCH_SET_FS, 0x7f6c0b122740) = 0
mprotect(0x7f6c0b305000, 12288, PROT_READ) = 0
mprotect(0x7f6c0b32b000, 4096, PROT_READ) = 0
mprotect(0x55986f0d0000, 4096, PROT_READ) = 0
mprotect(0x7f6c0b36c000, 4096, PROT_READ) = 0
munmap(0x7f6c0b333000, 43079)           = 0
set_tid_address(0x7f6c0b122a10)         = 80648
set_robust_list(0x7f6c0b122a20, 24)     = 0
rt_sigaction(SIGRTMIN, {sa_handler=0x7f6c0b316b90, sa_mask=[], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x7f6c0b323bb0}, NULL, 8) = 0
rt_sigaction(SIGRT_1, {sa_handler=0x7f6c0b316c30, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART|SA_SIGINFO, sa_restorer=0x7f6c0b323bb0}, 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
getpid()                                = 80648
brk(NULL)                               = 0x559870e9d000
brk(0x559870ebe000)                     = 0x559870ebe000
rt_sigaction(SIGHUP, {sa_handler=0x55986f0c59b0, sa_mask=[HUP], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f6c0b166950}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
rt_sigaction(SIGINT, {sa_handler=0x55986f0c59b0, sa_mask=[INT], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f6c0b166950}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
rt_sigaction(SIGPIPE, {sa_handler=0x55986f0c59b0, sa_mask=[PIPE], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f6c0b166950}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
rt_sigaction(SIGALRM, {sa_handler=0x55986f0c59b0, sa_mask=[ALRM], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f6c0b166950}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
rt_sigaction(SIGTERM, {sa_handler=0x55986f0c59b0, sa_mask=[TERM], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f6c0b166950}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
rt_sigaction(SIGXCPU, {sa_handler=0x55986f0c59b0, sa_mask=[XCPU], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f6c0b166950}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
rt_sigaction(SIGXFSZ, {sa_handler=0x55986f0c59b0, sa_mask=[XFSZ], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f6c0b166950}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
rt_sigaction(SIGVTALRM, {sa_handler=0x55986f0c59b0, sa_mask=[VTALRM], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f6c0b166950}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
rt_sigaction(SIGUSR1, {sa_handler=0x55986f0c59b0, sa_mask=[USR1], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f6c0b166950}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
rt_sigaction(SIGUSR2, {sa_handler=0x55986f0c59b0, sa_mask=[USR2], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f6c0b166950}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
fstat(1, {st_mode=S_IFREG|0664, st_size=5961, ...}) = 0
write(1, "Seed set to 86955\n", 18Seed set to 86955
)     = 18
openat(AT_FDCWD, "/testpool/test", O_RDWR|O_CREAT|O_TRUNC, 0666) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
ioctl(3, _IOC(_IOC_WRITE, 0x58, 0x28, 0x30), 0x7fffa1511650) = 0
openat(AT_FDCWD, "/testpool/test.fsxgood", O_RDWR|O_CREAT|O_TRUNC, 0666) = 4
openat(AT_FDCWD, "/testpool/test.fsxlog", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 5
unlink("/testpool/test.fsxops")         = -1 ENOENT (No such file or directory)
mmap(NULL, 10489856, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f6c0a721000
mmap(NULL, 10489856, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f6c09d20000
ftruncate(3, 0)                         = 0
ftruncate(3, 100000)                    = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=100000, ...}) = 0
ftruncate(3, 0)                         = 0
fallocate(3, 0, 0, 1)                   = 0
ftruncate(3, 0)                         = 0
fallocate(3, FALLOC_FL_KEEP_SIZE, 0, 1) = 0
ftruncate(3, 0)                         = 0
fallocate(3, FALLOC_FL_KEEP_SIZE|FALLOC_FL_PUNCH_HOLE, 0, 1) = 0
ftruncate(3, 0)                         = 0
fallocate(3, FALLOC_FL_ZERO_RANGE, 0, 1) = -1 EOPNOTSUPP (Operation not supported)
write(2, "main: filesystem does not suppor"..., 82main: filesystem does not support fallocate mode FALLOC_FL_ZERO_RANGE, disabling!
) = 82
fallocate(3, FALLOC_FL_COLLAPSE_RANGE, 0, 1) = -1 EOPNOTSUPP (Operation not supported)
write(2, "main: filesystem does not suppor"..., 86main: filesystem does not support fallocate mode FALLOC_FL_COLLAPSE_RANGE, disabling!
) = 86
fallocate(3, FALLOC_FL_INSERT_RANGE, 0, 1) = -1 EOPNOTSUPP (Operation not supported)
write(2, "main: filesystem does not suppor"..., 84main: filesystem does not support fallocate mode FALLOC_FL_INSERT_RANGE, disabling!
) = 84
ioctl(3, BTRFS_IOC_CLONE_RANGE or FICLONERANGE, {src_fd=3, src_offset=0, src_length=0, dest_offset=0}) = -1 EOPNOTSUPP (Operation not supported)
write(2, "main: filesystem does not suppor"..., 58main: filesystem does not support clone range, disabling!
) = 58
ftruncate(3, 262144)                    = 0
ioctl(3, BTRFS_IOC_FILE_EXTENT_SAME or FIDEDUPERANGE, {src_offset=0, src_length=131072, dest_count=1, info=[{dest_fd=3, dest_offset=131072}]}) = -1 EOPNOTSUPP (Operation not supported)
write(2, "main: filesystem does not suppor"..., 59main: filesystem does not support dedupe range, disabling!
) = 59
ftruncate(3, 0)                         = 0
copy_file_range(3, [0], 3, [1], 1, 0)   = 0
write(1, "1 mapwrite\t0x402969 thru\t0x40b3b"..., 491 mapwrite	0x402969 thru	0x40b3b0	(0x8a48 bytes)
) = 49
fstat(5, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
ftruncate(3, 4240305)                   = 0
mmap(NULL, 37809, PROT_READ|PROT_WRITE, MAP_SHARED, 3, 0x402000) = 0x7f6c0b334000
msync(0x7f6c0b334000, 37809, MS_SYNC)   = 0
munmap(0x7f6c0b334000, 37809)           = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=4240305, ...}) = 0
lseek(3, 0, SEEK_END)                   = 4240305
fstat(3, {st_mode=S_IFREG|0644, st_size=4240305, ...}) = 0
lseek(3, 0, SEEK_END)                   = 4240305
write(1, "3 mapwrite\t0x225815 thru\t0x225d9"..., 483 mapwrite	0x225815 thru	0x225d9d	(0x589 bytes)
) = 48
mmap(NULL, 3486, PROT_READ|PROT_WRITE, MAP_SHARED, 3, 0x225000) = 0x7f6c0b33d000
msync(0x7f6c0b33d000, 3486, MS_SYNC)    = 0
munmap(0x7f6c0b33d000, 3486)            = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=4240305, ...}) = 0
lseek(3, 0, SEEK_END)                   = 4240305
write(1, "4 punch\tfrom 0x3c6257 to 0x3ce79"..., 504 punch	from 0x3c6257 to 0x3ce791, (0x853a bytes)
) = 50
fallocate(3, FALLOC_FL_KEEP_SIZE|FALLOC_FL_PUNCH_HOLE, 3957335, 34106) = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=4240305, ...}) = 0
lseek(3, 0, SEEK_END)                   = 4240305
write(1, "5 mapwrite\t0x2146 thru\t0xce2d\t(0"..., 455 mapwrite	0x2146 thru	0xce2d	(0xace8 bytes)
) = 45
mmap(NULL, 44590, PROT_READ|PROT_WRITE, MAP_SHARED, 3, 0x2000) = 0x7f6c0b333000
msync(0x7f6c0b333000, 44590, MS_SYNC)   = 0
munmap(0x7f6c0b333000, 44590)           = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=4240305, ...}) = 0
lseek(3, 0, SEEK_END)                   = 4240305
write(1, "6 mapwrite\t0x2c6295 thru\t0x2ce60"..., 496 mapwrite	0x2c6295 thru	0x2ce602	(0x836e bytes)
) = 49
mmap(NULL, 34307, PROT_READ|PROT_WRITE, MAP_SHARED, 3, 0x2c6000) = 0x7f6c0b335000
msync(0x7f6c0b335000, 34307, MS_SYNC)   = 0
munmap(0x7f6c0b335000, 34307)           = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=4240305, ...}) = 0
lseek(3, 0, SEEK_END)                   = 4240305
write(1, "copying to largest ever: 0x9b9d8"..., 34copying to largest ever: 0x9b9d8f
) = 34
write(1, "7 copy\tfrom 0x164bd3 to 0x16b06b"..., 617 copy	from 0x164bd3 to 0x16b06b, (0x6498 bytes) at 0x9b38f7
) = 61
copy_file_range(3, [1461203], 3, [10172663], 25752, 0) = 25752
fstat(3, {st_mode=S_IFREG|0644, st_size=10198415, ...}) = 0
lseek(3, 0, SEEK_END)                   = 10198415
fstat(3, {st_mode=S_IFREG|0644, st_size=10198415, ...}) = 0
lseek(3, 0, SEEK_END)                   = 10198415
write(1, "9 copy\tfrom 0x6f9672 to 0x701c55"..., 619 copy	from 0x6f9672 to 0x701c55, (0x85e3 bytes) at 0x3c14a9
) = 61
copy_file_range(3, [7313010], 3, [3937449], 34275, 0) = 34275
fstat(3, {st_mode=S_IFREG|0644, st_size=10198415, ...}) = 0
lseek(3, 0, SEEK_END)                   = 10198415
fstat(3, {st_mode=S_IFREG|0644, st_size=10198415, ...}) = 0
lseek(3, 0, SEEK_END)                   = 10198415
write(1, "11 write\t0x1a1d88 thru\t0x1aa747\t"..., 4711 write	0x1a1d88 thru	0x1aa747	(0x89c0 bytes)
) = 47
lseek(3, 1711496, SEEK_SET)             = 1711496
write(3, "\v\36\vd\v\312\v\1\v\24\v\342\v\252\vz\v\317\v8\v\222\v\312\v\24\vd\v8\v\273"..., 35264) = 35264
fstat(3, {st_mode=S_IFREG|0644, st_size=10198415, ...}) = 0
lseek(3, 0, SEEK_END)                   = 10198415
write(1, "12 mapwrite\t0x5c9679 thru\t0x5cd3"..., 5012 mapwrite	0x5c9679 thru	0x5cd330	(0x3cb8 bytes)
) = 50
mmap(NULL, 17201, PROT_READ|PROT_WRITE, MAP_SHARED, 3, 0x5c9000) = 0x7f6c0b339000
msync(0x7f6c0b339000, 17201, MS_SYNC)   = 0
munmap(0x7f6c0b339000, 17201)           = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=10198415, ...}) = 0
lseek(3, 0, SEEK_END)                   = 10198415
write(1, "13 mapwrite\t0x940c32 thru\t0x9419"..., 4913 mapwrite	0x940c32 thru	0x941926	(0xcf5 bytes)
) = 49
mmap(NULL, 6439, PROT_READ|PROT_WRITE, MAP_SHARED, 3, 0x940000) = 0x7f6c0b33c000
msync(0x7f6c0b33c000, 6439, MS_SYNC)    = 0
munmap(0x7f6c0b33c000, 6439)            = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=10198415, ...}) = 0
lseek(3, 0, SEEK_END)                   = 10198415
fstat(3, {st_mode=S_IFREG|0644, st_size=10198415, ...}) = 0
lseek(3, 0, SEEK_END)                   = 10198415
write(1, "15 mapread\t0x81f4b8 thru\t0x8241e"..., 4915 mapread	0x81f4b8 thru	0x8241ed	(0x4d36 bytes)
) = 49
mmap(NULL, 20974, PROT_READ, MAP_SHARED, 3, 0x81f000) = 0x7f6c0b338000
munmap(0x7f6c0b338000, 20974)           = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=10198415, ...}) = 0
lseek(3, 0, SEEK_END)                   = 10198415
fstat(3, {st_mode=S_IFREG|0644, st_size=10198415, ...}) = 0
lseek(3, 0, SEEK_END)                   = 10198415
fstat(3, {st_mode=S_IFREG|0644, st_size=10198415, ...}) = 0
lseek(3, 0, SEEK_END)                   = 10198415
fstat(3, {st_mode=S_IFREG|0644, st_size=10198415, ...}) = 0
lseek(3, 0, SEEK_END)                   = 10198415
write(1, "19 falloc\tfrom 0x7d4dc4 to 0x7da"..., 5119 falloc	from 0x7d4dc4 to 0x7daf84 (0x61c0 bytes)
) = 51
fallocate(3, 0, 8211908, 25024)         = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=10198415, ...}) = 0
lseek(3, 0, SEEK_END)                   = 10198415
write(1, "20 falloc\tfrom 0x1a6832 to 0x1b3"..., 5120 falloc	from 0x1a6832 to 0x1b3141 (0xc90f bytes)
) = 51
fallocate(3, 0, 1730610, 51471)         = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=10198415, ...}) = 0
lseek(3, 0, SEEK_END)                   = 10198415
write(1, "21 read\t0x9131c thru\t0x9da4d\t(0x"..., 4421 read	0x9131c thru	0x9da4d	(0xc732 bytes)
) = 44
lseek(3, 594716, SEEK_SET)              = 594716
read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 50994) = 50994
fstat(3, {st_mode=S_IFREG|0644, st_size=10198415, ...}) = 0
lseek(3, 0, SEEK_END)                   = 10198415
write(1, "22 mapread\t0x99a529 thru\t0x99c28"..., 4922 mapread	0x99a529 thru	0x99c284	(0x1d5c bytes)
) = 49
mmap(NULL, 8837, PROT_READ, MAP_SHARED, 3, 0x99a000) = 0x7f6c0b33b000
munmap(0x7f6c0b33b000, 8837)            = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=10198415, ...}) = 0
lseek(3, 0, SEEK_END)                   = 10198415
write(1, "23 copy\tfrom 0x6d0c8a to 0x6d7f4"..., 6223 copy	from 0x6d0c8a to 0x6d7f42, (0x72b8 bytes) at 0x6a5be1
) = 62
copy_file_range(3, [7146634], 3, [6970337], 29368, 0) = 29368
fstat(3, {st_mode=S_IFREG|0644, st_size=10198415, ...}) = 0
lseek(3, 0, SEEK_END)                   = 10198415
write(1, "24 write\t0x1324fa thru\t0x13ddb6\t"..., 4724 write	0x1324fa thru	0x13ddb6	(0xb8bd bytes)
) = 47
lseek(3, 1254650, SEEK_SET)             = 1254650
write(3, "\30\235\30,\30\20\30\307\30W\30\356\30\247\30R\30\253\30\205\30O\30\36\30z\30D\30\332\30\177"..., 47293) = 47293
fstat(3, {st_mode=S_IFREG|0644, st_size=10198415, ...}) = 0
lseek(3, 0, SEEK_END)                   = 10198415
write(1, "25 falloc\tfrom 0x13b8a3 to 0x144"..., 5125 falloc	from 0x13b8a3 to 0x14432e (0x8a8b bytes)
) = 51
fallocate(3, 0, 1292451, 35467)         = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=10198415, ...}) = 0
lseek(3, 0, SEEK_END)                   = 10198415
fstat(3, {st_mode=S_IFREG|0644, st_size=10198415, ...}) = 0
lseek(3, 0, SEEK_END)                   = 10198415
fstat(3, {st_mode=S_IFREG|0644, st_size=10198415, ...}) = 0
lseek(3, 0, SEEK_END)                   = 10198415
write(1, "28 copy\tfrom 0x802aa9 to 0x80fd5"..., 6228 copy	from 0x802aa9 to 0x80fd57, (0xd2ae bytes) at 0x29ee5c
) = 62
copy_file_range(3, [8399529], 3, [2747996], 53934, 0) = 53934

..etc

[behlendorf]

Closing as duplicate of #11151