Closed wipash closed 5 years ago
tuxoko
commented
8 years ago @wipash If I'm correct you don't have this patch in spl? https://github.com/zfsonlinux/spl/commit/e843553d0341c4edd880f5ad40da8211669348bd If so, you're likely want to do an upgrade.
foosinn
commented
8 years ago Hello,
i have excat the same issues with 0.6.5.6 on ubuntu trusty.
seems to happen mostly when deleting a lot of files. The delete process and ark_prune get 100% cpu load. sometimes its also caused by a rsync process. The server is under heavy load and has the issue every one to three days.
foosinn
commented
8 years ago We have moved to 4.4 kernel on our servers, the issue is gone. The system is stable since two weeks. This also worked on a Debian Jessy Server, which had the same issues.
behlendorf
commented
8 years ago @foosinn were you previously observing this issue with a 3.10 kernel?
foosinn
commented
8 years ago I had 100% stock Debian Jessie (3.16) and Ubuntu Trusty (3.13) kernels.
On Debian i compiled the modules from source, since the repo was once outdated. On Ubuntu i used the repo.
waltersteinlein
commented
7 years ago I'm seeing similar things on 0.7.0-rc2 with kernel 3.10.0 on CentOS 7.2:
[Sa Jan 14 00:36:08 2017] INFO: task send_traverse:145465 blocked for more than 120 seconds.
[Sa Jan 14 00:36:08 2017] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[Sa Jan 14 00:36:08 2017] send_traverse D 0000000000000000 0 145465 2 0x00000080
[Sa Jan 14 00:36:08 2017] ffff881f61553690 0000000000000046 ffff880a9e173980 ffff881f61553fd8
[Sa Jan 14 00:36:08 2017] ffff881f61553fd8 ffff881f61553fd8 ffff880a9e173980 ffff8814c33bfb98
[Sa Jan 14 00:36:08 2017] ffff8814c33bfb68 ffff8814c33bfba0 ffff8814c33bfb90 0000000000000000
[Sa Jan 14 00:36:08 2017] Call Trace:
[Sa Jan 14 00:36:08 2017] [<ffffffff8163bb59>] schedule+0x29/0x70
[Sa Jan 14 00:36:08 2017] [<ffffffffa035c1ad>] cv_wait_common+0x10d/0x130 [spl]
[Sa Jan 14 00:36:08 2017] [<ffffffff810a6b20>] ? wake_up_atomic_t+0x30/0x30
[Sa Jan 14 00:36:08 2017] [<ffffffffa035c1e5>] __cv_wait+0x15/0x20 [spl]
[Sa Jan 14 00:36:08 2017] [<ffffffffa147bacb>] bqueue_enqueue+0x5b/0xc0 [zfs]
[Sa Jan 14 00:36:08 2017] [<ffffffffa148b8fa>] send_cb+0x15a/0x180 [zfs]
[Sa Jan 14 00:36:08 2017] [<ffffffffa148ecf9>] traverse_visitbp+0x4e9/0x840 [zfs]
[Sa Jan 14 00:36:08 2017] [<ffffffffa03551b0>] ? spl_kmem_zalloc+0xc0/0x170 [spl]
[Sa Jan 14 00:36:08 2017] [<ffffffffa148f7f0>] traverse_dnode+0x1d0/0x1f0 [zfs]
[Sa Jan 14 00:36:08 2017] [<ffffffffa148eecb>] traverse_visitbp+0x6bb/0x840 [zfs]
[Sa Jan 14 00:36:08 2017] [<ffffffffa148eb05>] traverse_visitbp+0x2f5/0x840 [zfs]
[Sa Jan 14 00:36:08 2017] [<ffffffffa148eb05>] traverse_visitbp+0x2f5/0x840 [zfs]
[Sa Jan 14 00:36:08 2017] [<ffffffffa148eb05>] traverse_visitbp+0x2f5/0x840 [zfs]
[Sa Jan 14 00:36:08 2017] [<ffffffffa148eb05>] traverse_visitbp+0x2f5/0x840 [zfs]
[Sa Jan 14 00:36:08 2017] [<ffffffffa148eb05>] traverse_visitbp+0x2f5/0x840 [zfs]
[Sa Jan 14 00:36:08 2017] [<ffffffffa148eb05>] traverse_visitbp+0x2f5/0x840 [zfs]
[Sa Jan 14 00:36:08 2017] [<ffffffffa148f6d1>] traverse_dnode+0xb1/0x1f0 [zfs]
[Sa Jan 14 00:36:08 2017] [<ffffffffa148ef95>] traverse_visitbp+0x785/0x840 [zfs]
[Sa Jan 14 00:36:08 2017] [<ffffffffa148f221>] traverse_impl+0x1d1/0x450 [zfs]
[Sa Jan 14 00:36:08 2017] [<ffffffffa148b7a0>] ? dmu_send_impl+0x1690/0x1690 [zfs]
[Sa Jan 14 00:36:08 2017] [<ffffffffa148f865>] traverse_dataset_resume+0x55/0x60 [zfs]
[Sa Jan 14 00:36:08 2017] [<ffffffffa148b7a0>] ? dmu_send_impl+0x1690/0x1690 [zfs]
[Sa Jan 14 00:36:08 2017] [<ffffffffa1487ab9>] send_traverse_thread+0x59/0xb0 [zfs]
[Sa Jan 14 00:36:08 2017] [<ffffffffa1487a60>] ? byteswap_record+0x2e0/0x2e0 [zfs]
[Sa Jan 14 00:36:08 2017] [<ffffffffa0356f01>] thread_generic_wrapper+0x71/0x80 [spl]
[Sa Jan 14 00:36:08 2017] [<ffffffffa0356e90>] ? __thread_exit+0x20/0x20 [spl]
[Sa Jan 14 00:36:08 2017] [<ffffffff810a5b2f>] kthread+0xcf/0xe0
[Sa Jan 14 00:36:08 2017] [<ffffffff810b4856>] ? finish_task_switch+0x56/0x170
[Sa Jan 14 00:36:08 2017] [<ffffffff810a5a60>] ? kthread_create_on_node+0x140/0x140
[Sa Jan 14 00:36:08 2017] [<ffffffff81646a98>] ret_from_fork+0x58/0x90
[Sa Jan 14 00:36:08 2017] [<ffffffff810a5a60>] ? kthread_create_on_node+0x140/0x140
[Sa Jan 14 00:38:08 2017] INFO: task send_traverse:145465 blocked for more than 120 seconds.
[Sa Jan 14 00:38:08 2017] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[Sa Jan 14 00:38:08 2017] send_traverse D 0000000000000000 0 145465 2 0x00000080
[Sa Jan 14 00:38:08 2017] ffff881f61553690 0000000000000046 ffff880a9e173980 ffff881f61553fd8
[Sa Jan 14 00:38:08 2017] ffff881f61553fd8 ffff881f61553fd8 ffff880a9e173980 ffff8814c33bfb98
[Sa Jan 14 00:38:08 2017] ffff8814c33bfb68 ffff8814c33bfba0 ffff8814c33bfb90 0000000000000000
[Sa Jan 14 00:38:08 2017] Call Trace:
[Sa Jan 14 00:38:08 2017] [<ffffffff8163bb59>] schedule+0x29/0x70
[Sa Jan 14 00:38:08 2017] [<ffffffffa035c1ad>] cv_wait_common+0x10d/0x130 [spl]
[Sa Jan 14 00:38:08 2017] [<ffffffff810a6b20>] ? wake_up_atomic_t+0x30/0x30
[Sa Jan 14 00:38:08 2017] [<ffffffffa035c1e5>] __cv_wait+0x15/0x20 [spl]
[Sa Jan 14 00:38:08 2017] [<ffffffffa147bacb>] bqueue_enqueue+0x5b/0xc0 [zfs]
[Sa Jan 14 00:38:08 2017] [<ffffffffa148b8fa>] send_cb+0x15a/0x180 [zfs]
[Sa Jan 14 00:38:08 2017] [<ffffffffa148ecf9>] traverse_visitbp+0x4e9/0x840 [zfs]
[Sa Jan 14 00:38:08 2017] [<ffffffffa03551b0>] ? spl_kmem_zalloc+0xc0/0x170 [spl]
[Sa Jan 14 00:38:08 2017] [<ffffffffa148f7f0>] traverse_dnode+0x1d0/0x1f0 [zfs]
[Sa Jan 14 00:38:08 2017] [<ffffffffa148eecb>] traverse_visitbp+0x6bb/0x840 [zfs]
[Sa Jan 14 00:38:08 2017] [<ffffffffa148eb05>] traverse_visitbp+0x2f5/0x840 [zfs]
[Sa Jan 14 00:38:08 2017] [<ffffffffa148eb05>] traverse_visitbp+0x2f5/0x840 [zfs]
[Sa Jan 14 00:38:08 2017] [<ffffffffa148eb05>] traverse_visitbp+0x2f5/0x840 [zfs]
[Sa Jan 14 00:38:08 2017] [<ffffffffa148eb05>] traverse_visitbp+0x2f5/0x840 [zfs]
[Sa Jan 14 00:38:08 2017] [<ffffffffa148eb05>] traverse_visitbp+0x2f5/0x840 [zfs]
[Sa Jan 14 00:38:08 2017] [<ffffffffa148eb05>] traverse_visitbp+0x2f5/0x840 [zfs]
[Sa Jan 14 00:38:08 2017] [<ffffffffa148f6d1>] traverse_dnode+0xb1/0x1f0 [zfs]
[Sa Jan 14 00:38:08 2017] [<ffffffffa148ef95>] traverse_visitbp+0x785/0x840 [zfs]
[Sa Jan 14 00:38:08 2017] [<ffffffffa148f221>] traverse_impl+0x1d1/0x450 [zfs]
[Sa Jan 14 00:38:08 2017] [<ffffffffa148b7a0>] ? dmu_send_impl+0x1690/0x1690 [zfs]
[Sa Jan 14 00:38:08 2017] [<ffffffffa148f865>] traverse_dataset_resume+0x55/0x60 [zfs]
[Sa Jan 14 00:38:08 2017] [<ffffffffa148b7a0>] ? dmu_send_impl+0x1690/0x1690 [zfs]
[Sa Jan 14 00:38:08 2017] [<ffffffffa1487ab9>] send_traverse_thread+0x59/0xb0 [zfs]
[Sa Jan 14 00:38:08 2017] [<ffffffffa1487a60>] ? byteswap_record+0x2e0/0x2e0 [zfs]
[Sa Jan 14 00:38:08 2017] [<ffffffffa0356f01>] thread_generic_wrapper+0x71/0x80 [spl]
[Sa Jan 14 00:38:08 2017] [<ffffffffa0356e90>] ? __thread_exit+0x20/0x20 [spl]
[Sa Jan 14 00:38:08 2017] [<ffffffff810a5b2f>] kthread+0xcf/0xe0
[Sa Jan 14 00:38:08 2017] [<ffffffff810b4856>] ? finish_task_switch+0x56/0x170
[Sa Jan 14 00:38:08 2017] [<ffffffff810a5a60>] ? kthread_create_on_node+0x140/0x140
[Sa Jan 14 00:38:08 2017] [<ffffffff81646a98>] ret_from_fork+0x58/0x90
[Sa Jan 14 00:38:08 2017] [<ffffffff810a5a60>] ? kthread_create_on_node+0x140/0x140
[Sa Jan 14 00:40:08 2017] INFO: task send_traverse:145465 blocked for more than 120 seconds.
[Sa Jan 14 00:40:08 2017] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[Sa Jan 14 00:40:08 2017] send_traverse D 0000000000000000 0 145465 2 0x00000080
[Sa Jan 14 00:40:08 2017] ffff881f61553690 0000000000000046 ffff880a9e173980 ffff881f61553fd8
[Sa Jan 14 00:40:08 2017] ffff881f61553fd8 ffff881f61553fd8 ffff880a9e173980 ffff8814c33bfb98
[Sa Jan 14 00:40:08 2017] ffff8814c33bfb68 ffff8814c33bfba0 ffff8814c33bfb90 0000000000000000
[Sa Jan 14 00:40:08 2017] Call Trace:
[Sa Jan 14 00:40:08 2017] [<ffffffff8163bb59>] schedule+0x29/0x70
[Sa Jan 14 00:40:08 2017] [<ffffffffa035c1ad>] cv_wait_common+0x10d/0x130 [spl]
[Sa Jan 14 00:40:08 2017] [<ffffffff810a6b20>] ? wake_up_atomic_t+0x30/0x30
[Sa Jan 14 00:40:08 2017] [<ffffffffa035c1e5>] __cv_wait+0x15/0x20 [spl]
[Sa Jan 14 00:40:08 2017] [<ffffffffa147bacb>] bqueue_enqueue+0x5b/0xc0 [zfs]
[Sa Jan 14 00:40:08 2017] [<ffffffffa148b8fa>] send_cb+0x15a/0x180 [zfs]
[Sa Jan 14 00:40:08 2017] [<ffffffffa148ecf9>] traverse_visitbp+0x4e9/0x840 [zfs]
[Sa Jan 14 00:40:08 2017] [<ffffffffa03551b0>] ? spl_kmem_zalloc+0xc0/0x170 [spl]
[Sa Jan 14 00:40:08 2017] [<ffffffffa148f7f0>] traverse_dnode+0x1d0/0x1f0 [zfs]
[Sa Jan 14 00:40:08 2017] [<ffffffffa148eecb>] traverse_visitbp+0x6bb/0x840 [zfs]
[Sa Jan 14 00:40:08 2017] [<ffffffffa148eb05>] traverse_visitbp+0x2f5/0x840 [zfs]
[Sa Jan 14 00:40:08 2017] [<ffffffffa148eb05>] traverse_visitbp+0x2f5/0x840 [zfs]
[Sa Jan 14 00:40:08 2017] [<ffffffffa148eb05>] traverse_visitbp+0x2f5/0x840 [zfs]
[Sa Jan 14 00:40:08 2017] [<ffffffffa148eb05>] traverse_visitbp+0x2f5/0x840 [zfs]
[Sa Jan 14 00:40:08 2017] [<ffffffffa148eb05>] traverse_visitbp+0x2f5/0x840 [zfs]
[Sa Jan 14 00:40:08 2017] [<ffffffffa148eb05>] traverse_visitbp+0x2f5/0x840 [zfs]
[Sa Jan 14 00:40:08 2017] [<ffffffffa148f6d1>] traverse_dnode+0xb1/0x1f0 [zfs]
[Sa Jan 14 00:40:08 2017] [<ffffffffa148ef95>] traverse_visitbp+0x785/0x840 [zfs]
[Sa Jan 14 00:40:08 2017] [<ffffffffa148f221>] traverse_impl+0x1d1/0x450 [zfs]
[Sa Jan 14 00:40:08 2017] [<ffffffffa148b7a0>] ? dmu_send_impl+0x1690/0x1690 [zfs]
[Sa Jan 14 00:40:08 2017] [<ffffffffa148f865>] traverse_dataset_resume+0x55/0x60 [zfs]
[Sa Jan 14 00:40:08 2017] [<ffffffffa148b7a0>] ? dmu_send_impl+0x1690/0x1690 [zfs]
[Sa Jan 14 00:40:08 2017] [<ffffffffa1487ab9>] send_traverse_thread+0x59/0xb0 [zfs]
[Sa Jan 14 00:40:08 2017] [<ffffffffa1487a60>] ? byteswap_record+0x2e0/0x2e0 [zfs]
[Sa Jan 14 00:40:08 2017] [<ffffffffa0356f01>] thread_generic_wrapper+0x71/0x80 [spl]
[Sa Jan 14 00:40:08 2017] [<ffffffffa0356e90>] ? __thread_exit+0x20/0x20 [spl]
[Sa Jan 14 00:40:08 2017] [<ffffffff810a5b2f>] kthread+0xcf/0xe0
[Sa Jan 14 00:40:08 2017] [<ffffffff810b4856>] ? finish_task_switch+0x56/0x170
[Sa Jan 14 00:40:08 2017] [<ffffffff810a5a60>] ? kthread_create_on_node+0x140/0x140
[Sa Jan 14 00:40:08 2017] [<ffffffff81646a98>] ret_from_fork+0x58/0x90
[Sa Jan 14 00:40:08 2017] [<ffffffff810a5a60>] ? kthread_create_on_node+0x140/0x140
[Sa Jan 14 00:42:08 2017] INFO: task send_traverse:145465 blocked for more than 120 seconds.
[Sa Jan 14 00:42:08 2017] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[Sa Jan 14 00:42:08 2017] send_traverse D 0000000000000000 0 145465 2 0x00000080
[Sa Jan 14 00:42:08 2017] ffff881f61553690 0000000000000046 ffff880a9e173980 ffff881f61553fd8
[Sa Jan 14 00:42:08 2017] ffff881f61553fd8 ffff881f61553fd8 ffff880a9e173980 ffff8814c33bfb98
[Sa Jan 14 00:42:08 2017] ffff8814c33bfb68 ffff8814c33bfba0 ffff8814c33bfb90 0000000000000000
[Sa Jan 14 00:42:08 2017] Call Trace:
[Sa Jan 14 00:42:08 2017] [<ffffffff8163bb59>] schedule+0x29/0x70
[Sa Jan 14 00:42:08 2017] [<ffffffffa035c1ad>] cv_wait_common+0x10d/0x130 [spl]
[Sa Jan 14 00:42:08 2017] [<ffffffff810a6b20>] ? wake_up_atomic_t+0x30/0x30
[Sa Jan 14 00:42:08 2017] [<ffffffffa035c1e5>] __cv_wait+0x15/0x20 [spl]
[Sa Jan 14 00:42:08 2017] [<ffffffffa147bacb>] bqueue_enqueue+0x5b/0xc0 [zfs]
[Sa Jan 14 00:42:08 2017] [<ffffffffa148b8fa>] send_cb+0x15a/0x180 [zfs]
[Sa Jan 14 00:42:08 2017] [<ffffffffa148ecf9>] traverse_visitbp+0x4e9/0x840 [zfs]
[Sa Jan 14 00:42:08 2017] [<ffffffffa03551b0>] ? spl_kmem_zalloc+0xc0/0x170 [spl]
[Sa Jan 14 00:42:08 2017] [<ffffffffa148f7f0>] traverse_dnode+0x1d0/0x1f0 [zfs]
[Sa Jan 14 00:42:08 2017] [<ffffffffa148eecb>] traverse_visitbp+0x6bb/0x840 [zfs]
[Sa Jan 14 00:42:08 2017] [<ffffffffa148eb05>] traverse_visitbp+0x2f5/0x840 [zfs]
[Sa Jan 14 00:42:08 2017] [<ffffffffa148eb05>] traverse_visitbp+0x2f5/0x840 [zfs]
[Sa Jan 14 00:42:08 2017] [<ffffffffa148eb05>] traverse_visitbp+0x2f5/0x840 [zfs]
[Sa Jan 14 00:42:08 2017] [<ffffffffa148eb05>] traverse_visitbp+0x2f5/0x840 [zfs]
[Sa Jan 14 00:42:08 2017] [<ffffffffa148eb05>] traverse_visitbp+0x2f5/0x840 [zfs]
[Sa Jan 14 00:42:08 2017] [<ffffffffa148eb05>] traverse_visitbp+0x2f5/0x840 [zfs]
[Sa Jan 14 00:42:08 2017] [<ffffffffa148f6d1>] traverse_dnode+0xb1/0x1f0 [zfs]
[Sa Jan 14 00:42:08 2017] [<ffffffffa148ef95>] traverse_visitbp+0x785/0x840 [zfs]
[Sa Jan 14 00:42:08 2017] [<ffffffffa148f221>] traverse_impl+0x1d1/0x450 [zfs]
[Sa Jan 14 00:42:08 2017] [<ffffffffa148b7a0>] ? dmu_send_impl+0x1690/0x1690 [zfs]
[Sa Jan 14 00:42:08 2017] [<ffffffffa148f865>] traverse_dataset_resume+0x55/0x60 [zfs]
[Sa Jan 14 00:42:08 2017] [<ffffffffa148b7a0>] ? dmu_send_impl+0x1690/0x1690 [zfs]
[Sa Jan 14 00:42:08 2017] [<ffffffffa1487ab9>] send_traverse_thread+0x59/0xb0 [zfs]
[Sa Jan 14 00:42:08 2017] [<ffffffffa1487a60>] ? byteswap_record+0x2e0/0x2e0 [zfs]
[Sa Jan 14 00:42:08 2017] [<ffffffffa0356f01>] thread_generic_wrapper+0x71/0x80 [spl]
[Sa Jan 14 00:42:08 2017] [<ffffffffa0356e90>] ? __thread_exit+0x20/0x20 [spl]
[Sa Jan 14 00:42:08 2017] [<ffffffff810a5b2f>] kthread+0xcf/0xe0
[Sa Jan 14 00:42:08 2017] [<ffffffff810b4856>] ? finish_task_switch+0x56/0x170
[Sa Jan 14 00:42:08 2017] [<ffffffff810a5a60>] ? kthread_create_on_node+0x140/0x140
[Sa Jan 14 00:42:08 2017] [<ffffffff81646a98>] ret_from_fork+0x58/0x90
[Sa Jan 14 00:42:08 2017] [<ffffffff810a5a60>] ? kthread_create_on_node+0x140/0x140
[Sa Jan 14 00:44:08 2017] INFO: task send_traverse:145465 blocked for more than 120 seconds.
[Sa Jan 14 00:44:08 2017] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[Sa Jan 14 00:44:08 2017] send_traverse D 0000000000000000 0 145465 2 0x00000080
[Sa Jan 14 00:44:08 2017] ffff881f61553690 0000000000000046 ffff880a9e173980 ffff881f61553fd8
[Sa Jan 14 00:44:08 2017] ffff881f61553fd8 ffff881f61553fd8 ffff880a9e173980 ffff8814c33bfb98
[Sa Jan 14 00:44:08 2017] ffff8814c33bfb68 ffff8814c33bfba0 ffff8814c33bfb90 0000000000000000
[Sa Jan 14 00:44:08 2017] Call Trace:
[Sa Jan 14 00:44:08 2017] [<ffffffff8163bb59>] schedule+0x29/0x70
[Sa Jan 14 00:44:08 2017] [<ffffffffa035c1ad>] cv_wait_common+0x10d/0x130 [spl]
[Sa Jan 14 00:44:08 2017] [<ffffffff810a6b20>] ? wake_up_atomic_t+0x30/0x30
[Sa Jan 14 00:44:08 2017] [<ffffffffa035c1e5>] __cv_wait+0x15/0x20 [spl]
[Sa Jan 14 00:44:08 2017] [<ffffffffa147bacb>] bqueue_enqueue+0x5b/0xc0 [zfs]
[Sa Jan 14 00:44:08 2017] [<ffffffffa148b8fa>] send_cb+0x15a/0x180 [zfs]
[Sa Jan 14 00:44:08 2017] [<ffffffffa148ecf9>] traverse_visitbp+0x4e9/0x840 [zfs]
[Sa Jan 14 00:44:08 2017] [<ffffffffa03551b0>] ? spl_kmem_zalloc+0xc0/0x170 [spl]
[Sa Jan 14 00:44:08 2017] [<ffffffffa148f7f0>] traverse_dnode+0x1d0/0x1f0 [zfs]
[Sa Jan 14 00:44:08 2017] [<ffffffffa148eecb>] traverse_visitbp+0x6bb/0x840 [zfs]
[Sa Jan 14 00:44:08 2017] [<ffffffffa148eb05>] traverse_visitbp+0x2f5/0x840 [zfs]
[Sa Jan 14 00:44:08 2017] [<ffffffffa148eb05>] traverse_visitbp+0x2f5/0x840 [zfs]
[Sa Jan 14 00:44:08 2017] [<ffffffffa148eb05>] traverse_visitbp+0x2f5/0x840 [zfs]
[Sa Jan 14 00:44:08 2017] [<ffffffffa148eb05>] traverse_visitbp+0x2f5/0x840 [zfs]
[Sa Jan 14 00:44:08 2017] [<ffffffffa148eb05>] traverse_visitbp+0x2f5/0x840 [zfs]
[Sa Jan 14 00:44:08 2017] [<ffffffffa148eb05>] traverse_visitbp+0x2f5/0x840 [zfs]
[Sa Jan 14 00:44:08 2017] [<ffffffffa148f6d1>] traverse_dnode+0xb1/0x1f0 [zfs]
[Sa Jan 14 00:44:08 2017] [<ffffffffa148ef95>] traverse_visitbp+0x785/0x840 [zfs]
[Sa Jan 14 00:44:08 2017] [<ffffffffa148f221>] traverse_impl+0x1d1/0x450 [zfs]
[Sa Jan 14 00:44:08 2017] [<ffffffffa148b7a0>] ? dmu_send_impl+0x1690/0x1690 [zfs]
[Sa Jan 14 00:44:08 2017] [<ffffffffa148f865>] traverse_dataset_resume+0x55/0x60 [zfs]
[Sa Jan 14 00:44:08 2017] [<ffffffffa148b7a0>] ? dmu_send_impl+0x1690/0x1690 [zfs]
[Sa Jan 14 00:44:08 2017] [<ffffffffa1487ab9>] send_traverse_thread+0x59/0xb0 [zfs]
[Sa Jan 14 00:44:08 2017] [<ffffffffa1487a60>] ? byteswap_record+0x2e0/0x2e0 [zfs]
[Sa Jan 14 00:44:08 2017] [<ffffffffa0356f01>] thread_generic_wrapper+0x71/0x80 [spl]
[Sa Jan 14 00:44:08 2017] [<ffffffffa0356e90>] ? __thread_exit+0x20/0x20 [spl]
[Sa Jan 14 00:44:08 2017] [<ffffffff810a5b2f>] kthread+0xcf/0xe0
[Sa Jan 14 00:44:08 2017] [<ffffffff810b4856>] ? finish_task_switch+0x56/0x170
[Sa Jan 14 00:44:08 2017] [<ffffffff810a5a60>] ? kthread_create_on_node+0x140/0x140
[Sa Jan 14 00:44:08 2017] [<ffffffff81646a98>] ret_from_fork+0x58/0x90
[Sa Jan 14 00:44:08 2017] [<ffffffff810a5a60>] ? kthread_create_on_node+0x140/0x140
[Sa Jan 14 00:46:08 2017] INFO: task send_traverse:145465 blocked for more than 120 seconds.
[Sa Jan 14 00:46:08 2017] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[Sa Jan 14 00:46:08 2017] send_traverse D 0000000000000000 0 145465 2 0x00000080
[Sa Jan 14 00:46:08 2017] ffff881f61553690 0000000000000046 ffff880a9e173980 ffff881f61553fd8
[Sa Jan 14 00:46:08 2017] ffff881f61553fd8 ffff881f61553fd8 ffff880a9e173980 ffff8814c33bfb98
[Sa Jan 14 00:46:08 2017] ffff8814c33bfb68 ffff8814c33bfba0 ffff8814c33bfb90 0000000000000000
[Sa Jan 14 00:46:08 2017] Call Trace:
[Sa Jan 14 00:46:08 2017] [<ffffffff8163bb59>] schedule+0x29/0x70
[Sa Jan 14 00:46:08 2017] [<ffffffffa035c1ad>] cv_wait_common+0x10d/0x130 [spl]
[Sa Jan 14 00:46:08 2017] [<ffffffff810a6b20>] ? wake_up_atomic_t+0x30/0x30
[Sa Jan 14 00:46:08 2017] [<ffffffffa035c1e5>] __cv_wait+0x15/0x20 [spl]
[Sa Jan 14 00:46:08 2017] [<ffffffffa147bacb>] bqueue_enqueue+0x5b/0xc0 [zfs]
[Sa Jan 14 00:46:08 2017] [<ffffffffa148b8fa>] send_cb+0x15a/0x180 [zfs]
[Sa Jan 14 00:46:08 2017] [<ffffffffa148ecf9>] traverse_visitbp+0x4e9/0x840 [zfs]
[Sa Jan 14 00:46:08 2017] [<ffffffffa03551b0>] ? spl_kmem_zalloc+0xc0/0x170 [spl]
[Sa Jan 14 00:46:08 2017] [<ffffffffa148f7f0>] traverse_dnode+0x1d0/0x1f0 [zfs]
[Sa Jan 14 00:46:08 2017] [<ffffffffa148eecb>] traverse_visitbp+0x6bb/0x840 [zfs]
[Sa Jan 14 00:46:08 2017] [<ffffffffa148eb05>] traverse_visitbp+0x2f5/0x840 [zfs]
[Sa Jan 14 00:46:08 2017] [<ffffffffa148eb05>] traverse_visitbp+0x2f5/0x840 [zfs]
[Sa Jan 14 00:46:08 2017] [<ffffffffa148eb05>] traverse_visitbp+0x2f5/0x840 [zfs]
[Sa Jan 14 00:46:08 2017] [<ffffffffa148eb05>] traverse_visitbp+0x2f5/0x840 [zfs]
[Sa Jan 14 00:46:08 2017] [<ffffffffa148eb05>] traverse_visitbp+0x2f5/0x840 [zfs]
[Sa Jan 14 00:46:08 2017] [<ffffffffa148eb05>] traverse_visitbp+0x2f5/0x840 [zfs]
[Sa Jan 14 00:46:08 2017] [<ffffffffa148f6d1>] traverse_dnode+0xb1/0x1f0 [zfs]
[Sa Jan 14 00:46:08 2017] [<ffffffffa148ef95>] traverse_visitbp+0x785/0x840 [zfs]
[Sa Jan 14 00:46:08 2017] [<ffffffffa148f221>] traverse_impl+0x1d1/0x450 [zfs]
[Sa Jan 14 00:46:08 2017] [<ffffffffa148b7a0>] ? dmu_send_impl+0x1690/0x1690 [zfs]
[Sa Jan 14 00:46:08 2017] [<ffffffffa148f865>] traverse_dataset_resume+0x55/0x60 [zfs]
[Sa Jan 14 00:46:08 2017] [<ffffffffa148b7a0>] ? dmu_send_impl+0x1690/0x1690 [zfs]
[Sa Jan 14 00:46:08 2017] [<ffffffffa1487ab9>] send_traverse_thread+0x59/0xb0 [zfs]
[Sa Jan 14 00:46:08 2017] [<ffffffffa1487a60>] ? byteswap_record+0x2e0/0x2e0 [zfs]
[Sa Jan 14 00:46:08 2017] [<ffffffffa0356f01>] thread_generic_wrapper+0x71/0x80 [spl]
[Sa Jan 14 00:46:08 2017] [<ffffffffa0356e90>] ? __thread_exit+0x20/0x20 [spl]
[Sa Jan 14 00:46:08 2017] [<ffffffff810a5b2f>] kthread+0xcf/0xe0
[Sa Jan 14 00:46:08 2017] [<ffffffff810b4856>] ? finish_task_switch+0x56/0x170
[Sa Jan 14 00:46:08 2017] [<ffffffff810a5a60>] ? kthread_create_on_node+0x140/0x140
[Sa Jan 14 00:46:08 2017] [<ffffffff81646a98>] ret_from_fork+0x58/0x90
[Sa Jan 14 00:46:08 2017] [<ffffffff810a5a60>] ? kthread_create_on_node+0x140/0x140
[Sa Jan 14 00:48:08 2017] INFO: task send_traverse:145465 blocked for more than 120 seconds.
[Sa Jan 14 00:48:08 2017] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[Sa Jan 14 00:48:08 2017] send_traverse D 0000000000000000 0 145465 2 0x00000080
[Sa Jan 14 00:48:08 2017] ffff881f61553690 0000000000000046 ffff880a9e173980 ffff881f61553fd8
[Sa Jan 14 00:48:08 2017] ffff881f61553fd8 ffff881f61553fd8 ffff880a9e173980 ffff8814c33bfb98
[Sa Jan 14 00:48:08 2017] ffff8814c33bfb68 ffff8814c33bfba0 ffff8814c33bfb90 0000000000000000
[Sa Jan 14 00:48:08 2017] Call Trace:
[Sa Jan 14 00:48:08 2017] [<ffffffff8163bb59>] schedule+0x29/0x70
[Sa Jan 14 00:48:08 2017] [<ffffffffa035c1ad>] cv_wait_common+0x10d/0x130 [spl]
[Sa Jan 14 00:48:08 2017] [<ffffffff810a6b20>] ? wake_up_atomic_t+0x30/0x30
[Sa Jan 14 00:48:08 2017] [<ffffffffa035c1e5>] __cv_wait+0x15/0x20 [spl]
[Sa Jan 14 00:48:08 2017] [<ffffffffa147bacb>] bqueue_enqueue+0x5b/0xc0 [zfs]
[Sa Jan 14 00:48:08 2017] [<ffffffffa148b8fa>] send_cb+0x15a/0x180 [zfs]
[Sa Jan 14 00:48:08 2017] [<ffffffffa148ecf9>] traverse_visitbp+0x4e9/0x840 [zfs]
[Sa Jan 14 00:48:08 2017] [<ffffffffa03551b0>] ? spl_kmem_zalloc+0xc0/0x170 [spl]
[Sa Jan 14 00:48:08 2017] [<ffffffffa148f7f0>] traverse_dnode+0x1d0/0x1f0 [zfs]
[Sa Jan 14 00:48:08 2017] [<ffffffffa148eecb>] traverse_visitbp+0x6bb/0x840 [zfs]
[Sa Jan 14 00:48:08 2017] [<ffffffffa148eb05>] traverse_visitbp+0x2f5/0x840 [zfs]
[Sa Jan 14 00:48:08 2017] [<ffffffffa148eb05>] traverse_visitbp+0x2f5/0x840 [zfs]
[Sa Jan 14 00:48:08 2017] [<ffffffffa148eb05>] traverse_visitbp+0x2f5/0x840 [zfs]
[Sa Jan 14 00:48:08 2017] [<ffffffffa148eb05>] traverse_visitbp+0x2f5/0x840 [zfs]
[Sa Jan 14 00:48:08 2017] [<ffffffffa148eb05>] traverse_visitbp+0x2f5/0x840 [zfs]
[Sa Jan 14 00:48:08 2017] [<ffffffffa148eb05>] traverse_visitbp+0x2f5/0x840 [zfs]
[Sa Jan 14 00:48:08 2017] [<ffffffffa148f6d1>] traverse_dnode+0xb1/0x1f0 [zfs]
[Sa Jan 14 00:48:08 2017] [<ffffffffa148ef95>] traverse_visitbp+0x785/0x840 [zfs]
[Sa Jan 14 00:48:08 2017] [<ffffffffa148f221>] traverse_impl+0x1d1/0x450 [zfs]
[Sa Jan 14 00:48:08 2017] [<ffffffffa148b7a0>] ? dmu_send_impl+0x1690/0x1690 [zfs]
[Sa Jan 14 00:48:08 2017] [<ffffffffa148f865>] traverse_dataset_resume+0x55/0x60 [zfs]
[Sa Jan 14 00:48:08 2017] [<ffffffffa148b7a0>] ? dmu_send_impl+0x1690/0x1690 [zfs]
[Sa Jan 14 00:48:08 2017] [<ffffffffa1487ab9>] send_traverse_thread+0x59/0xb0 [zfs]
[Sa Jan 14 00:48:08 2017] [<ffffffffa1487a60>] ? byteswap_record+0x2e0/0x2e0 [zfs]
[Sa Jan 14 00:48:08 2017] [<ffffffffa0356f01>] thread_generic_wrapper+0x71/0x80 [spl]
[Sa Jan 14 00:48:08 2017] [<ffffffffa0356e90>] ? __thread_exit+0x20/0x20 [spl]
[Sa Jan 14 00:48:08 2017] [<ffffffff810a5b2f>] kthread+0xcf/0xe0
[Sa Jan 14 00:48:08 2017] [<ffffffff810b4856>] ? finish_task_switch+0x56/0x170
[Sa Jan 14 00:48:08 2017] [<ffffffff810a5a60>] ? kthread_create_on_node+0x140/0x140
[Sa Jan 14 00:48:08 2017] [<ffffffff81646a98>] ret_from_fork+0x58/0x90
[Sa Jan 14 00:48:08 2017] [<ffffffff810a5a60>] ? kthread_create_on_node+0x140/0x140
[Sa Jan 14 00:50:08 2017] INFO: task send_traverse:145465 blocked for more than 120 seconds.
[Sa Jan 14 00:50:08 2017] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[Sa Jan 14 00:50:08 2017] send_traverse D 0000000000000000 0 145465 2 0x00000080
[Sa Jan 14 00:50:08 2017] ffff881f61553690 0000000000000046 ffff880a9e173980 ffff881f61553fd8
[Sa Jan 14 00:50:08 2017] ffff881f61553fd8 ffff881f61553fd8 ffff880a9e173980 ffff8814c33bfb98
[Sa Jan 14 00:50:08 2017] ffff8814c33bfb68 ffff8814c33bfba0 ffff8814c33bfb90 0000000000000000
[Sa Jan 14 00:50:08 2017] Call Trace:
[Sa Jan 14 00:50:08 2017] [<ffffffff8163bb59>] schedule+0x29/0x70
[Sa Jan 14 00:50:08 2017] [<ffffffffa035c1ad>] cv_wait_common+0x10d/0x130 [spl]
[Sa Jan 14 00:50:08 2017] [<ffffffff810a6b20>] ? wake_up_atomic_t+0x30/0x30
[Sa Jan 14 00:50:08 2017] [<ffffffffa035c1e5>] __cv_wait+0x15/0x20 [spl]
[Sa Jan 14 00:50:08 2017] [<ffffffffa147bacb>] bqueue_enqueue+0x5b/0xc0 [zfs]
[Sa Jan 14 00:50:08 2017] [<ffffffffa148b8fa>] send_cb+0x15a/0x180 [zfs]
[Sa Jan 14 00:50:08 2017] [<ffffffffa148ecf9>] traverse_visitbp+0x4e9/0x840 [zfs]
[Sa Jan 14 00:50:08 2017] [<ffffffffa03551b0>] ? spl_kmem_zalloc+0xc0/0x170 [spl]
[Sa Jan 14 00:50:08 2017] [<ffffffffa148f7f0>] traverse_dnode+0x1d0/0x1f0 [zfs]
[Sa Jan 14 00:50:08 2017] [<ffffffffa148eecb>] traverse_visitbp+0x6bb/0x840 [zfs]
[Sa Jan 14 00:50:08 2017] [<ffffffffa148eb05>] traverse_visitbp+0x2f5/0x840 [zfs]
[Sa Jan 14 00:50:08 2017] [<ffffffffa148eb05>] traverse_visitbp+0x2f5/0x840 [zfs]
[Sa Jan 14 00:50:08 2017] [<ffffffffa148eb05>] traverse_visitbp+0x2f5/0x840 [zfs]
[Sa Jan 14 00:50:08 2017] [<ffffffffa148eb05>] traverse_visitbp+0x2f5/0x840 [zfs]
[Sa Jan 14 00:50:08 2017] [<ffffffffa148eb05>] traverse_visitbp+0x2f5/0x840 [zfs]
[Sa Jan 14 00:50:08 2017] [<ffffffffa148eb05>] traverse_visitbp+0x2f5/0x840 [zfs]
[Sa Jan 14 00:50:08 2017] [<ffffffffa148f6d1>] traverse_dnode+0xb1/0x1f0 [zfs]
[Sa Jan 14 00:50:08 2017] [<ffffffffa148ef95>] traverse_visitbp+0x785/0x840 [zfs]
[Sa Jan 14 00:50:08 2017] [<ffffffffa148f221>] traverse_impl+0x1d1/0x450 [zfs]
[Sa Jan 14 00:50:08 2017] [<ffffffffa148b7a0>] ? dmu_send_impl+0x1690/0x1690 [zfs]
[Sa Jan 14 00:50:08 2017] [<ffffffffa148f865>] traverse_dataset_resume+0x55/0x60 [zfs]
[Sa Jan 14 00:50:08 2017] [<ffffffffa148b7a0>] ? dmu_send_impl+0x1690/0x1690 [zfs]
[Sa Jan 14 00:50:08 2017] [<ffffffffa1487ab9>] send_traverse_thread+0x59/0xb0 [zfs]
[Sa Jan 14 00:50:08 2017] [<ffffffffa1487a60>] ? byteswap_record+0x2e0/0x2e0 [zfs]
[Sa Jan 14 00:50:08 2017] [<ffffffffa0356f01>] thread_generic_wrapper+0x71/0x80 [spl]
[Sa Jan 14 00:50:08 2017] [<ffffffffa0356e90>] ? __thread_exit+0x20/0x20 [spl]
[Sa Jan 14 00:50:08 2017] [<ffffffff810a5b2f>] kthread+0xcf/0xe0
[Sa Jan 14 00:50:08 2017] [<ffffffff810b4856>] ? finish_task_switch+0x56/0x170
[Sa Jan 14 00:50:08 2017] [<ffffffff810a5a60>] ? kthread_create_on_node+0x140/0x140
[Sa Jan 14 00:50:08 2017] [<ffffffff81646a98>] ret_from_fork+0x58/0x90
[Sa Jan 14 00:50:08 2017] [<ffffffff810a5a60>] ? kthread_create_on_node+0x140/0x140
[Sa Jan 14 00:52:08 2017] INFO: task send_traverse:145465 blocked for more than 120 seconds.
[Sa Jan 14 00:52:08 2017] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[Sa Jan 14 00:52:08 2017] send_traverse D 0000000000000000 0 145465 2 0x00000080
[Sa Jan 14 00:52:08 2017] ffff881f61553690 0000000000000046 ffff880a9e173980 ffff881f61553fd8
[Sa Jan 14 00:52:08 2017] ffff881f61553fd8 ffff881f61553fd8 ffff880a9e173980 ffff8814c33bfb98
[Sa Jan 14 00:52:08 2017] ffff8814c33bfb68 ffff8814c33bfba0 ffff8814c33bfb90 0000000000000000
[Sa Jan 14 00:52:08 2017] Call Trace:
[Sa Jan 14 00:52:08 2017] [<ffffffff8163bb59>] schedule+0x29/0x70
[Sa Jan 14 00:52:08 2017] [<ffffffffa035c1ad>] cv_wait_common+0x10d/0x130 [spl]
[Sa Jan 14 00:52:08 2017] [<ffffffff810a6b20>] ? wake_up_atomic_t+0x30/0x30
[Sa Jan 14 00:52:08 2017] [<ffffffffa035c1e5>] __cv_wait+0x15/0x20 [spl]
[Sa Jan 14 00:52:08 2017] [<ffffffffa147bacb>] bqueue_enqueue+0x5b/0xc0 [zfs]
[Sa Jan 14 00:52:08 2017] [<ffffffffa148b8fa>] send_cb+0x15a/0x180 [zfs]
[Sa Jan 14 00:52:08 2017] [<ffffffffa148ecf9>] traverse_visitbp+0x4e9/0x840 [zfs]
[Sa Jan 14 00:52:08 2017] [<ffffffffa03551b0>] ? spl_kmem_zalloc+0xc0/0x170 [spl]
[Sa Jan 14 00:52:08 2017] [<ffffffffa148f7f0>] traverse_dnode+0x1d0/0x1f0 [zfs]
[Sa Jan 14 00:52:08 2017] [<ffffffffa148eecb>] traverse_visitbp+0x6bb/0x840 [zfs]
[Sa Jan 14 00:52:08 2017] [<ffffffffa148eb05>] traverse_visitbp+0x2f5/0x840 [zfs]
[Sa Jan 14 00:52:08 2017] [<ffffffffa148eb05>] traverse_visitbp+0x2f5/0x840 [zfs]
[Sa Jan 14 00:52:08 2017] [<ffffffffa148eb05>] traverse_visitbp+0x2f5/0x840 [zfs]
[Sa Jan 14 00:52:08 2017] [<ffffffffa148eb05>] traverse_visitbp+0x2f5/0x840 [zfs]
[Sa Jan 14 00:52:08 2017] [<ffffffffa148eb05>] traverse_visitbp+0x2f5/0x840 [zfs]
[Sa Jan 14 00:52:08 2017] [<ffffffffa148eb05>] traverse_visitbp+0x2f5/0x840 [zfs]
[Sa Jan 14 00:52:08 2017] [<ffffffffa148f6d1>] traverse_dnode+0xb1/0x1f0 [zfs]
[Sa Jan 14 00:52:08 2017] [<ffffffffa148ef95>] traverse_visitbp+0x785/0x840 [zfs]
[Sa Jan 14 00:52:08 2017] [<ffffffffa148f221>] traverse_impl+0x1d1/0x450 [zfs]
[Sa Jan 14 00:52:08 2017] [<ffffffffa148b7a0>] ? dmu_send_impl+0x1690/0x1690 [zfs]
[Sa Jan 14 00:52:08 2017] [<ffffffffa148f865>] traverse_dataset_resume+0x55/0x60 [zfs]
[Sa Jan 14 00:52:08 2017] [<ffffffffa148b7a0>] ? dmu_send_impl+0x1690/0x1690 [zfs]
[Sa Jan 14 00:52:08 2017] [<ffffffffa1487ab9>] send_traverse_thread+0x59/0xb0 [zfs]
[Sa Jan 14 00:52:08 2017] [<ffffffffa1487a60>] ? byteswap_record+0x2e0/0x2e0 [zfs]
[Sa Jan 14 00:52:08 2017] [<ffffffffa0356f01>] thread_generic_wrapper+0x71/0x80 [spl]
[Sa Jan 14 00:52:08 2017] [<ffffffffa0356e90>] ? __thread_exit+0x20/0x20 [spl]
[Sa Jan 14 00:52:08 2017] [<ffffffff810a5b2f>] kthread+0xcf/0xe0
[Sa Jan 14 00:52:08 2017] [<ffffffff810b4856>] ? finish_task_switch+0x56/0x170
[Sa Jan 14 00:52:08 2017] [<ffffffff810a5a60>] ? kthread_create_on_node+0x140/0x140
[Sa Jan 14 00:52:08 2017] [<ffffffff81646a98>] ret_from_fork+0x58/0x90
[Sa Jan 14 00:52:08 2017] [<ffffffff810a5a60>] ? kthread_create_on_node+0x140/0x140
Closing, believed to be resolved by 03928896e114cfc4752c089727474134a2b0204b.
jgottula
commented
7 years ago @behlendorf I'm thinking this issue probably needs to be reopened, because I'm experiencing consistent, permanent send_traverse task lockups just like @waltersteinlein described above when attempting certain zfs send's on completely-up-to-date kernel and ZoL versions.
Aug 15 14:43:28 jgpc kernel: INFO: task send_traverse:4073 blocked for more than 60 seconds.
Aug 15 14:43:28 jgpc kernel: Tainted: P W O 4.12.7-1 #4
Aug 15 14:43:28 jgpc kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Aug 15 14:43:28 jgpc kernel: send_traverse D 0 4073 2 0x00000000
Aug 15 14:43:28 jgpc kernel: Call Trace:
Aug 15 14:43:28 jgpc kernel: __schedule+0x21f/0x860
Aug 15 14:43:28 jgpc kernel: schedule+0x53/0xa8
Aug 15 14:43:28 jgpc kernel: cv_wait_common+0x10d/0x120 [spl]
Aug 15 14:43:28 jgpc kernel: ? wake_bit_function+0x68/0x68
Aug 15 14:43:28 jgpc kernel: __cv_wait+0x28/0x30 [spl]
Aug 15 14:43:28 jgpc kernel: bqueue_enqueue+0x75/0xe8 [zfs]
Aug 15 14:43:28 jgpc kernel: send_cb+0xe2/0x138 [zfs]
Aug 15 14:43:28 jgpc kernel: traverse_visitbp+0x38d/0x9e8 [zfs]
Aug 15 14:43:28 jgpc kernel: ? spl_kmem_alloc+0xdc/0x180 [spl]
Aug 15 14:43:28 jgpc kernel: traverse_visitbp+0x544/0x9e8 [zfs]
Aug 15 14:43:28 jgpc kernel: traverse_visitbp+0x544/0x9e8 [zfs]
Aug 15 14:43:28 jgpc kernel: traverse_visitbp+0x544/0x9e8 [zfs]
Aug 15 14:43:28 jgpc kernel: traverse_dnode+0xec/0x1a0 [zfs]
Aug 15 14:43:28 jgpc kernel: traverse_visitbp+0x7c9/0x9e8 [zfs]
Aug 15 14:43:28 jgpc kernel: traverse_visitbp+0x544/0x9e8 [zfs]
Aug 15 14:43:28 jgpc kernel: traverse_visitbp+0x544/0x9e8 [zfs]
Aug 15 14:43:28 jgpc kernel: traverse_visitbp+0x544/0x9e8 [zfs]
Aug 15 14:43:28 jgpc kernel: traverse_visitbp+0x544/0x9e8 [zfs]
Aug 15 14:43:28 jgpc kernel: traverse_visitbp+0x544/0x9e8 [zfs]
Aug 15 14:43:28 jgpc kernel: traverse_visitbp+0x544/0x9e8 [zfs]
Aug 15 14:43:28 jgpc kernel: traverse_dnode+0xec/0x1a0 [zfs]
Aug 15 14:43:28 jgpc kernel: traverse_visitbp+0x926/0x9e8 [zfs]
Aug 15 14:43:28 jgpc kernel: traverse_impl+0x1d1/0x448 [zfs]
Aug 15 14:43:28 jgpc kernel: ? byteswap_record+0x2e8/0x2e8 [zfs]
Aug 15 14:43:28 jgpc kernel: traverse_dataset_resume+0x59/0x60 [zfs]
Aug 15 14:43:28 jgpc kernel: ? dmu_recv_existing_end+0x90/0x90 [zfs]
Aug 15 14:43:28 jgpc kernel: send_traverse_thread+0x6c/0xc8 [zfs]
Aug 15 14:43:28 jgpc kernel: thread_generic_wrapper+0x81/0x90 [spl]
Aug 15 14:43:28 jgpc kernel: kthread+0x134/0x150
Aug 15 14:43:28 jgpc kernel: ? __thread_exit+0x30/0x30 [spl]
Aug 15 14:43:28 jgpc kernel: ? kthread_create_on_node+0x50/0x50
Aug 15 14:43:28 jgpc kernel: ? kthread_create_on_node+0x50/0x50
Aug 15 14:43:28 jgpc kernel: ret_from_fork+0x22/0x30
<...>
Aug 15 14:44:29 jgpc kernel: INFO: task send_traverse:4073 blocked for more than 60 seconds.
Aug 15 14:44:29 jgpc kernel: Tainted: P W O 4.12.7-1 #4
Aug 15 14:44:29 jgpc kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Aug 15 14:44:29 jgpc kernel: send_traverse D 0 4073 2 0x00000000
Aug 15 14:44:29 jgpc kernel: Call Trace:
Aug 15 14:44:29 jgpc kernel: __schedule+0x21f/0x860
Aug 15 14:44:29 jgpc kernel: schedule+0x53/0xa8
Aug 15 14:44:29 jgpc kernel: cv_wait_common+0x10d/0x120 [spl]
Aug 15 14:44:29 jgpc kernel: ? wake_bit_function+0x68/0x68
Aug 15 14:44:29 jgpc kernel: __cv_wait+0x28/0x30 [spl]
Aug 15 14:44:29 jgpc kernel: bqueue_enqueue+0x75/0xe8 [zfs]
Aug 15 14:44:29 jgpc kernel: send_cb+0xe2/0x138 [zfs]
Aug 15 14:44:29 jgpc kernel: traverse_visitbp+0x38d/0x9e8 [zfs]
Aug 15 14:44:29 jgpc kernel: ? spl_kmem_alloc+0xdc/0x180 [spl]
Aug 15 14:44:29 jgpc kernel: traverse_visitbp+0x544/0x9e8 [zfs]
Aug 15 14:44:29 jgpc kernel: traverse_visitbp+0x544/0x9e8 [zfs]
Aug 15 14:44:29 jgpc kernel: traverse_visitbp+0x544/0x9e8 [zfs]
Aug 15 14:44:29 jgpc kernel: traverse_dnode+0xec/0x1a0 [zfs]
Aug 15 14:44:29 jgpc kernel: traverse_visitbp+0x7c9/0x9e8 [zfs]
Aug 15 14:44:29 jgpc kernel: traverse_visitbp+0x544/0x9e8 [zfs]
Aug 15 14:44:29 jgpc kernel: traverse_visitbp+0x544/0x9e8 [zfs]
Aug 15 14:44:29 jgpc kernel: traverse_visitbp+0x544/0x9e8 [zfs]
Aug 15 14:44:29 jgpc kernel: traverse_visitbp+0x544/0x9e8 [zfs]
Aug 15 14:44:29 jgpc kernel: traverse_visitbp+0x544/0x9e8 [zfs]
Aug 15 14:44:29 jgpc kernel: traverse_visitbp+0x544/0x9e8 [zfs]
Aug 15 14:44:29 jgpc kernel: traverse_dnode+0xec/0x1a0 [zfs]
Aug 15 14:44:29 jgpc kernel: traverse_visitbp+0x926/0x9e8 [zfs]
Aug 15 14:44:29 jgpc kernel: traverse_impl+0x1d1/0x448 [zfs]
Aug 15 14:44:29 jgpc kernel: ? byteswap_record+0x2e8/0x2e8 [zfs]
Aug 15 14:44:29 jgpc kernel: traverse_dataset_resume+0x59/0x60 [zfs]
Aug 15 14:44:29 jgpc kernel: ? dmu_recv_existing_end+0x90/0x90 [zfs]
Aug 15 14:44:29 jgpc kernel: send_traverse_thread+0x6c/0xc8 [zfs]
Aug 15 14:44:29 jgpc kernel: thread_generic_wrapper+0x81/0x90 [spl]
Aug 15 14:44:29 jgpc kernel: kthread+0x134/0x150
Aug 15 14:44:29 jgpc kernel: ? __thread_exit+0x30/0x30 [spl]
Aug 15 14:44:29 jgpc kernel: ? kthread_create_on_node+0x50/0x50
Aug 15 14:44:29 jgpc kernel: ? kthread_create_on_node+0x50/0x50
Aug 15 14:44:29 jgpc kernel: ret_from_fork+0x22/0x30Currently I'm seeing this issue when I try to do a zfs send over the network from my machine running kernel 4.12.7 with zfsonlinux/spl@9df9692 and zfsonlinux/zfs@d49d9c2bd. But I was also experiencing it on kernel 4.11.3 with zfsonlinux/spl@ac48361 and zfsonlinux/zfs@829aaf280. (I don't know for sure about any other, earlier kernel/ZoL versions, since I hadn't been doing any notable zfs send's until just recently.)
(I also happen to be in a situation where I have a relatively urgent need to send this data off of the pool in question due to some hardware failures, so any temporary workarounds, if any are known, would be welcome.)
jgottula
commented
7 years ago Oh and I neglected to mention that the machine on the receiving end of this operation also gets stuck. It's currently running kernel 4.12.6 with zfsonlinux/spl@9df9692 and zfsonlinux/zfs@d49d9c2bd (very slightly older kernel version, but same ZoL versions, as the sending side).
Aug 15 14:45:50 helium kernel: INFO: task txg_quiesce:26727 blocked for more than 120 seconds.
Aug 15 14:45:50 helium kernel: Tainted: P O 4.12.6-1-ARCH #1
Aug 15 14:45:50 helium kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Aug 15 14:45:50 helium kernel: txg_quiesce D 0 26727 2 0x00000000
Aug 15 14:45:50 helium kernel: Call Trace:
Aug 15 14:45:50 helium kernel: __schedule+0x236/0x870
Aug 15 14:45:50 helium kernel: schedule+0x3d/0x90
Aug 15 14:45:50 helium kernel: cv_wait_common+0x11c/0x130 [spl]
Aug 15 14:45:50 helium kernel: ? wake_bit_function+0x60/0x60
Aug 15 14:45:50 helium kernel: __cv_wait+0x15/0x20 [spl]
Aug 15 14:45:50 helium kernel: txg_quiesce_thread+0x2d5/0x3e0 [zfs]
Aug 15 14:45:50 helium kernel: ? txg_wait_open+0x100/0x100 [zfs]
Aug 15 14:45:50 helium kernel: thread_generic_wrapper+0x72/0x80 [spl]
Aug 15 14:45:50 helium kernel: kthread+0x125/0x140
Aug 15 14:45:50 helium kernel: ? __thread_exit+0x20/0x20 [spl]
Aug 15 14:45:50 helium kernel: ? kthread_create_on_node+0x70/0x70
Aug 15 14:45:50 helium kernel: ? kthread_create_on_node+0x70/0x70
Aug 15 14:45:50 helium kernel: ret_from_fork+0x25/0x30
Aug 15 14:45:50 helium kernel: INFO: task zfs:28062 blocked for more than 120 seconds.
Aug 15 14:45:50 helium kernel: Tainted: P O 4.12.6-1-ARCH #1
Aug 15 14:45:50 helium kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Aug 15 14:45:50 helium kernel: zfs D 0 28062 28060 0x00000000
Aug 15 14:45:50 helium kernel: Call Trace:
Aug 15 14:45:50 helium kernel: __schedule+0x236/0x870
Aug 15 14:45:50 helium kernel: schedule+0x3d/0x90
Aug 15 14:45:50 helium kernel: cv_wait_common+0x11c/0x130 [spl]
Aug 15 14:45:50 helium kernel: ? wake_bit_function+0x60/0x60
Aug 15 14:45:50 helium kernel: __cv_wait+0x15/0x20 [spl]
Aug 15 14:45:50 helium kernel: txg_wait_synced+0xdd/0x130 [zfs]
Aug 15 14:45:50 helium kernel: dmu_recv_cleanup_ds+0x49/0xc0 [zfs]
Aug 15 14:45:50 helium kernel: ? __schedule+0x23e/0x870
Aug 15 14:45:50 helium kernel: ? __wake_up+0x44/0x50
Aug 15 14:45:50 helium kernel: ? cv_wait_common+0xeb/0x130 [spl]
Aug 15 14:45:50 helium kernel: ? wake_bit_function+0x60/0x60
Aug 15 14:45:50 helium kernel: dmu_recv_stream+0x28e/0x1080 [zfs]
Aug 15 14:45:50 helium kernel: ? kfree+0x175/0x190
Aug 15 14:45:50 helium kernel: zfs_ioc_recv_impl+0x48d/0x10f0 [zfs]
Aug 15 14:45:50 helium kernel: zfs_ioc_recv_new+0x31e/0x3e0 [zfs]
Aug 15 14:45:50 helium kernel: ? try_to_merge_one_page+0x539/0x790
Aug 15 14:45:50 helium kernel: ? spl_kmem_alloc_impl+0xd1/0x180 [spl]
Aug 15 14:45:50 helium kernel: ? spl_vmem_alloc+0x19/0x20 [spl]
Aug 15 14:45:50 helium kernel: ? nv_alloc_sleep_spl+0x1f/0x30 [znvpair]
Aug 15 14:45:50 helium kernel: ? nv_mem_zalloc.isra.12+0x28/0x40 [znvpair]
Aug 15 14:45:50 helium kernel: ? nvlist_xalloc.part.13+0x63/0xc0 [znvpair]
Aug 15 14:45:50 helium kernel: zfsdev_ioctl+0x442/0x600 [zfs]
Aug 15 14:45:50 helium kernel: do_vfs_ioctl+0xa5/0x600
Aug 15 14:45:50 helium kernel: ? vfs_write+0x166/0x1a0
Aug 15 14:45:50 helium kernel: SyS_ioctl+0x79/0x90
Aug 15 14:45:50 helium kernel: entry_SYSCALL_64_fastpath+0x1a/0xa5
Aug 15 14:45:50 helium kernel: RIP: 0033:0x7f980d6948b7
Aug 15 14:45:50 helium kernel: RSP: 002b:00007ffc6613f668 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
Aug 15 14:45:50 helium kernel: RAX: ffffffffffffffda RBX: 00000050ef3e9370 RCX: 00007f980d6948b7
Aug 15 14:45:50 helium kernel: RDX: 00007ffc6613f680 RSI: 0000000000005a46 RDI: 0000000000000005
Aug 15 14:45:50 helium kernel: RBP: 00000050ef3e9348 R08: 0000000000000003 R09: 000000000000007c
Aug 15 14:45:50 helium kernel: R10: 0000000000000830 R11: 0000000000000246 R12: 00000050ef3e5540
Aug 15 14:45:50 helium kernel: R13: 00000050ef160080 R14: 0000000000000002 R15: 00000050ef3e93c0
<...>
Aug 15 14:47:53 helium kernel: INFO: task txg_quiesce:26727 blocked for more than 120 seconds.
Aug 15 14:47:53 helium kernel: Tainted: P O 4.12.6-1-ARCH #1
Aug 15 14:47:53 helium kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Aug 15 14:47:53 helium kernel: txg_quiesce D 0 26727 2 0x00000000
Aug 15 14:47:53 helium kernel: Call Trace:
Aug 15 14:47:53 helium kernel: __schedule+0x236/0x870
Aug 15 14:47:53 helium kernel: schedule+0x3d/0x90
Aug 15 14:47:53 helium kernel: cv_wait_common+0x11c/0x130 [spl]
Aug 15 14:47:53 helium kernel: ? wake_bit_function+0x60/0x60
Aug 15 14:47:53 helium kernel: __cv_wait+0x15/0x20 [spl]
Aug 15 14:47:53 helium kernel: txg_quiesce_thread+0x2d5/0x3e0 [zfs]
Aug 15 14:47:53 helium kernel: ? txg_wait_open+0x100/0x100 [zfs]
Aug 15 14:47:53 helium kernel: thread_generic_wrapper+0x72/0x80 [spl]
Aug 15 14:47:53 helium kernel: kthread+0x125/0x140
Aug 15 14:47:53 helium kernel: ? __thread_exit+0x20/0x20 [spl]
Aug 15 14:47:53 helium kernel: ? kthread_create_on_node+0x70/0x70
Aug 15 14:47:53 helium kernel: ? kthread_create_on_node+0x70/0x70
Aug 15 14:47:53 helium kernel: ret_from_fork+0x25/0x30
Aug 15 14:47:53 helium kernel: INFO: task zfs:28062 blocked for more than 120 seconds.
Aug 15 14:47:53 helium kernel: Tainted: P O 4.12.6-1-ARCH #1
Aug 15 14:47:53 helium kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Aug 15 14:47:53 helium kernel: zfs D 0 28062 28060 0x00000000
Aug 15 14:47:53 helium kernel: Call Trace:
Aug 15 14:47:53 helium kernel: __schedule+0x236/0x870
Aug 15 14:47:53 helium kernel: schedule+0x3d/0x90
Aug 15 14:47:53 helium kernel: cv_wait_common+0x11c/0x130 [spl]
Aug 15 14:47:53 helium kernel: ? wake_bit_function+0x60/0x60
Aug 15 14:47:53 helium kernel: __cv_wait+0x15/0x20 [spl]
Aug 15 14:47:53 helium kernel: txg_wait_synced+0xdd/0x130 [zfs]
Aug 15 14:47:53 helium kernel: dmu_recv_cleanup_ds+0x49/0xc0 [zfs]
Aug 15 14:47:53 helium kernel: ? __schedule+0x23e/0x870
Aug 15 14:47:53 helium kernel: ? __wake_up+0x44/0x50
Aug 15 14:47:53 helium kernel: ? cv_wait_common+0xeb/0x130 [spl]
Aug 15 14:47:53 helium kernel: ? wake_bit_function+0x60/0x60
Aug 15 14:47:53 helium kernel: dmu_recv_stream+0x28e/0x1080 [zfs]
Aug 15 14:47:53 helium kernel: ? kfree+0x175/0x190
Aug 15 14:47:53 helium kernel: zfs_ioc_recv_impl+0x48d/0x10f0 [zfs]
Aug 15 14:47:53 helium kernel: zfs_ioc_recv_new+0x31e/0x3e0 [zfs]
Aug 15 14:47:53 helium kernel: ? try_to_merge_one_page+0x539/0x790
Aug 15 14:47:53 helium kernel: ? spl_kmem_alloc_impl+0xd1/0x180 [spl]
Aug 15 14:47:53 helium kernel: ? spl_vmem_alloc+0x19/0x20 [spl]
Aug 15 14:47:53 helium kernel: ? nv_alloc_sleep_spl+0x1f/0x30 [znvpair]
Aug 15 14:47:53 helium kernel: ? nv_mem_zalloc.isra.12+0x28/0x40 [znvpair]
Aug 15 14:47:53 helium kernel: ? nvlist_xalloc.part.13+0x63/0xc0 [znvpair]
Aug 15 14:47:53 helium kernel: zfsdev_ioctl+0x442/0x600 [zfs]
Aug 15 14:47:53 helium kernel: do_vfs_ioctl+0xa5/0x600
Aug 15 14:47:53 helium kernel: ? vfs_write+0x166/0x1a0
Aug 15 14:47:53 helium kernel: SyS_ioctl+0x79/0x90
Aug 15 14:47:53 helium kernel: entry_SYSCALL_64_fastpath+0x1a/0xa5
Aug 15 14:47:53 helium kernel: RIP: 0033:0x7f980d6948b7
Aug 15 14:47:53 helium kernel: RSP: 002b:00007ffc6613f668 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
Aug 15 14:47:53 helium kernel: RAX: ffffffffffffffda RBX: 00000050ef3e9370 RCX: 00007f980d6948b7
Aug 15 14:47:53 helium kernel: RDX: 00007ffc6613f680 RSI: 0000000000005a46 RDI: 0000000000000005
Aug 15 14:47:53 helium kernel: RBP: 00000050ef3e9348 R08: 0000000000000003 R09: 000000000000007c
Aug 15 14:47:53 helium kernel: R10: 0000000000000830 R11: 0000000000000246 R12: 00000050ef3e5540
Aug 15 14:47:53 helium kernel: R13: 00000050ef160080 R14: 0000000000000002 R15: 00000050ef3e93c0
<...>
Aug 15 14:49:56 helium kernel: INFO: task txg_quiesce:26727 blocked for more than 120 seconds.
Aug 15 14:49:56 helium kernel: Tainted: P O 4.12.6-1-ARCH #1
Aug 15 14:49:56 helium kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Aug 15 14:49:56 helium kernel: txg_quiesce D 0 26727 2 0x00000000
Aug 15 14:49:56 helium kernel: Call Trace:
Aug 15 14:49:56 helium kernel: __schedule+0x236/0x870
Aug 15 14:49:56 helium kernel: schedule+0x3d/0x90
Aug 15 14:49:56 helium kernel: cv_wait_common+0x11c/0x130 [spl]
Aug 15 14:49:56 helium kernel: ? wake_bit_function+0x60/0x60
Aug 15 14:49:56 helium kernel: __cv_wait+0x15/0x20 [spl]
Aug 15 14:49:56 helium kernel: txg_quiesce_thread+0x2d5/0x3e0 [zfs]
Aug 15 14:49:56 helium kernel: ? txg_wait_open+0x100/0x100 [zfs]
Aug 15 14:49:56 helium kernel: thread_generic_wrapper+0x72/0x80 [spl]
Aug 15 14:49:56 helium kernel: kthread+0x125/0x140
Aug 15 14:49:56 helium kernel: ? __thread_exit+0x20/0x20 [spl]
Aug 15 14:49:56 helium kernel: ? kthread_create_on_node+0x70/0x70
Aug 15 14:49:56 helium kernel: ? kthread_create_on_node+0x70/0x70
Aug 15 14:49:56 helium kernel: ret_from_fork+0x25/0x30
Aug 15 14:49:56 helium kernel: INFO: task zfs:28062 blocked for more than 120 seconds.
Aug 15 14:49:56 helium kernel: Tainted: P O 4.12.6-1-ARCH #1
Aug 15 14:49:56 helium kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Aug 15 14:49:56 helium kernel: zfs D 0 28062 28060 0x00000000
Aug 15 14:49:56 helium kernel: Call Trace:
Aug 15 14:49:56 helium kernel: __schedule+0x236/0x870
Aug 15 14:49:56 helium kernel: schedule+0x3d/0x90
Aug 15 14:49:56 helium kernel: cv_wait_common+0x11c/0x130 [spl]
Aug 15 14:49:56 helium kernel: ? wake_bit_function+0x60/0x60
Aug 15 14:49:56 helium kernel: __cv_wait+0x15/0x20 [spl]
Aug 15 14:49:56 helium kernel: txg_wait_synced+0xdd/0x130 [zfs]
Aug 15 14:49:56 helium kernel: dmu_recv_cleanup_ds+0x49/0xc0 [zfs]
Aug 15 14:49:56 helium kernel: ? __schedule+0x23e/0x870
Aug 15 14:49:56 helium kernel: ? __wake_up+0x44/0x50
Aug 15 14:49:56 helium kernel: ? cv_wait_common+0xeb/0x130 [spl]
Aug 15 14:49:56 helium kernel: ? wake_bit_function+0x60/0x60
Aug 15 14:49:56 helium kernel: dmu_recv_stream+0x28e/0x1080 [zfs]
Aug 15 14:49:56 helium kernel: ? kfree+0x175/0x190
Aug 15 14:49:56 helium kernel: zfs_ioc_recv_impl+0x48d/0x10f0 [zfs]
Aug 15 14:49:56 helium kernel: zfs_ioc_recv_new+0x31e/0x3e0 [zfs]
Aug 15 14:49:56 helium kernel: ? try_to_merge_one_page+0x539/0x790
Aug 15 14:49:56 helium kernel: ? spl_kmem_alloc_impl+0xd1/0x180 [spl]
Aug 15 14:49:56 helium kernel: ? spl_vmem_alloc+0x19/0x20 [spl]
Aug 15 14:49:56 helium kernel: ? nv_alloc_sleep_spl+0x1f/0x30 [znvpair]
Aug 15 14:49:56 helium kernel: ? nv_mem_zalloc.isra.12+0x28/0x40 [znvpair]
Aug 15 14:49:56 helium kernel: ? nvlist_xalloc.part.13+0x63/0xc0 [znvpair]
Aug 15 14:49:56 helium kernel: zfsdev_ioctl+0x442/0x600 [zfs]
Aug 15 14:49:56 helium kernel: do_vfs_ioctl+0xa5/0x600
Aug 15 14:49:56 helium kernel: ? vfs_write+0x166/0x1a0
Aug 15 14:49:56 helium kernel: SyS_ioctl+0x79/0x90
Aug 15 14:49:56 helium kernel: entry_SYSCALL_64_fastpath+0x1a/0xa5
Aug 15 14:49:56 helium kernel: RIP: 0033:0x7f980d6948b7
Aug 15 14:49:56 helium kernel: RSP: 002b:00007ffc6613f668 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
Aug 15 14:49:56 helium kernel: RAX: ffffffffffffffda RBX: 00000050ef3e9370 RCX: 00007f980d6948b7
Aug 15 14:49:56 helium kernel: RDX: 00007ffc6613f680 RSI: 0000000000005a46 RDI: 0000000000000005
Aug 15 14:49:56 helium kernel: RBP: 00000050ef3e9348 R08: 0000000000000003 R09: 000000000000007c
Aug 15 14:49:56 helium kernel: R10: 0000000000000830 R11: 0000000000000246 R12: 00000050ef3e5540
Aug 15 14:49:56 helium kernel: R13: 00000050ef160080 R14: 0000000000000002 R15: 00000050ef3e93c0
<...>
Aug 15 14:51:58 helium kernel: INFO: task txg_quiesce:26727 blocked for more than 120 seconds.
Aug 15 14:51:58 helium kernel: Tainted: P O 4.12.6-1-ARCH #1
Aug 15 14:51:58 helium kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Aug 15 14:51:58 helium kernel: txg_quiesce D 0 26727 2 0x00000000
Aug 15 14:51:58 helium kernel: Call Trace:
Aug 15 14:51:58 helium kernel: __schedule+0x236/0x870
Aug 15 14:51:58 helium kernel: schedule+0x3d/0x90
Aug 15 14:51:58 helium kernel: cv_wait_common+0x11c/0x130 [spl]
Aug 15 14:51:58 helium kernel: ? wake_bit_function+0x60/0x60
Aug 15 14:51:58 helium kernel: __cv_wait+0x15/0x20 [spl]
Aug 15 14:51:58 helium kernel: txg_quiesce_thread+0x2d5/0x3e0 [zfs]
Aug 15 14:51:58 helium kernel: ? txg_wait_open+0x100/0x100 [zfs]
Aug 15 14:51:58 helium kernel: thread_generic_wrapper+0x72/0x80 [spl]
Aug 15 14:51:58 helium kernel: kthread+0x125/0x140
Aug 15 14:51:58 helium kernel: ? __thread_exit+0x20/0x20 [spl]
Aug 15 14:51:58 helium kernel: ? kthread_create_on_node+0x70/0x70
Aug 15 14:51:58 helium kernel: ? kthread_create_on_node+0x70/0x70
Aug 15 14:51:58 helium kernel: ret_from_fork+0x25/0x30
Aug 15 14:51:58 helium kernel: INFO: task zfs:28062 blocked for more than 120 seconds.
Aug 15 14:51:58 helium kernel: Tainted: P O 4.12.6-1-ARCH #1
Aug 15 14:51:58 helium kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Aug 15 14:51:58 helium kernel: zfs D 0 28062 28060 0x00000000
Aug 15 14:51:58 helium kernel: Call Trace:
Aug 15 14:51:58 helium kernel: __schedule+0x236/0x870
Aug 15 14:51:58 helium kernel: schedule+0x3d/0x90
Aug 15 14:51:58 helium kernel: cv_wait_common+0x11c/0x130 [spl]
Aug 15 14:51:58 helium kernel: ? wake_bit_function+0x60/0x60
Aug 15 14:51:58 helium kernel: __cv_wait+0x15/0x20 [spl]
Aug 15 14:51:58 helium kernel: txg_wait_synced+0xdd/0x130 [zfs]
Aug 15 14:51:58 helium kernel: dmu_recv_cleanup_ds+0x49/0xc0 [zfs]
Aug 15 14:51:58 helium kernel: ? __schedule+0x23e/0x870
Aug 15 14:51:58 helium kernel: ? __wake_up+0x44/0x50
Aug 15 14:51:58 helium kernel: ? cv_wait_common+0xeb/0x130 [spl]
Aug 15 14:51:58 helium kernel: ? wake_bit_function+0x60/0x60
Aug 15 14:51:58 helium kernel: dmu_recv_stream+0x28e/0x1080 [zfs]
Aug 15 14:51:58 helium kernel: ? kfree+0x175/0x190
Aug 15 14:51:58 helium kernel: zfs_ioc_recv_impl+0x48d/0x10f0 [zfs]
Aug 15 14:51:58 helium kernel: zfs_ioc_recv_new+0x31e/0x3e0 [zfs]
Aug 15 14:51:58 helium kernel: ? try_to_merge_one_page+0x539/0x790
Aug 15 14:51:58 helium kernel: ? spl_kmem_alloc_impl+0xd1/0x180 [spl]
Aug 15 14:51:58 helium kernel: ? spl_vmem_alloc+0x19/0x20 [spl]
Aug 15 14:51:58 helium kernel: ? nv_alloc_sleep_spl+0x1f/0x30 [znvpair]
Aug 15 14:51:58 helium kernel: ? nv_mem_zalloc.isra.12+0x28/0x40 [znvpair]
Aug 15 14:51:58 helium kernel: ? nvlist_xalloc.part.13+0x63/0xc0 [znvpair]
Aug 15 14:51:58 helium kernel: zfsdev_ioctl+0x442/0x600 [zfs]
Aug 15 14:51:58 helium kernel: do_vfs_ioctl+0xa5/0x600
Aug 15 14:51:58 helium kernel: ? vfs_write+0x166/0x1a0
Aug 15 14:51:58 helium kernel: SyS_ioctl+0x79/0x90
Aug 15 14:51:58 helium kernel: entry_SYSCALL_64_fastpath+0x1a/0xa5
Aug 15 14:51:58 helium kernel: RIP: 0033:0x7f980d6948b7
Aug 15 14:51:58 helium kernel: RSP: 002b:00007ffc6613f668 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
Aug 15 14:51:58 helium kernel: RAX: ffffffffffffffda RBX: 00000050ef3e9370 RCX: 00007f980d6948b7
Aug 15 14:51:58 helium kernel: RDX: 00007ffc6613f680 RSI: 0000000000005a46 RDI: 0000000000000005
Aug 15 14:51:58 helium kernel: RBP: 00000050ef3e9348 R08: 0000000000000003 R09: 000000000000007c
Aug 15 14:51:58 helium kernel: R10: 0000000000000830 R11: 0000000000000246 R12: 00000050ef3e5540
Aug 15 14:51:58 helium kernel: R13: 00000050ef160080 R14: 0000000000000002 R15: 00000050ef3e93c0
<...>
Aug 15 14:54:01 helium kernel: INFO: task txg_quiesce:26727 blocked for more than 120 seconds.
Aug 15 14:54:01 helium kernel: Tainted: P O 4.12.6-1-ARCH #1
Aug 15 14:54:01 helium kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Aug 15 14:54:01 helium kernel: txg_quiesce D 0 26727 2 0x00000000
Aug 15 14:54:01 helium kernel: Call Trace:
Aug 15 14:54:01 helium kernel: __schedule+0x236/0x870
Aug 15 14:54:01 helium kernel: schedule+0x3d/0x90
Aug 15 14:54:01 helium kernel: cv_wait_common+0x11c/0x130 [spl]
Aug 15 14:54:01 helium kernel: ? wake_bit_function+0x60/0x60
Aug 15 14:54:01 helium kernel: __cv_wait+0x15/0x20 [spl]
Aug 15 14:54:01 helium kernel: txg_quiesce_thread+0x2d5/0x3e0 [zfs]
Aug 15 14:54:01 helium kernel: ? txg_wait_open+0x100/0x100 [zfs]
Aug 15 14:54:01 helium kernel: thread_generic_wrapper+0x72/0x80 [spl]
Aug 15 14:54:01 helium kernel: kthread+0x125/0x140
Aug 15 14:54:01 helium kernel: ? __thread_exit+0x20/0x20 [spl]
Aug 15 14:54:01 helium kernel: ? kthread_create_on_node+0x70/0x70
Aug 15 14:54:01 helium kernel: ? kthread_create_on_node+0x70/0x70
Aug 15 14:54:01 helium kernel: ret_from_fork+0x25/0x30
Aug 15 14:54:01 helium kernel: INFO: task zfs:28062 blocked for more than 120 seconds.
Aug 15 14:54:01 helium kernel: Tainted: P O 4.12.6-1-ARCH #1
Aug 15 14:54:01 helium kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Aug 15 14:54:01 helium kernel: zfs D 0 28062 28060 0x00000000
Aug 15 14:54:01 helium kernel: Call Trace:
Aug 15 14:54:01 helium kernel: __schedule+0x236/0x870
Aug 15 14:54:01 helium kernel: schedule+0x3d/0x90
Aug 15 14:54:01 helium kernel: cv_wait_common+0x11c/0x130 [spl]
Aug 15 14:54:01 helium kernel: ? wake_bit_function+0x60/0x60
Aug 15 14:54:01 helium kernel: __cv_wait+0x15/0x20 [spl]
Aug 15 14:54:01 helium kernel: txg_wait_synced+0xdd/0x130 [zfs]
Aug 15 14:54:01 helium kernel: dmu_recv_cleanup_ds+0x49/0xc0 [zfs]
Aug 15 14:54:01 helium kernel: ? __schedule+0x23e/0x870
Aug 15 14:54:01 helium kernel: ? __wake_up+0x44/0x50
Aug 15 14:54:01 helium kernel: ? cv_wait_common+0xeb/0x130 [spl]
Aug 15 14:54:01 helium kernel: ? wake_bit_function+0x60/0x60
Aug 15 14:54:01 helium kernel: dmu_recv_stream+0x28e/0x1080 [zfs]
Aug 15 14:54:01 helium kernel: ? kfree+0x175/0x190
Aug 15 14:54:01 helium kernel: zfs_ioc_recv_impl+0x48d/0x10f0 [zfs]
Aug 15 14:54:01 helium kernel: zfs_ioc_recv_new+0x31e/0x3e0 [zfs]
Aug 15 14:54:01 helium kernel: ? try_to_merge_one_page+0x539/0x790
Aug 15 14:54:01 helium kernel: ? spl_kmem_alloc_impl+0xd1/0x180 [spl]
Aug 15 14:54:01 helium kernel: ? spl_vmem_alloc+0x19/0x20 [spl]
Aug 15 14:54:01 helium kernel: ? nv_alloc_sleep_spl+0x1f/0x30 [znvpair]
Aug 15 14:54:01 helium kernel: ? nv_mem_zalloc.isra.12+0x28/0x40 [znvpair]
Aug 15 14:54:01 helium kernel: ? nvlist_xalloc.part.13+0x63/0xc0 [znvpair]
Aug 15 14:54:01 helium kernel: zfsdev_ioctl+0x442/0x600 [zfs]
Aug 15 14:54:01 helium kernel: do_vfs_ioctl+0xa5/0x600
Aug 15 14:54:01 helium kernel: ? vfs_write+0x166/0x1a0
Aug 15 14:54:01 helium kernel: SyS_ioctl+0x79/0x90
Aug 15 14:54:01 helium kernel: entry_SYSCALL_64_fastpath+0x1a/0xa5
Aug 15 14:54:01 helium kernel: RIP: 0033:0x7f980d6948b7
Aug 15 14:54:01 helium kernel: RSP: 002b:00007ffc6613f668 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
Aug 15 14:54:01 helium kernel: RAX: ffffffffffffffda RBX: 00000050ef3e9370 RCX: 00007f980d6948b7
Aug 15 14:54:01 helium kernel: RDX: 00007ffc6613f680 RSI: 0000000000005a46 RDI: 0000000000000005
Aug 15 14:54:01 helium kernel: RBP: 00000050ef3e9348 R08: 0000000000000003 R09: 000000000000007c
Aug 15 14:54:01 helium kernel: R10: 0000000000000830 R11: 0000000000000246 R12: 00000050ef3e5540
Aug 15 14:54:01 helium kernel: R13: 00000050ef160080 R14: 0000000000000002 R15: 00000050ef3e93c0The zfs send process on the sending side was able to be ctrl+C'd out of after a short delay; however the zfs recv process on the receiving side just won't die, no matter what I do to it (e.g. SIGKILL), and no matter how long I wait. Just stuck in that ioctl syscall eternally, I guess.
Note that I've tried the receive side of this operation on two different machines (same kernel/ZoL versions and drives however), with the same results.
Here's the exact command I've been executing (on the sending machine) to do the transfer:
zfs send -R -L -c -v pool@migration1-20170814-2010PDT | lz4 - | ssh helium 'lz4 -d - | zfs recv -s -o checksum=sha512 -d -F -v lifeboat/pool'So now I can't even tell for sure whether this is a send problem or a receive problem.
behlendorf
commented
7 years ago Reopening.
jgottula
commented
7 years ago I've managed to narrow things down somewhat, by sending snaps one-by-one and removing some of the command line options and such.
I've found that the receiving end always locks up if the snapshot it's receiving is from a particular point in time or onward.
So while these work just fine:
<...>
zfs send -p -v -i auto_2017-05-01-0700_monthly pool@auto_2017-06-01-0700_monthly | ssh helium 'zfs recv -v lifeboat/pool'
zfs send -p -v -i auto_2017-06-01-0700_monthly pool@auto_2017-06-07-1933_monthly | ssh helium 'zfs recv -v lifeboat/pool'Any of these will cause a lockup:
zfs send -p -v -i auto_2017-06-07-1933_monthly pool@auto_2017-06-26-0700_weekly | ssh helium 'zfs recv -v lifeboat/pool'
zfs send -p -v -i auto_2017-06-07-1933_monthly pool@auto_2017-07-01-0700_monthly | ssh helium 'zfs recv -v lifeboat/pool'
<...>(Based on the following send-side snapshot list:)
<...>
pool@auto_2017-04-01-0700_monthly 128K - 174K -
pool@auto_2017-05-01-0700_monthly 209K - 291K -
pool@auto_2017-06-01-0700_monthly 140K - 256K -
pool@auto_2017-06-07-1933_monthly 140K - 256K -
pool@auto_2017-06-26-0700_weekly 0B - 256K -
pool@auto_2017-07-01-0700_monthly 0B - 256K -
pool@auto_2017-07-03-0700_weekly 0B - 256K -
pool@auto_2017-07-10-0700_weekly 0B - 256K -
<...>And this top-level pool filesystem stores nothing except sub-filesystems; uses no encryption; etc.
I'm slightly suspicious of the encryption support commit, i.e. zfsonlinux/zfs@b52563034230b35f0562b6f40ad1a00f02bd9a05, since it's such a big commit that touches an awful lot of aspects of the codebase including send/receive (such as, e.g., changing in which cases the call to txg_wait_synced is done in dmu_recv_cleanup_ds; that's one of the relevant parts of the lockup, as far as I can tell from the stack traces I posted earlier).
But I don't know for sure if I'd be able to downgrade the receive-side ZoL version to test whether things work better before that commit, since I've already upgraded the send-side pool version/features to the very latest and I think that would break send/recv compat? Or maybe it wouldn't, since I haven't actually used encryption at all on the pool...? Not totally clear on that.
jgottula
commented
7 years ago I just checked my package manager history on the sending side (where the pool has been living its life), and it appears that pretty damn close to the time when the pool@auto_2017-06-07-1933_monthly snapshot was created (not 100% sure if this was right before or right after), I upgraded from kernel 4.10.3 with zfs zfsonlinux/zfs@a3478c074 and spl zfsonlinux/spl@e0aacd9, to kernel 4.11.3 with zfs zfsonlinux/zfs@829aaf280 and spl zfsonlinux/spl@ac48361. And then I've been running with the latter set of versions on the machine until literally yesterday.
So that might be relevant in some way; that software upgrade coincides with the "good snaps" / "bad snaps" boundary pretty nicely.
trisk
commented
7 years ago Can you check if the send side still encounters a problem if the stream for those snapshots is written to /dev/null? The producer thread is waiting for the bqueue to be drained by dmu_send_impl, which might just be stuck waiting for the receive side to consume the stream.
pruiz
commented
6 years ago I think I am facing the same issue here with CentOS 7.4 (3.10.0-693.21.1.el7.x86_64), using zfs-0.7.6-1.el7_4.x86_64. It happened too with 0.7.4 (upgraded to 0.7.6 hopping for a fix).
A zfs send -I old new + ssh zfs recv, hangs on recv side. I've narrowed it to recv, as writing send stream to file and applying it with 'zfs receive -v -d -F TANK/Stores/nas < /data/017454.snap, ends up on "zfs recv" hanging too.
The snap stream is over 12GB, but it hangs nearly after having read ~2GB, at this point, dmesg shows a few repetitions of:
[Tue Mar 20 01:11:51 2018] INFO: task zfs:15938 blocked for more than 120 seconds.
[Tue Mar 20 01:11:51 2018] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[Tue Mar 20 01:11:51 2018] zfs D ffff8800d8668000 0 15938 30898 0x00000080
[Tue Mar 20 01:11:51 2018] Call Trace:
[Tue Mar 20 01:11:51 2018] [<ffffffff816b40e9>] schedule+0x29/0x70
[Tue Mar 20 01:11:51 2018] [<ffffffffc059d515>] cv_wait_common+0x125/0x150 [spl]
[Tue Mar 20 01:11:51 2018] [<ffffffff810b4fc0>] ? wake_up_atomic_t+0x30/0x30
[Tue Mar 20 01:11:51 2018] [<ffffffffc059d555>] __cv_wait+0x15/0x20 [spl]
[Tue Mar 20 01:11:51 2018] [<ffffffffc07e156b>] bqueue_enqueue+0x6b/0xe0 [zfs]
[Tue Mar 20 01:11:51 2018] [<ffffffffc07f5b8b>] dmu_recv_stream+0x67b/0xec0 [zfs]
[Tue Mar 20 01:11:51 2018] [<ffffffffc0878489>] zfs_ioc_recv_impl+0x2d9/0x1100 [zfs]
[Tue Mar 20 01:11:51 2018] [<ffffffff816b2192>] ? mutex_lock+0x12/0x2f
[Tue Mar 20 01:11:51 2018] [<ffffffffc07d5601>] ? arc_buf_access+0x141/0x270 [zfs]
[Tue Mar 20 01:11:51 2018] [<ffffffffc0879485>] zfs_ioc_recv+0x1d5/0x2d0 [zfs]
[Tue Mar 20 01:11:51 2018] [<ffffffff812bf47e>] ? selinux_capable+0x2e/0x40
[Tue Mar 20 01:11:51 2018] [<ffffffff812b71ae>] ? security_capable+0x1e/0x20
[Tue Mar 20 01:11:51 2018] [<ffffffff81098149>] ? ns_capable+0x29/0x50
[Tue Mar 20 01:11:51 2018] [<ffffffff81098187>] ? capable+0x17/0x20
[Tue Mar 20 01:11:51 2018] [<ffffffffc082591a>] ? priv_policy.isra.1+0x3a/0x50 [zfs]
[Tue Mar 20 01:11:51 2018] [<ffffffffc0825b58>] ? secpolicy_zfs+0x18/0x20 [zfs]
[Tue Mar 20 01:11:51 2018] [<ffffffff811e4e55>] ? __kmalloc+0x55/0x230
[Tue Mar 20 01:11:51 2018] [<ffffffffc0595f0f>] ? strdup+0x3f/0x60 [spl]
[Tue Mar 20 01:11:51 2018] [<ffffffffc0876a56>] zfsdev_ioctl+0x606/0x650 [zfs]
[Tue Mar 20 01:11:51 2018] [<ffffffff81219e90>] do_vfs_ioctl+0x350/0x560
[Tue Mar 20 01:11:51 2018] [<ffffffff812bec3f>] ? file_has_perm+0x9f/0xb0
[Tue Mar 20 01:11:51 2018] [<ffffffff8121a141>] SyS_ioctl+0xa1/0xc0
[Tue Mar 20 01:11:51 2018] [<ffffffff816c0655>] ? system_call_after_swapgs+0xa2/0x146
[Tue Mar 20 01:11:51 2018] [<ffffffff816c0715>] system_call_fastpath+0x1c/0x21
[Tue Mar 20 01:11:51 2018] [<ffffffff816c0661>] ? system_call_after_swapgs+0xae/0x146And from this point onwards, I/O stops (even at zpool iostat) while CPU usage (by kernel) keeps spinning. Also, I am unable to kill 'zfs recv' process, no matter what signal I may try.
And a cat /proc/$zfs-recv-pid/stack show the following:
[<ffffffffc059d515>] cv_wait_common+0x125/0x150 [spl]
[<ffffffffc059d555>] __cv_wait+0x15/0x20 [spl]
[<ffffffffc07e156b>] bqueue_enqueue+0x6b/0xe0 [zfs]
[<ffffffffc07f5b8b>] dmu_recv_stream+0x67b/0xec0 [zfs]
[<ffffffffc0878489>] zfs_ioc_recv_impl+0x2d9/0x1100 [zfs]
[<ffffffffc0879485>] zfs_ioc_recv+0x1d5/0x2d0 [zfs]
[<ffffffffc0876a56>] zfsdev_ioctl+0x606/0x650 [zfs]
[<ffffffff81219e90>] do_vfs_ioctl+0x350/0x560
[<ffffffff8121a141>] SyS_ioctl+0xa1/0xc0
[<ffffffff816c0715>] system_call_fastpath+0x1c/0x21
[<ffffffffffffffff>] 0xffffffffffffffff
We recently experienced an issue where ZFS locked up, and files that were subsequently written to a Samba share were lost on reboot. It seemed like Samba acknowledged the write, but ZFS hadn't actually written anything to disk.
Samba audit logging showed the files being written, but after a reboot to restore ZFS functionality the logged files were no longer present.
System info:
Pool info:
Kernel trace: