task blocked for more than 122 seconds

[mabod]

System information

Type	Version/Name
Distribution Name	EndeavourOS Linux x86_64
Distribution Version
Linux Kernel	5.9.4-arch1-1
Architecture	x86_64
ZFS Version	2.0.0-rc5
SPL Version	2.0.0-rc5

Describe the problem you're observing

Today I wanted to test new compression algorithms for zfs 2.0 rc5
but I didnt get that far because zfs got hang up after some while.

I tested with an WesternDigital HD on USB and compression=lz4. fio was set to do one job with 64GB size (my RAM size, seq read/write).
After some time the whole job stopped moving and I saw the following messages in the log:

Nov 06 07:49:50 rakete kernel: INFO: task spl_delay_taskq:384 blocked for more than 122 seconds.
Nov 06 07:49:50 rakete kernel:       Tainted: P           OE     5.9.4-arch1-1 #1
Nov 06 07:49:50 rakete kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Nov 06 07:49:50 rakete kernel: task:spl_delay_taskq state:D stack:    0 pid:  384 ppid:     2 flags:0x00004000
Nov 06 07:49:50 rakete kernel: Call Trace:
Nov 06 07:49:50 rakete kernel:  __schedule+0x292/0x830
Nov 06 07:49:50 rakete kernel:  schedule+0x46/0xf0
Nov 06 07:49:50 rakete kernel:  schedule_timeout+0x12d/0x170
Nov 06 07:49:50 rakete kernel:  wait_for_completion+0x9e/0x100
Nov 06 07:49:50 rakete kernel:  call_usermodehelper_exec+0x13d/0x170
Nov 06 07:49:50 rakete kernel:  zfsctl_snapshot_unmount+0x110/0x1f0 [zfs]
Nov 06 07:49:50 rakete kernel:  snapentry_expire+0x38/0xd0 [zfs]
Nov 06 07:49:50 rakete kernel:  taskq_thread+0x28e/0x4b0 [spl]
Nov 06 07:49:50 rakete kernel:  ? wake_up_q+0xa0/0xa0
Nov 06 07:49:50 rakete kernel:  ? taskq_thread_spawn+0x50/0x50 [spl]
Nov 06 07:49:50 rakete kernel:  kthread+0x142/0x160
Nov 06 07:49:50 rakete kernel:  ? __kthread_bind_mask+0x60/0x60
Nov 06 07:49:50 rakete kernel:  ret_from_fork+0x22/0x30

Nov 06 07:49:50 rakete kernel: INFO: task gvfs-udisks2-vo:5965 blocked for more than 122 seconds.
Nov 06 07:49:50 rakete kernel:       Tainted: P           OE     5.9.4-arch1-1 #1
Nov 06 07:49:50 rakete kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Nov 06 07:49:50 rakete kernel: task:gvfs-udisks2-vo state:D stack:    0 pid: 5965 ppid:  5614 flags:0x00000080
Nov 06 07:49:50 rakete kernel: Call Trace:
Nov 06 07:49:50 rakete kernel:  __schedule+0x292/0x830
Nov 06 07:49:50 rakete kernel:  schedule+0x46/0xf0
Nov 06 07:49:50 rakete kernel:  rwsem_down_read_slowpath+0x206/0x4e0
Nov 06 07:49:50 rakete kernel:  m_start+0x1c/0xa0
Nov 06 07:49:50 rakete kernel:  seq_read+0x90/0x460
Nov 06 07:49:50 rakete kernel:  vfs_read+0x9c/0x180
Nov 06 07:49:50 rakete kernel:  ksys_read+0x67/0xe0
Nov 06 07:49:50 rakete kernel:  do_syscall_64+0x33/0x40
Nov 06 07:49:50 rakete kernel:  entry_SYSCALL_64_after_hwframe+0x44/0xa9
Nov 06 07:49:50 rakete kernel: RIP: 0033:0x7f3952b8aefc
Nov 06 07:49:50 rakete kernel: Code: Unable to access opcode bytes at RIP 0x7f3952b8aed2.
Nov 06 07:49:50 rakete kernel: RSP: 002b:00007ffd4f45b7a0 EFLAGS: 00000246 ORIG_RAX: 0000000000000000
Nov 06 07:49:50 rakete kernel: RAX: ffffffffffffffda RBX: 0000000000004000 RCX: 00007f3952b8aefc
Nov 06 07:49:50 rakete kernel: RDX: 0000000000004000 RSI: 000055ad05f58510 RDI: 000000000000000c
Nov 06 07:49:50 rakete kernel: RBP: 00007ffd4f45b850 R08: 0000000000000000 R09: 00007f3952c5ca60
Nov 06 07:49:50 rakete kernel: R10: 0000000000000100 R11: 0000000000000246 R12: 000000000000000c
Nov 06 07:49:50 rakete kernel: R13: 0000000000000000 R14: 00007f395022f6c8 R15: 000055ad05f58510

Nov 06 07:49:50 rakete kernel: INFO: task umount:57839 blocked for more than 122 seconds.
Nov 06 07:49:50 rakete kernel:       Tainted: P           OE     5.9.4-arch1-1 #1
Nov 06 07:49:50 rakete kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Nov 06 07:49:50 rakete kernel: task:umount          state:D stack:    0 pid:57839 ppid:   245 flags:0x00004080
Nov 06 07:49:50 rakete kernel: Call Trace:
Nov 06 07:49:50 rakete kernel:  __schedule+0x292/0x830
Nov 06 07:49:50 rakete kernel:  schedule+0x46/0xf0
Nov 06 07:49:50 rakete kernel:  taskq_wait_id+0xae/0x100 [spl]
Nov 06 07:49:50 rakete kernel:  ? wait_woken+0x80/0x80
Nov 06 07:49:50 rakete kernel:  taskq_cancel_id+0xd7/0x110 [spl]
Nov 06 07:49:50 rakete kernel:  zfsctl_snapshot_unmount_delay+0x48/0xd0 [zfs]
Nov 06 07:49:50 rakete kernel:  zpl_show_devname+0x81/0xc0 [zfs]
Nov 06 07:49:50 rakete kernel:  show_mountinfo+0x204/0x340
Nov 06 07:49:50 rakete kernel:  seq_read+0x308/0x460
Nov 06 07:49:50 rakete kernel:  vfs_read+0x9c/0x180
Nov 06 07:49:50 rakete kernel:  ksys_read+0x67/0xe0
Nov 06 07:49:50 rakete kernel:  do_syscall_64+0x33/0x40
Nov 06 07:49:50 rakete kernel:  entry_SYSCALL_64_after_hwframe+0x44/0xa9
Nov 06 07:49:50 rakete kernel: RIP: 0033:0x7f5445794ec2
Nov 06 07:49:50 rakete kernel: Code: Unable to access opcode bytes at RIP 0x7f5445794e98.
Nov 06 07:49:50 rakete kernel: RSP: 002b:00007ffe94226ec8 EFLAGS: 00000246 ORIG_RAX: 0000000000000000
Nov 06 07:49:50 rakete kernel: RAX: ffffffffffffffda RBX: 0000000000008000 RCX: 00007f5445794ec2
Nov 06 07:49:50 rakete kernel: RDX: 0000000000004000 RSI: 000055bc3be54610 RDI: 0000000000000000
Nov 06 07:49:50 rakete kernel: RBP: 00007ffe94226f50 R08: 000055bc3be50610 R09: 00007f5445866a60
Nov 06 07:49:50 rakete kernel: R10: 0000000000000130 R11: 0000000000000246 R12: 0000000000000000
Nov 06 07:49:50 rakete kernel: R13: 0000000000004000 R14: 00007f5445624500 R15: 000055bc3be54610

Nov 06 07:49:50 rakete kernel: INFO: task spl_delay_taskq:57840 blocked for more than 122 seconds.
Nov 06 07:49:50 rakete kernel:       Tainted: P           OE     5.9.4-arch1-1 #1
Nov 06 07:49:50 rakete kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Nov 06 07:49:50 rakete kernel: task:spl_delay_taskq state:D stack:    0 pid:57840 ppid:     2 flags:0x00004080
Nov 06 07:49:50 rakete kernel: Call Trace:
Nov 06 07:49:50 rakete kernel:  __schedule+0x292/0x830
Nov 06 07:49:50 rakete kernel:  schedule+0x46/0xf0
Nov 06 07:49:50 rakete kernel:  schedule_timeout+0x12d/0x170
Nov 06 07:49:50 rakete kernel:  wait_for_completion+0x9e/0x100
Nov 06 07:49:50 rakete kernel:  call_usermodehelper_exec+0x13d/0x170
Nov 06 07:49:50 rakete kernel:  zfsctl_snapshot_unmount+0x110/0x1f0 [zfs]
Nov 06 07:49:50 rakete kernel:  snapentry_expire+0x38/0xd0 [zfs]
Nov 06 07:49:50 rakete kernel:  taskq_thread+0x28e/0x4b0 [spl]
Nov 06 07:49:50 rakete kernel:  ? wake_up_q+0xa0/0xa0
Nov 06 07:49:50 rakete kernel:  ? taskq_thread_spawn+0x50/0x50 [spl]
Nov 06 07:49:50 rakete kernel:  kthread+0x142/0x160
Nov 06 07:49:50 rakete kernel:  ? __kthread_bind_mask+0x60/0x60
Nov 06 07:49:50 rakete kernel:  ret_from_fork+0x22/0x30

Nov 06 07:49:50 rakete kernel: INFO: task spl_delay_taskq:57841 blocked for more than 122 seconds.
Nov 06 07:49:50 rakete kernel:       Tainted: P           OE     5.9.4-arch1-1 #1
Nov 06 07:49:50 rakete kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Nov 06 07:49:50 rakete kernel: task:spl_delay_taskq state:D stack:    0 pid:57841 ppid:     2 flags:0x00004080
Nov 06 07:49:50 rakete kernel: Call Trace:
Nov 06 07:49:50 rakete kernel:  __schedule+0x292/0x830
Nov 06 07:49:50 rakete kernel:  schedule+0x46/0xf0
Nov 06 07:49:50 rakete kernel:  schedule_timeout+0x12d/0x170
Nov 06 07:49:50 rakete kernel:  wait_for_completion+0x9e/0x100
Nov 06 07:49:50 rakete kernel:  call_usermodehelper_exec+0x13d/0x170
Nov 06 07:49:50 rakete kernel:  zfsctl_snapshot_unmount+0x110/0x1f0 [zfs]
Nov 06 07:49:50 rakete kernel:  snapentry_expire+0x38/0xd0 [zfs]
Nov 06 07:49:50 rakete kernel:  taskq_thread+0x28e/0x4b0 [spl]
Nov 06 07:49:50 rakete kernel:  ? wake_up_q+0xa0/0xa0
Nov 06 07:49:50 rakete kernel:  ? taskq_thread_spawn+0x50/0x50 [spl]
Nov 06 07:49:50 rakete kernel:  kthread+0x142/0x160
Nov 06 07:49:50 rakete kernel:  ? __kthread_bind_mask+0x60/0x60
Nov 06 07:49:50 rakete kernel:  ret_from_fork+0x22/0x30

Nov 06 07:49:50 rakete kernel: INFO: task spl_delay_taskq:57843 blocked for more than 122 seconds.
Nov 06 07:49:50 rakete kernel:       Tainted: P           OE     5.9.4-arch1-1 #1
Nov 06 07:49:50 rakete kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Nov 06 07:49:50 rakete kernel: task:spl_delay_taskq state:D stack:    0 pid:57843 ppid:     2 flags:0x00004080
Nov 06 07:49:50 rakete kernel: Call Trace:
Nov 06 07:49:50 rakete kernel:  __schedule+0x292/0x830
Nov 06 07:49:50 rakete kernel:  schedule+0x46/0xf0
Nov 06 07:49:50 rakete kernel:  schedule_timeout+0x12d/0x170
Nov 06 07:49:50 rakete kernel:  wait_for_completion+0x9e/0x100
Nov 06 07:49:50 rakete kernel:  call_usermodehelper_exec+0x13d/0x170
Nov 06 07:49:50 rakete kernel:  zfsctl_snapshot_unmount+0x110/0x1f0 [zfs]
Nov 06 07:49:50 rakete kernel:  snapentry_expire+0x38/0xd0 [zfs]
Nov 06 07:49:50 rakete kernel:  taskq_thread+0x28e/0x4b0 [spl]
Nov 06 07:49:50 rakete kernel:  ? wake_up_q+0xa0/0xa0
Nov 06 07:49:50 rakete kernel:  ? taskq_thread_spawn+0x50/0x50 [spl]
Nov 06 07:49:50 rakete kernel:  kthread+0x142/0x160
Nov 06 07:49:50 rakete kernel:  ? __kthread_bind_mask+0x60/0x60
Nov 06 07:49:50 rakete kernel:  ret_from_fork+0x22/0x30

Nov 06 07:49:50 rakete kernel: INFO: task spl_delay_taskq:57844 blocked for more than 122 seconds.
Nov 06 07:49:50 rakete kernel:       Tainted: P           OE     5.9.4-arch1-1 #1
Nov 06 07:49:50 rakete kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Nov 06 07:49:50 rakete kernel: task:spl_delay_taskq state:D stack:    0 pid:57844 ppid:     2 flags:0x00004080
Nov 06 07:49:50 rakete kernel: Call Trace:
Nov 06 07:49:50 rakete kernel:  __schedule+0x292/0x830
Nov 06 07:49:50 rakete kernel:  schedule+0x46/0xf0
Nov 06 07:49:50 rakete kernel:  schedule_timeout+0x12d/0x170
Nov 06 07:49:50 rakete kernel:  wait_for_completion+0x9e/0x100
Nov 06 07:49:50 rakete kernel:  call_usermodehelper_exec+0x13d/0x170
Nov 06 07:49:50 rakete kernel:  zfsctl_snapshot_unmount+0x110/0x1f0 [zfs]
Nov 06 07:49:50 rakete kernel:  snapentry_expire+0x38/0xd0 [zfs]
Nov 06 07:49:50 rakete kernel:  taskq_thread+0x28e/0x4b0 [spl]
Nov 06 07:49:50 rakete kernel:  ? wake_up_q+0xa0/0xa0
Nov 06 07:49:50 rakete kernel:  ? taskq_thread_spawn+0x50/0x50 [spl]
Nov 06 07:49:50 rakete kernel:  kthread+0x142/0x160
Nov 06 07:49:50 rakete kernel:  ? __kthread_bind_mask+0x60/0x60
Nov 06 07:49:50 rakete kernel:  ret_from_fork+0x22/0x30

Nov 06 07:49:50 rakete kernel: INFO: task spl_delay_taskq:57847 blocked for more than 122 seconds.
Nov 06 07:49:50 rakete kernel:       Tainted: P           OE     5.9.4-arch1-1 #1
Nov 06 07:49:50 rakete kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Nov 06 07:49:50 rakete kernel: task:spl_delay_taskq state:D stack:    0 pid:57847 ppid:     2 flags:0x00004080
Nov 06 07:49:50 rakete kernel: Call Trace:
Nov 06 07:49:50 rakete kernel:  __schedule+0x292/0x830
Nov 06 07:49:50 rakete kernel:  schedule+0x46/0xf0
Nov 06 07:49:50 rakete kernel:  schedule_timeout+0x12d/0x170
Nov 06 07:49:50 rakete kernel:  wait_for_completion+0x9e/0x100
Nov 06 07:49:50 rakete kernel:  call_usermodehelper_exec+0x13d/0x170
Nov 06 07:49:50 rakete kernel:  zfsctl_snapshot_unmount+0x110/0x1f0 [zfs]
Nov 06 07:49:50 rakete kernel:  snapentry_expire+0x38/0xd0 [zfs]
Nov 06 07:49:50 rakete kernel:  taskq_thread+0x28e/0x4b0 [spl]
Nov 06 07:49:50 rakete kernel:  ? wake_up_q+0xa0/0xa0
Nov 06 07:49:50 rakete kernel:  ? taskq_thread_spawn+0x50/0x50 [spl]
Nov 06 07:49:50 rakete kernel:  kthread+0x142/0x160
Nov 06 07:49:50 rakete kernel:  ? __kthread_bind_mask+0x60/0x60
Nov 06 07:49:50 rakete kernel:  ret_from_fork+0x22/0x30

Nov 06 07:49:50 rakete kernel: INFO: task spl_delay_taskq:57849 blocked for more than 122 seconds.
Nov 06 07:49:50 rakete kernel:       Tainted: P           OE     5.9.4-arch1-1 #1
Nov 06 07:49:50 rakete kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Nov 06 07:49:50 rakete kernel: task:spl_delay_taskq state:D stack:    0 pid:57849 ppid:     2 flags:0x00004080
Nov 06 07:49:50 rakete kernel: Call Trace:
Nov 06 07:49:50 rakete kernel:  __schedule+0x292/0x830
Nov 06 07:49:50 rakete kernel:  schedule+0x46/0xf0
Nov 06 07:49:50 rakete kernel:  schedule_timeout+0x12d/0x170
Nov 06 07:49:50 rakete kernel:  wait_for_completion+0x9e/0x100
Nov 06 07:49:50 rakete kernel:  call_usermodehelper_exec+0x13d/0x170
Nov 06 07:49:50 rakete kernel:  zfsctl_snapshot_unmount+0x110/0x1f0 [zfs]
Nov 06 07:49:50 rakete kernel:  snapentry_expire+0x38/0xd0 [zfs]
Nov 06 07:49:50 rakete kernel:  taskq_thread+0x28e/0x4b0 [spl]
Nov 06 07:49:50 rakete kernel:  ? wake_up_q+0xa0/0xa0
Nov 06 07:49:50 rakete kernel:  ? taskq_thread_spawn+0x50/0x50 [spl]
Nov 06 07:49:50 rakete kernel:  kthread+0x142/0x160
Nov 06 07:49:50 rakete kernel:  ? __kthread_bind_mask+0x60/0x60
Nov 06 07:49:50 rakete kernel:  ret_from_fork+0x22/0x30

Nov 06 07:49:50 rakete kernel: INFO: task spl_delay_taskq:57852 blocked for more than 122 seconds.
Nov 06 07:49:50 rakete kernel:       Tainted: P           OE     5.9.4-arch1-1 #1
Nov 06 07:49:50 rakete kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Nov 06 07:49:50 rakete kernel: task:spl_delay_taskq state:D stack:    0 pid:57852 ppid:     2 flags:0x00004080
Nov 06 07:49:50 rakete kernel: Call Trace:
Nov 06 07:49:50 rakete kernel:  __schedule+0x292/0x830
Nov 06 07:49:50 rakete kernel:  schedule+0x46/0xf0
Nov 06 07:49:50 rakete kernel:  schedule_timeout+0x12d/0x170
Nov 06 07:49:50 rakete kernel:  wait_for_completion+0x9e/0x100
Nov 06 07:49:50 rakete kernel:  call_usermodehelper_exec+0x13d/0x170
Nov 06 07:49:50 rakete kernel:  zfsctl_snapshot_unmount+0x110/0x1f0 [zfs]
Nov 06 07:49:50 rakete kernel:  snapentry_expire+0x38/0xd0 [zfs]
Nov 06 07:49:50 rakete kernel:  taskq_thread+0x28e/0x4b0 [spl]
Nov 06 07:49:50 rakete kernel:  ? wake_up_q+0xa0/0xa0
Nov 06 07:49:50 rakete kernel:  ? taskq_thread_spawn+0x50/0x50 [spl]
Nov 06 07:49:50 rakete kernel:  kthread+0x142/0x160
Nov 06 07:49:50 rakete kernel:  ? __kthread_bind_mask+0x60/0x60
Nov 06 07:49:50 rakete kernel:  ret_from_fork+0x22/0x30

The whole PC started to become very slow. Anything related to HD activity came to a halt.
zpool status got stuck to a point that I could not even terminate it with control-C.

I killed the fio job. And initiated a reboot from the XFCE GUI. But that did not work well.
After some minutes XFCE got terminate and the console came up. But then it was sitting there forever.
I tried REISUB to reboot the PC but even that failed. It did an emergency sync and an emergency umount/remount
but not more. It refused to reboot so that I had to use the reset button.

The PC came up normal and I tried to reproduce the issue immediately after reboot. But that was not successful.
I was not able to reproduce it.

But I took the opportunity to search for similar log entries in the history and found some - with zfs 0.8.5.
May be I am mixing things up here. But I want to mention it just in case this is related.

Nov 02 12:40:39 rakete kernel: INFO: task txg_sync:179210 blocked for more than 122 seconds.
Nov 02 12:40:39 rakete kernel:       Tainted: P        W  OE     5.9.2-arch1-1 #1
Nov 02 12:40:39 rakete kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Nov 02 12:40:39 rakete kernel: task:txg_sync        state:D stack:    0 pid:179210 ppid:     2 flags:0x00004080
Nov 02 12:40:39 rakete kernel: Call Trace:
Nov 02 12:40:39 rakete kernel:  __schedule+0x292/0x830
Nov 02 12:40:39 rakete kernel:  schedule+0x46/0xf0
Nov 02 12:40:39 rakete kernel:  schedule_timeout+0x99/0x170
Nov 02 12:40:39 rakete kernel:  ? __next_timer_interrupt+0x100/0x100
Nov 02 12:40:39 rakete kernel:  io_schedule_timeout+0x4b/0x80
Nov 02 12:40:39 rakete kernel:  __cv_timedwait_common+0x120/0x160 [spl]
Nov 02 12:40:39 rakete kernel:  ? wait_woken+0x80/0x80
Nov 02 12:40:39 rakete kernel:  zio_wait+0x136/0x280 [zfs]
Nov 02 12:40:39 rakete kernel:  dsl_pool_sync+0xd2/0x4d0 [zfs]
Nov 02 12:40:39 rakete kernel:  spa_sync+0x57d/0xf70 [zfs]
Nov 02 12:40:39 rakete kernel:  ? _raw_spin_unlock+0x16/0x30
Nov 02 12:40:39 rakete kernel:  ? spa_txg_history_init_io+0x112/0x120 [zfs]
Nov 02 12:40:39 rakete kernel:  txg_sync_thread+0x2d1/0x490 [zfs]
Nov 02 12:40:39 rakete kernel:  ? txg_register_callbacks+0xa0/0xa0 [zfs]
Nov 02 12:40:39 rakete kernel:  ? __thread_exit+0x20/0x20 [spl]
Nov 02 12:40:39 rakete kernel:  thread_generic_wrapper+0x6f/0x80 [spl]
Nov 02 12:40:39 rakete kernel:  kthread+0x142/0x160
Nov 02 12:40:39 rakete kernel:  ? __kthread_bind_mask+0x60/0x60
Nov 02 12:40:39 rakete kernel:  ret_from_fork+0x22/0x30

Nov 02 12:40:39 rakete kernel: INFO: task txg_sync:179210 blocked for more than 122 seconds.
Nov 02 12:40:39 rakete kernel:       Tainted: P        W  OE     5.9.2-arch1-1 #1
Nov 02 12:40:39 rakete kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Nov 02 12:40:39 rakete kernel: task:txg_sync        state:D stack:    0 pid:179210 ppid:     2 flags:0x00004080
Nov 02 12:40:39 rakete kernel: Call Trace:
Nov 02 12:40:39 rakete kernel:  __schedule+0x292/0x830
Nov 02 12:40:39 rakete kernel:  schedule+0x46/0xf0
Nov 02 12:40:39 rakete kernel:  schedule_timeout+0x99/0x170
Nov 02 12:40:39 rakete kernel:  ? __next_timer_interrupt+0x100/0x100
Nov 02 12:40:39 rakete kernel:  io_schedule_timeout+0x4b/0x80
Nov 02 12:40:39 rakete kernel:  __cv_timedwait_common+0x120/0x160 [spl]
Nov 02 12:40:39 rakete kernel:  ? wait_woken+0x80/0x80
Nov 02 12:40:39 rakete kernel:  zio_wait+0x136/0x280 [zfs]
Nov 02 12:40:39 rakete kernel:  dsl_pool_sync+0xd2/0x4d0 [zfs]
Nov 02 12:40:39 rakete kernel:  spa_sync+0x57d/0xf70 [zfs]
Nov 02 12:40:39 rakete kernel:  ? _raw_spin_unlock+0x16/0x30
Nov 02 12:40:39 rakete kernel:  ? spa_txg_history_init_io+0x112/0x120 [zfs]
Nov 02 12:40:39 rakete kernel:  txg_sync_thread+0x2d1/0x490 [zfs]
Nov 02 12:40:39 rakete kernel:  ? txg_register_callbacks+0xa0/0xa0 [zfs]
Nov 02 12:40:39 rakete kernel:  ? __thread_exit+0x20/0x20 [spl]
Nov 02 12:40:39 rakete kernel:  thread_generic_wrapper+0x6f/0x80 [spl]
Nov 02 12:40:39 rakete kernel:  kthread+0x142/0x160
Nov 02 12:40:39 rakete kernel:  ? __kthread_bind_mask+0x60/0x60
Nov 02 12:40:39 rakete kernel:  ret_from_fork+0x22/0x30

Nov 02 13:50:17 rakete kernel: INFO: task txg_sync:179210 blocked for more than 122 seconds.
Nov 02 13:50:17 rakete kernel:       Tainted: P        W  OE     5.9.2-arch1-1 #1
Nov 02 13:50:17 rakete kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Nov 02 13:50:17 rakete kernel: task:txg_sync        state:D stack:    0 pid:179210 ppid:     2 flags:0x00004080
Nov 02 13:50:17 rakete kernel: Call Trace:
Nov 02 13:50:17 rakete kernel:  __schedule+0x292/0x830
Nov 02 13:50:17 rakete kernel:  schedule+0x46/0xf0
Nov 02 13:50:17 rakete kernel:  schedule_timeout+0x99/0x170
Nov 02 13:50:17 rakete kernel:  ? __next_timer_interrupt+0x100/0x100
Nov 02 13:50:17 rakete kernel:  io_schedule_timeout+0x4b/0x80
Nov 02 13:50:17 rakete kernel:  __cv_timedwait_common+0x120/0x160 [spl]
Nov 02 13:50:17 rakete kernel:  ? wait_woken+0x80/0x80
Nov 02 13:50:17 rakete kernel:  zio_wait+0x136/0x280 [zfs]
Nov 02 13:50:17 rakete kernel:  dsl_pool_sync+0xd2/0x4d0 [zfs]
Nov 02 13:50:17 rakete kernel:  spa_sync+0x57d/0xf70 [zfs]
Nov 02 13:50:17 rakete kernel:  ? _raw_spin_unlock+0x16/0x30
Nov 02 13:50:17 rakete kernel:  ? spa_txg_history_init_io+0x112/0x120 [zfs]
Nov 02 13:50:17 rakete kernel:  txg_sync_thread+0x2d1/0x490 [zfs]
Nov 02 13:50:17 rakete kernel:  ? txg_register_callbacks+0xa0/0xa0 [zfs]
Nov 02 13:50:17 rakete kernel:  ? __thread_exit+0x20/0x20 [spl]
Nov 02 13:50:17 rakete kernel:  thread_generic_wrapper+0x6f/0x80 [spl]
Nov 02 13:50:17 rakete kernel:  kthread+0x142/0x160
Nov 02 13:50:17 rakete kernel:  ? __kthread_bind_mask+0x60/0x60
Nov 02 13:50:17 rakete kernel:  ret_from_fork+0x22/0x30

Nov 02 15:30:38 rakete kernel: INFO: task txg_sync:179210 blocked for more than 122 seconds.
Nov 02 15:30:38 rakete kernel:       Tainted: P        W  OE     5.9.2-arch1-1 #1
Nov 02 15:30:38 rakete kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Nov 02 15:30:38 rakete kernel: task:txg_sync        state:D stack:    0 pid:179210 ppid:     2 flags:0x00004080
Nov 02 15:30:38 rakete kernel: Call Trace:
Nov 02 15:30:38 rakete kernel:  __schedule+0x292/0x830
Nov 02 15:30:38 rakete kernel:  schedule+0x46/0xf0
Nov 02 15:30:38 rakete kernel:  schedule_timeout+0x99/0x170
Nov 02 15:30:38 rakete kernel:  ? __next_timer_interrupt+0x100/0x100
Nov 02 15:30:38 rakete kernel:  io_schedule_timeout+0x4b/0x80
Nov 02 15:30:38 rakete kernel:  __cv_timedwait_common+0x120/0x160 [spl]
Nov 02 15:30:38 rakete kernel:  ? wait_woken+0x80/0x80
Nov 02 15:30:38 rakete kernel:  zio_wait+0x136/0x280 [zfs]
Nov 02 15:30:38 rakete kernel:  dsl_pool_sync+0xd2/0x4d0 [zfs]
Nov 02 15:30:38 rakete kernel:  spa_sync+0x57d/0xf70 [zfs]
Nov 02 15:30:38 rakete kernel:  ? _raw_spin_unlock+0x16/0x30
Nov 02 15:30:38 rakete kernel:  ? spa_txg_history_init_io+0x112/0x120 [zfs]
Nov 02 15:30:38 rakete kernel:  txg_sync_thread+0x2d1/0x490 [zfs]
Nov 02 15:30:38 rakete kernel:  ? txg_register_callbacks+0xa0/0xa0 [zfs]
Nov 02 15:30:38 rakete kernel:  ? __thread_exit+0x20/0x20 [spl]
Nov 02 15:30:38 rakete kernel:  thread_generic_wrapper+0x6f/0x80 [spl]
Nov 02 15:30:38 rakete kernel:  kthread+0x142/0x160
Nov 02 15:30:38 rakete kernel:  ? __kthread_bind_mask+0x60/0x60
Nov 02 15:30:38 rakete kernel:  ret_from_fork+0x22/0x30

Nov 02 15:30:38 rakete kernel: INFO: task zfs:3851241 blocked for more than 122 seconds.
Nov 02 15:30:38 rakete kernel:       Tainted: P        W  OE     5.9.2-arch1-1 #1
Nov 02 15:30:38 rakete kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Nov 02 15:30:38 rakete kernel: task:zfs             state:D stack:    0 pid:3851241 ppid:3851237 flags:0x80004080
Nov 02 15:30:38 rakete kernel: Call Trace:
Nov 02 15:30:38 rakete kernel:  __schedule+0x292/0x830
Nov 02 15:30:38 rakete kernel:  schedule+0x46/0xf0
Nov 02 15:30:38 rakete kernel:  io_schedule+0x41/0x70
Nov 02 15:30:38 rakete kernel:  cv_wait_common+0xaa/0x130 [spl]
Nov 02 15:30:38 rakete kernel:  ? wait_woken+0x80/0x80
Nov 02 15:30:38 rakete kernel:  txg_wait_synced_impl+0xc7/0x110 [zfs]
Nov 02 15:30:38 rakete kernel:  txg_wait_synced+0xc/0x40 [zfs]
Nov 02 15:30:38 rakete kernel:  dsl_sync_task_common+0x1b4/0x290 [zfs]
Nov 02 15:30:38 rakete kernel:  ? dmu_recv_cleanup_ds+0x140/0x140 [zfs]
Nov 02 15:30:38 rakete kernel:  ? dmu_recv_end_sync+0x5b0/0x5b0 [zfs]
Nov 02 15:30:38 rakete kernel:  ? dmu_recv_end_sync+0x5b0/0x5b0 [zfs]
Nov 02 15:30:38 rakete kernel:  ? dmu_recv_cleanup_ds+0x140/0x140 [zfs]
Nov 02 15:30:38 rakete kernel:  dsl_sync_task+0x16/0x20 [zfs]
Nov 02 15:30:38 rakete kernel:  dmu_recv_existing_end+0x67/0x90 [zfs]
Nov 02 15:30:38 rakete kernel:  dmu_recv_end+0xd3/0x1e0 [zfs]
Nov 02 15:30:38 rakete kernel:  zfs_ioc_recv_impl+0x6ab/0xfc0 [zfs]
Nov 02 15:30:38 rakete kernel:  ? dbuf_read+0x8ff/0xb90 [zfs]
Nov 02 15:30:38 rakete kernel:  zfs_ioc_recv_new+0x351/0x3f0 [zfs]
Nov 02 15:30:38 rakete kernel:  zfsdev_ioctl+0x366/0x900 [zfs]
Nov 02 15:30:38 rakete kernel:  __x64_sys_ioctl+0x83/0xb0
Nov 02 15:30:38 rakete kernel:  do_syscall_64+0x33/0x40
Nov 02 15:30:38 rakete kernel:  entry_SYSCALL_64_after_hwframe+0x44/0xa9
Nov 02 15:30:38 rakete kernel: RIP: 0033:0x7fa730596f6b
Nov 02 15:30:38 rakete kernel: Code: Unable to access opcode bytes at RIP 0x7fa730596f41.
Nov 02 15:30:38 rakete kernel: RSP: 002b:00007fff62139cc8 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
Nov 02 15:30:38 rakete kernel: RAX: ffffffffffffffda RBX: 00007fff6213d330 RCX: 00007fa730596f6b
Nov 02 15:30:38 rakete kernel: RDX: 00007fff62139cf0 RSI: 0000000000005a46 RDI: 0000000000000005
Nov 02 15:30:38 rakete kernel: RBP: 00007fff6213d2d0 R08: 0000559c0c244eb0 R09: 00007fa730662a60
Nov 02 15:30:38 rakete kernel: R10: 0000000000000001 R11: 0000000000000246 R12: 0000000000005a46
Nov 02 15:30:38 rakete kernel: R13: 00007fff62139cf0 R14: 0000000000000005 R15: 0000000000005a46

Nov 02 15:30:38 rakete kernel: INFO: task zfs:4145151 blocked for more than 122 seconds.
Nov 02 15:30:38 rakete kernel:       Tainted: P        W  OE     5.9.2-arch1-1 #1
Nov 02 15:30:38 rakete kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Nov 02 15:30:38 rakete kernel: task:zfs             state:D stack:    0 pid:4145151 ppid:4145147 flags:0x80004080
Nov 02 15:30:38 rakete kernel: Call Trace:
Nov 02 15:30:38 rakete kernel:  __schedule+0x292/0x830
Nov 02 15:30:38 rakete kernel:  schedule+0x46/0xf0
Nov 02 15:30:38 rakete kernel:  io_schedule+0x41/0x70
Nov 02 15:30:38 rakete kernel:  cv_wait_common+0xaa/0x130 [spl]
Nov 02 15:30:38 rakete kernel:  ? wait_woken+0x80/0x80
Nov 02 15:30:38 rakete kernel:  txg_wait_synced_impl+0xc7/0x110 [zfs]
Nov 02 15:30:38 rakete kernel:  txg_wait_synced+0xc/0x40 [zfs]
Nov 02 15:30:38 rakete kernel:  dsl_sync_task_common+0x1b4/0x290 [zfs]
Nov 02 15:30:38 rakete kernel:  ? dmu_recv_cleanup_ds+0x140/0x140 [zfs]
Nov 02 15:30:38 rakete kernel:  ? dmu_recv_end_sync+0x5b0/0x5b0 [zfs]
Nov 02 15:30:38 rakete kernel:  ? dmu_recv_end_sync+0x5b0/0x5b0 [zfs]
Nov 02 15:30:38 rakete kernel:  ? dmu_recv_cleanup_ds+0x140/0x140 [zfs]
Nov 02 15:30:38 rakete kernel:  dsl_sync_task+0x16/0x20 [zfs]
Nov 02 15:30:38 rakete kernel:  dmu_recv_existing_end+0x67/0x90 [zfs]
Nov 02 15:30:38 rakete kernel:  dmu_recv_end+0xd3/0x1e0 [zfs]
Nov 02 15:30:38 rakete kernel:  zfs_ioc_recv_impl+0x6ab/0xfc0 [zfs]
Nov 02 15:30:38 rakete kernel:  ? dbuf_read+0x8ff/0xb90 [zfs]
Nov 02 15:30:38 rakete kernel:  zfs_ioc_recv_new+0x351/0x3f0 [zfs]
Nov 02 15:30:38 rakete kernel:  zfsdev_ioctl+0x366/0x900 [zfs]
Nov 02 15:30:38 rakete kernel:  __x64_sys_ioctl+0x83/0xb0
Nov 02 15:30:38 rakete kernel:  do_syscall_64+0x33/0x40
Nov 02 15:30:38 rakete kernel:  entry_SYSCALL_64_after_hwframe+0x44/0xa9
Nov 02 15:30:38 rakete kernel: RIP: 0033:0x7f29accdff6b
Nov 02 15:30:38 rakete kernel: Code: Unable to access opcode bytes at RIP 0x7f29accdff41.
Nov 02 15:30:38 rakete kernel: RSP: 002b:00007ffdd6b307a8 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
Nov 02 15:30:38 rakete kernel: RAX: ffffffffffffffda RBX: 00007ffdd6b33e10 RCX: 00007f29accdff6b
Nov 02 15:30:38 rakete kernel: RDX: 00007ffdd6b307d0 RSI: 0000000000005a46 RDI: 0000000000000005
Nov 02 15:30:38 rakete kernel: RBP: 00007ffdd6b33db0 R08: 00005586a12b1f00 R09: 00007f29acdaba60
Nov 02 15:30:38 rakete kernel: R10: 0000000000400000 R11: 0000000000000246 R12: 0000000000005a46
Nov 02 15:30:38 rakete kernel: R13: 00007ffdd6b307d0 R14: 0000000000000005 R15: 0000000000005a46

This might be related to issue #11003. I dont know.

And by the way, why is this always 122 seconds? blocked for more than 122 seconds

[mabod]

I now have more insight into this issue because it happened today again.

There have been no file operations at that time. The PC was idle. I was in a root terminal checking the .zfs subdirectory of one of my backup data sets: e.g. /data/BACKUP/rakete_root/.zfs/snapshot/2020-10-21

When I then moved to a different .zfs directory in a different data set, e.g /data/BACKUP/rakete_home/user/.zfs/ the system has frozen like I described. It started with this INFO block

Nov 10 15:48:36 rakete kernel: INFO: task spl_delay_taskq:387 blocked for more than 122 seconds.
Nov 10 15:48:36 rakete kernel:       Tainted: P           OE     5.9.6-arch1-1 #1
Nov 10 15:48:36 rakete kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Nov 10 15:48:36 rakete kernel: task:spl_delay_taskq state:D stack:    0 pid:  387 ppid:     2 flags:0x00004000
Nov 10 15:48:36 rakete kernel: Call Trace:
Nov 10 15:48:36 rakete kernel:  __schedule+0x292/0x830
Nov 10 15:48:36 rakete kernel:  schedule+0x46/0xf0
Nov 10 15:48:36 rakete kernel:  schedule_timeout+0x12d/0x170
Nov 10 15:48:36 rakete kernel:  wait_for_completion+0x9e/0x100
Nov 10 15:48:36 rakete kernel:  call_usermodehelper_exec+0x13d/0x170
Nov 10 15:48:36 rakete kernel:  zfsctl_snapshot_unmount+0x110/0x1f0 [zfs]
Nov 10 15:48:36 rakete kernel:  snapentry_expire+0x38/0xd0 [zfs]
Nov 10 15:48:36 rakete kernel:  taskq_thread+0x28e/0x4b0 [spl]
Nov 10 15:48:36 rakete kernel:  ? wake_up_q+0xa0/0xa0
Nov 10 15:48:36 rakete kernel:  ? taskq_thread_spawn+0x50/0x50 [spl]
Nov 10 15:48:36 rakete kernel:  kthread+0x142/0x160
Nov 10 15:48:36 rakete kernel:  ? __kthread_bind_mask+0x60/0x60
Nov 10 15:48:36 rakete kernel:  ret_from_fork+0x22/0x30

filesystem related commands like df, du, did not work anymore. zpool status was printing a status but did not return. Anything related to the zfs filesystem did not work anymore.

And in the process list I found several umount commands for the first .zfs directory I visited:

UID          PID    PPID  C STIME TTY          TIME CMD
root      225792  225758  0 15:44 ?        00:00:00 umount -t zfs -n /data/BACKUP/rakete_root/.zfs/snapshot/2020-11-03--08:25
root      225793  224553  0 15:44 ?        00:00:00 umount -t zfs -n /data/BACKUP/rakete_root/.zfs/snapshot/2020-11-09--07:37-zf1
root      225794  225762  0 15:44 ?        00:00:00 umount -t zfs -n /data/BACKUP/rakete_root/.zfs/snapshot/2020-06-30--15:42
root      225795  225766  0 15:44 ?        00:00:00 umount -t zfs -n /data/BACKUP/rakete_root/.zfs/snapshot/2020-06-17--15:31
root      225796  196624  0 15:44 ?        00:00:00 umount -t zfs -n /data/BACKUP/rakete_root/.zfs/snapshot/2020-09-06--08:52
root      225797  225777  0 15:44 ?        00:00:00 umount -t zfs -n /data/BACKUP/rakete_root/.zfs/snapshot/2020-10-05--08:26
root      225798  225775  0 15:44 ?        00:00:00 umount -t zfs -n /data/BACKUP/rakete_root/.zfs/snapshot/2020-11-02--10:01-zf1
root      225799  225770  0 15:44 ?        00:00:00 umount -t zfs -n /data/BACKUP/rakete_root/.zfs/snapshot/2020-10-29--18:04
root      225800  225779  0 15:44 ?        00:00:00 umount -t zfs -n /data/BACKUP/rakete_root/.zfs/snapshot/2020-10-29--18:09-zf1
root      225801  225785  0 15:44 ?        00:00:00 umount -t zfs -n /data/BACKUP/rakete_root/.zfs/snapshot/2020-08-20--13:03
root      225802  225782  0 15:44 ?        00:00:00 umount -t zfs -n /data/BACKUP/rakete_root/.zfs/snapshot/2020-09-06--09:01-zf1
root      225805  225791  0 15:44 ?        00:00:00 umount -t zfs -n /data/BACKUP/rakete_root/.zfs/snapshot/2020-09-30--17:35-zf1

And this is where the PC sits forever. I waited more than one hour and nothing happend. I had to do the REISUB trick again. And, again, the final boot from REISUB did not excecut. I had to press the reset button.

[mabod]

This seems to be reproducible for me. I reproduced it today. Just by doing cd / ls activities in two different .zfs directories. After just a few commands it hangs with all the signs I have posted before incl. multiple umount processes.

[mabod]

I reproduced the hang also with zfs 2.0.0-rc6.

It is obvious when it happens. Can somebody else try to reproduce?

1. pick one or two datasets with lots of snapshots
2. cd to the directories <dataset>/.zfs/snapshot, ls, cd to a snapshot, cd+ls, back and forth a couple of times
3. check how many .zfs directories have been mounted. E.g. "mount | grep .zfs/snapshot". In my case it was 300.
4. move out of any .zfs directory and let the system sit idle for a while. zfs will start unmounting the .zfs directories. You can see that with ps -ef when lots of "umount -t zfs" processes pop up. This is where it starts to hang. The umount processes will never finish and zfs ist dysfunctional at that point.

[behlendorf]

@mabod would you mind verifying that PR #11201 resolves this issue.

[mabod]

I tested it with 2.0.0-rc6 and it works!
No hangs after I had 250+ .zfs/snapshot directories mounted. After a while the .zfs/snapshot directories are all unmounted without any issue.

Interesting is that this does not seem to involve umount -t zfs processes anymore. I did not see anything in the process list. Instead I see systemd activities for each of the 250+ umounts:

[...]
systemd[1]: data-BACKUP-rakete_home-home-.zfs-snapshot-2020\x2d09\x2d28\x2d\x2d15:26.mount: Succeeded.
systemd[1]: data-BACKUP-rakete_home-home-.zfs-snapshot-2020\x2d11\x2d12\x2d\x2d13:37.mount: Succeeded.
systemd[1]: data-BACKUP-rakete_home-home-.zfs-snapshot-2020\x2d10\x2d12\x2d\x2d07:11.mount: Succeeded.
systemd[1]: data-BACKUP-rakete_home-home-.zfs-snapshot-2020\x2d10\x2d17\x2d\x2d11:25.mount: Succeeded.
systemd[1]: data-BACKUP-rakete_home-home-.zfs-snapshot-2020\x2d09\x2d04\x2d\x2d17:13.mount: Succeeded.
systemd[1]: data-BACKUP-rakete_home-home-.zfs-snapshot-2020\x2d10\x2d05\x2d\x2d08:43.mount: Succeeded.
[...]