send/recv failed - spl_system_task stuck

[dscherger]

running this:
zfs send -RD -I alpha@zfs-auto-snap_daily-2014-06-16-0910 alpha@zfs-auto-snap_daily-2014-07-01-0910 | mbuffer -m 100m -s 64k | zfs recv -Fud backup

got this error:
cannot receive incremental stream: invalid backup stream

dmesg shows this:
[ 1322.490202] INFO: task spl_system_task:1363 blocked for more than 120 seconds.
[ 1322.490204] Tainted: P O 3.12.21-gentoo-r1 #1
[ 1322.490205] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1322.490205] spl_system_task D ffffffff81495600 0 1363 2 0x00000000
[ 1322.490208] ffff88081a5d8b40 0000000000000046 ffff88083b163540 0000000000004000
[ 1322.490209] ffff88081adabfd8 ffff88081adabfd8 0000000000000001 ffffffffa03d797d
[ 1322.490211] ffff880817930000 ffffc900b1423130 0000000000000000 ffffffffa03efe60
[ 1322.490213] Call Trace:
[ 1322.490224] [] ? zil_vdev_offline+0x30d/0x5b0 [zfs]
[ 1322.490229] [] ? zio_buf_free+0x433/0xd80 [zfs]
[ 1322.490233] [] ? zio_nowait+0xa4/0xf20 [zfs]
[ 1322.490237] [] ? arc_read+0x311/0x910 [zfs]
[ 1322.490240] [] ? _raw_spin_lock_irqsave+0x1e/0x50
[ 1322.490241] [] ? _raw_spin_unlock_irqrestore+0x13/0x40
[ 1322.490244] [] ? __cv_timedwait+0x115/0x130 [spl]
[ 1322.490247] [] ? abort_exclusive_wait+0xb0/0xb0
[ 1322.490253] [] ? dmu_objset_is_receiving+0x23b/0xee0 [zfs]
[ 1322.490258] [] ? dmu_objset_is_receiving+0x716/0xee0 [zfs]
[ 1322.490262] [] ? dmu_objset_is_receiving+0x88e/0xee0 [zfs]
[ 1322.490267] [] ? dmu_objset_is_receiving+0x88e/0xee0 [zfs]
[ 1322.490271] [] ? traverse_pool+0x24f/0x400 [zfs]
[ 1322.490275] [] ? dmu_objset_is_receiving+0x9b0/0xee0 [zfs]
[ 1322.490279] [] ? dmu_objset_is_receiving+0x88e/0xee0 [zfs]
[ 1322.490283] [] ? dmu_objset_is_receiving+0x88e/0xee0 [zfs]
[ 1322.490287] [] ? dmu_objset_is_receiving+0x88e/0xee0 [zfs]
[ 1322.490291] [] ? dmu_objset_is_receiving+0x88e/0xee0 [zfs]
[ 1322.490296] [] ? dmu_objset_is_receiving+0x88e/0xee0 [zfs]
[ 1322.490300] [] ? dmu_objset_is_receiving+0x88e/0xee0 [zfs]
[ 1322.490304] [] ? traverse_pool+0x24f/0x400 [zfs]
[ 1322.490308] [] ? dmu_objset_is_receiving+0xa76/0xee0 [zfs]
[ 1322.490312] [] ? traverse_pool+0x3a9/0x400 [zfs]
[ 1322.490315] [] ? dmu_objset_is_receiving+0x170/0xee0 [zfs]
[ 1322.490318] [] ? taskq_dispatch_delay+0x481/0x620 [spl]
[ 1322.490320] [] ? try_to_wake_up+0x2a0/0x2a0
[ 1322.490321] [] ? taskq_dispatch_delay+0x2e0/0x620 [spl]
[ 1322.490323] [] ? kthread+0xb3/0xc0
[ 1322.490324] [] ? up_read+0x10/0x20
[ 1322.490326] [] ? kthread_freezable_should_stop+0x60/0x60
[ 1322.490328] [] ? ret_from_fork+0x7c/0xb0
[ 1322.490329] [] ? kthread_freezable_should_stop+0x60/0x60
[ 1442.596686] INFO: task spl_system_task:1363 blocked for more than 120 seconds.
[ 1442.596688] Tainted: P O 3.12.21-gentoo-r1 #1
[ 1442.596689] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1442.596689] spl_system_task D ffffffff81495600 0 1363 2 0x00000000
[ 1442.596692] ffff88081a5d8b40 0000000000000046 ffff88083b163540 0000000000004000
[ 1442.596693] ffff88081adabfd8 ffff88081adabfd8 0000000000000001 ffffffffa03d797d
[ 1442.596695] ffff880817930000 ffffc900b1423130 0000000000000000 ffffffffa03efe60
[ 1442.596696] Call Trace:
[ 1442.596709] [] ? zil_vdev_offline+0x30d/0x5b0 [zfs]
[ 1442.596713] [] ? zio_buf_free+0x433/0xd80 [zfs]
[ 1442.596718] [] ? zio_nowait+0xa4/0xf20 [zfs]
[ 1442.596721] [] ? arc_read+0x311/0x910 [zfs]
[ 1442.596724] [] ? _raw_spin_lock_irqsave+0x1e/0x50
[ 1442.596726] [] ? _raw_spin_unlock_irqrestore+0x13/0x40
[ 1442.596729] [] ? __cv_timedwait+0x115/0x130 [spl]
[ 1442.596732] [] ? abort_exclusive_wait+0xb0/0xb0
[ 1442.596737] [] ? dmu_objset_is_receiving+0x23b/0xee0 [zfs]
[ 1442.596743] [] ? dmu_objset_is_receiving+0x716/0xee0 [zfs]
[ 1442.596747] [] ? dmu_objset_is_receiving+0x88e/0xee0 [zfs]
[ 1442.596751] [] ? dmu_objset_is_receiving+0x88e/0xee0 [zfs]
[ 1442.596756] [] ? traverse_pool+0x24f/0x400 [zfs]
[ 1442.596760] [] ? dmu_objset_is_receiving+0x9b0/0xee0 [zfs]
[ 1442.596764] [] ? dmu_objset_is_receiving+0x88e/0xee0 [zfs]
[ 1442.596768] [] ? dmu_objset_is_receiving+0x88e/0xee0 [zfs]
[ 1442.596772] [] ? dmu_objset_is_receiving+0x88e/0xee0 [zfs]
[ 1442.596776] [] ? dmu_objset_is_receiving+0x88e/0xee0 [zfs]
[ 1442.596780] [] ? dmu_objset_is_receiving+0x88e/0xee0 [zfs]
[ 1442.596784] [] ? dmu_objset_is_receiving+0x88e/0xee0 [zfs]
[ 1442.596788] [] ? traverse_pool+0x24f/0x400 [zfs]
[ 1442.596792] [] ? dmu_objset_is_receiving+0xa76/0xee0 [zfs]
[ 1442.596796] [] ? traverse_pool+0x3a9/0x400 [zfs]
[ 1442.596799] [] ? dmu_objset_is_receiving+0x170/0xee0 [zfs]
[ 1442.596802] [] ? taskq_dispatch_delay+0x481/0x620 [spl]
[ 1442.596804] [] ? try_to_wake_up+0x2a0/0x2a0
[ 1442.596806] [] ? taskq_dispatch_delay+0x2e0/0x620 [spl]
[ 1442.596807] [] ? kthread+0xb3/0xc0
[ 1442.596808] [] ? up_read+0x10/0x20
[ 1442.596810] [] ? kthread_freezable_should_stop+0x60/0x60
[ 1442.596812] [] ? ret_from_fork+0x7c/0xb0
[ 1442.596813] [] ? kthread_freezable_should_stop+0x60/0x60

[dscherger]

Note that this is with 0.6.3 on gentoo with kernel 3.12.21-gentoo-r1

[pyavdr]

Try to send without dedup ( -D), i have seen this issue too. Look at #2210.

[dscherger]

@pyavdr Thanks, just tried again without -D and it did work. I'll run without -D for a while and see if I get any more failures. I recall only having one similar failure on 0.6.2 but had several this morning on 0.6.3.

[ryao]

Pull request #2338 might fix this. I plan to include it in the next Gentoo patch set.

[pyavdr]

@ryao

Richard, i tried your hint (#2338) but it didnt fix this issue (#2210, #2453) . Latest HEAD on kernel 3.11. with #2338 added. STRACE added

linux-ts3r:/tank # strace zfs recv -v tank/zfstest < /tank/zfstest2/testD.zfs
execve("/sbin/zfs", ["zfs", "recv", "-v", "tank/zfstest"], [/* 61 vars _/]) = 0
brk(0) = 0x1791000
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f50af92a000
access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
open("/usr/lib64/mpi/gcc/openmpi/lib64/tls/x86_64/libnvpair.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/usr/lib64/mpi/gcc/openmpi/lib64/tls/x86_64", 0x7fff607a6a80) = -1 ENOENT (No such file or directory)
open("/usr/lib64/mpi/gcc/openmpi/lib64/tls/libnvpair.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/usr/lib64/mpi/gcc/openmpi/lib64/tls", 0x7fff607a6a80) = -1 ENOENT (No such file or directory)
open("/usr/lib64/mpi/gcc/openmpi/lib64/x86_64/libnvpair.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/usr/lib64/mpi/gcc/openmpi/lib64/x86_64", 0x7fff607a6a80) = -1 ENOENT (No such file or directory)
open("/usr/lib64/mpi/gcc/openmpi/lib64/libnvpair.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/usr/lib64/mpi/gcc/openmpi/lib64", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
open("/lib64/tls/x86_64/libnvpair.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/lib64/tls/x86_64", 0x7fff607a6a80) = -1 ENOENT (No such file or directory)
open("/lib64/tls/libnvpair.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/lib64/tls", 0x7fff607a6a80) = -1 ENOENT (No such file or directory)
open("/lib64/x86_64/libnvpair.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/lib64/x86_64", 0x7fff607a6a80) = -1 ENOENT (No such file or directory)
open("/lib64/libnvpair.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\300U\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=345814, ...}) = 0
mmap(NULL, 2180144, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f50af4f7000
mprotect(0x7f50af50b000, 2093056, PROT_NONE) = 0
mmap(0x7f50af70a000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x13000) = 0x7f50af70a000
close(3) = 0
open("/usr/lib64/mpi/gcc/openmpi/lib64/libuutil.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/lib64/libuutil.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\0a\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=277845, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f50af929000
mmap(NULL, 2177400, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f50af2e3000
mprotect(0x7f50af2f5000, 2093056, PROT_NONE) = 0
mmap(0x7f50af4f4000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x11000) = 0x7f50af4f4000
mmap(0x7f50af4f6000, 2424, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f50af4f6000
close(3) = 0
open("/usr/lib64/mpi/gcc/openmpi/lib64/libzpool.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/lib64/libzpool.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`\177\2\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=4548419, ...}) = 0
mmap(NULL, 3367160, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f50aefac000
mprotect(0x7f50af0ce000, 2097152, PROT_NONE) = 0
mmap(0x7f50af2ce000, 32768, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x122000) = 0x7f50af2ce000
mmap(0x7f50af2d6000, 49400, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f50af2d6000
close(3) = 0
open("/usr/lib64/mpi/gcc/openmpi/lib64/libzfs.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/lib64/libzfs.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\0\257\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=1043575, ...}) = 0
mmap(NULL, 2362888, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f50aed6b000
mprotect(0x7f50aedab000, 2093056, PROT_NONE) = 0
mmap(0x7f50aefaa000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x3f000) = 0x7f50aefaa000
close(3) = 0
open("/usr/lib64/mpi/gcc/openmpi/lib64/libzfs_core.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/lib64/libzfs_core.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\20\23\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=49642, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f50af928000
mmap(NULL, 2109840, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f50aeb67000
mprotect(0x7f50aeb6a000, 2093056, PROT_NONE) = 0
mmap(0x7f50aed69000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x2000) = 0x7f50aed69000
close(3) = 0
open("/usr/lib64/mpi/gcc/openmpi/lib64/libm.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/lib64/libm.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\0PX\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=1127824, ...}) = 0
mmap(NULL, 3154264, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f50ae864000
mprotect(0x7f50ae966000, 2093056, PROT_NONE) = 0
mmap(0x7f50aeb65000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x101000) = 0x7f50aeb65000
close(3) = 0
open("/usr/lib64/mpi/gcc/openmpi/lib64/libdl.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/lib64/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\320\16\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=18904, ...}) = 0
mmap(NULL, 2109712, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f50ae660000
mprotect(0x7f50ae663000, 2093056, PROT_NONE) = 0
mmap(0x7f50ae862000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x2000) = 0x7f50ae862000
close(3) = 0
open("/usr/lib64/mpi/gcc/openmpi/lib64/librt.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/lib64/librt.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 #\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=42594, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f50af927000
mmap(NULL, 2128888, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f50ae458000
mprotect(0x7f50ae45f000, 2093056, PROT_NONE) = 0
mmap(0x7f50ae65e000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x6000) = 0x7f50ae65e000
close(3) = 0
open("/usr/lib64/mpi/gcc/openmpi/lib64/libuuid.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/lib64/libuuid.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=146215, ...}) = 0
mmap(NULL, 146215, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f50af903000
close(3) = 0
open("/usr/lib64/libuuid.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\240\26\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=18968, ...}) = 0
mmap(NULL, 2113928, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f50ae253000
mprotect(0x7f50ae257000, 2093056, PROT_NONE) = 0
mmap(0x7f50ae456000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x3000) = 0x7f50ae456000
close(3) = 0
open("/usr/lib64/mpi/gcc/openmpi/lib64/libz.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/lib64/libz.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\0%\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=88216, ...}) = 0
mmap(NULL, 2183304, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f50ae03d000
mprotect(0x7f50ae052000, 2093056, PROT_NONE) = 0
mmap(0x7f50ae251000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x14000) = 0x7f50ae251000
close(3) = 0
open("/usr/lib64/mpi/gcc/openmpi/lib64/libpthread.so.0", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/lib64/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\0\20o\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=141506, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f50af902000
mmap(NULL, 2217104, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f50ade1f000
mprotect(0x7f50ade37000, 2097152, PROT_NONE) = 0
mmap(0x7f50ae037000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x18000) = 0x7f50ae037000
mmap(0x7f50ae039000, 13456, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f50ae039000
close(3) = 0
open("/usr/lib64/mpi/gcc/openmpi/lib64/libc.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/lib64/libc.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\360\34\2\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=2008128, ...}) = 0
mmap(NULL, 3861056, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f50ada70000
mprotect(0x7f50adc15000, 2097152, PROT_NONE) = 0
mmap(0x7f50ade15000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1a5000) = 0x7f50ade15000
mmap(0x7f50ade1b000, 14912, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f50ade1b000
close(3) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f50af901000
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f50af900000
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f50af8fe000
arch_prctl(ARCH_SET_FS, 0x7f50af8feb80) = 0
mprotect(0x7f50ade15000, 16384, PROT_READ) = 0
mprotect(0x7f50ae037000, 4096, PROT_READ) = 0
mprotect(0x7f50ae251000, 4096, PROT_READ) = 0
mprotect(0x7f50ae456000, 4096, PROT_READ) = 0
mprotect(0x7f50ae65e000, 4096, PROT_READ) = 0
mprotect(0x7f50ae862000, 4096, PROT_READ) = 0
mprotect(0x7f50aeb65000, 4096, PROT_READ) = 0
mprotect(0x7f50af4f4000, 4096, PROT_READ) = 0
mprotect(0x7f50af70a000, 4096, PROT_READ) = 0
mprotect(0x7f50aed69000, 4096, PROT_READ) = 0
mprotect(0x7f50af2ce000, 8192, PROT_READ) = 0
mprotect(0x7f50aefaa000, 4096, PROT_READ) = 0
mprotect(0x616000, 4096, PROT_READ) = 0
mprotect(0x7f50af92b000, 4096, PROT_READ) = 0
munmap(0x7f50af903000, 146215) = 0
set_tid_address(0x7f50af8fee50) = 3722
set_robust_list(0x7f50af8fee60, 24) = 0
rt_sigaction(SIGRTMIN, {0x7f50ade259f0, [], SA_RESTORER|SA_SIGINFO, 0x7f50ade2e9f0}, NULL, 8) = 0
rt_sigaction(SIGRT_1, {0x7f50ade25a80, [], SA_RESTORER|SA_RESTART|SA_SIGINFO, 0x7f50ade2e9f0}, NULL, 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [RTMIN RT_1], NULL, 8) = 0
getrlimit(RLIMIT_STACK, {rlim_cur=8192_1024, rlim_max=RLIM64_INFINITY}) = 0
brk(0) = 0x1791000
brk(0x17b2000) = 0x17b2000
open("/usr/lib/locale/locale-archive", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/usr/share/locale/locale.alias", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=2434, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f50af926000
read(3, "# Locale name alias data base.\n#"..., 4096) = 2434
read(3, "", 4096) = 0
close(3) = 0
munmap(0x7f50af926000, 4096) = 0
open("/usr/lib/locale/de_DE.UTF-8/LC_CTYPE", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/usr/lib/locale/de_DE.utf8/LC_CTYPE", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=256516, ...}) = 0
mmap(NULL, 256516, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f50af8bf000
close(3) = 0
open("/usr/lib64/gconv/gconv-modules.cache", O_RDONLY) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=26244, ...}) = 0
mmap(NULL, 26244, PROT_READ, MAP_SHARED, 3, 0) = 0x7f50af920000
close(3) = 0
futex(0x7f50ade1a8f8, FUTEX_WAKE_PRIVATE, 2147483647) = 0
access("/sys/module/zfs", F_OK) = 0
open("/dev/zfs", O_RDWR) = 3
open("/etc/mtab", O_RDONLY) = 4
open("/etc/dfs/sharetab", O_RDONLY) = 5
open("/dev/zfs", O_RDWR) = 6
ioctl(0, SNDCTL_TMR_TIMEBASE or SNDRV_TIMER_IOCTL_NEXT_DEVICE or TCGETS, 0x7fff607a71e0) = -1 ENOTTY (Inappropriate ioctl for device)
open("/dev/zfs", O_RDWR) = 7
read(0, "\0\0\0\0\364\10\0\0\254\313\272\365\2\0\0\0\36\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 312) = 312
read(0, "", 0) = 0
read(0, "\1\1\0\0\0\0\0\0\0\0\0\1\0\0\0$\0\0\0 \0\0\0\6tosnap\0\0"..., 2292) = 2292
read(0, "", 0) = 0
read(0, "\5\0\0\0\0\0\0\0\323\205|\271G\0\0\0\206\315\245'\257a\0\0\362\276\262#\264"P\0"..., 312) = 312
read(0, "", 0) = 0
read(0, "\0\0\0\0\0\0\0\0\254\313\272\365\2\0\0\0\35\0\0\0\0\0\0\0,\275\273S\0\0\0\0"..., 312) = 312
read(0, "", 0) = 0
ioctl(3, 0x5a12, 0x7fff6079aa10) = 0
ioctl(3, 0x5a05, 0x7fff607973c0) = 0
ioctl(3, 0x5a12, 0x7fff6079aa10) = -1 ENOENT (No such file or directory)
fstat(1, {st_mode=S_IFCHR|0600, st_rdev=makedev(136, 2), ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f50af91f000
write(1, "receiving full stream of tank/zf"..., 76receiving full stream of tank/zfstest@750505295 into tank/zfstest@750505295
) = 76
ioctl(3, 0x5a1b, 0x7fff6079e8d0) = 0
ioctl(3, 0x5a16, 0x7fff607a1e70) = 0
ioctl(3, 0x5a12, 0x7fff6079a5f0) = 0
write(1, "received 229MB stream in 9 secon"..., 48received 229MB stream in 9 seconds (25.5MB/sec)
) = 48
read(0, "\0\0\0\0\0\0\0\0\254\313\272\365\2\0\0\0\35\0\0\0\0\0\0\0001\275\273S\0\0\0\0"..., 312) = 312
read(0, "", 0) = 0
ioctl(3, 0x5a12, 0x7fff6079aa10) = 0
ioctl(3, 0x5a12, 0x7fff6079a5f0) = 0
write(1, "receiving incremental stream of "..., 83receiving incremental stream of tank/zfstest@904891796 into tank/zfstest@904891796
) = 83
ioctl(3, 0x5a1b, 0x7fff6079e8d0) = 0
ioctl(3, 0x5a16, 0x7fff607a1e70) = 0
ioctl(3, 0x5a12, 0x7fff6079a5f0) = 0
write(1, "received 495MB stream in 14 seco"..., 49received 495MB stream in 14 seconds (35.3MB/sec)
) = 49
read(0, "\0\0\0\0\0\0\0\0\254\313\272\365\2\0\0\0\35\0\0\0\0\0\0\0<\275\273S\0\0\0\0"..., 312) = 312
read(0, "", 0) = 0
ioctl(3, 0x5a12, 0x7fff6079aa10) = 0
ioctl(3, 0x5a12, 0x7fff6079a5f0) = 0
write(1, "receiving incremental stream of "..., 83receiving incremental stream of tank/zfstest@133530903 into tank/zfstest@133530903
) = 83
ioctl(3, 0x5a1b, 0x7fff6079e8d0) = -1 EINVAL (Invalid argument)
write(2, "cannot receive incremental strea"..., 57cannot receive incremental stream: invalid backup stream
) = 57
ioctl(3, 0x5a12, 0x7fff6079a5f0) = 0
close(7) = 0
close(3) = 0
close(4) = 0
close(5) = 0
close(6) = 0
exit_group(1) = ?
+++ exited with 1 +++

[ryao]

@dscherger Would you reproduce this with the kernel changes that setting USE=debug on the zfs-kmod ebuild requires? It should cleanup the stacks.

[behlendorf]

From the posted strace output it's clear that the kernel is returning EINVAL in zio_ioc_recv(). There are quite a few places where this is possible so we'll need to run down exactly where it's being returned from.

Also since this appears to be a regression somewhere between 0.6.2 and 0.6.3 it would be useful to do a git bisect to see what patch introduced this.

[dscherger]

@ryao here's another set of stacks with debug enabled on zfs-kmod

[ 481.807196] INFO: task spl_system_task:1358 blocked for more than 120 seconds.
[ 481.807208] Tainted: P O 3.12.21-gentoo-r1 #1
[ 481.807209] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 481.807210] spl_system_task D ffffffff81495600 0 1358 2 0x00000000
[ 481.807212] ffff88081a68a980 0000000000000046 ffff88083b1360c0 0000000000004000
[ 481.807214] ffff88081b681fd8 ffff88081b681fd8 ffffc900238a6588 0000000000000000
[ 481.807215] ffffffffa03faa60 ffff88081a68a980 ffff88081b681508 ffffffffa03e2461
[ 481.807216] Call Trace:
[ 481.807242] [] ? zio_vdev_io_done+0x71/0x160 [zfs]
[ 481.807248] [] ? zio_nowait+0xc2/0x1a0 [zfs]
[ 481.807250] [] ? _raw_spin_lock_irqsave+0x1e/0x50
[ 481.807251] [] ? _raw_spin_unlock_irqrestore+0x13/0x40
[ 481.807255] [] ? __cv_timedwait+0x10d/0x120 [spl]
[ 481.807257] [] ? abort_exclusive_wait+0xb0/0xb0
[ 481.807259] [] ? __cv_wait+0x10/0x20 [spl]
[ 481.807264] [] ? traverse_prefetcher+0xbb/0x170 [zfs]
[ 481.807270] [] ? traverse_visitbp+0x2ee/0x740 [zfs]
[ 481.807274] [] ? traverse_visitbp+0x45f/0x740 [zfs]
[ 481.807279] [] ? traverse_dnode+0x75/0x130 [zfs]
[ 481.807284] [] ? traverse_visitbp+0x57f/0x740 [zfs]
[ 481.807289] [] ? traverse_visitbp+0x45f/0x740 [zfs]
[ 481.807293] [] ? traverse_visitbp+0x45f/0x740 [zfs]
[ 481.807298] [] ? traverse_visitbp+0x45f/0x740 [zfs]
[ 481.807303] [] ? traverse_visitbp+0x45f/0x740 [zfs]
[ 481.807308] [] ? traverse_visitbp+0x45f/0x740 [zfs]
[ 481.807312] [] ? traverse_visitbp+0x45f/0x740 [zfs]
[ 481.807317] [] ? traverse_dnode+0x75/0x130 [zfs]
[ 481.807321] [] ? traverse_visitbp+0x641/0x740 [zfs]
[ 481.807322] [] ? __schedule+0x2e8/0x8a0
[ 481.807327] [] ? traverse_prefetch_thread+0x7e/0xe0 [zfs]
[ 481.807332] [] ? prefetch_dnode_metadata+0xb0/0xb0 [zfs]
[ 481.807334] [] ? taskq_dispatch_delay+0x48b/0x630 [spl]
[ 481.807335] [] ? try_to_wake_up+0x2a0/0x2a0
[ 481.807337] [] ? taskq_dispatch_delay+0x2e0/0x630 [spl]
[ 481.807339] [] ? kthread+0xb3/0xc0
[ 481.807340] [] ? up_read+0x10/0x20
[ 481.807341] [] ? kthread_freezable_should_stop+0x60/0x60
[ 481.807342] [] ? ret_from_fork+0x7c/0xb0
[ 481.807344] [] ? kthread_freezable_should_stop+0x60/0x60

I'm able to reproduce this with 100% reliability using:
zfs send -RD -I [email protected] [email protected] | mbuffer -m 100m -s 64k | zfs recv -Fud backup

[clefru]

Another stacktrace for a stuck system task in the context of a "zfs send" on 0.6.3

[97166.886977] INFO: task spl_system_task:192 blocked for more than 120 seconds.
[97166.887035]       Tainted: P           O 3.14.26-1-lts #1
[97166.887066] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[97166.887109] spl_system_task D ffff8807ef4c4f00     0   192      2 0x00000000
[97166.887115]  ffff8807ef54b5b8 0000000000000046 ffff8807ef54b528 ffff8807ef4c4f00
[97166.887120]  0000000000013540 ffff8807ef54bfd8 0000000000013540 ffff8807ef4c4f00
[97166.887124]  ffff8807ad2efed0 ffff8807ef54b528 ffffffffa058e29f ffff8807ef4c4f00
[97166.887128] Call Trace:
[97166.887188]  [<ffffffffa058e29f>] ? spa_config_enter+0xaf/0xf0 [zfs]
[97166.887209]  [<ffffffffa05da093>] ? zio_wait_for_children+0x53/0x60 [zfs]
[97166.887231]  [<ffffffffa05da94b>] ? zio_vdev_io_done+0x6b/0x190 [zfs]
[97166.887251]  [<ffffffffa05dd945>] ? zio_nowait+0xc5/0x190 [zfs]
[97166.887258]  [<ffffffff81501329>] schedule+0x29/0x70
[97166.887271]  [<ffffffffa048f125>] cv_wait_common+0x125/0x1b0 [spl]
[97166.887276]  [<ffffffff810b23e0>] ? __wake_up_sync+0x20/0x20
[97166.887286]  [<ffffffffa048f1c5>] __cv_wait+0x15/0x20 [spl]
[97166.887307]  [<ffffffffa055364b>] traverse_prefetcher+0xbb/0x160 [zfs]
[97166.887325]  [<ffffffffa0553955>] traverse_visitbp+0x105/0x790 [zfs]
[97166.887339]  [<ffffffffa053a170>] ? arc_buf_remove_ref+0x110/0x110 [zfs]
[97166.887357]  [<ffffffffa0553cb8>] traverse_visitbp+0x468/0x790 [zfs]
[97166.887374]  [<ffffffffa0554705>] traverse_dnode+0x85/0x130 [zfs]
[97166.887391]  [<ffffffffa0553e13>] traverse_visitbp+0x5c3/0x790 [zfs]
[97166.887407]  [<ffffffffa0553cb8>] traverse_visitbp+0x468/0x790 [zfs]
[97166.887425]  [<ffffffffa0553cb8>] traverse_visitbp+0x468/0x790 [zfs]
[97166.887443]  [<ffffffffa0553cb8>] traverse_visitbp+0x468/0x790 [zfs]
[97166.887461]  [<ffffffffa0553cb8>] traverse_visitbp+0x468/0x790 [zfs]
[97166.887478]  [<ffffffffa0553cb8>] traverse_visitbp+0x468/0x790 [zfs]
[97166.887496]  [<ffffffffa0553cb8>] traverse_visitbp+0x468/0x790 [zfs]
[97166.887512]  [<ffffffffa0554705>] traverse_dnode+0x85/0x130 [zfs]
[97166.887527]  [<ffffffffa0553edd>] traverse_visitbp+0x68d/0x790 [zfs]
[97166.887531]  [<ffffffff810b1f64>] ? __wake_up+0x44/0x50
[97166.887547]  [<ffffffffa0554632>] traverse_prefetch_thread+0x92/0xe0 [zfs]
[97166.887562]  [<ffffffffa0553590>] ? prefetch_dnode_metadata+0xe0/0xe0 [zfs]
[97166.887573]  [<ffffffffa0489447>] taskq_thread+0x267/0x510 [spl]
[97166.887578]  [<ffffffff8109f690>] ? wake_up_process+0x50/0x50
[97166.887588]  [<ffffffffa04891e0>] ? taskq_cancel_id+0x200/0x200 [spl]
[97166.887593]  [<ffffffff8108e38a>] kthread+0xea/0x100
[97166.887597]  [<ffffffff8108e2a0>] ? kthread_create_on_node+0x1a0/0x1a0
[97166.887601]  [<ffffffff8150dc7c>] ret_from_fork+0x7c/0xb0
[97166.887605]  [<ffffffff8108e2a0>] ? kthread_create_on_node+0x1a0/0x1a0

[behlendorf]

There has been numerous fixes made in this area in the master source. Has anyone verified that can still be reproduced with the latest code?

[dscherger]

Here's a stack from another failed attempt yesterday.

Mar 22 21:01:00 haswell kernel: INFO: task spl_system_task:1384 blocked for more than 120 seconds.
Mar 22 21:01:00 haswell kernel: Tainted: P O 3.17.8-gentoo-r1 #1
Mar 22 21:01:00 haswell kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Mar 22 21:01:00 haswell kernel: spl_system_task D ffff88083ed50600 0 1384 2 0x00000000
Mar 22 21:01:00 haswell kernel: ffff88081b48b7f0 0000000000000046 0000000000009000 ffff88081a7cc010
Mar 22 21:01:00 haswell kernel: ffff88081b48bfd8 ffff88083b2897d0 ffff88081b48b730 ffffffff814a4619
Mar 22 21:01:00 haswell kernel: ffff88081b48b760 ffffffffa0407df8 ffff8802bf79ecd8 0000000000000000
Mar 22 21:01:00 haswell kernel: Call Trace:
Mar 22 21:01:00 haswell kernel: [] ? mutex_unlock+0x9/0x10
Mar 22 21:01:00 haswell kernel: [] ? zio_wait_for_children+0x88/0xf0 [zfs]
Mar 22 21:01:00 haswell kernel: [] ? zio_vdev_io_done+0x33/0x1a0 [zfs]
Mar 22 21:01:00 haswell kernel: [] ? get_parent_ip+0xd/0x50
Mar 22 21:01:00 haswell kernel: [] ? preempt_count_add+0x4d/0xa0
Mar 22 21:01:00 haswell kernel: [] ? _raw_spin_lock_irqsave+0x18/0x40
Mar 22 21:01:00 haswell kernel: [] schedule+0x24/0x70
Mar 22 21:01:00 haswell kernel: [] __cv_destroy+0x19d/0x1d0 [spl]
Mar 22 21:01:00 haswell kernel: [] ? __wake_up_sync+0x10/0x10
Mar 22 21:01:00 haswell kernel: [] __cv_wait+0x10/0x20 [spl]
Mar 22 21:01:00 haswell kernel: [] traverse_prefetcher+0xd3/0x200 [zfs]
Mar 22 21:01:00 haswell kernel: [] traverse_visitbp+0x326/0x790 [zfs]
Mar 22 21:01:00 haswell kernel: [] traverse_dnode+0x75/0xd0 [zfs]
Mar 22 21:01:00 haswell kernel: [] traverse_visitbp+0x5ae/0x790 [zfs]
Mar 22 21:01:00 haswell kernel: [] traverse_visitbp+0x47b/0x790 [zfs]
Mar 22 21:01:00 haswell kernel: [] traverse_visitbp+0x47b/0x790 [zfs]
Mar 22 21:01:00 haswell kernel: [] traverse_visitbp+0x47b/0x790 [zfs]
Mar 22 21:01:00 haswell kernel: [] traverse_visitbp+0x47b/0x790 [zfs]
Mar 22 21:01:00 haswell kernel: [] traverse_visitbp+0x47b/0x790 [zfs]
Mar 22 21:01:00 haswell kernel: [] traverse_visitbp+0x47b/0x790 [zfs]
Mar 22 21:01:00 haswell kernel: [] traverse_dnode+0x75/0xd0 [zfs]
Mar 22 21:01:00 haswell kernel: [] traverse_visitbp+0x654/0x790 [zfs]
Mar 22 21:01:00 haswell kernel: [] ? __wake_up+0x3f/0x50
Mar 22 21:01:00 haswell kernel: [] traverse_prefetch_thread+0x86/0x120 [zfs]
Mar 22 21:01:00 haswell kernel: [] ? prefetch_dnode_metadata+0xb0/0xb0 [zfs]
Mar 22 21:01:00 haswell kernel: [] taskq_cancel_id+0x2c8/0x470 [spl]
Mar 22 21:01:00 haswell kernel: [] ? wake_up_process+0x40/0x40
Mar 22 21:01:00 haswell kernel: [] ? taskq_cancel_id+0x120/0x470 [spl]
Mar 22 21:01:00 haswell kernel: [] kthread+0xc4/0xe0
Mar 22 21:01:00 haswell kernel: [] ? kthread_create_on_node+0x170/0x170
Mar 22 21:01:00 haswell kernel: [] ret_from_fork+0x7c/0xb0
Mar 22 21:01:00 haswell kernel: [] ? kthread_create_on_node+0x170/0x170
Mar 22 21:01:16 haswell kernel: BUG: unable to handle kernel NULL pointer dereference at 0000000000000018
Mar 22 21:01:16 haswell kernel: IP: [] feature_do_action+0x24/0x340 [zfs]
Mar 22 21:01:16 haswell kernel: PGD 0
Mar 22 21:01:16 haswell kernel: Oops: 0000 [#1] PREEMPT SMP

I've since enabled debug on zfs, zfs-kmod and spl ebuilds but I can't seem to get another stack trace. send/recv now just hang without reporting anything.

I do see the following stack trace on boot up:

Mar 23 08:27:32 haswell kernel: SPL: using hostid 0x00000000
Mar 23 08:27:32 haswell systemd[1]: systemd 216 running in system mode. (+PAM -AUDIT -SELINUX +IMA -APPARMOR +SMACK -SYSVINIT -LIBCRYPTSETUP -GCRYPT -GNUTLS +ACL -XZ -LZ4 +SECCOMP +BLKID -ELFUTILS +KMOD -IDN )
Mar 23 08:27:32 haswell systemd[1]: Detected architecture 'x86-64'.
Mar 23 08:27:32 haswell systemd[1]: Set hostname to .
Mar 23 08:27:32 haswell kernel: BUG: unable to handle kernel NULL pointer dereference at 0000000000000018
Mar 23 08:27:32 haswell kernel: IP: [] feature_do_action+0x24/0x340 [zfs]
Mar 23 08:27:32 haswell kernel: PGD 0
Mar 23 08:27:32 haswell kernel: Oops: 0000 [#1] PREEMPT SMP
Mar 23 08:27:32 haswell kernel: Modules linked in: zfs(PO) zunicode(PO) zcommon(PO) znvpair(PO) tg3 libphy e1000 zavl(PO) spl(O) zlib_deflate nfs lockd sunrpc dm_snapshot dm_bufio dm_mirror dm_region_hash dm_log hi
Mar 23 08:27:32 haswell kernel: CPU: 1 PID: 1720 Comm: txg_sync Tainted: P O 3.17.8-gentoo-r1 #2
Mar 23 08:27:32 haswell kernel: Hardware name: ASUS All Series/SABERTOOTH Z87, BIOS 1803 02/17/2014
Mar 23 08:27:32 haswell kernel: task: ffff880036d99010 ti: ffff88080f29c000 task.ti: ffff88080f29c000
Mar 23 08:27:32 haswell kernel: RIP: 0010:[] [] feature_do_action+0x24/0x340 [zfs]
Mar 23 08:27:32 haswell kernel: RSP: 0018:ffff88080f29fc10 EFLAGS: 00010282
Mar 23 08:27:32 haswell kernel: RAX: 000000000000001d RBX: ffff88081a8a5000 RCX: 000000000000001e
Mar 23 08:27:32 haswell kernel: RDX: 000000000000001d RSI: 000000000000001c RDI: ffff88081a8a5000
Mar 23 08:27:32 haswell kernel: RBP: ffff88080f29fc68 R08: 0000000000000000 R09: 0000000000000002
Mar 23 08:27:32 haswell kernel: R10: 0000000000000000 R11: 0000000000000000 R12: 000000000000001c
Mar 23 08:27:32 haswell kernel: R13: 000000000000001d R14: ffff880810bf6000 R15: 0000000000000000
Mar 23 08:27:32 haswell kernel: FS: 0000000000000000(0000) GS:ffff88083ec40000(0000) knlGS:0000000000000000
Mar 23 08:27:32 haswell kernel: CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
Mar 23 08:27:32 haswell kernel: CR2: 0000000000000018 CR3: 0000000001639000 CR4: 00000000001407e0
Mar 23 08:27:32 haswell kernel: Stack:
Mar 23 08:27:32 haswell kernel: 0000000000000001 ffff88080d4dedc0 ffff88080f29fc30 000000000000001e
Mar 23 08:27:32 haswell kernel: ffff88080f29fc50 ffffffffa03552ec ffff880810bf6000 0000000000000000
Mar 23 08:27:32 haswell kernel: ffff88080d4dedc0 ffff880810bf6000 0000000000000000 ffff88080f29fc98
Mar 23 08:27:32 haswell kernel: Call Trace:
Mar 23 08:27:32 haswell kernel: [] ? dbuf_rele_and_unlock+0x16c/0x310 [zfs]
Mar 23 08:27:32 haswell kernel: [] spa_feature_decr+0x55/0x100 [zfs]
Mar 23 08:27:32 haswell kernel: [] dsl_scan_sync+0x96a/0xd00 [zfs]
Mar 23 08:27:32 haswell kernel: [] ? zio_wait+0x22e/0x3c0 [zfs]
Mar 23 08:27:32 haswell kernel: [] spa_sync+0x45a/0xc80 [zfs]
Mar 23 08:27:32 haswell kernel: [] ? default_wake_function+0xd/0x10
Mar 23 08:27:32 haswell kernel: [] ? autoremove_wake_function+0xd/0x30
Mar 23 08:27:32 haswell kernel: [] ? ktime_get_ts64+0x45/0xf0
Mar 23 08:27:32 haswell kernel: [] txg_sync_thread+0x2f5/0x580 [zfs]
Mar 23 08:27:32 haswell kernel: [] ? txg_thread_wait+0xd0/0xd0 [zfs]
Mar 23 08:27:32 haswell kernel: [] thread_generic_wrapper+0x75/0xb0 [spl]
Mar 23 08:27:32 haswell kernel: [] ? __thread_exit+0x20/0x20 [spl]
Mar 23 08:27:32 haswell kernel: [] kthread+0xc4/0xe0
Mar 23 08:27:32 haswell kernel: [] ? kthread_create_on_node+0x170/0x170
Mar 23 08:27:32 haswell kernel: [] ret_from_fork+0x7c/0xb0
Mar 23 08:27:32 haswell kernel: [] ? kthread_create_on_node+0x170/0x170
Mar 23 08:27:32 haswell kernel: Code: 00 00 00 00 0f 1f 00 55 48 89 d0 48 89 e5 41 57 4d 89 c7 41 56 41 55 49 89 d5 41 54 49 89 f4 53 48 89 fb 48 83 ec 30 48 89 4d c0 <41> 8b 70 18 44 89 4d c8 85 f6 49 0f 44 c4 48
Mar 23 08:27:32 haswell kernel: RIP [] feature_do_action+0x24/0x340 [zfs]
Mar 23 08:27:32 haswell kernel: RSP
Mar 23 08:27:32 haswell kernel: CR2: 0000000000000018
Mar 23 08:27:32 haswell kernel: ---[ end trace 3647211e6f921dfb ]---

[gmelikov]

I think that #5689 closes this issue, reopen it again if it's not.