Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

PANIC in zio_data_buf_alloc locked up the file system irrecoverably #11531

Closed
ericonr opened this issue Jan 27, 2021 · 28 comments
Closed

PANIC in zio_data_buf_alloc locked up the file system irrecoverably #11531

ericonr opened this issue Jan 27, 2021 · 28 comments
Labels
Status: Triage Needed New issue which needs to be triaged Type: Defect Incorrect behavior (e.g. crash, hang)

Comments

@ericonr
Copy link
Contributor

ericonr commented Jan 27, 2021

System information

Type Version/Name
Distribution Name Void Linux
Distribution Version rolling
Linux Kernel 5.10.9
Architecture x86_64
ZFS Version ZFS: Loaded module v2.0.1-1
SPL Version ZFS: Loaded module v2.0.1-1

Describe the problem you're observing

In normal usage (watching a movie, browser and other applications in the background, including torrent client potentially reading from the same file) on a simple layout (single zpool, zpool with a single NVME drive), I got a panic in the ZFS kernel module (shown below).

Looks a bit like #2932, and for what it's worth I also have xattrs=sa and acltype=posixacl.

It seems to have mostly locked up the device, since after this I got multiple timeout warnings in dmesg (also shown below).

With my normal shell (fish) I was unable to even launch commands (it failed to lock its history file, for example), since it relies on filesystem access quite a bit, and apparently some specific accesses were failing. I eventually launched dash, but it got to a point where ls in a directory backed by ZFS, such as ~/ and / hung (though I could still interrupt it with Ctrl-C). Calling sync also hung. The interface for some applications simply locked up (thunderbird and qutebrowser), and others that were working still couldn't actually be quit.

As a last ditch, I tried SysRq. After sysrq S and U (sync and remount ro), I tried E and finally I (SIGTERM and SIGKILL all processes). Since I use runit, SIGTERM'ing all processes already tried to shutdown the system, but that simply hung completely. I had to resort to SysRq B (unconditional reboot) for the system to close up.

The dmesg was dumped into my EFI partition, which could be accessed without any issues at all.

Describe how to reproduce the problem

I don't know for sure what caused it. qbittorrent might have been accessing a file that mpv was accessing as well.

Include any warning/errors/backtraces from the system logs

Panic

[132515.566980] VERIFY3(c < SPA_MAXBLOCKSIZE >> SPA_MINBLOCKSHIFT) failed (36028797018963967 < 32768)
[132515.566988] PANIC at zio.c:314:zio_data_buf_alloc()
[132515.566990] Showing stack for process 10663
[132515.566993] CPU: 8 PID: 10663 Comm: qbittorrent Tainted: P S   U  W  O      5.10.9_1 #1
[132515.566995] Hardware name: Dell Inc. XPS 15 9570/0D0T05, BIOS 1.15.0 12/25/2019
[132515.566995] Call Trace:
[132515.567007]  dump_stack+0x6b/0x83
[132515.567014]  spl_panic+0xd4/0xfc [spl]
[132515.567020]  ? spl_kmem_cache_alloc+0x74/0x7e0 [spl]
[132515.567026]  ? kmem_cache_alloc+0xed/0x1f0
[132515.567031]  ? spl_kmem_cache_alloc+0x97/0x7e0 [spl]
[132515.567100]  ? aggsum_add+0x153/0x170 [zfs]
[132515.567106]  ? mutex_lock+0xe/0x30
[132515.567148]  ? aggsum_add+0x153/0x170 [zfs]
[132515.567203]  zio_data_buf_alloc+0x55/0x60 [zfs]
[132515.567249]  abd_alloc_linear+0x8a/0xc0 [zfs]
[132515.567295]  arc_hdr_alloc_abd+0xdf/0x1e0 [zfs]
[132515.567340]  arc_hdr_alloc+0x104/0x170 [zfs]
[132515.567387]  arc_alloc_buf+0x46/0x150 [zfs]
[132515.567434]  dbuf_hold_copy.constprop.0+0x31/0xa0 [zfs]
[132515.567480]  dbuf_hold_impl+0x476/0x650 [zfs]
[132515.567525]  dbuf_hold_level+0x2b/0x60 [zfs]
[132515.567568]  dmu_tx_check_ioerr+0x35/0xd0 [zfs]
[132515.567593]  dmu_tx_count_write+0xe5/0x1a0 [zfs]
[132515.567617]  dmu_tx_hold_write_by_dnode+0x35/0x50 [zfs]
[132515.567657]  zfs_write+0x3ed/0xc60 [zfs]
[132515.567661]  ? reweight_entity+0x11e/0x130
[132515.567664]  ? ttwu_do_wakeup.constprop.0+0x12/0xd0
[132515.567684]  zpl_iter_write+0x109/0x190 [zfs]
[132515.567687]  do_iter_readv_writev+0x152/0x1b0
[132515.567690]  do_iter_write+0x7c/0x1b0
[132515.567691]  vfs_writev+0xa4/0x140
[132515.567694]  ? nvme_process_cq+0x159/0x1f0
[132515.567696]  ? __x64_sys_futex+0x13d/0x1c0
[132515.567698]  __x64_sys_pwritev+0xad/0xf0
[132515.567701]  do_syscall_64+0x33/0x40
[132515.567702]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[132515.567705] RIP: 0033:0x7ff818be5d53
[132515.567707] Code: c3 8b 07 85 c0 75 24 49 89 fb 48 89 f0 48 89 d7 48 89 ce 4c 89 c2 4d 89 ca 4c 8b 44 24 08 4c 8b 4c 24 10 4c 89 5c 24 08 0f 05 <c3> e9 07 10 ff ff 48 31 ed 48 89 e7 48 8d 35 5a 80 03 00 48 83 e4
[132515.567708] RSP: 002b:00007ff7e32ed5a8 EFLAGS: 00000246 ORIG_RAX: 0000000000000128
[132515.567710] RAX: ffffffffffffffda RBX: 00007ff7e32efb20 RCX: 00007ff818be5d53
[132515.567711] RDX: 0000000000000010 RSI: 00007ff7e32ed610 RDI: 000000000000003a
[132515.567712] RBP: 00007ff7e32ed5e0 R08: 0000000000000000 R09: 0000000000000000
[132515.567713] R10: 00000000e67ab093 R11: 0000000000000246 R12: 0000000000000128
[132515.567713] R13: 000000000000003a R14: 00007ff7e32ed610 R15: 0000000000000000

Timeouts

[132683.240777] INFO: task z_wr_int:524 blocked for more than 122 seconds.
[132683.240786]       Tainted: P S   U  W  O      5.10.9_1 #1
[132683.240788] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[132683.240791] task:z_wr_int        state:D stack:    0 pid:  524 ppid:     2 flags:0x00004000
[132683.240796] Call Trace:
[132683.240807]  __schedule+0x249/0x770
[132683.240812]  schedule+0x46/0xb0
[132683.240817]  schedule_preempt_disabled+0xa/0x10
[132683.240821]  __mutex_lock.constprop.0+0x236/0x470
[132683.240888]  ? dsl_dataset_block_born+0x23f/0x380 [zfs]
[132683.240937]  dbuf_write_done+0x3c/0x200 [zfs]
[132683.240983]  arc_write_done+0x8f/0x420 [zfs]
[132683.241043]  zio_done+0x403/0x1120 [zfs]
[132683.241104]  zio_execute+0x81/0x120 [zfs]
[132683.241112]  taskq_thread+0x2da/0x520 [spl]
[132683.241119]  ? wake_up_q+0xa0/0xa0
[132683.241178]  ? zio_vdev_io_done+0x1f0/0x1f0 [zfs]
[132683.241184]  ? taskq_thread_spawn+0x50/0x50 [spl]
[132683.241190]  kthread+0x11b/0x140
[132683.241195]  ? __kthread_bind_mask+0x60/0x60
[132683.241200]  ret_from_fork+0x22/0x30
[132683.241213] INFO: task txg_sync:623 blocked for more than 122 seconds.
[132683.241217]       Tainted: P S   U  W  O      5.10.9_1 #1
[132683.241218] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[132683.241221] task:txg_sync        state:D stack:    0 pid:  623 ppid:     2 flags:0x00004000
[132683.241224] Call Trace:
[132683.241229]  __schedule+0x249/0x770
[132683.241233]  schedule+0x46/0xb0
[132683.241238]  schedule_timeout+0x8b/0x140
[132683.241243]  ? __next_timer_interrupt+0x100/0x100
[132683.241247]  io_schedule_timeout+0x4c/0x80
[132683.241252]  __cv_timedwait_common+0x11e/0x160 [spl]
[132683.241256]  ? add_wait_queue_exclusive+0x70/0x70
[132683.241262]  __cv_timedwait_io+0x15/0x20 [spl]
[132683.241321]  zio_wait+0x129/0x2b0 [zfs]
[132683.241387]  dsl_pool_sync+0xfe/0x4e0 [zfs]
[132683.241457]  spa_sync+0x56e/0xf90 [zfs]
[132683.241464]  ? mutex_lock+0xe/0x30
[132683.241543]  ? spa_txg_history_init_io+0x101/0x110 [zfs]
[132683.241630]  txg_sync_thread+0x2d4/0x4a0 [zfs]
[132683.241704]  ? txg_fini+0x250/0x250 [zfs]
[132683.241714]  thread_generic_wrapper+0x6f/0x80 [spl]
[132683.241724]  ? __thread_exit+0x20/0x20 [spl]
[132683.241734]  kthread+0x11b/0x140
[132683.241742]  ? __kthread_bind_mask+0x60/0x60
[132683.241749]  ret_from_fork+0x22/0x30
[132683.241759] INFO: task vdev_autotrim:641 blocked for more than 122 seconds.
[132683.241767]       Tainted: P S   U  W  O      5.10.9_1 #1
[132683.241775] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[132683.241783] task:vdev_autotrim   state:D stack:    0 pid:  641 ppid:     2 flags:0x00004000
[132683.241793] Call Trace:
[132683.241802]  __schedule+0x249/0x770
[132683.241810]  ? __wake_up_common_lock+0x8a/0xc0
[132683.241817]  schedule+0x46/0xb0
[132683.241825]  io_schedule+0x42/0x70
[132683.241834]  cv_wait_common+0xa1/0x120 [spl]
[132683.241837]  ? add_wait_queue_exclusive+0x70/0x70
[132683.241906]  txg_wait_synced_impl+0xc3/0x100 [zfs]
[132683.241975]  txg_wait_synced+0xc/0x40 [zfs]
[132683.242047]  metaslab_enable+0xbd/0x100 [zfs]
[132683.242133]  vdev_autotrim_thread+0x553/0x790 [zfs]
[132683.242199]  ? vdev_trim_l2arc_thread+0x350/0x350 [zfs]
[132683.242211]  thread_generic_wrapper+0x6f/0x80 [spl]
[132683.242221]  ? __thread_exit+0x20/0x20 [spl]
[132683.242230]  kthread+0x11b/0x140
[132683.242237]  ? __kthread_bind_mask+0x60/0x60
[132683.242241]  ret_from_fork+0x22/0x30
[132683.242367] INFO: task qbittorrent:10663 blocked for more than 122 seconds.
[132683.242370]       Tainted: P S   U  W  O      5.10.9_1 #1
[132683.242372] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[132683.242375] task:qbittorrent     state:D stack:    0 pid:10663 ppid:     1 flags:0x00000000
[132683.242378] Call Trace:
[132683.242383]  __schedule+0x249/0x770
[132683.242389]  schedule+0x46/0xb0
[132683.242394]  spl_panic+0xfa/0xfc [spl]
[132683.242402]  ? spl_kmem_cache_alloc+0x74/0x7e0 [spl]
[132683.242407]  ? kmem_cache_alloc+0xed/0x1f0
[132683.242415]  ? spl_kmem_cache_alloc+0x97/0x7e0 [spl]
[132683.242492]  ? aggsum_add+0x153/0x170 [zfs]
[132683.242513]  ? mutex_lock+0xe/0x30
[132683.242558]  ? aggsum_add+0x153/0x170 [zfs]
[132683.242621]  zio_data_buf_alloc+0x55/0x60 [zfs]
[132683.242669]  abd_alloc_linear+0x8a/0xc0 [zfs]
[132683.242717]  arc_hdr_alloc_abd+0xdf/0x1e0 [zfs]
[132683.242765]  arc_hdr_alloc+0x104/0x170 [zfs]
[132683.242813]  arc_alloc_buf+0x46/0x150 [zfs]
[132683.242864]  dbuf_hold_copy.constprop.0+0x31/0xa0 [zfs]
[132683.242915]  dbuf_hold_impl+0x476/0x650 [zfs]
[132683.242963]  dbuf_hold_level+0x2b/0x60 [zfs]
[132683.243017]  dmu_tx_check_ioerr+0x35/0xd0 [zfs]
[132683.243072]  dmu_tx_count_write+0xe5/0x1a0 [zfs]
[132683.243132]  dmu_tx_hold_write_by_dnode+0x35/0x50 [zfs]
[132683.243193]  zfs_write+0x3ed/0xc60 [zfs]
[132683.243200]  ? reweight_entity+0x11e/0x130
[132683.243205]  ? ttwu_do_wakeup.constprop.0+0x12/0xd0
[132683.243250]  zpl_iter_write+0x109/0x190 [zfs]
[132683.243257]  do_iter_readv_writev+0x152/0x1b0
[132683.243261]  do_iter_write+0x7c/0x1b0
[132683.243266]  vfs_writev+0xa4/0x140
[132683.243271]  ? nvme_process_cq+0x159/0x1f0
[132683.243276]  ? __x64_sys_futex+0x13d/0x1c0
[132683.243280]  __x64_sys_pwritev+0xad/0xf0
[132683.243285]  do_syscall_64+0x33/0x40
[132683.243288]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[132683.243293] RIP: 0033:0x7ff818be5d53
[132683.243295] RSP: 002b:00007ff7e32ed5a8 EFLAGS: 00000246 ORIG_RAX: 0000000000000128
[132683.243299] RAX: ffffffffffffffda RBX: 00007ff7e32efb20 RCX: 00007ff818be5d53
[132683.243301] RDX: 0000000000000010 RSI: 00007ff7e32ed610 RDI: 000000000000003a
[132683.243303] RBP: 00007ff7e32ed5e0 R08: 0000000000000000 R09: 0000000000000000
[132683.243305] R10: 00000000e67ab093 R11: 0000000000000246 R12: 0000000000000128
[132683.243307] R13: 000000000000003a R14: 00007ff7e32ed610 R15: 0000000000000000
[132806.120104] INFO: task z_wr_int:524 blocked for more than 245 seconds.
[132806.120109]       Tainted: P S   U  W  O      5.10.9_1 #1
[132806.120111] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[132806.120113] task:z_wr_int        state:D stack:    0 pid:  524 ppid:     2 flags:0x00004000
[132806.120118] Call Trace:
[132806.120126]  __schedule+0x249/0x770
[132806.120131]  schedule+0x46/0xb0
[132806.120134]  schedule_preempt_disabled+0xa/0x10
[132806.120137]  __mutex_lock.constprop.0+0x236/0x470
[132806.120202]  ? dsl_dataset_block_born+0x23f/0x380 [zfs]
[132806.120256]  dbuf_write_done+0x3c/0x200 [zfs]
[132806.120314]  arc_write_done+0x8f/0x420 [zfs]
[132806.120373]  zio_done+0x403/0x1120 [zfs]
[132806.120444]  zio_execute+0x81/0x120 [zfs]
[132806.120452]  taskq_thread+0x2da/0x520 [spl]
[132806.120458]  ? wake_up_q+0xa0/0xa0
[132806.120523]  ? zio_vdev_io_done+0x1f0/0x1f0 [zfs]
[132806.120529]  ? taskq_thread_spawn+0x50/0x50 [spl]
[132806.120533]  kthread+0x11b/0x140
[132806.120536]  ? __kthread_bind_mask+0x60/0x60
[132806.120539]  ret_from_fork+0x22/0x30
[132806.120549] INFO: task txg_sync:623 blocked for more than 245 seconds.
[132806.120551]       Tainted: P S   U  W  O      5.10.9_1 #1
[132806.120553] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[132806.120554] task:txg_sync        state:D stack:    0 pid:  623 ppid:     2 flags:0x00004000
[132806.120557] Call Trace:
[132806.120561]  __schedule+0x249/0x770
[132806.120563]  schedule+0x46/0xb0
[132806.120567]  schedule_timeout+0x8b/0x140
[132806.120570]  ? __next_timer_interrupt+0x100/0x100
[132806.120572]  io_schedule_timeout+0x4c/0x80
[132806.120576]  __cv_timedwait_common+0x11e/0x160 [spl]
[132806.120579]  ? add_wait_queue_exclusive+0x70/0x70
[132806.120582]  __cv_timedwait_io+0x15/0x20 [spl]
[132806.120619]  zio_wait+0x129/0x2b0 [zfs]
[132806.120662]  dsl_pool_sync+0xfe/0x4e0 [zfs]
[132806.120726]  spa_sync+0x56e/0xf90 [zfs]
[132806.120731]  ? mutex_lock+0xe/0x30
[132806.120796]  ? spa_txg_history_init_io+0x101/0x110 [zfs]
[132806.120862]  txg_sync_thread+0x2d4/0x4a0 [zfs]
[132806.120923]  ? txg_fini+0x250/0x250 [zfs]
[132806.120928]  thread_generic_wrapper+0x6f/0x80 [spl]
[132806.120932]  ? __thread_exit+0x20/0x20 [spl]
[132806.120936]  kthread+0x11b/0x140
[132806.120939]  ? __kthread_bind_mask+0x60/0x60
[132806.120941]  ret_from_fork+0x22/0x30
[132806.120945] INFO: task vdev_autotrim:641 blocked for more than 245 seconds.
[132806.120948]       Tainted: P S   U  W  O      5.10.9_1 #1
[132806.120949] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[132806.120950] task:vdev_autotrim   state:D stack:    0 pid:  641 ppid:     2 flags:0x00004000
[132806.120953] Call Trace:
[132806.120956]  __schedule+0x249/0x770
[132806.120958]  ? __wake_up_common_lock+0x8a/0xc0
[132806.120961]  schedule+0x46/0xb0
[132806.120963]  io_schedule+0x42/0x70
[132806.120966]  cv_wait_common+0xa1/0x120 [spl]
[132806.120969]  ? add_wait_queue_exclusive+0x70/0x70
[132806.121015]  txg_wait_synced_impl+0xc3/0x100 [zfs]
[132806.121071]  txg_wait_synced+0xc/0x40 [zfs]
[132806.121135]  metaslab_enable+0xbd/0x100 [zfs]
[132806.121204]  vdev_autotrim_thread+0x553/0x790 [zfs]
[132806.121264]  ? vdev_trim_l2arc_thread+0x350/0x350 [zfs]
[132806.121272]  thread_generic_wrapper+0x6f/0x80 [spl]
[132806.121279]  ? __thread_exit+0x20/0x20 [spl]
[132806.121286]  kthread+0x11b/0x140
[132806.121292]  ? __kthread_bind_mask+0x60/0x60
[132806.121297]  ret_from_fork+0x22/0x30
[132806.121398] INFO: task qbittorrent:10663 blocked for more than 245 seconds.
[132806.121400]       Tainted: P S   U  W  O      5.10.9_1 #1
[132806.121402] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[132806.121404] task:qbittorrent     state:D stack:    0 pid:10663 ppid:     1 flags:0x00000000
[132806.121406] Call Trace:
[132806.121410]  __schedule+0x249/0x770
[132806.121413]  schedule+0x46/0xb0
[132806.121417]  spl_panic+0xfa/0xfc [spl]
[132806.121423]  ? spl_kmem_cache_alloc+0x74/0x7e0 [spl]
[132806.121426]  ? kmem_cache_alloc+0xed/0x1f0
[132806.121430]  ? spl_kmem_cache_alloc+0x97/0x7e0 [spl]
[132806.121459]  ? aggsum_add+0x153/0x170 [zfs]
[132806.121462]  ? mutex_lock+0xe/0x30
[132806.121508]  ? aggsum_add+0x153/0x170 [zfs]
[132806.121568]  zio_data_buf_alloc+0x55/0x60 [zfs]
[132806.121617]  abd_alloc_linear+0x8a/0xc0 [zfs]
[132806.121671]  arc_hdr_alloc_abd+0xdf/0x1e0 [zfs]
[132806.121720]  arc_hdr_alloc+0x104/0x170 [zfs]
[132806.121752]  arc_alloc_buf+0x46/0x150 [zfs]
[132806.121785]  dbuf_hold_copy.constprop.0+0x31/0xa0 [zfs]
[132806.121818]  dbuf_hold_impl+0x476/0x650 [zfs]
[132806.121851]  dbuf_hold_level+0x2b/0x60 [zfs]
[132806.121907]  dmu_tx_check_ioerr+0x35/0xd0 [zfs]
[132806.121961]  dmu_tx_count_write+0xe5/0x1a0 [zfs]
[132806.122000]  dmu_tx_hold_write_by_dnode+0x35/0x50 [zfs]
[132806.122057]  zfs_write+0x3ed/0xc60 [zfs]
[132806.122075]  ? reweight_entity+0x11e/0x130
[132806.122080]  ? ttwu_do_wakeup.constprop.0+0x12/0xd0
[132806.122114]  zpl_iter_write+0x109/0x190 [zfs]
[132806.122124]  do_iter_readv_writev+0x152/0x1b0
[132806.122130]  do_iter_write+0x7c/0x1b0
[132806.122135]  vfs_writev+0xa4/0x140
[132806.122139]  ? nvme_process_cq+0x159/0x1f0
[132806.122142]  ? __x64_sys_futex+0x13d/0x1c0
[132806.122144]  __x64_sys_pwritev+0xad/0xf0
[132806.122148]  do_syscall_64+0x33/0x40
[132806.122150]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[132806.122153] RIP: 0033:0x7ff818be5d53
[132806.122155] RSP: 002b:00007ff7e32ed5a8 EFLAGS: 00000246 ORIG_RAX: 0000000000000128
[132806.122163] RAX: ffffffffffffffda RBX: 00007ff7e32efb20 RCX: 00007ff818be5d53
[132806.122168] RDX: 0000000000000010 RSI: 00007ff7e32ed610 RDI: 000000000000003a
[132806.122170] RBP: 00007ff7e32ed5e0 R08: 0000000000000000 R09: 0000000000000000
[132806.122172] R10: 00000000e67ab093 R11: 0000000000000246 R12: 0000000000000128
[132806.122173] R13: 000000000000003a R14: 00007ff7e32ed610 R15: 0000000000000000
[132928.999727] INFO: task z_wr_int:524 blocked for more than 368 seconds.
[132928.999735]       Tainted: P S   U  W  O      5.10.9_1 #1
[132928.999738] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[132928.999741] task:z_wr_int        state:D stack:    0 pid:  524 ppid:     2 flags:0x00004000
[132928.999748] Call Trace:
[132928.999760]  __schedule+0x249/0x770
[132928.999767]  schedule+0x46/0xb0
[132928.999772]  schedule_preempt_disabled+0xa/0x10
[132928.999777]  __mutex_lock.constprop.0+0x236/0x470
[132928.999858]  ? dsl_dataset_block_born+0x23f/0x380 [zfs]
[132928.999917]  dbuf_write_done+0x3c/0x200 [zfs]
[132928.999973]  arc_write_done+0x8f/0x420 [zfs]
[132929.000047]  zio_done+0x403/0x1120 [zfs]
[132929.000121]  zio_execute+0x81/0x120 [zfs]
[132929.000130]  taskq_thread+0x2da/0x520 [spl]
[132929.000138]  ? wake_up_q+0xa0/0xa0
[132929.000211]  ? zio_vdev_io_done+0x1f0/0x1f0 [zfs]
[132929.000219]  ? taskq_thread_spawn+0x50/0x50 [spl]
[132929.000225]  kthread+0x11b/0x140
[132929.000231]  ? __kthread_bind_mask+0x60/0x60
[132929.000237]  ret_from_fork+0x22/0x30
[132929.000253] INFO: task vdev_autotrim:641 blocked for more than 368 seconds.
[132929.000257]       Tainted: P S   U  W  O      5.10.9_1 #1
[132929.000260] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[132929.000263] task:vdev_autotrim   state:D stack:    0 pid:  641 ppid:     2 flags:0x00004000
[132929.000267] Call Trace:
[132929.000275]  __schedule+0x249/0x770
[132929.000281]  ? __wake_up_common_lock+0x8a/0xc0
[132929.000286]  schedule+0x46/0xb0
[132929.000292]  io_schedule+0x42/0x70
[132929.000301]  cv_wait_common+0xa1/0x120 [spl]
[132929.000306]  ? add_wait_queue_exclusive+0x70/0x70
[132929.000423]  txg_wait_synced_impl+0xc3/0x100 [zfs]
[132929.000510]  txg_wait_synced+0xc/0x40 [zfs]
[132929.000623]  metaslab_enable+0xbd/0x100 [zfs]
[132929.000734]  vdev_autotrim_thread+0x553/0x790 [zfs]
[132929.000837]  ? vdev_trim_l2arc_thread+0x350/0x350 [zfs]
[132929.000856]  thread_generic_wrapper+0x6f/0x80 [spl]
[132929.000868]  ? __thread_exit+0x20/0x20 [spl]
[132929.000880]  kthread+0x11b/0x140
[132929.000890]  ? __kthread_bind_mask+0x60/0x60
[132929.000899]  ret_from_fork+0x22/0x30
@ericonr ericonr added Status: Triage Needed New issue which needs to be triaged Type: Defect Incorrect behavior (e.g. crash, hang) labels Jan 27, 2021
@aerusso
Copy link
Contributor

aerusso commented Feb 7, 2021

@ericonr Thanks for reporting this. Has this happened more than once?

@ericonr
Copy link
Contributor Author

ericonr commented Feb 7, 2021

Fortunately for me, and unfortunately for the bug report, no.

I have tried forcing similar circumstances, but no such bug was triggered again.

@phreaker0
Copy link

Got the same panic with zfs 2.0.3 (zfs-kmod-2.0.3-1~bpo10+1 from debian buster backports). The system has 3 pools (2 on mirrored NVME drives and one on ordinary HDD's with special class mirror device on SATA SSD's). Pools were scrubbed 2 days before (there were checksum errors on both NVME mirror devices which were fixed successfully). I needed to reboot the system after the panic and scrubbed all pools again without errors. The system has ECC memory and 2 of the pools are encrypted:

Mar 16 15:15:32 sam kernel: VERIFY3(c < SPA_MAXBLOCKSIZE >> SPA_MINBLOCKSHIFT) failed (36028797018963967 < 32768)
Mar 16 15:15:32 sam kernel: PANIC at zio.c:314:zio_data_buf_alloc()
Mar 16 15:15:32 sam kernel: Showing stack for process 20206
Mar 16 15:15:32 sam kernel: CPU: 25 PID: 20206 Comm: php-fpm7.3 Tainted: P           OE     4.19.0-14-amd64 #1 Debian 4.19.171-2
Mar 16 15:15:32 sam kernel: Hardware name: To Be Filled By O.E.M. To Be Filled By O.E.M./X470D4U2-2T, BIOS P3.30 10/03/2019
Mar 16 15:15:32 sam kernel: Call Trace:
Mar 16 15:15:32 sam kernel:  dump_stack+0x66/0x81
Mar 16 15:15:32 sam kernel:  spl_panic+0xd3/0xfb [spl]
Mar 16 15:15:32 sam kernel:  ? sg_init_table+0x11/0x30
Mar 16 15:15:32 sam kernel:  ? __sg_alloc_table+0x72/0x150
Mar 16 15:15:32 sam kernel:  ? _cond_resched+0x15/0x30
Mar 16 15:15:32 sam kernel:  ? kmem_cache_alloc+0x167/0x1d0
Mar 16 15:15:32 sam kernel:  ? spl_kmem_cache_alloc+0x152/0x7a0 [spl]
Mar 16 15:15:32 sam kernel:  ? _cond_resched+0x15/0x30
Mar 16 15:15:32 sam kernel:  ? mutex_lock+0xe/0x30
Mar 16 15:15:32 sam kernel:  zio_data_buf_alloc+0x52/0x60 [zfs]
Mar 16 15:15:32 sam kernel:  abd_alloc_linear+0x7f/0xc0 [zfs]
Mar 16 15:15:32 sam kernel:  arc_hdr_alloc_abd+0x56/0xb0 [zfs]
Mar 16 15:15:32 sam kernel:  arc_hdr_alloc+0xed/0x160 [zfs]
Mar 16 15:15:32 sam kernel:  arc_alloc_buf+0x45/0xd0 [zfs]
Mar 16 15:15:32 sam kernel:  dbuf_alloc_arcbuf_from_arcbuf+0xf7/0x190 [zfs]
Mar 16 15:15:32 sam kernel:  ? _cond_resched+0x15/0x30
Mar 16 15:15:32 sam kernel:  ? mutex_lock+0xe/0x30
Mar 16 15:15:32 sam kernel:  dbuf_hold_copy.isra.19+0x31/0xa0 [zfs]
Mar 16 15:15:32 sam kernel:  dbuf_hold_impl+0x43e/0x600 [zfs]
Mar 16 15:15:32 sam kernel:  dbuf_hold_level+0x2b/0x60 [zfs]
Mar 16 15:15:32 sam kernel:  dmu_tx_check_ioerr+0x32/0xc0 [zfs]
Mar 16 15:15:32 sam kernel:  dmu_tx_count_write+0xe5/0x1a0 [zfs]
Mar 16 15:15:32 sam kernel:  dmu_tx_hold_write_by_dnode+0x35/0x50 [zfs]
Mar 16 15:15:32 sam kernel:  zfs_write+0x3e6/0xc50 [zfs]
Mar 16 15:15:32 sam kernel:  ? generic_update_time+0xb6/0xd0
Mar 16 15:15:32 sam kernel:  zpl_iter_write+0x102/0x190 [zfs]
Mar 16 15:15:32 sam kernel:  new_sync_write+0xfb/0x160
Mar 16 15:15:32 sam kernel:  vfs_write+0xa5/0x1a0
Mar 16 15:15:32 sam kernel:  ksys_write+0x57/0xd0
Mar 16 15:15:32 sam kernel:  do_syscall_64+0x53/0x110
Mar 16 15:15:32 sam kernel:  entry_SYSCALL_64_after_hwframe+0x44/0xa9
Mar 16 15:15:32 sam kernel: RIP: 0033:0x7fcbb4b2f504
Mar 16 15:15:32 sam kernel: Code: 00 f7 d8 64 89 02 48 c7 c0 ff ff ff ff eb b3 0f 1f 80 00 00 00 00 48 8d 05 f9 61 0d 00 8b 00 85 c0 75 13 b8 01 00 00 00 0f 05 <48> 3d 00 f0 ff ff 77 54 c3 0f 1f 00 41 54 49 89 d4 55 48 89 f5 53
Mar 16 15:15:32 sam kernel: RSP: 002b:00007ffc4e795dc8 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
Mar 16 15:15:32 sam kernel: RAX: ffffffffffffffda RBX: 00007fcba3be21c0 RCX: 00007fcbb4b2f504
Mar 16 15:15:32 sam kernel: RDX: 0000000000002000 RSI: 00007ffc4e795ee0 RDI: 0000000000000006
Mar 16 15:15:32 sam kernel: RBP: 0000000000002000 R08: 0000000000000000 R09: 00007ffc4e795f40
Mar 16 15:15:32 sam kernel: R10: 000056064ce8d240 R11: 0000000000000246 R12: 00007ffc4e795ee0
Mar 16 15:15:32 sam kernel: R13: 0000000000000000 R14: 00007ffc4e795ee0 R15: 0000000000002000

@chrisrd
Copy link
Contributor

chrisrd commented Mar 17, 2021

VERIFY3(c < SPA_MAXBLOCKSIZE >> SPA_MINBLOCKSHIFT) failed (36028797018963967 < 32768)
PANIC at zio.c:314:zio_data_buf_alloc()

Panic is coming from:

zio_data_buf_alloc(size_t size)
{               
        size_t c = (size - 1) >> SPA_MINBLOCKSHIFT;
        VERIFY3U(c, <, SPA_MAXBLOCKSIZE >> SPA_MINBLOCKSHIFT);

The 36028797018963967 from the panic message is (size_t)-1 >> SPA_MINBLOCKSHIFT

I.e. something's calling zio_data_buf_alloc(0).

The stack trace indicates we're passing through dbuf_hold_impl() and dbuf_hold_copy(), which looks... intricate:

int
dbuf_hold_impl(dnode_t *dn, uint8_t level, uint64_t blkid,
    boolean_t fail_sparse, boolean_t fail_uncached,
    void *tag, dmu_buf_impl_t **dbp)
{
        ...
        /*
         * If this buffer is currently syncing out, and we are
         * still referencing it from db_data, we need to make a copy
         * of it in case we decide we want to dirty it again in this txg.
         */
        if (db->db_level == 0 && db->db_blkid != DMU_BONUS_BLKID &&
            dn->dn_object != DMU_META_DNODE_OBJECT &&
            db->db_state == DB_CACHED && db->db_data_pending) {
                dbuf_dirty_record_t *dr = db->db_data_pending;
                if (dr->dt.dl.dr_data == db->db_buf)
                        dbuf_hold_copy(dn, db);
        }

Further back in the stack we have:

static void
dmu_tx_count_write(dmu_tx_hold_t *txh, uint64_t off, uint64_t len)
{
        ...
        if (len == 0)
                return;

Presumably that len is the length of the actual data to be written, so the size=0 that's causing our problem isn't directly related to a zero sized write, it's something related to the dmu_tx_check_ioerr() which is called from that dmu_tx_count_write().

Sorry, I've no idea where to go from there, it requires someone with better understanding of this stuff to track down how this size=0 is getting in there, and what to do about it.

@chrisrd
Copy link
Contributor

chrisrd commented Mar 17, 2021

@mattmacy - can you take a look at this? I suspect your "Consolidate arc_buf allocation checks" 13fac09 commit (dated 2020-02-27, first seen in zfs-2.0.0-rc1) introduced the problem.

The PANIC occurs in zio_data_buf_alloc() due to being called with size=0. Looking through the call stack, that size can be traced back to dbuf_alloc_arcbuf_from_arcbuf() calling arc_alloc_buf() with size=0:

zfs_write
  dmu_tx_hold_write_by_dnode
    dmu_tx_count_write
      dmu_tx_check_ioerr
        dbuf_hold_level
          dbuf_hold_impl
            dbuf_hold_copy.isra.19
              dbuf_alloc_arcbuf_from_arcbuf
                arc_alloc_buf                <<< called with size=0
                  arc_hdr_alloc
                    arc_hdr_alloc_abd
                      abd_alloc_linear
                        zio_data_buf_alloc   <<< PANIC on size=0

Commit 13fac09 changed an arc_alloc_buf() allocation size from db->db.db_size to arc_buf_size(db->db_data_pending->dt.dl.dr_data) (once you expand out some of the assignments) in dbuf_hold_copy() / dbuf_alloc_arcbuf_from_arcbuf().

I.e. from:

noinline static void
dbuf_hold_copy(dnode_t *dn, dmu_buf_impl_t *db)
{
        ...
        if (arc_is_encrypted(data)) {
                ...
        } else if (compress_type != ZIO_COMPRESS_OFF) {
                ...
        } else {
                dbuf_set_data(db, arc_alloc_buf(dn->dn_objset->os_spa, db,
                    DBUF_GET_BUFC_TYPE(db), db->db.db_size));  <<<<
        }
        ...
}

to:

noinline static void
dbuf_hold_copy(dnode_t *dn, dmu_buf_impl_t *db)
{
        dbuf_dirty_record_t *dr = db->db_data_pending;         <<<<
        arc_buf_t *newdata, *data = dr->dt.dl.dr_data;         <<<<

        newdata = dbuf_alloc_arcbuf_from_arcbuf(db, data);     <<<<
        dbuf_set_data(db, newdata);
        ...
}

static arc_buf_t *
dbuf_alloc_arcbuf_from_arcbuf(dmu_buf_impl_t *db, arc_buf_t *data)
{
        ...
        psize = arc_buf_size(data);                            <<<<
        ...
        if (arc_is_encrypted(data)) {
                ...
        } else if (compress_type != ZIO_COMPRESS_OFF) {
                ...
        } else {
                data = arc_alloc_buf(spa, db, type, psize);    <<<<
        }
        return (data);
}

I don't know the best way to fix this - perhaps just reverting the 13fac09 commit which was nominally a code cleanup / deduplication rather than a functional change.

@behlendorf
Copy link
Contributor

@chrisrd thanks for digging in to this. Unless @mattmacy has an alternate fix I agree we should go ahead and revert this change since it does appear to have introduced a subtle functional change.

@chrisrd
Copy link
Contributor

chrisrd commented Mar 18, 2021

Huh. I've been working off the stack trace from @phreaker0's stack trace, but I just noticed that the original stack trace from @ericonr does NOT include the dbuf_alloc_arcbuf_from_arcbuf() I've been identifying as problematic.

@ericonr - are you sure you were running zfs v2.0.1-1 at the time of the problem per your original report? I guess the dbuf_alloc_arcbuf_from_arcbuf() could have been inlined - does your Void Linux use particularly aggressive compile flags?

@ericonr
Copy link
Contributor Author

ericonr commented Mar 19, 2021

@chrisrd directly from the dmesg from which I picked those backtraces:

[ 1.106141] ZFS: Loaded module v2.0.1-1, ZFS pool version 5000, ZFS filesystem version 5

I don't think we use particularly aggressive optimization flags, only whatever DKMS exports by default.

@chrisrd
Copy link
Contributor

chrisrd commented Mar 19, 2021

@ericonr Assuming you still have the zfs.ko from when your stack dump was generated, let's see what's in your dbuf_hold_copy() routine. Please post the output of:

$ gdb --batch -ex 'disassemble dbuf_hold_copy' zfs.ko

@ericonr
Copy link
Contributor Author

ericonr commented Mar 19, 2021

I don't think I have it any more, I didn't know it would be useful here... Do you think reproducing it by reinstalling a 5.10.9 kernel and ZFS 2.0.1 would be worth it?

@chrisrd
Copy link
Contributor

chrisrd commented Mar 29, 2021

@ericonr Apologies for delay in responding, stuff keeps getting in the way. It would be interesting but perhaps not critical to see the code from the actual version of the module where you saw the error. If you get around to reproducing the 2.0.1 module, perhaps copy the entire zfs.ko somewhere we can pick it up and look in more detail.

Do you have encryption enabled, and have you tried scrubbing your data?

@ericonr
Copy link
Contributor Author

ericonr commented Mar 29, 2021

@chrisrd no worries :)

Do you have encryption enabled, and have you tried scrubbing your data?

Yes to both. I use aes-256-gcm. I scrubbed my pool right after I rebooted into another kernel (5.4), and it didn't actually complain about any file, that I remember.

@chrisrd
Copy link
Contributor

chrisrd commented Mar 30, 2021

@behlendorf I'm no longer convinced commit 13fac09 which introduced dbuf_alloc_arcbuf_from_arcbuf() caused this problem. That commit certainly introduced a change in behaviour per the arc_alloc_buf() allocation size noted above, however it seems the underlying problem may have been present before that commit - e.g. dbuf_alloc_arcbuf_from_arcbuf() doesn't appear in the first call trace of this issue. It's unclear if that's because that code was prior to the commit or if the dbuf_alloc_arcbuf_from_arcbuf() function was inlined - but certainly the function doesn't get inlined with my own standard compiles (debian 10 buster, gcc-8.3.0). However that doesn't actually matter because...

As noted previously, the PANICs are coming about because we have something calling zio_data_buf_alloc(0) i.e. with size=0.

The last few calls from our call trace are:

arc_alloc_buf
  arc_hdr_alloc
    arc_hdr_alloc_abd
      [ arc_get_data_abd ]       (inlined)
        [ abd_alloc ]            (inlined)
          abd_alloc_linear
            zio_data_buf_alloc   <<< PANIC on size=0

Following the call trace down from the top, in arc_alloc_buf() we have:

arc_hdr_alloc(spa_load_guid(spa), size, size, B_FALSE, ZIO_COMPRESS_OFF, 0, type, >>> B_FALSE <<<);

The last parameter is alloc_rdata and it's static and false. In arc_hdr_alloc() we then have:

static arc_buf_hdr_t *
arc_hdr_alloc(uint64_t spa, int32_t psize, int32_t lsize,
    boolean_t protected, enum zio_compress compression_type, uint8_t complevel,
    arc_buf_contents_t type, boolean_t alloc_rdata)
{
        arc_buf_hdr_t *hdr;
        int flags = ARC_HDR_DO_ADAPT;
...
        flags |= alloc_rdata ? ARC_HDR_ALLOC_RDATA : 0;    /* alloc_rdata=B_FALSE */
...
        HDR_SET_PSIZE(hdr, psize);
        HDR_SET_LSIZE(hdr, lsize);
...
        arc_hdr_alloc_abd(hdr, flags);
...
}

I.e. arc_hdr_alloc_abd() is called with flags=ARC_HDR_DO_ADAPT (and !ARC_HDR_ALLOC_RDATA). In arc_hdr_alloc_abd() we have:

static void
arc_hdr_alloc_abd(arc_buf_hdr_t *hdr, int alloc_flags)
{
        uint64_t size;
        boolean_t alloc_rdata = ((alloc_flags & ARC_HDR_ALLOC_RDATA) != 0);
...
        if (alloc_rdata) {
                size = HDR_GET_PSIZE(hdr);
                ASSERT3P(hdr->b_crypt_hdr.b_rabd, ==, NULL);
                hdr->b_crypt_hdr.b_rabd = arc_get_data_abd(hdr, size, hdr,
                    do_adapt);
...
        } else {
                size = arc_hdr_size(hdr);
                ASSERT3P(hdr->b_l1hdr.b_pabd, ==, NULL);
                hdr->b_l1hdr.b_pabd = arc_get_data_abd(hdr, size, hdr,
                    do_adapt);
...
        }
...
}

We've seen alloc_rdata is false, which means we're taking the other branch and doing:

size = arc_hdr_size(hdr);

And that looks like:

static uint64_t
arc_hdr_size(arc_buf_hdr_t *hdr)
{
        uint64_t size;

        if (arc_hdr_get_compress(hdr) != ZIO_COMPRESS_OFF &&
            HDR_GET_PSIZE(hdr) > 0) {
                size = HDR_GET_PSIZE(hdr);
        } else {
                ASSERT3U(HDR_GET_LSIZE(hdr), !=, 0);
                size = HDR_GET_LSIZE(hdr);
        }
        return (size);
}

I.e. we are guaranteed that size > 0: we only return HDR_GET_PSIZE() if that's greater than zero, otherwise we assert HDR_GET_LSIZE() is not zero and return that.

Back to arc_hdr_alloc_abd(), we're then calling:

arc_get_data_abd(hdr, size, hdr, do_adapt);

which calls abd_alloc(size, flag), where flag is either true or false depending on whether we're dealing with metadata or plain data. And abd_alloc() then does:

        if (!zfs_abd_scatter_enabled || abd_size_alloc_linear(size))
                return (abd_alloc_linear(size, is_metadata));

From the call trace we see we call abd_alloc_linear(), which in turn calls either zio_buf_alloc(size) or zio_data_buf_alloc(size), again depending on metadata or plain data. The call trace shows us calling zio_data_buf_alloc(), and that's where we hit the PANIC because, at that point, size=0.

Tracking back, we see that size is set by the call to arc_hdr_size(), but we can also see above that can't return zero!!!

So what on earth is happening here???

I further note that we see a very similar panic in issue #7603, with a call trace that ends in the same sequence:

arc_read
  arc_hdr_alloc
    arc_hdr_alloc_abd
      [ arc_get_data_abd ]    (inlined)
        [ abd_alloc ]         (inlined)
          abd_alloc_linear
            zio_buf_alloc     <<< PANIC on size=0

Compared to the call traces in this issue which look like:

zfs_write
  dmu_tx_hold_write_by_dnode
    dmu_tx_count_write
      dmu_tx_check_ioerr
        dbuf_hold_level
          dbuf_hold_impl
            dbuf_hold_copy
              [ dbuf_alloc_arcbuf_from_arcbuf ]  (in one trace, not the other)
                arc_alloc_buf
                  arc_hdr_alloc
                    arc_hdr_alloc_abd
                      [ arc_get_data_abd ]       (inlined)
                        [ abd_alloc ]            (inlined)
                          abd_alloc_linear
                            zio_data_buf_alloc   <<< PANIC on size=0

Whilst the arc_read() in #7603 vs zfs_write() in the current issue look like a completely different operations, note that the comments for dmu_tx_check_ioerr() say "This function reads specified data from disk", i.e. even in the zfs_write() case we're actually in a read operation when we panic, the same as the arc_read() case.

#7603 also mentions #8099, in which we see @linvinus had added some debugging to arc_hdr_size() and he also was mystified as to how it could be returning zero: #8099 (comment)

Something very weird is going on here.

At this point I'm stumped - I don't think I can take this any further without someone else coming up with some bright ideas or showing me where I've stuffed up the this analysis.

@behlendorf
Copy link
Contributor

Nice analysis. It seems to me it would be possible for arc_hdr_size() to return zero in a non-debug build where the ASSERTs are disabled. The debugging patch in #8099 (comment) would seem to confirm this.

The question is how to we end up with a zero lsize in the arc_buf_hdr_t. I see we have some existing ASSERTs in the code to check for this, for example in arc_buf_alloc_l2only, but none in arc_buf_alloc. It wouldn't be a bad idea to add a similar check there as well, that might help us detect where the arc_buf_hdr_t first gets set to the invalid size. In fact, since this has been a tricky issue to chase down it probably makes sense to use a VERIFY instead of an ASSERT so it's always enabled and we can get a little more information the next time it occurs.

@titanous
Copy link

titanous commented Apr 9, 2021

I've been able to trigger this pretty reliably by running a specific workload, so if anyone wants to link me to a patch to try with some debugging instructions, I'm happy to dump more output to help track it down.

@tolbrino
Copy link

I've seen this error on 2 machines which are running the same setup with Linux Kernel 5.4.89, ZFS v2.0.1-1 and an encrypted ZFS mirror over 2 NVMe devices. Here are the logs.

Machine 1:

Linux version 5.4.89 (nixbld@localhost) (gcc version 10.2.0 (GCC)) #1-NixOS SMP Tue Jan 12 19:16:25 UTC 2021
ZFS: Loaded module v2.0.1-1, ZFS pool version 5000, ZFS filesystem version 5

VERIFY3(c < SPA_MAXBLOCKSIZE >> SPA_MINBLOCKSHIFT) failed (36028797018963967 < 32768)
PANIC at zio.c:314:zio_data_buf_alloc()
Showing stack for process 10775
CPU: 5 PID: 10775 Comm: z_wr_int Tainted: P           O      5.4.89 #1-NixOS
Hardware name: HPE ProLiant DL325 Gen10/ProLiant DL325 Gen10, BIOS A41 07/17/2020
Call Trace:
 dump_stack+0x64/0x88
 spl_panic+0xd4/0xfc [spl]
 ? _cond_resched+0x16/0x40
 ? kmem_cache_alloc+0x157/0x210
 ? spl_kmem_cache_alloc+0x98/0x790 [spl]
 ? aggsum_add+0x171/0x190 [zfs]
 ? mutex_lock+0xe/0x30
 ? aggsum_add+0x171/0x190 [zfs]
 zio_data_buf_alloc+0x55/0x60 [zfs]
 abd_alloc_linear+0x8a/0xc0 [zfs]
 arc_hdr_alloc_abd+0xdf/0x1e0 [zfs]
 arc_hdr_alloc+0x104/0x170 [zfs]
 arc_alloc_buf+0x46/0x150 [zfs]
 dbuf_hold_copy.constprop.0+0x31/0xa0 [zfs]
 dbuf_hold_impl+0x47c/0x670 [zfs]
 dbuf_hold_level+0x2b/0x60 [zfs]
 dmu_tx_check_ioerr+0x35/0xd0 [zfs]
 dmu_tx_count_write+0xe5/0x1a0 [zfs]
 dmu_tx_hold_write_by_dnode+0x35/0x50 [zfs]
 zfs_write+0x3ed/0xc70 [zfs]
 zpl_iter_write+0x106/0x190 [zfs]
 new_sync_write+0x119/0x1b0
 __kernel_write+0x51/0x100
 do_acct_process+0x422/0x4f0
 acct_process+0xb5/0xd4
 do_exit+0x73b/0xa00
 ? taskq_thread_spawn+0x50/0x50 [spl]
 kthread+0xe2/0x130
 ? __kthread_bind_mask+0x60/0x60
 ret_from_fork+0x22/0x40
INFO: task z_wr_int:745 blocked for more than 122 seconds.
      Tainted: P           O      5.4.89 #1-NixOS
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
z_wr_int        D    0   745      2 0x80004000
Call Trace:
 __schedule+0x226/0x720
 schedule+0x39/0xa0
 schedule_preempt_disabled+0xa/0x10
 __mutex_lock.constprop.0+0x14f/0x4a0
 ? dsl_dataset_block_born+0x244/0x380 [zfs]
 dbuf_write_done+0x3c/0x1e0 [zfs]
 arc_write_done+0x8f/0x420 [zfs]
 zio_done+0x403/0x1160 [zfs]
 zio_execute+0x81/0x120 [zfs]
 taskq_thread+0x28e/0x4b0 [spl]
 ? wake_up_q+0x60/0x60
 ? zio_subblock+0x30/0x30 [zfs]
 ? taskq_thread_spawn+0x50/0x50 [spl]
 kthread+0x117/0x130
 ? __kthread_bind_mask+0x60/0x60
 ret_from_fork+0x22/0x40
INFO: task txg_sync:946 blocked for more than 122 seconds.
      Tainted: P           O      5.4.89 #1-NixOS
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
txg_sync        D    0   946      2 0x80004000
Call Trace:
 __schedule+0x226/0x720
 schedule+0x39/0xa0
 schedule_timeout+0x89/0x160
 ? zio_issue_async+0x52/0x90 [zfs]
 ? __next_timer_interrupt+0xd0/0xd0
 io_schedule_timeout+0x4b/0x80
 __cv_timedwait_common+0x12e/0x160 [spl]
 ? wait_woken+0x80/0x80
 __cv_timedwait_io+0x15/0x20 [spl]
 zio_wait+0x129/0x2b0 [zfs]
 dsl_pool_sync+0xd0/0x4c0 [zfs]
 spa_sync+0x575/0xfa0 [zfs]
 ? mutex_lock+0xe/0x30
 ? spa_txg_history_init_io+0x101/0x110 [zfs]
 txg_sync_thread+0x2e0/0x4b0 [zfs]
 ? txg_wait_callbacks+0x20/0x20 [zfs]
 thread_generic_wrapper+0x6f/0x80 [spl]
 ? __thread_exit+0x20/0x20 [spl]
 kthread+0x117/0x130
 ? __kthread_bind_mask+0x60/0x60
 ret_from_fork+0x22/0x40
INFO: task atop:6569 blocked for more than 122 seconds.
      Tainted: P           O      5.4.89 #1-NixOS
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
atop            D    0  6569   6447 0x00000004
Call Trace:
 __schedule+0x226/0x720
 schedule+0x39/0xa0
 schedule_preempt_disabled+0xa/0x10
 __mutex_lock.constprop.0+0x14f/0x4a0
 ? __switch_to_asm+0x40/0x70
 ? __switch_to_asm+0x34/0x70
 dbuf_find+0xdd/0x200 [zfs]
 dbuf_hold_impl+0x60/0x670 [zfs]
 dbuf_hold+0x2c/0x60 [zfs]
 dmu_buf_hold_array_by_dnode+0xd8/0x550 [zfs]
 dmu_read_uio_dnode+0x4b/0x140 [zfs]
 dmu_read_uio_dbuf+0x42/0x60 [zfs]
 zfs_read+0x130/0x3a0 [zfs]
 zpl_iter_read+0xe1/0x180 [zfs]
 new_sync_read+0x112/0x1a0
 vfs_read+0x9d/0x150
 ksys_read+0x5f/0xe0
 do_syscall_64+0x4e/0x120
 entry_SYSCALL_64_after_hwframe+0x44/0xa9
RIP: 0033:0x7f280f48a289
Code: Bad RIP value.
RSP: 002b:00007ffdececd368 EFLAGS: 00000246 ORIG_RAX: 0000000000000000
RAX: ffffffffffffffda RBX: 0000000000000040 RCX: 00007f280f48a289
RDX: 0000000000000040 RSI: 00007ffdececd3b0 RDI: 0000000000000003
RBP: 0000000000000293 R08: 0000000000087258 R09: 0000000000000001
R10: 0000000000000000 R11: 0000000000000246 R12: 00007ffdececd3b0
R13: 00007ffdececd3f0 R14: 0000000002358ef0 R15: 0000000000000000
INFO: task kworker/dying:27536 blocked for more than 122 seconds.
      Tainted: P           O      5.4.89 #1-NixOS
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
kworker/dying   D    0 27536      2 0x80004000
Call Trace:
 __schedule+0x226/0x720
 ? __switch_to_asm+0x40/0x70
 schedule+0x39/0xa0
 schedule_preempt_disabled+0xa/0x10
 __mutex_lock.constprop.0+0x14f/0x4a0
 ? xas_store+0x56/0x5e0
 acct_process+0x65/0xd4
 do_exit+0x73b/0xa00
 ? worker_thread+0x2c2/0x410
 ? process_one_work+0x3a0/0x3a0
 kthread+0xe2/0x130
 ? __kthread_bind_mask+0x60/0x60
 ret_from_fork+0x22/0x40
INFO: task z_wr_iss_h:10694 blocked for more than 122 seconds.
      Tainted: P           O      5.4.89 #1-NixOS
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
z_wr_iss_h      D    0 10694      2 0x80004000
Call Trace:
 __schedule+0x226/0x720
 schedule+0x39/0xa0
 schedule_preempt_disabled+0xa/0x10
 __mutex_lock.constprop.0+0x14f/0x4a0
 acct_process+0x65/0xd4
 do_exit+0x73b/0xa00
 ? zio_subblock+0x30/0x30 [zfs]
 ? taskq_thread_spawn+0x50/0x50 [spl]
 kthread+0xe2/0x130
 ? __kthread_bind_mask+0x60/0x60
 ret_from_fork+0x22/0x40
INFO: task .postgres-wrapp:10700 blocked for more than 122 seconds.
      Tainted: P           O      5.4.89 #1-NixOS
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
.postgres-wrapp D    0 10700   3331 0x80000000
Call Trace:
 __schedule+0x226/0x720
 ? remove_vma+0x5b/0x70
 schedule+0x39/0xa0
 schedule_preempt_disabled+0xa/0x10
 __mutex_lock.constprop.0+0x14f/0x4a0
 acct_process+0x65/0xd4
 do_exit+0x73b/0xa00
 ? handle_mm_fault+0xc0/0x1e0
 do_group_exit+0x33/0xa0
 __x64_sys_exit_group+0x14/0x20
 do_syscall_64+0x4e/0x120
 entry_SYSCALL_64_after_hwframe+0x44/0xa9
RIP: 0033:0x7f23d32a73e6
Code: Bad RIP value.
RSP: 002b:00007ffd1ddfa408 EFLAGS: 00000246 ORIG_RAX: 00000000000000e7
RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007f23d32a73e6
RDX: 0000000000000000 RSI: 000000000000003c RDI: 0000000000000000
RBP: 00007f23d3399490 R08: 00000000000000e7 R09: fffffffffffffee8
R10: 00007ffd1ddfa220 R11: 0000000000000246 R12: 00007f23d3399490
R13: 000000000000000c R14: 00007f23d339cdc8 R15: 0000000000000000
INFO: task z_wr_iss_h:10773 blocked for more than 122 seconds.
      Tainted: P           O      5.4.89 #1-NixOS
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
z_wr_iss_h      D    0 10773      2 0x80004000
Call Trace:
 __schedule+0x226/0x720
 schedule+0x39/0xa0
 schedule_preempt_disabled+0xa/0x10
 __mutex_lock.constprop.0+0x14f/0x4a0
 acct_process+0x65/0xd4
 do_exit+0x73b/0xa00
 ? zio_subblock+0x30/0x30 [zfs]
 ? taskq_thread_spawn+0x50/0x50 [spl]
 kthread+0xe2/0x130
 ? __kthread_bind_mask+0x60/0x60
 ret_from_fork+0x22/0x40
INFO: task z_wr_int:10774 blocked for more than 122 seconds.
      Tainted: P           O      5.4.89 #1-NixOS
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
z_wr_int        D    0 10774      2 0x80004000
Call Trace:
 __schedule+0x226/0x720
 schedule+0x39/0xa0
 schedule_preempt_disabled+0xa/0x10
 __mutex_lock.constprop.0+0x14f/0x4a0
 acct_process+0x65/0xd4
 do_exit+0x73b/0xa00
 ? zio_subblock+0x30/0x30 [zfs]
 ? taskq_thread_spawn+0x50/0x50 [spl]
 kthread+0xe2/0x130
 ? __kthread_bind_mask+0x60/0x60
 ret_from_fork+0x22/0x40
INFO: task z_wr_int:10775 blocked for more than 122 seconds.
      Tainted: P           O      5.4.89 #1-NixOS
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
z_wr_int        D    0 10775      2 0x80004000
Call Trace:
 __schedule+0x226/0x720
 schedule+0x39/0xa0
 spl_panic+0xfa/0xfc [spl]
 ? _cond_resched+0x16/0x40
 ? kmem_cache_alloc+0x157/0x210
 ? spl_kmem_cache_alloc+0x98/0x790 [spl]
 ? aggsum_add+0x171/0x190 [zfs]
 ? mutex_lock+0xe/0x30
 ? aggsum_add+0x171/0x190 [zfs]
 zio_data_buf_alloc+0x55/0x60 [zfs]
 abd_alloc_linear+0x8a/0xc0 [zfs]
 arc_hdr_alloc_abd+0xdf/0x1e0 [zfs]
 arc_hdr_alloc+0x104/0x170 [zfs]
 arc_alloc_buf+0x46/0x150 [zfs]
 dbuf_hold_copy.constprop.0+0x31/0xa0 [zfs]
 dbuf_hold_impl+0x47c/0x670 [zfs]
 dbuf_hold_level+0x2b/0x60 [zfs]
 dmu_tx_check_ioerr+0x35/0xd0 [zfs]
 dmu_tx_count_write+0xe5/0x1a0 [zfs]
 dmu_tx_hold_write_by_dnode+0x35/0x50 [zfs]
 zfs_write+0x3ed/0xc70 [zfs]
 zpl_iter_write+0x106/0x190 [zfs]
 new_sync_write+0x119/0x1b0
 __kernel_write+0x51/0x100
 do_acct_process+0x422/0x4f0
 acct_process+0xb5/0xd4
 do_exit+0x73b/0xa00
 ? taskq_thread_spawn+0x50/0x50 [spl]
 kthread+0xe2/0x130
 ? __kthread_bind_mask+0x60/0x60
 ret_from_fork+0x22/0x40
INFO: task z_wr_int:10776 blocked for more than 122 seconds.
      Tainted: P           O      5.4.89 #1-NixOS
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
z_wr_int        D    0 10776      2 0x80004000
Call Trace:
 __schedule+0x226/0x720
 schedule+0x39/0xa0
 schedule_preempt_disabled+0xa/0x10
 __mutex_lock.constprop.0+0x14f/0x4a0
 acct_process+0x65/0xd4
 do_exit+0x73b/0xa00
 ? taskq_thread_spawn+0x50/0x50 [spl]
 kthread+0xe2/0x130
 ? __kthread_bind_mask+0x60/0x60
 ret_from_fork+0x22/0x40

Machine 2:

Linux version 5.4.89 (nixbld@localhost) (gcc version 10.2.0 (GCC)) #1-NixOS SMP Tue Jan 12 19:16:25 UTC 2021
ZFS: Loaded module v2.0.1-1, ZFS pool version 5000, ZFS filesystem version 5

VERIFY3(c < SPA_MAXBLOCKSIZE >> SPA_MINBLOCKSHIFT) failed (36028797018963967 < 32768)
PANIC at zio.c:314:zio_data_buf_alloc()
Showing stack for process 5673
CPU: 8 PID: 5673 Comm: .postgres-wrapp Tainted: P           O      5.4.89 #1-NixOS
Hardware name: HPE ProLiant DL325 Gen10/ProLiant DL325 Gen10, BIOS A41 07/17/2020
Call Trace:
 dump_stack+0x64/0x88
 spl_panic+0xd4/0xfc [spl]
 ? _cond_resched+0x16/0x40
 ? dbuf_read+0x2e8/0x570 [zfs]
 ? _cond_resched+0x16/0x40
 ? mutex_lock+0xe/0x30
 ? _cond_resched+0x16/0x40
 ? kmem_cache_alloc+0x157/0x210
 ? spl_kmem_cache_alloc+0x98/0x790 [spl]
 ? aggsum_add+0x171/0x190 [zfs]
 ? mutex_lock+0xe/0x30
 ? aggsum_add+0x171/0x190 [zfs]
 zio_data_buf_alloc+0x55/0x60 [zfs]
 abd_alloc_linear+0x8a/0xc0 [zfs]
 arc_hdr_alloc_abd+0xdf/0x1e0 [zfs]
 arc_hdr_alloc+0x104/0x170 [zfs]
 arc_alloc_buf+0x46/0x150 [zfs]
 dbuf_hold_copy.constprop.0+0x31/0xa0 [zfs]
 dbuf_hold_impl+0x47c/0x670 [zfs]
 dbuf_hold_level+0x2b/0x60 [zfs]
 dmu_tx_check_ioerr+0x35/0xd0 [zfs]
 dmu_tx_count_write+0xe5/0x1a0 [zfs]
 dmu_tx_hold_write_by_dnode+0x35/0x50 [zfs]
 zfs_write+0x3ed/0xc70 [zfs]
 ? __switch_to_asm+0x40/0x70
 ? __switch_to_asm+0x34/0x70
 ? __switch_to_asm+0x40/0x70
 ? ep_poll_callback+0x1d2/0x2c0
 ? avc_has_perm+0x4b/0x180
 zpl_iter_write+0x106/0x190 [zfs]
 new_sync_write+0x119/0x1b0
 vfs_write+0xb6/0x1a0
 ksys_write+0x5f/0xe0
 do_syscall_64+0x4e/0x120
 entry_SYSCALL_64_after_hwframe+0x44/0xa9
RIP: 0033:0x7fefc7dcc213
Code: 0c 00 f7 d8 64 89 02 48 c7 c0 ff ff ff ff eb b3 0f 1f 80 00 00 00 00 64 8b 04 25 18 00 00 00 85 c0 75 14 b8 01 00 00 00 0f 05 <48> 3d 00 f0 ff ff 77 55 c3 0f 1f 40 00 41 54 49 89 d4 55 48 89 f5
RSP: 002b:00007fff32d71328 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
RAX: ffffffffffffffda RBX: 000000000000012c RCX: 00007fefc7dcc213
RDX: 000000000000012c RSI: 00000000014f12f0 RDI: 0000000000000004
RBP: 00000000014f12f0 R08: 00000000014f12f0 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 000000000000012c
R13: 00000000014e3010 R14: 00007fefc7e9a720 R15: 000000000000012c
INFO: task txg_sync:984 blocked for more than 122 seconds.
      Tainted: P           O      5.4.89 #1-NixOS
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
txg_sync        D    0   984      2 0x80004000
Call Trace:
 __schedule+0x226/0x720
 schedule+0x39/0xa0
 schedule_timeout+0x89/0x160
 ? zio_issue_async+0x52/0x90 [zfs]
 ? __next_timer_interrupt+0xd0/0xd0
 io_schedule_timeout+0x4b/0x80
 __cv_timedwait_common+0x12e/0x160 [spl]
 ? wait_woken+0x80/0x80
 __cv_timedwait_io+0x15/0x20 [spl]
 zio_wait+0x129/0x2b0 [zfs]
 dsl_pool_sync+0xd0/0x4c0 [zfs]
 spa_sync+0x575/0xfa0 [zfs]
 ? mutex_lock+0xe/0x30
 ? spa_txg_history_init_io+0x101/0x110 [zfs]
 txg_sync_thread+0x2e0/0x4b0 [zfs]
 ? txg_wait_callbacks+0x20/0x20 [zfs]
 thread_generic_wrapper+0x6f/0x80 [spl]
 ? __thread_exit+0x20/0x20 [spl]
 kthread+0x117/0x130
 ? __kthread_bind_mask+0x60/0x60
 ret_from_fork+0x22/0x40
INFO: task .postgres-wrapp:5673 blocked for more than 122 seconds.
      Tainted: P           O      5.4.89 #1-NixOS
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
.postgres-wrapp D    0  5673   5587 0x80000000
Call Trace:
 __schedule+0x226/0x720
 schedule+0x39/0xa0
 spl_panic+0xfa/0xfc [spl]
 ? dbuf_read+0x2e8/0x570 [zfs]
 ? _cond_resched+0x16/0x40
 ? mutex_lock+0xe/0x30
 ? _cond_resched+0x16/0x40
 ? kmem_cache_alloc+0x157/0x210
 ? spl_kmem_cache_alloc+0x98/0x790 [spl]
 ? aggsum_add+0x171/0x190 [zfs]
 ? mutex_lock+0xe/0x30
 ? aggsum_add+0x171/0x190 [zfs]
 zio_data_buf_alloc+0x55/0x60 [zfs]
 abd_alloc_linear+0x8a/0xc0 [zfs]
 arc_hdr_alloc_abd+0xdf/0x1e0 [zfs]
 arc_hdr_alloc+0x104/0x170 [zfs]
 arc_alloc_buf+0x46/0x150 [zfs]
 dbuf_hold_copy.constprop.0+0x31/0xa0 [zfs]
 dbuf_hold_impl+0x47c/0x670 [zfs]
 dbuf_hold_level+0x2b/0x60 [zfs]
 dmu_tx_check_ioerr+0x35/0xd0 [zfs]
 dmu_tx_count_write+0xe5/0x1a0 [zfs]
 dmu_tx_hold_write_by_dnode+0x35/0x50 [zfs]
 zfs_write+0x3ed/0xc70 [zfs]
 ? __switch_to_asm+0x40/0x70
 ? __switch_to_asm+0x34/0x70
 ? __switch_to_asm+0x40/0x70
 ? ep_poll_callback+0x1d2/0x2c0
 ? avc_has_perm+0x4b/0x180
 zpl_iter_write+0x106/0x190 [zfs]
 new_sync_write+0x119/0x1b0
 vfs_write+0xb6/0x1a0
 ksys_write+0x5f/0xe0
 do_syscall_64+0x4e/0x120
 entry_SYSCALL_64_after_hwframe+0x44/0xa9
RIP: 0033:0x7fefc7dcc213
Code: 0c 00 f7 d8 64 89 02 48 c7 c0 ff ff ff ff eb b3 0f 1f 80 00 00 00 00 64 8b 04 25 18 00 00 00 85 c0 75 14 b8 01 00 00 00 0f 05 <48> 3d 00 f0 ff ff 77 55 c3 0f 1f 40 00 41 54 49 89 d4 55 48 89 f5
RSP: 002b:00007fff32d71328 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
RAX: ffffffffffffffda RBX: 000000000000012c RCX: 00007fefc7dcc213
RDX: 000000000000012c RSI: 00000000014f12f0 RDI: 0000000000000004
RBP: 00000000014f12f0 R08: 00000000014f12f0 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 000000000000012c
R13: 00000000014e3010 R14: 00007fefc7e9a720 R15: 000000000000012c
INFO: task z_wr_int:2066 blocked for more than 122 seconds.
      Tainted: P           O      5.4.89 #1-NixOS
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
z_wr_int        D    0  2066      2 0x80004000
Call Trace:
 __schedule+0x226/0x720
 schedule+0x39/0xa0
 schedule_preempt_disabled+0xa/0x10
 __mutex_lock.constprop.0+0x14f/0x4a0
 ? dsl_dataset_block_born+0x244/0x380 [zfs]
 dbuf_write_done+0x3c/0x1e0 [zfs]
 arc_write_done+0x8f/0x420 [zfs]
 zio_done+0x403/0x1160 [zfs]
 zio_execute+0x81/0x120 [zfs]
 taskq_thread+0x28e/0x4b0 [spl]
 ? __switch_to_asm+0x40/0x70
 ? wake_up_q+0x60/0x60
 ? zio_subblock+0x30/0x30 [zfs]
 ? taskq_thread_spawn+0x50/0x50 [spl]
 kthread+0x117/0x130
 ? __kthread_bind_mask+0x60/0x60
 ret_from_fork+0x22/0x40
INFO: task txg_sync:984 blocked for more than 245 seconds.
      Tainted: P           O      5.4.89 #1-NixOS
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
txg_sync        D    0   984      2 0x80004000
Call Trace:
 __schedule+0x226/0x720
 schedule+0x39/0xa0
 schedule_timeout+0x89/0x160
 ? zio_issue_async+0x52/0x90 [zfs]
 ? __next_timer_interrupt+0xd0/0xd0
 io_schedule_timeout+0x4b/0x80
 __cv_timedwait_common+0x12e/0x160 [spl]
 ? wait_woken+0x80/0x80
 __cv_timedwait_io+0x15/0x20 [spl]
 zio_wait+0x129/0x2b0 [zfs]
 dsl_pool_sync+0xd0/0x4c0 [zfs]
 spa_sync+0x575/0xfa0 [zfs]
 ? mutex_lock+0xe/0x30
 ? spa_txg_history_init_io+0x101/0x110 [zfs]
 txg_sync_thread+0x2e0/0x4b0 [zfs]
 ? txg_wait_callbacks+0x20/0x20 [zfs]
 thread_generic_wrapper+0x6f/0x80 [spl]
 ? __thread_exit+0x20/0x20 [spl]
 kthread+0x117/0x130
 ? __kthread_bind_mask+0x60/0x60
 ret_from_fork+0x22/0x40
INFO: task .postgres-wrapp:5673 blocked for more than 245 seconds.
      Tainted: P           O      5.4.89 #1-NixOS
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
.postgres-wrapp D    0  5673   5587 0x80000000
Call Trace:
 __schedule+0x226/0x720
 schedule+0x39/0xa0
 spl_panic+0xfa/0xfc [spl]
 ? dbuf_read+0x2e8/0x570 [zfs]
 ? _cond_resched+0x16/0x40
 ? mutex_lock+0xe/0x30
 ? _cond_resched+0x16/0x40
 ? kmem_cache_alloc+0x157/0x210
 ? spl_kmem_cache_alloc+0x98/0x790 [spl]
 ? aggsum_add+0x171/0x190 [zfs]
 ? mutex_lock+0xe/0x30
 ? aggsum_add+0x171/0x190 [zfs]
 zio_data_buf_alloc+0x55/0x60 [zfs]
 abd_alloc_linear+0x8a/0xc0 [zfs]
 arc_hdr_alloc_abd+0xdf/0x1e0 [zfs]
 arc_hdr_alloc+0x104/0x170 [zfs]
 arc_alloc_buf+0x46/0x150 [zfs]
 dbuf_hold_copy.constprop.0+0x31/0xa0 [zfs]
 dbuf_hold_impl+0x47c/0x670 [zfs]
 dbuf_hold_level+0x2b/0x60 [zfs]
 dmu_tx_check_ioerr+0x35/0xd0 [zfs]
 dmu_tx_count_write+0xe5/0x1a0 [zfs]
 dmu_tx_hold_write_by_dnode+0x35/0x50 [zfs]
 zfs_write+0x3ed/0xc70 [zfs]
 ? __switch_to_asm+0x40/0x70
 ? __switch_to_asm+0x34/0x70
 ? __switch_to_asm+0x40/0x70
 ? ep_poll_callback+0x1d2/0x2c0
 ? avc_has_perm+0x4b/0x180
 zpl_iter_write+0x106/0x190 [zfs]
 new_sync_write+0x119/0x1b0
 vfs_write+0xb6/0x1a0
 ksys_write+0x5f/0xe0
 do_syscall_64+0x4e/0x120
 entry_SYSCALL_64_after_hwframe+0x44/0xa9
RIP: 0033:0x7fefc7dcc213
Code: Bad RIP value.
RSP: 002b:00007fff32d71328 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
RAX: ffffffffffffffda RBX: 000000000000012c RCX: 00007fefc7dcc213
RDX: 000000000000012c RSI: 00000000014f12f0 RDI: 0000000000000004
RBP: 00000000014f12f0 R08: 00000000014f12f0 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 000000000000012c
R13: 00000000014e3010 R14: 00007fefc7e9a720 R15: 000000000000012c
INFO: task z_wr_int:2066 blocked for more than 245 seconds.
      Tainted: P           O      5.4.89 #1-NixOS
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
z_wr_int        D    0  2066      2 0x80004000
Call Trace:
 __schedule+0x226/0x720
 schedule+0x39/0xa0
 schedule_preempt_disabled+0xa/0x10
 __mutex_lock.constprop.0+0x14f/0x4a0
 ? dsl_dataset_block_born+0x244/0x380 [zfs]
 dbuf_write_done+0x3c/0x1e0 [zfs]
 arc_write_done+0x8f/0x420 [zfs]
 zio_done+0x403/0x1160 [zfs]
 zio_execute+0x81/0x120 [zfs]
 taskq_thread+0x28e/0x4b0 [spl]
 ? __switch_to_asm+0x40/0x70
 ? wake_up_q+0x60/0x60
 ? zio_subblock+0x30/0x30 [zfs]
 ? taskq_thread_spawn+0x50/0x50 [spl]
 kthread+0x117/0x130
 ? __kthread_bind_mask+0x60/0x60
 ret_from_fork+0x22/0x40
INFO: task .postgres-wrapp:5673 blocked for more than 368 seconds.
      Tainted: P           O      5.4.89 #1-NixOS
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
.postgres-wrapp D    0  5673   5587 0x80000000
Call Trace:
 __schedule+0x226/0x720
 schedule+0x39/0xa0
 spl_panic+0xfa/0xfc [spl]
 ? dbuf_read+0x2e8/0x570 [zfs]
 ? _cond_resched+0x16/0x40
 ? mutex_lock+0xe/0x30
 ? _cond_resched+0x16/0x40
 ? kmem_cache_alloc+0x157/0x210
 ? spl_kmem_cache_alloc+0x98/0x790 [spl]
 ? aggsum_add+0x171/0x190 [zfs]
 ? mutex_lock+0xe/0x30
 ? aggsum_add+0x171/0x190 [zfs]
 zio_data_buf_alloc+0x55/0x60 [zfs]
 abd_alloc_linear+0x8a/0xc0 [zfs]
 arc_hdr_alloc_abd+0xdf/0x1e0 [zfs]
 arc_hdr_alloc+0x104/0x170 [zfs]
 arc_alloc_buf+0x46/0x150 [zfs]
 dbuf_hold_copy.constprop.0+0x31/0xa0 [zfs]
 dbuf_hold_impl+0x47c/0x670 [zfs]
 dbuf_hold_level+0x2b/0x60 [zfs]
 dmu_tx_check_ioerr+0x35/0xd0 [zfs]
 dmu_tx_count_write+0xe5/0x1a0 [zfs]
 dmu_tx_hold_write_by_dnode+0x35/0x50 [zfs]
 zfs_write+0x3ed/0xc70 [zfs]
 ? __switch_to_asm+0x40/0x70
 ? __switch_to_asm+0x34/0x70
 ? __switch_to_asm+0x40/0x70
 ? ep_poll_callback+0x1d2/0x2c0
 ? avc_has_perm+0x4b/0x180
 zpl_iter_write+0x106/0x190 [zfs]
 new_sync_write+0x119/0x1b0
 vfs_write+0xb6/0x1a0
 ksys_write+0x5f/0xe0
 do_syscall_64+0x4e/0x120
 entry_SYSCALL_64_after_hwframe+0x44/0xa9
RIP: 0033:0x7fefc7dcc213
Code: Bad RIP value.
RSP: 002b:00007fff32d71328 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
RAX: ffffffffffffffda RBX: 000000000000012c RCX: 00007fefc7dcc213
RDX: 000000000000012c RSI: 00000000014f12f0 RDI: 0000000000000004
RBP: 00000000014f12f0 R08: 00000000014f12f0 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 000000000000012c
R13: 00000000014e3010 R14: 00007fefc7e9a720 R15: 000000000000012c
INFO: task z_wr_int:2066 blocked for more than 368 seconds.
      Tainted: P           O      5.4.89 #1-NixOS
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
z_wr_int        D    0  2066      2 0x80004000
Call Trace:
 __schedule+0x226/0x720
 schedule+0x39/0xa0
 schedule_preempt_disabled+0xa/0x10
 __mutex_lock.constprop.0+0x14f/0x4a0
 ? dsl_dataset_block_born+0x244/0x380 [zfs]
 dbuf_write_done+0x3c/0x1e0 [zfs]
 arc_write_done+0x8f/0x420 [zfs]
 zio_done+0x403/0x1160 [zfs]
 zio_execute+0x81/0x120 [zfs]
 taskq_thread+0x28e/0x4b0 [spl]
 ? __switch_to_asm+0x40/0x70
 ? wake_up_q+0x60/0x60
 ? zio_subblock+0x30/0x30 [zfs]
 ? taskq_thread_spawn+0x50/0x50 [spl]
 kthread+0x117/0x130
 ? __kthread_bind_mask+0x60/0x60
 ret_from_fork+0x22/0x40
INFO: task .postgres-wrapp:5673 blocked for more than 491 seconds.
      Tainted: P           O      5.4.89 #1-NixOS
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
.postgres-wrapp D    0  5673   5587 0x80000000
Call Trace:
 __schedule+0x226/0x720
 schedule+0x39/0xa0
 spl_panic+0xfa/0xfc [spl]
 ? dbuf_read+0x2e8/0x570 [zfs]
 ? _cond_resched+0x16/0x40
 ? mutex_lock+0xe/0x30
 ? _cond_resched+0x16/0x40
 ? kmem_cache_alloc+0x157/0x210
 ? spl_kmem_cache_alloc+0x98/0x790 [spl]
 ? aggsum_add+0x171/0x190 [zfs]
 ? mutex_lock+0xe/0x30
 ? aggsum_add+0x171/0x190 [zfs]
 zio_data_buf_alloc+0x55/0x60 [zfs]
 abd_alloc_linear+0x8a/0xc0 [zfs]
 arc_hdr_alloc_abd+0xdf/0x1e0 [zfs]
 arc_hdr_alloc+0x104/0x170 [zfs]
 arc_alloc_buf+0x46/0x150 [zfs]
 dbuf_hold_copy.constprop.0+0x31/0xa0 [zfs]
 dbuf_hold_impl+0x47c/0x670 [zfs]
 dbuf_hold_level+0x2b/0x60 [zfs]
 dmu_tx_check_ioerr+0x35/0xd0 [zfs]
 dmu_tx_count_write+0xe5/0x1a0 [zfs]
 dmu_tx_hold_write_by_dnode+0x35/0x50 [zfs]
 zfs_write+0x3ed/0xc70 [zfs]
 ? __switch_to_asm+0x40/0x70
 ? __switch_to_asm+0x34/0x70
 ? __switch_to_asm+0x40/0x70
 ? ep_poll_callback+0x1d2/0x2c0
 ? avc_has_perm+0x4b/0x180
 zpl_iter_write+0x106/0x190 [zfs]
 new_sync_write+0x119/0x1b0
 vfs_write+0xb6/0x1a0
 ksys_write+0x5f/0xe0
 do_syscall_64+0x4e/0x120
 entry_SYSCALL_64_after_hwframe+0x44/0xa9
RIP: 0033:0x7fefc7dcc213
Code: 0c 00 f7 d8 64 89 02 48 c7 c0 ff ff ff ff eb b3 0f 1f 80 00 00 00 00 64 8b 04 25 18 00 00 00 85 c0 75 14 b8 01 00 00 00 0f 05 <48> 3d 00 f0 ff ff 77 55 c3 0f 1f 40 00 41 54 49 89 d4 55 48 89 f5
RSP: 002b:00007fff32d71328 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
RAX: ffffffffffffffda RBX: 000000000000012c RCX: 00007fefc7dcc213
RDX: 000000000000012c RSI: 00000000014f12f0 RDI: 0000000000000004
RBP: 00000000014f12f0 R08: 00000000014f12f0 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 000000000000012c
R13: 00000000014e3010 R14: 00007fefc7e9a720 R15: 000000000000012c
INFO: task z_wr_int:2066 blocked for more than 491 seconds.
      Tainted: P           O      5.4.89 #1-NixOS
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
z_wr_int        D    0  2066      2 0x80004000
Call Trace:
 __schedule+0x226/0x720
 schedule+0x39/0xa0
 schedule_preempt_disabled+0xa/0x10
 __mutex_lock.constprop.0+0x14f/0x4a0
 ? dsl_dataset_block_born+0x244/0x380 [zfs]
 dbuf_write_done+0x3c/0x1e0 [zfs]
 arc_write_done+0x8f/0x420 [zfs]
 zio_done+0x403/0x1160 [zfs]
 zio_execute+0x81/0x120 [zfs]
 taskq_thread+0x28e/0x4b0 [spl]
 ? __switch_to_asm+0x40/0x70
 ? wake_up_q+0x60/0x60
 ? zio_subblock+0x30/0x30 [zfs]
 ? taskq_thread_spawn+0x50/0x50 [spl]
 kthread+0x117/0x130
 ? __kthread_bind_mask+0x60/0x60
 ret_from_fork+0x22/0x40

@phreaker0
Copy link

Just hit it again on a different machine with the same hardware setup:

[4390903.430198] VERIFY3(c < SPA_MAXBLOCKSIZE >> SPA_MINBLOCKSHIFT) failed (36028797018963967 < 32768)
[4390903.431222] PANIC at zio.c:314:zio_data_buf_alloc()
[4390903.432096] Showing stack for process 9895
[4390903.432963] CPU: 5 PID: 9895 Comm: kworker/u64:1 Tainted: P           OE     4.19.0-14-amd64 #1 Debian 4.19.171-2
[4390903.433861] Hardware name: To Be Filled By O.E.M. To Be Filled By O.E.M./X470D4U2-2T, BIOS P3.20 08/13/2019
[4390903.434802] Workqueue: writeback wb_workfn (flush-zfs-615)
[4390903.435695] Call Trace:
[4390903.436578]  dump_stack+0x66/0x81
[4390903.437264]  spl_panic+0xd3/0xfb [spl]
[4390903.437847]  ? spl_kmem_cache_alloc+0x6f/0x7a0 [spl]
[4390903.438408]  ? kmem_cache_alloc+0x167/0x1d0
[4390903.438959]  ? spl_kmem_cache_alloc+0x152/0x7a0 [spl]
[4390903.439513]  ? _cond_resched+0x15/0x30
[4390903.440066]  ? mutex_lock+0xe/0x30
[4390903.440674]  zio_data_buf_alloc+0x52/0x60 [zfs]
[4390903.441249]  abd_alloc_linear+0x7f/0xc0 [zfs]
[4390903.441823]  arc_hdr_alloc_abd+0x56/0xb0 [zfs]
[4390903.442402]  arc_hdr_alloc+0xed/0x160 [zfs]
[4390903.442957]  arc_alloc_buf+0x45/0xd0 [zfs]
[4390903.443498]  dbuf_alloc_arcbuf_from_arcbuf+0xf7/0x190 [zfs]
[4390903.443994]  ? _cond_resched+0x15/0x30
[4390903.444481]  ? mutex_lock+0xe/0x30
[4390903.444993]  dbuf_hold_copy.isra.19+0x31/0xa0 [zfs]
[4390903.445502]  dbuf_hold_impl+0x43e/0x600 [zfs]
[4390903.446007]  dbuf_hold_level+0x2b/0x60 [zfs]
[4390903.446522]  dmu_tx_check_ioerr+0x32/0xc0 [zfs]
[4390903.447032]  dmu_tx_count_write+0xe5/0x1a0 [zfs]
[4390903.447541]  dmu_tx_hold_write+0x3c/0x50 [zfs]
[4390903.448055]  zfs_putpage+0x1b4/0x530 [zfs]
[4390903.448526]  ? rmap_walk_file+0x126/0x260
[4390903.448992]  ? page_mkclean+0xa4/0xc0
[4390903.449456]  ? __set_page_dirty_buffers+0x92/0xf0
[4390903.449963]  zpl_putpage+0x31/0x40 [zfs]
[4390903.450442]  write_cache_pages+0x1aa/0x440
[4390903.450946]  ? zpl_writepages+0x160/0x160 [zfs]
[4390903.451537]  ? do_wait_intr_irq+0xaf/0xb0
[4390903.452186]  zpl_writepages+0x8a/0x160 [zfs]
[4390903.452780]  do_writepages+0x41/0xd0
[4390903.453395]  ? __wb_calc_thresh+0x3a/0x120
[4390903.453984]  ? wb_calc_thresh+0x4f/0x70
[4390903.454570]  __writeback_single_inode+0x3d/0x350
[4390903.455160]  writeback_sb_inodes+0x1e7/0x440
[4390903.455739]  __writeback_inodes_wb+0x5f/0xc0
[4390903.456308]  wb_writeback+0x25b/0x2f0
[4390903.456874]  wb_workfn+0x30d/0x400
[4390903.457439]  ? sched_clock_cpu+0xc/0xb0
[4390903.458002]  process_one_work+0x1a7/0x3a0
[4390903.458575]  worker_thread+0x30/0x390
[4390903.459121]  ? create_worker+0x1a0/0x1a0
[4390903.459654]  kthread+0x112/0x130
[4390903.460180]  ? kthread_bind+0x30/0x30
[4390903.460692]  ret_from_fork+0x22/0x40

@tlaguz
Copy link

tlaguz commented Apr 23, 2021

Hello, happened to me tomorrow morning. Below are my logs. After crash only SSD pool was not accessible. SSD zpool configuration also posted below, this is an encrypted stripe of four mirrors. Operating System is Proxmox, updated and restarted 26 days ago and then updated without a restart yesterday.

> zfs --version
zfs-2.0.4-pve1
zfs-kmod-2.0.4-pve1
> uname -a
Linux Zeus 5.4.106-1-pve #1 SMP PVE 5.4.106-1 (Fri, 19 Mar 2021 11:08:47 +0100) x86_64 GNU/Linux
[2256241.882666] VERIFY3(c < SPA_MAXBLOCKSIZE >> SPA_MINBLOCKSHIFT) failed (36028797018963967 < 32768)
[2256241.883180] PANIC at zio.c:314:zio_data_buf_alloc()
[2256241.883606] Showing stack for process 647
[2256241.884016] CPU: 10 PID: 647 Comm: zvol Tainted: P           O      5.4.106-1-pve #1
[2256241.884431] Hardware name: Dell Inc. PowerEdge R720/0C4Y3R, BIOS 2.9.0 12/06/2019
[2256241.884855] Call Trace:
[2256241.885281]  dump_stack+0x6d/0x8b
[2256241.885701]  spl_dumpstack+0x29/0x2b [spl]
[2256241.886122]  spl_panic+0xd3/0xfb [spl]
[2256241.886536]  ? sg_kmalloc+0x19/0x30
[2256241.886997]  ? bmov+0x17/0x20 [zfs]
[2256241.887408]  ? _cond_resched+0x19/0x30
[2256241.887814]  ? kmem_cache_alloc+0x17e/0x240
[2256241.888226]  ? spl_kmem_cache_alloc+0x7c/0x770 [spl]
[2256241.888635]  ? spl_kmem_cache_alloc+0x14d/0x770 [spl]
[2256241.889043]  ? _cond_resched+0x19/0x30
[2256241.889454]  ? mutex_lock+0x12/0x30
[2256241.889920]  zio_data_buf_alloc+0x58/0x60 [zfs]
[2256241.890357]  abd_alloc_linear+0x88/0xc0 [zfs]
[2256241.890790]  abd_alloc+0x8e/0xd0 [zfs]
[2256241.891224]  arc_get_data_abd.isra.44+0x45/0x70 [zfs]
[2256241.891660]  arc_hdr_alloc_abd+0x5d/0xb0 [zfs]
[2256241.892091]  arc_hdr_alloc+0xec/0x160 [zfs]
[2256241.892522]  arc_alloc_buf+0x4c/0xd0 [zfs]
[2256241.892947]  dbuf_alloc_arcbuf_from_arcbuf+0xf6/0x180 [zfs]
[2256241.893353]  ? _cond_resched+0x19/0x30
[2256241.893752]  ? _cond_resched+0x19/0x30
[2256241.894173]  dbuf_hold_copy.isra.24+0x36/0xb0 [zfs]
[2256241.894599]  dbuf_hold_impl+0x43b/0x600 [zfs]
[2256241.895024]  dbuf_hold+0x33/0x60 [zfs]
[2256241.895450]  dmu_buf_hold_array_by_dnode+0xe6/0x4a0 [zfs]
[2256241.895886]  dmu_read_impl+0xae/0x170 [zfs]
[2256241.896324]  dmu_read_by_dnode+0xe/0x10 [zfs]
[2256241.896766]  zvol_get_data+0xa0/0x170 [zfs]
[2256241.897204]  zil_commit_impl+0x9d6/0xdb0 [zfs]
[2256241.897648]  zil_commit+0x3d/0x60 [zfs]
[2256241.898081]  zvol_write+0x325/0x4e0 [zfs]
[2256241.898469]  ? __switch_to+0x85/0x480
[2256241.898863]  taskq_thread+0x2f7/0x4e0 [spl]
[2256241.899250]  ? wake_up_q+0x80/0x80
[2256241.899678]  ? zvol_os_create_minor+0x7a0/0x7a0 [zfs]
[2256241.900067]  kthread+0x120/0x140
[2256241.900451]  ? task_done+0xb0/0xb0 [spl]
[2256241.900837]  ? kthread_park+0x90/0x90
[2256241.901221]  ret_from_fork+0x35/0x40
[2256392.655126] INFO: task zvol:647 blocked for more than 120 seconds.
[2256392.656318]       Tainted: P           O      5.4.106-1-pve #1
[2256392.657378] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[2256392.658409] zvol            D    0   647      2 0x80004000
[2256392.659448] Call Trace:
[2256392.660448]  __schedule+0x2e6/0x700
[2256392.661424]  schedule+0x33/0xa0
[2256392.662385]  spl_panic+0xf9/0xfb [spl]
[2256392.663354]  ? sg_kmalloc+0x19/0x30
[2256392.664397]  ? bmov+0x17/0x20 [zfs]
[2256392.665321]  ? _cond_resched+0x19/0x30
[2256392.666247]  ? kmem_cache_alloc+0x17e/0x240
[2256392.667210]  ? spl_kmem_cache_alloc+0x7c/0x770 [spl]
[2256392.668162]  ? spl_kmem_cache_alloc+0x14d/0x770 [spl]
[2256392.669101]  ? _cond_resched+0x19/0x30
[2256392.670035]  ? mutex_lock+0x12/0x30
[2256392.671075]  zio_data_buf_alloc+0x58/0x60 [zfs]
[2256392.672118]  abd_alloc_linear+0x88/0xc0 [zfs]
[2256392.673129]  abd_alloc+0x8e/0xd0 [zfs]
[2256392.674140]  arc_get_data_abd.isra.44+0x45/0x70 [zfs]
[2256392.675184]  arc_hdr_alloc_abd+0x5d/0xb0 [zfs]
[2256392.676209]  arc_hdr_alloc+0xec/0x160 [zfs]
[2256392.677223]  arc_alloc_buf+0x4c/0xd0 [zfs]
[2256392.678233]  dbuf_alloc_arcbuf_from_arcbuf+0xf6/0x180 [zfs]
[2256392.679198]  ? _cond_resched+0x19/0x30
[2256392.680149]  ? _cond_resched+0x19/0x30
[2256392.681166]  dbuf_hold_copy.isra.24+0x36/0xb0 [zfs]
[2256392.682187]  dbuf_hold_impl+0x43b/0x600 [zfs]
[2256392.683218]  dbuf_hold+0x33/0x60 [zfs]
[2256392.684242]  dmu_buf_hold_array_by_dnode+0xe6/0x4a0 [zfs]
[2256392.685277]  dmu_read_impl+0xae/0x170 [zfs]
[2256392.686305]  dmu_read_by_dnode+0xe/0x10 [zfs]
[2256392.687389]  zvol_get_data+0xa0/0x170 [zfs]
[2256392.688450]  zil_commit_impl+0x9d6/0xdb0 [zfs]
[2256392.689503]  zil_commit+0x3d/0x60 [zfs]
[2256392.690547]  zvol_write+0x325/0x4e0 [zfs]
[2256392.691518]  ? __switch_to+0x85/0x480
[2256392.692467]  taskq_thread+0x2f7/0x4e0 [spl]
[2256392.693414]  ? wake_up_q+0x80/0x80
[2256392.694457]  ? zvol_os_create_minor+0x7a0/0x7a0 [zfs]
[2256392.695438]  kthread+0x120/0x140
[2256392.696398]  ? task_done+0xb0/0xb0 [spl]
[2256392.697349]  ? kthread_park+0x90/0x90
[2256392.698296]  ret_from_fork+0x35/0x40
[2256392.699331] INFO: task z_wr_int:5030 blocked for more than 120 seconds.
[2256392.700298]       Tainted: P           O      5.4.106-1-pve #1
[2256392.701274] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[2256392.702282] z_wr_int        D    0  5030      2 0x80004000
[2256392.703312] Call Trace:
[2256392.704297]  __schedule+0x2e6/0x700
[2256392.705260]  schedule+0x33/0xa0
[2256392.706194]  schedule_preempt_disabled+0xe/0x10
[2256392.707157]  __mutex_lock.isra.10+0x2c9/0x4c0
[2256392.708108]  __mutex_lock_slowpath+0x13/0x20
[2256392.709052]  mutex_lock+0x2c/0x30
[2256392.710070]  dbuf_write_done+0x43/0x220 [zfs]
[2256392.711091]  arc_write_done+0x8f/0x410 [zfs]
[2256392.712177]  zio_done+0x43f/0x1020 [zfs]
[2256392.713240]  zio_execute+0x99/0xf0 [zfs]
[2256392.714200]  taskq_thread+0x2f7/0x4e0 [spl]
[2256392.715178]  ? wake_up_q+0x80/0x80
[2256392.716244]  ? zio_taskq_member.isra.14.constprop.20+0x70/0x70 [zfs]
[2256392.717222]  kthread+0x120/0x140
[2256392.718199]  ? task_done+0xb0/0xb0 [spl]
[2256392.719192]  ? kthread_park+0x90/0x90
[2256392.720164]  ret_from_fork+0x35/0x40
[2256392.721145] INFO: task txg_sync:5281 blocked for more than 120 seconds.
[2256392.722134]       Tainted: P           O      5.4.106-1-pve #1
[2256392.723151] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[2256392.724187] txg_sync        D    0  5281      2 0x80004000
[2256392.725232] Call Trace:
[2256392.726257]  __schedule+0x2e6/0x700
[2256392.727303]  schedule+0x33/0xa0
[2256392.728339]  schedule_timeout+0x152/0x330
[2256392.729370]  ? __next_timer_interrupt+0xd0/0xd0
[2256392.730401]  io_schedule_timeout+0x1e/0x50
[2256392.731461]  __cv_timedwait_common+0x138/0x170 [spl]
[2256392.732504]  ? wait_woken+0x80/0x80
[2256392.733537]  __cv_timedwait_io+0x19/0x20 [spl]
[2256392.734680]  zio_wait+0x139/0x280 [zfs]
[2256392.735736]  ? _cond_resched+0x19/0x30
[2256392.736863]  dsl_pool_sync+0xdc/0x510 [zfs]
[2256392.738002]  spa_sync+0x5a4/0xfe0 [zfs]
[2256392.739060]  ? mutex_lock+0x12/0x30
[2256392.740202]  ? spa_txg_history_init_io+0x104/0x110 [zfs]
[2256392.741360]  txg_sync_thread+0x2e1/0x4a0 [zfs]
[2256392.742521]  ? txg_thread_exit.isra.13+0x60/0x60 [zfs]
[2256392.743615]  thread_generic_wrapper+0x74/0x90 [spl]
[2256392.744677]  kthread+0x120/0x140
[2256392.745736]  ? __thread_exit+0x20/0x20 [spl]
[2256392.746798]  ? kthread_park+0x90/0x90
[2256392.747880]  ret_from_fork+0x35/0x40
[2256392.748931] INFO: task vdev_autotrim:5583 blocked for more than 120 seconds.
[2256392.749995]       Tainted: P           O      5.4.106-1-pve #1
[2256392.751066] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[2256392.752134] vdev_autotrim   D    0  5583      2 0x80004000
[2256392.753204] Call Trace:
[2256392.754263]  __schedule+0x2e6/0x700
[2256392.755432]  ? dmu_tx_destroy+0xd8/0xf0 [zfs]
[2256392.756510]  schedule+0x33/0xa0
[2256392.757572]  io_schedule+0x16/0x40
[2256392.758645]  cv_wait_common+0xb5/0x130 [spl]
[2256392.759737]  ? wait_woken+0x80/0x80
[2256392.760811]  __cv_wait_io+0x18/0x20 [spl]
[2256392.761983]  txg_wait_synced_impl+0xc9/0x110 [zfs]
[2256392.763185]  txg_wait_synced+0x10/0x40 [zfs]
[2256392.764361]  metaslab_enable+0xd7/0x120 [zfs]
[2256392.765539]  vdev_autotrim_thread+0x37b/0x770 [zfs]
[2256392.766725]  ? vdev_trim_restart+0x230/0x230 [zfs]
[2256392.767823]  thread_generic_wrapper+0x74/0x90 [spl]
[2256392.768891]  kthread+0x120/0x140
[2256392.769956]  ? __thread_exit+0x20/0x20 [spl]
[2256392.771025]  ? kthread_park+0x90/0x90
[2256392.772117]  ret_from_fork+0x35/0x40
[2256392.773730] INFO: task kvm:29335 blocked for more than 120 seconds.
[2256392.774825]       Tainted: P           O      5.4.106-1-pve #1
[2256392.775907] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[2256392.776993] kvm             D    0 29335      1 0x00000000
[2256392.778067] Call Trace:
[2256392.779163]  __schedule+0x2e6/0x700
[2256392.780237]  schedule+0x33/0xa0
[2256392.781320]  schedule_timeout+0x205/0x330
[2256392.782523]  ? zvol_request+0x271/0x2f0 [zfs]
[2256392.783621]  ? generic_make_request+0xcf/0x310
[2256392.784690]  io_schedule_timeout+0x1e/0x50
[2256392.785753]  wait_for_completion_io+0xb7/0x140
[2256392.786817]  ? wake_up_q+0x80/0x80
[2256392.787898]  submit_bio_wait+0x61/0x90
[2256392.788959]  blkdev_issue_flush+0x8e/0xc0
[2256392.790020]  blkdev_fsync+0x35/0x50
[2256392.791133]  vfs_fsync_range+0x48/0x80
[2256392.792202]  ? __fget_light+0x59/0x70
[2256392.793258]  do_fsync+0x3d/0x70
[2256392.794291]  __x64_sys_fdatasync+0x17/0x20
[2256392.795344]  do_syscall_64+0x57/0x190
[2256392.796371]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[2256392.797403] RIP: 0033:0x7f6e2010a2e7
[2256392.798436] Code: Bad RIP value.
[2256392.799476] RSP: 002b:00007f65e7ffbcf0 EFLAGS: 00000293 ORIG_RAX: 000000000000004b
[2256392.800547] RAX: ffffffffffffffda RBX: 0000000000000019 RCX: 00007f6e2010a2e7
[2256392.801614] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000019
[2256392.802669] RBP: 000055f2d192e002 R08: 0000000000000000 R09: 00000000ffffffff
[2256392.803724] R10: 00007f65e7ffbce0 R11: 0000000000000293 R12: 000055f2d1ca7398
[2256392.804747] R13: 000055f2d32f3758 R14: 000055f2d32f36e0 R15: 000055f2d3b07b70
[2256513.481685] INFO: task zvol:647 blocked for more than 241 seconds.
[2256513.482931]       Tainted: P           O      5.4.106-1-pve #1
[2256513.484014] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[2256513.485108] zvol            D    0   647      2 0x80004000
[2256513.486234] Call Trace:
[2256513.487345]  __schedule+0x2e6/0x700
[2256513.488427]  schedule+0x33/0xa0
[2256513.489516]  spl_panic+0xf9/0xfb [spl]
[2256513.490615]  ? sg_kmalloc+0x19/0x30
[2256513.491809]  ? bmov+0x17/0x20 [zfs]
[2256513.492889]  ? _cond_resched+0x19/0x30
[2256513.493973]  ? kmem_cache_alloc+0x17e/0x240
[2256513.495042]  ? spl_kmem_cache_alloc+0x7c/0x770 [spl]
[2256513.496109]  ? spl_kmem_cache_alloc+0x14d/0x770 [spl]
[2256513.497162]  ? _cond_resched+0x19/0x30
[2256513.498233]  ? mutex_lock+0x12/0x30
[2256513.499411]  zio_data_buf_alloc+0x58/0x60 [zfs]
[2256513.500537]  abd_alloc_linear+0x88/0xc0 [zfs]
[2256513.501709]  abd_alloc+0x8e/0xd0 [zfs]
[2256513.502814]  arc_get_data_abd.isra.44+0x45/0x70 [zfs]
[2256513.503904]  arc_hdr_alloc_abd+0x5d/0xb0 [zfs]
[2256513.504973]  arc_hdr_alloc+0xec/0x160 [zfs]
[2256513.506055]  arc_alloc_buf+0x4c/0xd0 [zfs]
[2256513.507129]  dbuf_alloc_arcbuf_from_arcbuf+0xf6/0x180 [zfs]
[2256513.508148]  ? _cond_resched+0x19/0x30
[2256513.509166]  ? _cond_resched+0x19/0x30
[2256513.510259]  dbuf_hold_copy.isra.24+0x36/0xb0 [zfs]
[2256513.511343]  dbuf_hold_impl+0x43b/0x600 [zfs]
[2256513.512418]  dbuf_hold+0x33/0x60 [zfs]
[2256513.513487]  dmu_buf_hold_array_by_dnode+0xe6/0x4a0 [zfs]
[2256513.514589]  dmu_read_impl+0xae/0x170 [zfs]
[2256513.515677]  dmu_read_by_dnode+0xe/0x10 [zfs]
[2256513.516782]  zvol_get_data+0xa0/0x170 [zfs]
[2256513.517911]  zil_commit_impl+0x9d6/0xdb0 [zfs]
[2256513.519036]  zil_commit+0x3d/0x60 [zfs]
[2256513.520142]  zvol_write+0x325/0x4e0 [zfs]
[2256513.521160]  ? __switch_to+0x85/0x480
[2256513.522195]  taskq_thread+0x2f7/0x4e0 [spl]
[2256513.523209]  ? wake_up_q+0x80/0x80
[2256513.524308]  ? zvol_os_create_minor+0x7a0/0x7a0 [zfs]
[2256513.525317]  kthread+0x120/0x140
[2256513.526356]  ? task_done+0xb0/0xb0 [spl]
[2256513.527357]  ? kthread_park+0x90/0x90
[2256513.528333]  ret_from_fork+0x35/0x40
[2256513.529367] INFO: task z_wr_int:5030 blocked for more than 241 seconds.
[2256513.530375]       Tainted: P           O      5.4.106-1-pve #1
[2256513.531370] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[2256513.532386] z_wr_int        D    0  5030      2 0x80004000
[2256513.533388] Call Trace:
[2256513.534387]  __schedule+0x2e6/0x700
[2256513.535352]  schedule+0x33/0xa0
[2256513.536288]  schedule_preempt_disabled+0xe/0x10
[2256513.537236]  __mutex_lock.isra.10+0x2c9/0x4c0
[2256513.538204]  __mutex_lock_slowpath+0x13/0x20
[2256513.539162]  mutex_lock+0x2c/0x30
[2256513.540191]  dbuf_write_done+0x43/0x220 [zfs]
[2256513.541216]  arc_write_done+0x8f/0x410 [zfs]
[2256513.542299]  zio_done+0x43f/0x1020 [zfs]
[2256513.543376]  zio_execute+0x99/0xf0 [zfs]
[2256513.544338]  taskq_thread+0x2f7/0x4e0 [spl]
[2256513.545293]  ? wake_up_q+0x80/0x80
[2256513.546373]  ? zio_taskq_member.isra.14.constprop.20+0x70/0x70 [zfs]
[2256513.547354]  kthread+0x120/0x140
[2256513.548336]  ? task_done+0xb0/0xb0 [spl]
[2256513.549308]  ? kthread_park+0x90/0x90
[2256513.550294]  ret_from_fork+0x35/0x40
[2256513.551275] INFO: task txg_sync:5281 blocked for more than 241 seconds.
[2256513.552268]       Tainted: P           O      5.4.106-1-pve #1
[2256513.553263] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[2256513.554311] txg_sync        D    0  5281      2 0x80004000
[2256513.555360] Call Trace:
[2256513.556387]  __schedule+0x2e6/0x700
[2256513.557406]  schedule+0x33/0xa0
[2256513.558453]  schedule_timeout+0x152/0x330
[2256513.559487]  ? __next_timer_interrupt+0xd0/0xd0
[2256513.560515]  io_schedule_timeout+0x1e/0x50
[2256513.561554]  __cv_timedwait_common+0x138/0x170 [spl]
[2256513.562613]  ? wait_woken+0x80/0x80
[2256513.563650]  __cv_timedwait_io+0x19/0x20 [spl]
[2256513.564793]  zio_wait+0x139/0x280 [zfs]
[2256513.565849]  ? _cond_resched+0x19/0x30
[2256513.566977]  dsl_pool_sync+0xdc/0x510 [zfs]
[2256513.568128]  spa_sync+0x5a4/0xfe0 [zfs]
[2256513.569182]  ? mutex_lock+0x12/0x30
[2256513.570343]  ? spa_txg_history_init_io+0x104/0x110 [zfs]
[2256513.571503]  txg_sync_thread+0x2e1/0x4a0 [zfs]
[2256513.572663]  ? txg_thread_exit.isra.13+0x60/0x60 [zfs]
[2256513.573745]  thread_generic_wrapper+0x74/0x90 [spl]
[2256513.574806]  kthread+0x120/0x140
[2256513.575865]  ? __thread_exit+0x20/0x20 [spl]
[2256513.576926]  ? kthread_park+0x90/0x90
[2256513.578002]  ret_from_fork+0x35/0x40
[2256513.579049] INFO: task vdev_autotrim:5583 blocked for more than 241 seconds.
[2256513.580113]       Tainted: P           O      5.4.106-1-pve #1
[2256513.581166] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[2256513.582254] vdev_autotrim   D    0  5583      2 0x80004000
[2256513.583332] Call Trace:
[2256513.584394]  __schedule+0x2e6/0x700
[2256513.585556]  ? dmu_tx_destroy+0xd8/0xf0 [zfs]
[2256513.586649]  schedule+0x33/0xa0
[2256513.587719]  io_schedule+0x16/0x40
[2256513.588800]  cv_wait_common+0xb5/0x130 [spl]
[2256513.589893]  ? wait_woken+0x80/0x80
[2256513.590969]  __cv_wait_io+0x18/0x20 [spl]
[2256513.592145]  txg_wait_synced_impl+0xc9/0x110 [zfs]
[2256513.593324]  txg_wait_synced+0x10/0x40 [zfs]
[2256513.594509]  metaslab_enable+0xd7/0x120 [zfs]
[2256513.595696]  vdev_autotrim_thread+0x37b/0x770 [zfs]
[2256513.596883]  ? vdev_trim_restart+0x230/0x230 [zfs]
[2256513.597978]  thread_generic_wrapper+0x74/0x90 [spl]
[2256513.599048]  kthread+0x120/0x140
[2256513.600115]  ? __thread_exit+0x20/0x20 [spl]
[2256513.601186]  ? kthread_park+0x90/0x90
[2256513.602273]  ret_from_fork+0x35/0x40
[2256513.603430] INFO: task kvm:29335 blocked for more than 241 seconds.
[2256513.604542]       Tainted: P           O      5.4.106-1-pve #1
[2256513.605648] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[2256513.606717] kvm             D    0 29335      1 0x00000000
[2256513.607790] Call Trace:
[2256513.608855]  __schedule+0x2e6/0x700
[2256513.609940]  schedule+0x33/0xa0
[2256513.611009]  schedule_timeout+0x205/0x330
[2256513.612197]  ? zvol_request+0x271/0x2f0 [zfs]
[2256513.613280]  ? generic_make_request+0xcf/0x310
[2256513.614362]  io_schedule_timeout+0x1e/0x50
[2256513.615423]  wait_for_completion_io+0xb7/0x140
[2256513.616488]  ? wake_up_q+0x80/0x80
[2256513.617544]  submit_bio_wait+0x61/0x90
[2256513.618617]  blkdev_issue_flush+0x8e/0xc0
[2256513.619678]  blkdev_fsync+0x35/0x50
[2256513.620729]  vfs_fsync_range+0x48/0x80
[2256513.621799]  ? __fget_light+0x59/0x70
[2256513.622843]  do_fsync+0x3d/0x70
[2256513.623873]  __x64_sys_fdatasync+0x17/0x20
[2256513.624907]  do_syscall_64+0x57/0x190
[2256513.625953]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[2256513.626991] RIP: 0033:0x7f6e2010a2e7
[2256513.628023] Code: Bad RIP value.
[2256513.629046] RSP: 002b:00007f65e7ffbcf0 EFLAGS: 00000293 ORIG_RAX: 000000000000004b
[2256513.630129] RAX: ffffffffffffffda RBX: 0000000000000019 RCX: 00007f6e2010a2e7
[2256513.631203] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000019
[2256513.632257] RBP: 000055f2d192e002 R08: 0000000000000000 R09: 00000000ffffffff
[2256513.633291] R10: 00007f65e7ffbce0 R11: 0000000000000293 R12: 000055f2d1ca7398
[2256513.634326] R13: 000055f2d32f3758 R14: 000055f2d32f36e0 R15: 000055f2d3b07b70
> zpool get all
NAME      PROPERTY                       VALUE                          SOURCE
zeus-ssd  size                           3.47T                          -
zeus-ssd  capacity                       47%                            -
zeus-ssd  altroot                        -                              default
zeus-ssd  health                         ONLINE                         -
zeus-ssd  guid                           16779179751986038685           -
zeus-ssd  version                        -                              default
zeus-ssd  bootfs                         -                              default
zeus-ssd  delegation                     on                             default
zeus-ssd  autoreplace                    off                            default
zeus-ssd  cachefile                      none                           local
zeus-ssd  failmode                       wait                           default
zeus-ssd  listsnapshots                  off                            default
zeus-ssd  autoexpand                     off                            default
zeus-ssd  dedupratio                     1.00x                          -
zeus-ssd  free                           1.82T                          -
zeus-ssd  allocated                      1.65T                          -
zeus-ssd  readonly                       off                            -
zeus-ssd  ashift                         12                             local
zeus-ssd  comment                        -                              default
zeus-ssd  expandsize                     -                              -
zeus-ssd  freeing                        0                              -
zeus-ssd  fragmentation                  38%                            -
zeus-ssd  leaked                         0                              -
zeus-ssd  multihost                      off                            default
zeus-ssd  checkpoint                     -                              -
zeus-ssd  load_guid                      6603875687016436555            -
zeus-ssd  autotrim                       on                             local
zeus-ssd  feature@async_destroy          enabled                        local
zeus-ssd  feature@empty_bpobj            active                         local
zeus-ssd  feature@lz4_compress           active                         local
zeus-ssd  feature@multi_vdev_crash_dump  enabled                        local
zeus-ssd  feature@spacemap_histogram     active                         local
zeus-ssd  feature@enabled_txg            active                         local
zeus-ssd  feature@hole_birth             active                         local
zeus-ssd  feature@extensible_dataset     active                         local
zeus-ssd  feature@embedded_data          active                         local
zeus-ssd  feature@bookmarks              enabled                        local
zeus-ssd  feature@filesystem_limits      enabled                        local
zeus-ssd  feature@large_blocks           enabled                        local
zeus-ssd  feature@large_dnode            active                         local
zeus-ssd  feature@sha512                 enabled                        local
zeus-ssd  feature@skein                  enabled                        local
zeus-ssd  feature@edonr                  enabled                        local
zeus-ssd  feature@userobj_accounting     active                         local
zeus-ssd  feature@encryption             active                         local
zeus-ssd  feature@project_quota          active                         local
zeus-ssd  feature@device_removal         enabled                        local
zeus-ssd  feature@obsolete_counts        enabled                        local
zeus-ssd  feature@zpool_checkpoint       enabled                        local
zeus-ssd  feature@spacemap_v2            active                         local
zeus-ssd  feature@allocation_classes     enabled                        local
zeus-ssd  feature@resilver_defer         enabled                        local
zeus-ssd  feature@bookmark_v2            enabled                        local
zeus-ssd  feature@redaction_bookmarks    enabled                        local
zeus-ssd  feature@redacted_datasets      enabled                        local
zeus-ssd  feature@bookmark_written       enabled                        local
zeus-ssd  feature@log_spacemap           active                         local
zeus-ssd  feature@livelist               enabled                        local
zeus-ssd  feature@device_rebuild         enabled                        local
zeus-ssd  feature@zstd_compress          enabled                        local
NAME      PROPERTY              VALUE                              SOURCE
zeus-ssd  type                  filesystem                         -
zeus-ssd  creation              Wed Aug 19  2:50 2020              -
zeus-ssd  used                  1.65T                              -
zeus-ssd  available             1.71T                              -
zeus-ssd  referenced            200K                               -
zeus-ssd  compressratio         1.55x                              -
zeus-ssd  mounted               no                                 -
zeus-ssd  quota                 none                               default
zeus-ssd  reservation           none                               default
zeus-ssd  recordsize            128K                               default
zeus-ssd  mountpoint            /mnt/ssd                           local
zeus-ssd  sharenfs              off                                default
zeus-ssd  checksum              on                                 default
zeus-ssd  compression           lz4                                local
zeus-ssd  atime                 on                                 default
zeus-ssd  devices               on                                 default
zeus-ssd  exec                  on                                 default
zeus-ssd  setuid                on                                 default
zeus-ssd  readonly              off                                default
zeus-ssd  zoned                 off                                default
zeus-ssd  snapdir               hidden                             default
zeus-ssd  aclmode               discard                            default
zeus-ssd  aclinherit            restricted                         default
zeus-ssd  createtxg             1                                  -
zeus-ssd  canmount              noauto                             local
zeus-ssd  xattr                 sa                                 local
zeus-ssd  copies                1                                  default
zeus-ssd  version               5                                  -
zeus-ssd  utf8only              on                                 -
zeus-ssd  normalization         formD                              -
zeus-ssd  casesensitivity       sensitive                          -
zeus-ssd  vscan                 off                                default
zeus-ssd  nbmand                off                                default
zeus-ssd  sharesmb              off                                default
zeus-ssd  refquota              none                               default
zeus-ssd  refreservation        none                               default
zeus-ssd  guid                  16452799426164107783               -
zeus-ssd  primarycache          all                                default
zeus-ssd  secondarycache        all                                default
zeus-ssd  usedbysnapshots       0B                                 -
zeus-ssd  usedbydataset         200K                               -
zeus-ssd  usedbychildren        1.65T                              -
zeus-ssd  usedbyrefreservation  0B                                 -
zeus-ssd  logbias               latency                            default
zeus-ssd  objsetid              54                                 -
zeus-ssd  dedup                 off                                default
zeus-ssd  mlslabel              none                               default
zeus-ssd  sync                  standard                           default
zeus-ssd  dnodesize             auto                               local
zeus-ssd  refcompressratio      1.00x                              -
zeus-ssd  written               200K                               -
zeus-ssd  logicalused           2.54T                              -
zeus-ssd  logicalreferenced     69.5K                              -
zeus-ssd  volmode               default                            default
zeus-ssd  filesystem_limit      none                               default
zeus-ssd  snapshot_limit        none                               default
zeus-ssd  filesystem_count      none                               default
zeus-ssd  snapshot_count        none                               default
zeus-ssd  snapdev               hidden                             default
zeus-ssd  acltype               posix                              local
zeus-ssd  context               none                               default
zeus-ssd  fscontext             none                               default
zeus-ssd  defcontext            none                               default
zeus-ssd  rootcontext           none                               default
zeus-ssd  relatime              on                                 local
zeus-ssd  redundant_metadata    all                                default
zeus-ssd  overlay               on                                 default
zeus-ssd  encryption            aes-256-gcm                        -
zeus-ssd  keylocation           xxx                                local
zeus-ssd  keyformat             raw                                -
zeus-ssd  pbkdf2iters           0                                  default
zeus-ssd  encryptionroot        zeus-ssd                           -
zeus-ssd  keystatus             available                          -
zeus-ssd  special_small_blocks  0                                  default

@devyn
Copy link

devyn commented May 29, 2021

I believe I just hit this bug too. I am also using aes-256-gcm encryption. Same issue with tasks subsequently locking up, but after a reset everything appeared fine and a scrub completed with no errors.

May 28 21:42:13 Eliza kernel: VERIFY3(c < SPA_MAXBLOCKSIZE >> SPA_MINBLOCKSHIFT) failed (36028797018963967 < 32768)
May 28 21:42:13 Eliza kernel: PANIC at zio.c:314:zio_data_buf_alloc()
May 28 21:42:13 Eliza kernel: Showing stack for process 172066
May 28 21:42:13 Eliza kernel: CPU: 11 PID: 172066 Comm: postgres Tainted: P        W  OE     5.12.6-arch1-2-vfio #1
May 28 21:42:13 Eliza kernel: Hardware name: Gigabyte Technology Co., Ltd. X399 DESIGNARE EX/X399 DESIGNARE EX-CF, BIOS F12 12/11>
May 28 21:42:13 Eliza kernel: Call Trace:
May 28 21:42:13 Eliza kernel:  dump_stack+0x76/0x94
May 28 21:42:13 Eliza kernel:  spl_panic+0xef/0x117 [spl]
May 28 21:42:13 Eliza kernel:  ? hdr_full_cons+0xef/0x100 [zfs]
May 28 21:42:13 Eliza kernel:  ? aggsum_add+0x174/0x190 [zfs]
May 28 21:42:13 Eliza kernel:  zio_data_buf_alloc+0x55/0x60 [zfs]
May 28 21:42:13 Eliza kernel:  abd_alloc_linear+0x8a/0xc0 [zfs]
May 28 21:42:13 Eliza kernel:  arc_hdr_alloc_abd+0xdf/0x1e0 [zfs]
May 28 21:42:13 Eliza kernel:  arc_hdr_alloc+0x104/0x170 [zfs]
May 28 21:42:13 Eliza kernel:  arc_alloc_buf+0x4e/0x150 [zfs]
May 28 21:42:13 Eliza kernel:  dbuf_alloc_arcbuf_from_arcbuf+0x10e/0x1a0 [zfs]
May 28 21:42:13 Eliza kernel:  dbuf_hold_copy.constprop.0+0x31/0xa0 [zfs]
May 28 21:42:13 Eliza kernel:  dbuf_hold_impl+0x45d/0x6b0 [zfs]
May 28 21:42:13 Eliza kernel:  dbuf_hold_level+0x33/0x60 [zfs]
May 28 21:42:13 Eliza kernel:  dmu_tx_check_ioerr+0x35/0xd0 [zfs]
May 28 21:42:13 Eliza kernel:  dmu_tx_count_write+0xe0/0x1a0 [zfs]
May 28 21:42:13 Eliza kernel:  dmu_tx_hold_write_by_dnode+0x35/0x50 [zfs]
May 28 21:42:13 Eliza kernel:  zfs_write+0x446/0xcc0 [zfs]
May 28 21:42:13 Eliza kernel:  zpl_iter_write+0x114/0x1b0 [zfs]
May 28 21:42:13 Eliza kernel:  new_sync_write+0x159/0x1f0
May 28 21:42:13 Eliza kernel:  vfs_write+0x1ff/0x290
May 28 21:42:13 Eliza kernel:  __x64_sys_pwrite64+0x8c/0xc0
May 28 21:42:13 Eliza kernel:  do_syscall_64+0x33/0x40
May 28 21:42:13 Eliza kernel:  entry_SYSCALL_64_after_hwframe+0x44/0xae
May 28 21:42:13 Eliza kernel: RIP: 0033:0x7faaa46ddea4
May 28 21:42:13 Eliza kernel: Code: c0 ff ff ff ff eb b6 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 8b 05 aa e5 00 00 49 89 ca >
May 28 21:42:13 Eliza kernel: RSP: 002b:00007fffc1972788 EFLAGS: 00000246 ORIG_RAX: 0000000000000012
May 28 21:42:13 Eliza kernel: RAX: ffffffffffffffda RBX: 00000000000042b8 RCX: 00007faaa46ddea4
May 28 21:42:13 Eliza kernel: RDX: 0000000000002000 RSI: 000055804d028730 RDI: 0000000000000139
May 28 21:42:13 Eliza kernel: RBP: 00007fffc19727e0 R08: 000000000a000001 R09: 000055804aa38364
May 28 21:42:13 Eliza kernel: R10: 0000000000666000 R11: 0000000000000246 R12: 0000000000002000
May 28 21:42:13 Eliza kernel: R13: 0000000000002000 R14: 0000000000666000 R15: 00007faaa0fd95b8

@robn
Copy link
Contributor

robn commented Jun 10, 2021

We hit this ourselves today on 2.0.4, 2x12 raidz2, zstd + encryption enabled.

[Wed Jun  9 18:42:10 2021] VERIFY3(c < SPA_MAXBLOCKSIZE >> SPA_MINBLOCKSHIFT) failed (36028797018963967 < 32768)
[Wed Jun  9 18:42:10 2021] PANIC at zio.c:314:zio_data_buf_alloc()
[Wed Jun  9 18:42:10 2021] Showing stack for process 1740490
[Wed Jun  9 18:42:10 2021] CPU: 3 PID: 1740490 Comm: sync_client Tainted: P           OE     5.10.0-0.bpo.4-amd64 #1 Debian 5.10.19-1~bpo10+1
[Wed Jun  9 18:42:10 2021] Hardware name: Supermicro AS -2113S-WN24RT/H11SSW-NT, BIOS 2.2 10/08/2020
[Wed Jun  9 18:42:10 2021] Call Trace:
[Wed Jun  9 18:42:10 2021]  dump_stack+0x6d/0x88
[Wed Jun  9 18:42:10 2021]  spl_panic+0xd3/0xfb [spl]
[Wed Jun  9 18:42:10 2021]  ? spl_kmem_cache_alloc+0x6f/0x7a0 [spl]
[Wed Jun  9 18:42:10 2021]  ? kmem_cache_alloc+0x30c/0x420
[Wed Jun  9 18:42:10 2021]  ? spl_kmem_cache_alloc+0x152/0x7a0 [spl]
[Wed Jun  9 18:42:10 2021]  ? _cond_resched+0x15/0x30
[Wed Jun  9 18:42:10 2021]  ? mutex_lock+0xe/0x30
[Wed Jun  9 18:42:10 2021]  zio_data_buf_alloc+0x52/0x60 [zfs]
[Wed Jun  9 18:42:10 2021]  abd_alloc_linear+0x7f/0xc0 [zfs]
[Wed Jun  9 18:42:10 2021]  arc_hdr_alloc_abd+0x56/0xb0 [zfs]
[Wed Jun  9 18:42:10 2021]  arc_hdr_alloc+0xed/0x160 [zfs]
[Wed Jun  9 18:42:10 2021]  arc_alloc_buf+0x45/0xd0 [zfs]
[Wed Jun  9 18:42:10 2021]  dbuf_alloc_arcbuf_from_arcbuf+0xf7/0x190 [zfs]
[Wed Jun  9 18:42:10 2021]  ? _cond_resched+0x15/0x30
[Wed Jun  9 18:42:10 2021]  ? mutex_lock+0xe/0x30
[Wed Jun  9 18:42:10 2021]  dbuf_hold_copy.isra.21+0x31/0xa0 [zfs]
[Wed Jun  9 18:42:10 2021]  dbuf_hold_impl+0x43e/0x600 [zfs]
[Wed Jun  9 18:42:10 2021]  dbuf_hold+0x2c/0x60 [zfs]
[Wed Jun  9 18:42:10 2021]  dmu_buf_hold_array_by_dnode+0xda/0x4a0 [zfs]
[Wed Jun  9 18:42:10 2021]  dmu_read_uio_dnode+0x47/0xf0 [zfs]
[Wed Jun  9 18:42:10 2021]  ? zfs_rangelock_enter_impl+0x25b/0x560 [zfs]
[Wed Jun  9 18:42:10 2021]  dmu_read_uio_dbuf+0x3f/0x60 [zfs]
[Wed Jun  9 18:42:10 2021]  zfs_read+0x135/0x3b0 [zfs]
[Wed Jun  9 18:42:10 2021]  zpl_iter_read+0xe3/0x180 [zfs]
[Wed Jun  9 18:42:10 2021]  new_sync_read+0x118/0x1a0
[Wed Jun  9 18:42:10 2021]  vfs_read+0xf1/0x180
[Wed Jun  9 18:42:10 2021]  ksys_read+0x59/0xd0
[Wed Jun  9 18:42:10 2021]  do_syscall_64+0x33/0x80
[Wed Jun  9 18:42:10 2021]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[Wed Jun  9 18:42:10 2021] RIP: 0033:0x7fb898d99461
[Wed Jun  9 18:42:10 2021] Code: fe ff ff 50 48 8d 3d fe d0 09 00 e8 e9 03 02 00 66 0f 1f 84 00 00 00 00 00 48 8d 05 99 62 0d 00 8b 00 85 c0 75 13 31 c0 0f 05 <48> 3d 00 f0 ff ff 77 57 c3 66 0f 1f 44 00 00 41 54 49 89 d4 55 48
[Wed Jun  9 18:42:10 2021] RSP: 002b:00007ffcb7f74ef8 EFLAGS: 00000246 ORIG_RAX: 0000000000000000
[Wed Jun  9 18:42:10 2021] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007fb898d99461
[Wed Jun  9 18:42:10 2021] RDX: 0000000000001000 RSI: 000055e49ef96030 RDI: 0000000000000005
[Wed Jun  9 18:42:10 2021] RBP: 00007ffcb7f75020 R08: 0000000000000000 R09: 00007fb898e6acf0
[Wed Jun  9 18:42:10 2021] R10: 000055e49eebf010 R11: 0000000000000246 R12: 000055e49de5f1a0
[Wed Jun  9 18:42:10 2021] R13: 00007ffcb7f75670 R14: 0000000000000000 R15: 0000000000000000

One of our programmers has been trying to follow the trace back through the source code, and says:

  • it looks like its trying to copy a block with PSIZE of zero (that is, a hole or embedded block)
  • basically its not safe to call arc_hdr_alloc_abd for a hdr with a zero PSIZE and alloc_rdata set

Meanwhile, we're looking at further debugging we can add. Switching the ASSERT to a VERIFY as described in #11531 (comment) seems like a sensible start.

As relative ZFS greenhorns, its not clear if zero is allowed here. We thought to try and log when we see one and include block id, flags etc so maybe we could use zdb to look around on disk, and also to see if it comes up much or if it immediately crashes on the first one, but we're not entirely sure what we'd do with that info either way.

I actually have the machine up right now, with ZFS stopped after panic. I'm trying to get us set up for live kernel memory debugging without upsetting anything, so if there's anything that would be useful and you can tell me how to get it, let me know (in the next 24hrs, I can't keep this machine offline forever).

@chrisrd
Copy link
Contributor

chrisrd commented Jun 10, 2021

I also don't know if zero should be allowed in this code. Given the asserts, I guess not - but it's possible other things have changed in the meantime which would make zero size ok.

I also don't have any particular knowledge of this code, I've just been reading through it and trying to analyse what's going on. I was hoping my prior analysis might prompt whomever had recently touched this area to get involved but it seems they're also not in a position to do so. I'm only able to look at this stuff when I have spare time, and unfortunately I'm not going to have any significant spare time in the near (and maybe medium 😞) future.

If I had the time I'd be trying to look into tracing where the zero size is coming from, per @behlendorf's comment at #11531 (comment) Perhaps your programmer could start with there?

@aerusso
Copy link
Contributor

aerusso commented Jun 10, 2021

If anyone is feeling particularly daring, they can try this branch of mine which reverts the arc_buf consolidation in question. It's not a simple revert of that commit because 10b3c7f clashes with it -- so that patch set tries to be as transparent as possible by partially reverting the zstd support commit, reverting the commit in question, and then reverting the revert commit.

I ran this through the ZTS back when I has re-based it on top of 2.0.4, but it's now re-based on top of tonyhutter's zfs-2.0.5 staging branch. I'm currently running the ZTS on it right now (on a machine of my own in addition to with the official testrunners).

robn added a commit to fastmailops/zfs that referenced this issue Jun 10, 2021
@robn
Copy link
Contributor

robn commented Jun 10, 2021

We've reintroduced the server that failed to production (as a hot spare for our application only at this point) with fastmailops/zfs@946ff14 applied, which enables (changes to VERIFY) a couple of assertions and adds a couple of new ones, all trying to help localise the problem of trying to allocate for a zero-sized block (basically @behlendorf's suggestion).

I'll be running in this mode until at least next week, and if it doesn't turn up anything, I'll consider reintroducing the server to active service. I'm wary of it as its an awkward failure to clean up from, but also, this machine has been running for weeks in various modes and hasn't shown an issue, so I don't have a lot of confidence that it'll just magically reappear.

If anyone can reproduce more reliably, it'd be great if they could try a similar patch. If anyone knows how to induce a failure, do share!

@robn
Copy link
Contributor

robn commented Jun 10, 2021

@aerusso Good-looking patch series. I'm holding it in my back pocket for the moment because I'd like to see if we can understand the problem first. There's definitely a future where I give it a try, if we start to reproduce the crash more often and don't have an easy answer. I'm glad to have it available, thank you!

@robn
Copy link
Contributor

robn commented Jun 11, 2021

I spent some hours today working backward from the crash site to try and piece together how we got there. I don't have concrete answers, but I think maybe I have a place where an expert could start looking.

As best as I can tell, arc_alloc_buf cannot, by design, create a zero-sized ARC header & buffer (at least for the unencrypted, uncompressed option). Maybe its supposed to be able, but I don't see a way that it possibly can.

Given that, there's only one other place way a zero-sized header can be obtained, which is through arc_write_ready if the thing being written is a "hole". I'm not sure if the resultant arc_hdr_buf_t is a convenience wrapper or actually "in" the ARC though.

So, I was lead to look at the caller, dbuf_alloc_arcbuf_from_arcbuf, and I think there may be a bug here. In 13fac09, this function was created to consolidate three similar bits of code into one. In the change to dbuf_hold_copy, the call to arc_alloc_buf used to take db->db.db_size as the size for the new arcbuf, whereas now it takes (effectively) arc_buf_size(db->db_buf).

Now I don't know anything about the dbuf system (I got tired!), but there's enough evidence from assignments, checks and assertions that the expectation is that db_size is non-zero (I think actually a multiple of a block size), and also from dbuf_hold_copy trying to call bcopy on it immediately after allocating it - clearly there's an expectation that the buffer exists!

In the previous version, if the "old" arcbuf in db_buf was zero-sized, but db_size was not, then it would have been a non-zero allocation and continue working. I don't know what under what circumstances we might get here, but it does seem like the action taken is subtly different after 13fac09.

(Much longer analysis notes at https://gist.github.com/robn/42c0f77a30f666136e4477a3dc3ae827).

I'd love it if someone could check my working and tell me if this gets us closer to the truth or just shows how confused I am. Thanks!

@robn
Copy link
Contributor

robn commented Jun 11, 2021

@chrisrd sorry, now that I've had a chance to absorb all this I realised that you'd already come to the same conclusion! Still, I don't feel bad having arrived at it from first principles.

Tomorrow I'll try to make a test case. I don't k ow if I can, but I've got a couple of ideas on how to start (mostly turn of encryption and compression and try to make some zero extents in an effort to force these code paths into play).

aerusso added a commit to aerusso/zfs that referenced this issue Jun 16, 2021
This reverts commit 13fac09.

Per the discussion in openzfs#11531, the reverted commit---which intended only
to be a cleanup commit---introduced a subtle, unintended change in
behavior.

Suggested-by: @chrisrd
Suggested-by: robn@despairlabs.com
Signed-off-by: Antonio Russo <aerusso@aerusso.net>
behlendorf pushed a commit that referenced this issue Jun 24, 2021
This reverts commit 13fac09.

Per the discussion in #11531, the reverted commit---which intended only
to be a cleanup commit---introduced a subtle, unintended change in
behavior.

Care was taken to partially revert and then reapply 10b3c7f
which would otherwise have caused a conflict.  These changes were
squashed in to this commit.

Reviewed-by: Brian Behlendorf <behlendorf1@llnl.gov>
Suggested-by: @chrisrd
Suggested-by: robn@despairlabs.com
Signed-off-by: Antonio Russo <aerusso@aerusso.net>
Closes #11531 
Closes #12227
aerusso added a commit to aerusso/zfs that referenced this issue Jul 10, 2021
This reverts commit 13fac09.

Per the discussion in openzfs#11531, the reverted commit---which intended only
to be a cleanup commit---introduced a subtle, unintended change in
behavior.

Care was taken to partially revert and then reapply 10b3c7f
which would otherwise have caused a conflict.  These changes were
squashed in to this commit.

Reviewed-by: Brian Behlendorf <behlendorf1@llnl.gov>
Suggested-by: @chrisrd
Suggested-by: robn@despairlabs.com
Signed-off-by: Antonio Russo <aerusso@aerusso.net>
Closes openzfs#11531
Closes openzfs#12227
tonyhutter pushed a commit that referenced this issue Aug 31, 2021
This reverts commit 13fac09.

Per the discussion in #11531, the reverted commit---which intended only
to be a cleanup commit---introduced a subtle, unintended change in
behavior.

Care was taken to partially revert and then reapply 10b3c7f
which would otherwise have caused a conflict.  These changes were
squashed in to this commit.

Reviewed-by: Brian Behlendorf <behlendorf1@llnl.gov>
Suggested-by: @chrisrd
Suggested-by: robn@despairlabs.com
Signed-off-by: Antonio Russo <aerusso@aerusso.net>
Closes #11531
Closes #12227
tonyhutter pushed a commit that referenced this issue Sep 22, 2021
This reverts commit 13fac09.

Per the discussion in #11531, the reverted commit---which intended only
to be a cleanup commit---introduced a subtle, unintended change in
behavior.

Care was taken to partially revert and then reapply 10b3c7f
which would otherwise have caused a conflict.  These changes were
squashed in to this commit.

Reviewed-by: Brian Behlendorf <behlendorf1@llnl.gov>
Suggested-by: @chrisrd
Suggested-by: robn@despairlabs.com
Signed-off-by: Antonio Russo <aerusso@aerusso.net>
Closes #11531
Closes #12227
@verymilan
Copy link

verymilan commented Jan 15, 2022

Hi there, i am currently being hunted by this problem. It appears to be triggered by a big pg_dump backupfile, but weirdly does not happen every time (i couldn't track it down further so far and am not sure on what the issue depends on in my case). I have installed ZFS from backports in Debian as suggested by the wiki. It is at 2.0.3. Should i change the source to get a newer version?

Didn't see these referenced commits mentioned in releasenotes, that's why i am asking like this... .

Edit: oops, looks like i have forgotten to update that 90_zfs file. Upgrading now, i hope fixes are included.

Carlo-Hu pushed a commit to Carlo-Hu/zfsonlinux that referenced this issue Feb 23, 2022
see openzfs/zfs#11531

Signed-off-by: Thomas Lamprecht <t.lamprecht@proxmox.com>
@chromakode
Copy link

I'm experiencing something similar with zfs-2.1.9-2ubuntu1 on Ubuntu 23.04. I've seen ZFS panic with this error twice in the past week.

Once the panic occurs, software on the host doing disk IO will hang, and rebooting/shutting down the system seems to hang as well.

Here's a recent trace from dmesg:

[36604.691204] VERIFY3(c < SPA_MAXBLOCKSIZE >> SPA_MINBLOCKSHIFT) failed (36028797018963967 < 32768)
[36604.691212] PANIC at zio.c:341:zio_data_buf_alloc()
[36604.691216] Showing stack for process 2291584
[36604.691218] CPU: 6 PID: 2291584 Comm: z_wr_iss Tainted: P           O       6.2.0-20-generic #20-Ubuntu
[36604.691221] Hardware name: Framework Laptop/FRANBMCP06, BIOS 03.09 06/17/2022
[36604.691223] Call Trace:
[36604.691225]  <TASK>
[36604.691229]  dump_stack_lvl+0x48/0x70
[36604.691238]  dump_stack+0x10/0x20
[36604.691243]  spl_dumpstack+0x29/0x40 [spl]
[36604.691260]  spl_panic+0xfc/0x120 [spl]
[36604.691277]  ? percpu_counter_inc+0xe/0x20 [spl]
[36604.691293]  zio_data_buf_alloc+0x70/0x90 [zfs]
[36604.691486]  abd_alloc_linear+0x41/0xb0 [zfs]
[36604.691558]  vdev_raidz_map_alloc+0x2bf/0x3e0 [zfs]
[36604.691704]  ? percpu_counter_inc+0xe/0x20 [spl]
[36604.691717]  vdev_raidz_io_start+0x2f/0xa0 [zfs]
[36604.691874]  zio_vdev_io_start+0x10e/0x2d0 [zfs]
[36604.692047]  zio_nowait+0xa6/0x140 [zfs]
[36604.692192]  vdev_mirror_io_start+0xa7/0x250 [zfs]
[36604.692337]  zio_vdev_io_start+0x23c/0x2d0 [zfs]
[36604.692566]  ? taskq_of_curthread+0x14/0x20 [spl]
[36604.692580]  zio_execute+0x8f/0xf0 [zfs]
[36604.692752]  taskq_thread+0x226/0x400 [spl]
[36604.692767]  ? __pfx_default_wake_function+0x10/0x10
[36604.692771]  ? __pfx_zio_execute+0x10/0x10 [zfs]
[36604.692927]  ? __pfx_taskq_thread+0x10/0x10 [spl]
[36604.692940]  kthread+0xe6/0x110
[36604.692944]  ? __pfx_kthread+0x10/0x10
[36604.692946]  ret_from_fork+0x29/0x50
[36604.692950]  </TASK>
[36733.926263] INFO: task txg_sync:7899 blocked for more than 120 seconds.
[36733.926278]       Tainted: P           O       6.2.0-20-generic #20-Ubuntu
[36733.926282] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[36733.926286] task:txg_sync        state:D stack:0     pid:7899  ppid:2      flags:0x00004000
[36733.926292] Call Trace:
[36733.926295]  <TASK>
[36733.926300]  __schedule+0x2aa/0x610
[36733.926310]  schedule+0x63/0x110
[36733.926314]  schedule_timeout+0x95/0x170
[36733.926319]  ? __pfx_process_timeout+0x10/0x10
[36733.926325]  io_schedule_timeout+0x51/0x80
[36733.926332]  __cv_timedwait_common+0x139/0x180 [spl]
[36733.926353]  ? __pfx_autoremove_wake_function+0x10/0x10
[36733.926360]  __cv_timedwait_io+0x19/0x30 [spl]
[36733.926380]  zio_wait+0x116/0x230 [zfs]
[36733.927059]  dsl_pool_sync+0xb7/0x400 [zfs]
[36733.927283]  spa_sync_iterate_to_convergence+0xde/0x200 [zfs]
[36733.927469]  spa_sync+0x2e9/0x5e0 [zfs]
[36733.927650]  txg_sync_thread+0x20c/0x290 [zfs]
[36733.927842]  ? __pfx_txg_sync_thread+0x10/0x10 [zfs]
[36733.928033]  ? __pfx_thread_generic_wrapper+0x10/0x10 [spl]
[36733.928051]  thread_generic_wrapper+0x5c/0x70 [spl]
[36733.928067]  kthread+0xe6/0x110
[36733.928072]  ? __pfx_kthread+0x10/0x10
[36733.928081]  ret_from_fork+0x29/0x50
[36733.928086]  </TASK>
(snip more "task blocked for more than 120 seconds" messages)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Status: Triage Needed New issue which needs to be triaged Type: Defect Incorrect behavior (e.g. crash, hang)
Projects
None yet
Development

No branches or pull requests