Package: zfsutils-linux
Version: 0.7.13-1
Severity: important
Dear Maintainer,
When doing a scrub of my ZFS filesystem with 4.19 I get warnings of hung
processes, followed by the system going catatonic. This happens within
seconds of starting the scrub.
When doing the same operation after reloading into 4.9 everything works
out just fine.
I've logged the kernel logs to a ext4 partition to get the logs below.
Open to do limited testing as I need to be physically close to the machine to
reboot it :/.
Best regards, Peter
Mar 25 16:01:15 frost kernel: [ 0.000000] microcode: microcode updated early
to revision 0x25, date = 2018-04-02
Mar 25 16:01:15 frost kernel: [ 0.000000] Linux version 4.19.0-4-amd64
(debian-ker...@lists.debian.org) (gcc version 8.3.0 (Debian 8.3.0-2)) #1 SMP
Debian 4.19.28-2 (2019-03-15)
Mar 25 16:01:15 frost kernel: [ 0.000000] Command line:
BOOT_IMAGE=/vmlinuz-4.19.0-4-amd64 root=ZFS=mypool/ROOT/debian-1 ro
init=/lib/systemd/systemd video=VGA-1:1440x900 boot=zfs quiet splash
...
Mar 25 16:01:15 frost kernel: [ 0.238508] Kernel command line:
BOOT_IMAGE=/vmlinuz-4.19.0-4-amd64 root=ZFS=mypool/ROOT/debian-1 ro
init=/lib/systemd/systemd video=VGA-1:1440x900 boot=zfs quiet splash
...
Mar 25 16:01:15 frost kernel: [ 0.320525] Memory: 32754948K/33430156K
available (10252K kernel code, 1240K rwdata, 3268K rodata, 1576K init, 2308K
bss, 675208K reserved, 0K cma-reserved)
Mar 25 16:01:15 frost kernel: [ 0.320593] SLUB: HWalign=64, Order=0-3,
MinObjects=0, CPUs=4, Nodes=1
Mar 25 16:01:15 frost kernel: [ 0.320597] Kernel/User page tables isolation:
enabled
...
Mar 25 16:01:15 frost kernel: [ 1.287299] io scheduler noop registered
Mar 25 16:01:15 frost kernel: [ 1.287300] io scheduler deadline registered
Mar 25 16:01:15 frost kernel: [ 1.287323] io scheduler cfq registered
(default)
Mar 25 16:01:15 frost kernel: [ 1.287324] io scheduler mq-deadline registered
...
Mar 25 16:01:15 frost kernel: [ 3.654967] spl: loading out-of-tree module
taints kernel.
Mar 25 16:01:15 frost kernel: [ 3.655088] spl: module verification failed:
signature and/or required key missing - tainting kernel
Mar 25 16:01:15 frost kernel: [ 3.659020] SPL: Loaded module v0.7.13-1
Mar 25 16:01:15 frost kernel: [ 3.659161] znvpair: module license 'CDDL'
taints kernel.
Mar 25 16:01:15 frost kernel: [ 3.659162] Disabling lock debugging due to
kernel taint
Mar 25 16:01:15 frost kernel: [ 5.594392] ZFS: Loaded module v0.7.13-1, ZFS
pool version 5000, ZFS filesystem version 5
[starting scrub...]
Mar 29 22:40:51 frost kernel: [369625.485185] INFO: task l2arc_feed:356 blocked
for more than 120 seconds.
Mar 29 22:40:51 frost kernel: [369625.486199] Tainted: P OE
4.19.0-4-amd64 #1 Debian 4.19.28-2
Mar 29 22:40:51 frost kernel: [369625.487265] "echo 0 >
/proc/sys/kernel/hung_task_timeout_secs" disables this message.
Mar 29 22:40:51 frost kernel: [369625.488377] l2arc_feed D 0 356
2 0x80000000
Mar 29 22:40:51 frost kernel: [369625.488383] Call Trace:
Mar 29 22:40:51 frost kernel: [369625.488398] ? __schedule+0x2a2/0x870
Mar 29 22:40:51 frost kernel: [369625.488405] schedule+0x28/0x80
Mar 29 22:40:51 frost kernel: [369625.488425] cv_wait_common+0xf8/0x130 [spl]
Mar 29 22:40:51 frost kernel: [369625.488436] ? finish_wait+0x80/0x80
Mar 29 22:40:51 frost kernel: [369625.488553] spa_config_enter+0xed/0x100 [zfs]
Mar 29 22:40:51 frost kernel: [369625.488619] l2arc_feed_thread+0x1ea/0xb70
[zfs]
Mar 29 22:40:51 frost kernel: [369625.488683] ? l2arc_evict+0x340/0x340 [zfs]
Mar 29 22:40:51 frost kernel: [369625.488696] ? __thread_exit+0x20/0x20 [spl]
Mar 29 22:40:51 frost kernel: [369625.488706] thread_generic_wrapper+0x6f/0x80
[spl]
Mar 29 22:40:51 frost kernel: [369625.488714] kthread+0x112/0x130
Mar 29 22:40:51 frost kernel: [369625.488719] ? kthread_bind+0x30/0x30
Mar 29 22:40:51 frost kernel: [369625.488727] ret_from_fork+0x35/0x40
Mar 29 22:40:51 frost kernel: [369625.488743] INFO: task txg_sync:928 blocked
for more than 120 seconds.
Mar 29 22:40:51 frost kernel: [369625.489931] Tainted: P OE
4.19.0-4-amd64 #1 Debian 4.19.28-2
Mar 29 22:40:51 frost kernel: [369625.491149] "echo 0 >
/proc/sys/kernel/hung_task_timeout_secs" disables this message.
Mar 29 22:40:51 frost kernel: [369625.491152] txg_sync D 0 928
2 0x80000000
Mar 29 22:40:51 frost kernel: [369625.491157] Call Trace:
Mar 29 22:40:51 frost kernel: [369625.491166] ? __schedule+0x2a2/0x870
Mar 29 22:40:51 frost kernel: [369625.491170] schedule+0x28/0x80
Mar 29 22:40:51 frost kernel: [369625.491187] cv_wait_common+0xf8/0x130 [spl]
Mar 29 22:40:51 frost kernel: [369625.491197] ? finish_wait+0x80/0x80
Mar 29 22:40:51 frost kernel: [369625.491302] spa_config_enter+0xed/0x100 [zfs]
Mar 29 22:40:51 frost kernel: [369625.492606] spa_sync+0x15c/0xd20 [zfs]
Mar 29 22:40:51 frost kernel: [369625.492708] txg_sync_thread+0x2c8/0x4a0 [zfs]
Mar 29 22:40:51 frost kernel: [369625.492716] ? __switch_to+0x8c/0x440
Mar 29 22:40:51 frost kernel: [369625.492814] ?
txg_thread_exit.isra.9+0x60/0x60 [zfs]
Mar 29 22:40:51 frost kernel: [369625.492840] ? __thread_exit+0x20/0x20 [spl]
Mar 29 22:40:51 frost kernel: [369625.492851] thread_generic_wrapper+0x6f/0x80
[spl]
Mar 29 22:40:51 frost kernel: [369625.492859] kthread+0x112/0x130
Mar 29 22:40:51 frost kernel: [369625.492863] ? kthread_bind+0x30/0x30
Mar 29 22:40:51 frost kernel: [369625.492870] ret_from_fork+0x35/0x40
Mar 29 22:40:51 frost kernel: [369625.493015] INFO: task zpool:12795 blocked
for more than 120 seconds.
Mar 29 22:40:51 frost kernel: [369625.494348] Tainted: P OE
4.19.0-4-amd64 #1 Debian 4.19.28-2
Mar 29 22:40:51 frost kernel: [369625.494349] "echo 0 >
/proc/sys/kernel/hung_task_timeout_secs" disables this message.
Mar 29 22:40:51 frost kernel: [369625.494351] zpool D 0 12795
24507 0x00000000
Mar 29 22:40:51 frost kernel: [369625.494356] Call Trace:
Mar 29 22:40:51 frost kernel: [369625.494362] ? __schedule+0x2a2/0x870
Mar 29 22:40:51 frost kernel: [369625.494464] ? vdev_open_children+0x160/0x160
[zfs]
Mar 29 22:40:51 frost kernel: [369625.494480] schedule+0x28/0x80
Mar 29 22:40:51 frost kernel: [369625.496563] taskq_wait+0x7a/0xc0 [spl]
Mar 29 22:40:51 frost kernel: [369625.496567] ? finish_wait+0x80/0x80
Mar 29 22:40:51 frost kernel: [369625.496573] taskq_destroy+0x42/0x180 [spl]
Mar 29 22:40:51 frost kernel: [369625.496621] ? vdev_open_children+0x160/0x160
[zfs]
Mar 29 22:40:51 frost kernel: [369625.496667] vdev_open_children+0x10a/0x160
[zfs]
Mar 29 22:40:51 frost kernel: [369625.496715] vdev_root_open+0x2a/0xe0 [zfs]
Mar 29 22:40:51 frost kernel: [369625.496762] vdev_open+0xa8/0x660 [zfs]
Mar 29 22:40:51 frost kernel: [369625.496807] ? vdev_cache_purge+0x6e/0x80
[zfs]
Mar 29 22:40:51 frost kernel: [369625.496852] vdev_reopen+0x2e/0xc0 [zfs]
Mar 29 22:40:51 frost kernel: [369625.496894] dsl_scan+0x36/0xd0 [zfs]
Mar 29 22:40:51 frost kernel: [369625.496941] zfs_ioc_pool_scan+0x87/0xc0 [zfs]
Mar 29 22:40:51 frost kernel: [369625.496988] zfsdev_ioctl+0x544/0x630 [zfs]
Mar 29 22:40:51 frost kernel: [369625.496992] do_vfs_ioctl+0xa4/0x630
Mar 29 22:40:51 frost kernel: [369625.496997] ? handle_mm_fault+0xda/0x200
Mar 29 22:40:51 frost kernel: [369625.496999] ksys_ioctl+0x60/0x90
Mar 29 22:40:51 frost kernel: [369625.497003] __x64_sys_ioctl+0x16/0x20
Mar 29 22:40:51 frost kernel: [369625.497007] do_syscall_64+0x53/0x100
Mar 29 22:40:51 frost kernel: [369625.497010]
entry_SYSCALL_64_after_hwframe+0x44/0xa9
Mar 29 22:40:51 frost kernel: [369625.497013] RIP: 0033:0x7fb40b320777
Mar 29 22:40:51 frost kernel: [369625.497018] Code: Bad RIP value.
Mar 29 22:40:51 frost kernel: [369625.497020] RSP: 002b:00007ffe1eaf0e58
EFLAGS: 00000246 ORIG_RAX: 0000000000000010
Mar 29 22:40:51 frost kernel: [369625.497022] RAX: ffffffffffffffda RBX:
00007ffe1eaf0e80 RCX: 00007fb40b320777
Mar 29 22:40:51 frost kernel: [369625.497024] RDX: 00007ffe1eaf0e80 RSI:
0000000000005a07 RDI: 0000000000000003
Mar 29 22:40:51 frost kernel: [369625.497025] RBP: 0000000000000001 R08:
0000000000000008 R09: 00007fb40b3ec420
Mar 29 22:40:51 frost kernel: [369625.497026] R10: 0000556b4760c010 R11:
0000000000000246 R12: 0000556b4760e480
Mar 29 22:40:51 frost kernel: [369625.497027] R13: 0000000000000000 R14:
0000556b4760d430 R15: 0000556b4760e5d0
Mar 29 22:40:51 frost kernel: [369625.497030] INFO: task vdev_open:12796
blocked for more than 120 seconds.
Mar 29 22:40:51 frost kernel: [369625.497748] Tainted: P OE
4.19.0-4-amd64 #1 Debian 4.19.28-2
Mar 29 22:40:51 frost kernel: [369625.497748] "echo 0 >
/proc/sys/kernel/hung_task_timeout_secs" disables this message.
Mar 29 22:40:51 frost kernel: [369625.497749] vdev_open D 0 12796
2 0x80000000
Mar 29 22:40:51 frost kernel: [369625.497768] Call Trace:
Mar 29 22:40:51 frost kernel: [369625.497770] ? __schedule+0x2a2/0x870
Mar 29 22:40:51 frost kernel: [369625.497796] ? vdev_open_children+0x160/0x160
[zfs]
Mar 29 22:40:51 frost kernel: [369625.497799] schedule+0x28/0x80
Mar 29 22:40:51 frost kernel: [369625.498637] taskq_wait+0x7a/0xc0 [spl]
Mar 29 22:40:51 frost kernel: [369625.498650] ? finish_wait+0x80/0x80
Mar 29 22:40:51 frost kernel: [369625.498652] taskq_destroy+0x42/0x180 [spl]
Mar 29 22:40:51 frost kernel: [369625.498677] ? vdev_open_children+0x160/0x160
[zfs]
Mar 29 22:40:51 frost kernel: [369625.498701] vdev_open_children+0x10a/0x160
[zfs]
Mar 29 22:40:51 frost kernel: [369625.498731] vdev_mirror_open+0x2a/0x120 [zfs]
Mar 29 22:40:51 frost kernel: [369625.498755] vdev_open+0xa8/0x660 [zfs]
Mar 29 22:40:51 frost kernel: [369625.498758] ? __wake_up_common_lock+0x89/0xc0
Mar 29 22:40:51 frost kernel: [369625.498781] vdev_open_child+0x1e/0x40 [zfs]
Mar 29 22:40:51 frost kernel: [369625.498784] taskq_thread+0x2df/0x520 [spl]
Mar 29 22:40:51 frost kernel: [369625.498786] ? __switch_to_asm+0x34/0x70
Mar 29 22:40:51 frost kernel: [369625.498789] ? wake_up_q+0x70/0x70
Mar 29 22:40:51 frost kernel: [369625.498792] ? taskq_thread_spawn+0x50/0x50
[spl]
Mar 29 22:40:51 frost kernel: [369625.498794] kthread+0x112/0x130
Mar 29 22:40:51 frost kernel: [369625.498796] ? kthread_bind+0x30/0x30
Mar 29 22:40:51 frost kernel: [369625.498797] ret_from_fork+0x35/0x40
Mar 29 22:40:51 frost kernel: [369625.498799] INFO: task vdev_open:12797
blocked for more than 120 seconds.
Mar 29 22:40:51 frost kernel: [369625.498801] Tainted: P OE
4.19.0-4-amd64 #1 Debian 4.19.28-2
Mar 29 22:40:51 frost kernel: [369625.499649] "echo 0 >
/proc/sys/kernel/hung_task_timeout_secs" disables this message.
Mar 29 22:40:51 frost kernel: [369625.499649] vdev_open D 0 12797
2 0x80000000
Mar 29 22:40:51 frost kernel: [369625.499660] Call Trace:
Mar 29 22:40:51 frost kernel: [369625.499661] ? __schedule+0x2a2/0x870
Mar 29 22:40:51 frost kernel: [369625.499693] ? vdev_open_children+0x160/0x160
[zfs]
Mar 29 22:40:51 frost kernel: [369625.499696] schedule+0x28/0x80
Mar 29 22:40:51 frost kernel: [369625.500124] taskq_wait+0x7a/0xc0 [spl]
Mar 29 22:40:51 frost kernel: [369625.500126] ? finish_wait+0x80/0x80
Mar 29 22:40:51 frost kernel: [369625.500129] taskq_destroy+0x42/0x180 [spl]
Mar 29 22:40:51 frost kernel: [369625.500151] ? vdev_open_children+0x160/0x160
[zfs]
Mar 29 22:40:51 frost kernel: [369625.500174] vdev_open_children+0x10a/0x160
[zfs]
Mar 29 22:40:51 frost kernel: [369625.500196] vdev_mirror_open+0x2a/0x120 [zfs]
Mar 29 22:40:51 frost kernel: [369625.500219] vdev_open+0xa8/0x660 [zfs]
Mar 29 22:40:51 frost kernel: [369625.500221] ? __wake_up_common_lock+0x89/0xc0
Mar 29 22:40:51 frost kernel: [369625.500243] vdev_open_child+0x1e/0x40 [zfs]
Mar 29 22:40:51 frost kernel: [369625.500246] taskq_thread+0x2df/0x520 [spl]
Mar 29 22:40:51 frost kernel: [369625.500248] ? __switch_to_asm+0x34/0x70
Mar 29 22:40:51 frost kernel: [369625.500249] ? wake_up_q+0x70/0x70
Mar 29 22:40:51 frost kernel: [369625.500252] ? taskq_thread_spawn+0x50/0x50
[spl]
Mar 29 22:40:51 frost kernel: [369625.500253] kthread+0x112/0x130
Mar 29 22:40:51 frost kernel: [369625.500254] ? kthread_bind+0x30/0x30
Mar 29 22:40:51 frost kernel: [369625.500256] ret_from_fork+0x35/0x40
Mar 29 22:40:51 frost kernel: [369625.500258] INFO: task vdev_open:12799
blocked for more than 120 seconds.
Mar 29 22:40:51 frost kernel: [369625.500258] Tainted: P OE
4.19.0-4-amd64 #1 Debian 4.19.28-2
Mar 29 22:40:51 frost kernel: [369625.500259] "echo 0 >
/proc/sys/kernel/hung_task_timeout_secs" disables this message.
Mar 29 22:40:51 frost kernel: [369625.500260] vdev_open D 0 12799
2 0x80000000
Mar 29 22:40:51 frost kernel: [369625.501671] Call Trace:
Mar 29 22:40:51 frost kernel: [369625.501673] ? __schedule+0x2a2/0x870
Mar 29 22:40:51 frost kernel: [369625.501674] schedule+0x28/0x80
Mar 29 22:40:51 frost kernel: [369625.501685] schedule_timeout+0x26d/0x390
Mar 29 22:40:51 frost kernel: [369625.501686] ? try_to_wake_up+0x54/0x490
Mar 29 22:40:51 frost kernel: [369625.501687] wait_for_completion+0x11f/0x190
Mar 29 22:40:51 frost kernel: [369625.501689] ? wake_up_q+0x70/0x70
Mar 29 22:40:51 frost kernel: [369625.501690]
call_usermodehelper_exec+0x12e/0x160
Mar 29 22:40:51 frost kernel: [369625.501715] vdev_elevator_switch+0x10e/0x190
[zfs]
Mar 29 22:40:51 frost kernel: [369625.501739] vdev_disk_open+0xed/0x420 [zfs]
Mar 29 22:40:51 frost kernel: [369625.501742] ? __switch_to_asm+0x40/0x70
Mar 29 22:40:51 frost kernel: [369625.501743] ? __switch_to_asm+0x34/0x70
Mar 29 22:40:51 frost kernel: [369625.501745] ? __switch_to+0x8c/0x440
Mar 29 22:40:51 frost kernel: [369625.501746] ? __switch_to_asm+0x34/0x70
Mar 29 22:40:51 frost kernel: [369625.501747] ? __switch_to_asm+0x40/0x70
Mar 29 22:40:51 frost kernel: [369625.501771] vdev_open+0xa8/0x660 [zfs]
Mar 29 22:40:51 frost kernel: [369625.501773] ? __wake_up_common_lock+0x89/0xc0
Mar 29 22:40:51 frost kernel: [369625.501796] vdev_open_child+0x1e/0x40 [zfs]
Mar 29 22:40:51 frost kernel: [369625.501800] taskq_thread+0x2df/0x520 [spl]
Mar 29 22:40:51 frost kernel: [369625.501802] ? __switch_to_asm+0x34/0x70
Mar 29 22:40:51 frost kernel: [369625.501803] ? wake_up_q+0x70/0x70
Mar 29 22:40:51 frost kernel: [369625.501806] ? taskq_thread_spawn+0x50/0x50
[spl]
Mar 29 22:40:51 frost kernel: [369625.501807] kthread+0x112/0x130
Mar 29 22:40:51 frost kernel: [369625.501814] ? kthread_bind+0x30/0x30
Mar 29 22:40:51 frost kernel: [369625.501815] ret_from_fork+0x35/0x40
Mar 29 22:40:51 frost kernel: [369625.501816] INFO: task vdev_open:12801
blocked for more than 120 seconds.
Mar 29 22:40:51 frost kernel: [369625.502295] Tainted: P OE
4.19.0-4-amd64 #1 Debian 4.19.28-2
Mar 29 22:40:51 frost kernel: [369625.502295] "echo 0 >
/proc/sys/kernel/hung_task_timeout_secs" disables this message.
Mar 29 22:40:51 frost kernel: [369625.502295] vdev_open D 0 12801
2 0x80000000
Mar 29 22:40:51 frost kernel: [369625.502296] Call Trace:
Mar 29 22:40:51 frost kernel: [369625.502298] ? __schedule+0x2a2/0x870
Mar 29 22:40:51 frost kernel: [369625.502309] schedule+0x28/0x80
Mar 29 22:40:51 frost kernel: [369625.502310] schedule_timeout+0x26d/0x390
Mar 29 22:40:51 frost kernel: [369625.502311] ? vsnprintf+0x138/0x4d0
Mar 29 22:40:51 frost kernel: [369625.502312] wait_for_completion+0x11f/0x190
Mar 29 22:40:51 frost kernel: [369625.502313] ? wake_up_q+0x70/0x70
Mar 29 22:40:51 frost kernel: [369625.502315]
call_usermodehelper_exec+0x12e/0x160
Mar 29 22:40:51 frost kernel: [369625.502339] vdev_elevator_switch+0x10e/0x190
[zfs]
Mar 29 22:40:51 frost kernel: [369625.502364] vdev_disk_open+0xed/0x420 [zfs]
Mar 29 22:40:51 frost kernel: [369625.503371] ? __switch_to_asm+0x40/0x70
Mar 29 22:40:51 frost kernel: [369625.503372] ? __switch_to_asm+0x34/0x70
Mar 29 22:40:51 frost kernel: [369625.503383] ? __switch_to+0x8c/0x440
Mar 29 22:40:51 frost kernel: [369625.503384] ? __switch_to_asm+0x34/0x70
Mar 29 22:40:51 frost kernel: [369625.503385] ? __switch_to_asm+0x40/0x70
Mar 29 22:40:51 frost kernel: [369625.503409] vdev_open+0xa8/0x660 [zfs]
Mar 29 22:40:51 frost kernel: [369625.503411] ? __wake_up_common_lock+0x89/0xc0
Mar 29 22:40:51 frost kernel: [369625.503435] vdev_open_child+0x1e/0x40 [zfs]
Mar 29 22:40:51 frost kernel: [369625.503439] taskq_thread+0x2df/0x520 [spl]
Mar 29 22:40:51 frost kernel: [369625.503441] ? __switch_to_asm+0x34/0x70
Mar 29 22:40:51 frost kernel: [369625.503442] ? wake_up_q+0x70/0x70
Mar 29 22:40:51 frost kernel: [369625.503445] ? taskq_thread_spawn+0x50/0x50
[spl]
Mar 29 22:40:51 frost kernel: [369625.503447] kthread+0x112/0x130
Mar 29 22:40:51 frost kernel: [369625.503450] ? kthread_bind+0x30/0x30
Mar 29 22:40:51 frost kernel: [369625.503451] ret_from_fork+0x35/0x40
Mar 29 22:40:51 frost kernel: [369625.503453] INFO: task vdev_open:12802
blocked for more than 120 seconds.
Mar 29 22:40:51 frost kernel: [369625.503454] Tainted: P OE
4.19.0-4-amd64 #1 Debian 4.19.28-2
Mar 29 22:40:51 frost kernel: [369625.503454] "echo 0 >
/proc/sys/kernel/hung_task_timeout_secs" disables this message.
Mar 29 22:40:51 frost kernel: [369625.503454] vdev_open D 0 12802
2 0x80000000
Mar 29 22:40:51 frost kernel: [369625.505031] Call Trace:
Mar 29 22:40:51 frost kernel: [369625.505032] ? __schedule+0x2a2/0x870
Mar 29 22:40:51 frost kernel: [369625.505033] ? __switch_to_asm+0x40/0x70
Mar 29 22:40:51 frost kernel: [369625.505034] ? __switch_to_asm+0x34/0x70
Mar 29 22:40:51 frost kernel: [369625.505045] schedule+0x28/0x80
Mar 29 22:40:51 frost kernel: [369625.505046] schedule_timeout+0x26d/0x390
Mar 29 22:40:51 frost kernel: [369625.505047] ? __schedule+0x2aa/0x870
Mar 29 22:40:51 frost kernel: [369625.505048] ? try_to_wake_up+0x54/0x490
Mar 29 22:40:51 frost kernel: [369625.505049] wait_for_completion+0x11f/0x190
Mar 29 22:40:51 frost kernel: [369625.505051] ? wake_up_q+0x70/0x70
Mar 29 22:40:51 frost kernel: [369625.505052]
call_usermodehelper_exec+0x12e/0x160
Mar 29 22:40:51 frost kernel: [369625.505076] vdev_elevator_switch+0x10e/0x190
[zfs]
Mar 29 22:40:51 frost kernel: [369625.505101] vdev_disk_open+0xed/0x420 [zfs]
Mar 29 22:40:51 frost kernel: [369625.505117] ? __switch_to_asm+0x40/0x70
Mar 29 22:40:51 frost kernel: [369625.505119] ? __switch_to_asm+0x34/0x70
Mar 29 22:40:51 frost kernel: [369625.505120] ? __switch_to+0x8c/0x440
Mar 29 22:40:51 frost kernel: [369625.505121] ? __switch_to_asm+0x34/0x70
Mar 29 22:40:51 frost kernel: [369625.505122] ? __switch_to_asm+0x40/0x70
Mar 29 22:40:51 frost kernel: [369625.505147] vdev_open+0xa8/0x660 [zfs]
Mar 29 22:40:51 frost kernel: [369625.505152] ? __wake_up_common_lock+0x89/0xc0
Mar 29 22:40:51 frost kernel: [369625.505178] vdev_open_child+0x1e/0x40 [zfs]
Mar 29 22:40:51 frost kernel: [369625.505183] taskq_thread+0x2df/0x520 [spl]
Mar 29 22:40:51 frost kernel: [369625.505186] ? __switch_to_asm+0x34/0x70
Mar 29 22:40:51 frost kernel: [369625.505190] ? wake_up_q+0x70/0x70
Mar 29 22:40:51 frost kernel: [369625.505195] ? taskq_thread_spawn+0x50/0x50
[spl]
Mar 29 22:40:51 frost kernel: [369625.505197] kthread+0x112/0x130
Mar 29 22:40:51 frost kernel: [369625.505200] ? kthread_bind+0x30/0x30
Mar 29 22:40:51 frost kernel: [369625.505203] ret_from_fork+0x35/0x40
Mar 29 22:40:51 frost kernel: [369625.505206] INFO: task vdev_open:12804
blocked for more than 120 seconds.
Mar 29 22:40:51 frost kernel: [369625.505770] Tainted: P OE
4.19.0-4-amd64 #1 Debian 4.19.28-2
Mar 29 22:40:51 frost kernel: [369625.505770] "echo 0 >
/proc/sys/kernel/hung_task_timeout_secs" disables this message.
Mar 29 22:40:51 frost kernel: [369625.505771] vdev_open D 0 12804
2 0x80000000
Mar 29 22:40:51 frost kernel: [369625.505772] Call Trace:
Mar 29 22:40:51 frost kernel: [369625.505783] ? __schedule+0x2a2/0x870
Mar 29 22:40:51 frost kernel: [369625.505784] ? __switch_to_asm+0x40/0x70
Mar 29 22:40:51 frost kernel: [369625.505785] ? __switch_to_asm+0x34/0x70
Mar 29 22:40:51 frost kernel: [369625.505786] schedule+0x28/0x80
Mar 29 22:40:51 frost kernel: [369625.505787] schedule_timeout+0x26d/0x390
Mar 29 22:40:51 frost kernel: [369625.505789] ? __schedule+0x2aa/0x870
Mar 29 22:40:51 frost kernel: [369625.506951] ? try_to_wake_up+0x54/0x490
Mar 29 22:40:51 frost kernel: [369625.506952] wait_for_completion+0x11f/0x190
Mar 29 22:40:51 frost kernel: [369625.506953] ? wake_up_q+0x70/0x70
Mar 29 22:40:51 frost kernel: [369625.506964]
call_usermodehelper_exec+0x12e/0x160
Mar 29 22:40:51 frost kernel: [369625.506986] vdev_elevator_switch+0x10e/0x190
[zfs]
Mar 29 22:40:51 frost kernel: [369625.507009] vdev_disk_open+0xed/0x420 [zfs]
Mar 29 22:40:51 frost kernel: [369625.507011] ? __switch_to_asm+0x40/0x70
Mar 29 22:40:51 frost kernel: [369625.507012] ? __switch_to_asm+0x34/0x70
Mar 29 22:40:51 frost kernel: [369625.507013] ? __switch_to+0x8c/0x440
Mar 29 22:40:51 frost kernel: [369625.507018] ? __switch_to_asm+0x34/0x70
Mar 29 22:40:51 frost kernel: [369625.507019] ? __switch_to_asm+0x40/0x70
Mar 29 22:40:51 frost kernel: [369625.507042] vdev_open+0xa8/0x660 [zfs]
Mar 29 22:40:51 frost kernel: [369625.507044] ? __wake_up_common_lock+0x89/0xc0
Mar 29 22:40:51 frost kernel: [369625.507066] vdev_open_child+0x1e/0x40 [zfs]
Mar 29 22:40:51 frost kernel: [369625.507070] taskq_thread+0x2df/0x520 [spl]
Mar 29 22:40:51 frost kernel: [369625.507072] ? __switch_to_asm+0x34/0x70
Mar 29 22:40:51 frost kernel: [369625.507073] ? wake_up_q+0x70/0x70
Mar 29 22:40:51 frost kernel: [369625.507077] ? taskq_thread_spawn+0x50/0x50
[spl]
Mar 29 22:40:51 frost kernel: [369625.507078] kthread+0x112/0x130
Mar 29 22:40:51 frost kernel: [369625.507079] ? kthread_bind+0x30/0x30
Mar 29 22:40:51 frost kernel: [369625.507080] ret_from_fork+0x35/0x40
Mar 29 22:40:51 frost kernel: [369625.507083] INFO: task modprobe:12812 blocked
for more than 120 seconds.
Mar 29 22:40:51 frost kernel: [369625.507085] Tainted: P OE
4.19.0-4-amd64 #1 Debian 4.19.28-2
Mar 29 22:40:51 frost kernel: [369625.508224] "echo 0 >
/proc/sys/kernel/hung_task_timeout_secs" disables this message.
Mar 29 22:40:51 frost kernel: [369625.508224] modprobe D 0 12812
12809 0x00000000
Mar 29 22:40:51 frost kernel: [369625.508225] Call Trace:
Mar 29 22:40:51 frost kernel: [369625.508226] ? __schedule+0x2a2/0x870
Mar 29 22:40:51 frost kernel: [369625.508227] schedule+0x28/0x80
Mar 29 22:40:51 frost kernel: [369625.508241] cv_wait_common+0xf8/0x130 [spl]
Mar 29 22:40:51 frost kernel: [369625.508242] ? finish_wait+0x80/0x80
Mar 29 22:40:51 frost kernel: [369625.508266] spa_config_enter+0xed/0x100 [zfs]
Mar 29 22:40:51 frost kernel: [369625.508859] zio_vdev_io_start+0x326/0x330
[zfs]
Mar 29 22:40:51 frost kernel: [369625.508863] ? tsd_get_by_thread+0x2a/0x40
[spl]
Mar 29 22:40:51 frost kernel: [369625.508885] zio_nowait+0xc3/0x150 [zfs]
Mar 29 22:40:51 frost kernel: [369625.508899] arc_read+0x617/0xa50 [zfs]
Mar 29 22:40:51 frost kernel: [369625.508914] ?
dbuf_rele_and_unlock+0x4f0/0x4f0 [zfs]
Mar 29 22:40:51 frost kernel: [369625.508936] ? zio_null+0x2b/0x30 [zfs]
Mar 29 22:40:51 frost kernel: [369625.508950] dbuf_read+0x1f6/0x950 [zfs]
Mar 29 22:40:51 frost kernel: [369625.508968] ?
dnode_rele_and_unlock+0x53/0xb0 [zfs]
Mar 29 22:40:51 frost kernel: [369625.508984] dmu_buf_hold+0x49/0x80 [zfs]
Mar 29 22:40:51 frost kernel: [369625.509008] zap_lockdir+0x4e/0xb0 [zfs]
Mar 29 22:40:51 frost kernel: [369625.509031] zap_cursor_retrieve+0x179/0x2d0
[zfs]
Mar 29 22:40:51 frost kernel: [369625.509033] ? __check_object_size+0x41/0x189
Mar 29 22:40:51 frost kernel: [369625.509035] ? _copy_to_user+0x26/0x30
Mar 29 22:40:51 frost kernel: [369625.509037] ? filldir64+0xce/0x130
Mar 29 22:40:51 frost kernel: [369625.509060] zfs_readdir+0x127/0x3f0 [zfs]
Mar 29 22:40:51 frost kernel: [369625.509062] ?
filename_lookup.part.62+0xe0/0x170
Mar 29 22:40:51 frost kernel: [369625.509064] ?
mem_cgroup_commit_charge+0x7a/0x560
Mar 29 22:40:51 frost kernel: [369625.509066] ?
mem_cgroup_try_charge+0x8b/0x1a0
Mar 29 22:40:51 frost kernel: [369625.509070] ? _cond_resched+0x15/0x30
Mar 29 22:40:51 frost kernel: [369625.509071] ? dput.part.32+0x29/0x110
Mar 29 22:40:51 frost kernel: [369625.509073] ? __fsnotify_parent+0x96/0x120
Mar 29 22:40:51 frost kernel: [369625.509095] zpl_iterate+0x4c/0x70 [zfs]
Mar 29 22:40:51 frost kernel: [369625.509097] iterate_dir+0x138/0x180
Mar 29 22:40:51 frost kernel: [369625.509099] ksys_getdents64+0x9c/0x130
Mar 29 22:40:51 frost kernel: [369625.509100] ? iterate_dir+0x180/0x180
Mar 29 22:40:51 frost kernel: [369625.509115] __x64_sys_getdents64+0x16/0x20
Mar 29 22:40:51 frost kernel: [369625.509118] do_syscall_64+0x53/0x100
Mar 29 22:40:51 frost kernel: [369625.509121]
entry_SYSCALL_64_after_hwframe+0x44/0xa9
Mar 29 22:40:51 frost kernel: [369625.509123] RIP: 0033:0x7fa1d89b9147
Mar 29 22:40:51 frost kernel: [369625.509125] Code: Bad RIP value.
Mar 29 22:40:51 frost kernel: [369625.509125] RSP: 002b:00007fff0f97ccf8
EFLAGS: 00000246 ORIG_RAX: 00000000000000d9
Mar 29 22:40:51 frost kernel: [369625.509126] RAX: ffffffffffffffda RBX:
000055ec880a5440 RCX: 00007fa1d89b9147
Mar 29 22:40:51 frost kernel: [369625.509127] RDX: 0000000000008000 RSI:
000055ec880a5470 RDI: 0000000000000000
Mar 29 22:40:51 frost kernel: [369625.509131] RBP: 000055ec880a5470 R08:
0000000000000003 R09: 0000000000000078
Mar 29 22:40:51 frost kernel: [369625.509132] R10: 000055ec880a5010 R11:
0000000000000246 R12: ffffffffffffff80
Mar 29 22:40:51 frost kernel: [369625.509136] R13: 0000000000000000 R14:
000055ec86225068 R15: 000055ec880a52d0
# arc_summary
------------------------------------------------------------------------
ZFS Subsystem Report Tue Apr 02 09:07:34 2019
ARC Summary: (HEALTHY)
Memory Throttle Count: 0
ARC Misc:
Deleted: 4.98M
Mutex Misses: 72
Evict Skips: 468
ARC Size: 99.32% 15.55 GiB
Target Size: (Adaptive) 100.00% 15.65 GiB
Min Size (Hard Limit): 6.25% 1001.84 MiB
Max Size (High Water): 16:1 15.65 GiB
ARC Size Breakdown:
Recently Used Cache Size: 59.06% 7.80 GiB
Frequently Used Cache Size: 40.94% 5.41 GiB
ARC Hash Breakdown:
Elements Max: 2.67M
Elements Current: 45.20% 1.21M
Collisions: 5.30M
Chain Max: 7
Chains: 143.29k
ARC Total accesses: 3.41G
Cache Hit Ratio: 97.04% 3.31G
Cache Miss Ratio: 2.96% 100.81M
Actual Hit Ratio: 96.86% 3.30G
Data Demand Efficiency: 99.86% 2.13G
Data Prefetch Efficiency: 32.03% 721.72k
CACHE HITS BY CACHE LIST:
Anonymously Used: 0.17% 5.69M
Most Recently Used: 0.76% 25.01M
Most Frequently Used: 99.05% 3.28G
Most Recently Used Ghost: 0.00% 160.54k
Most Frequently Used Ghost: 0.02% 551.08k
CACHE HITS BY DATA TYPE:
Demand Data: 64.24% 2.13G
Prefetch Data: 0.01% 231.20k
Demand Metadata: 35.37% 1.17G
Prefetch Metadata: 0.38% 12.71M
CACHE MISSES BY DATA TYPE:
Demand Data: 2.91% 2.94M
Prefetch Data: 0.49% 490.52k
Demand Metadata: 91.70% 92.45M
Prefetch Metadata: 4.90% 4.94M
L2 ARC Summary: (HEALTHY)
Low Memory Aborts: 0
Free on Write: 8.15k
R/W Clashes: 0
Bad Checksums: 0
IO Errors: 0
L2 ARC Size: (Adaptive) 34.56 GiB
Compressed: 78.56% 27.15 GiB
Header Size: 0.07% 25.47 MiB
L2 ARC Breakdown: 100.81M
Hit Ratio: 0.52% 526.05k
Miss Ratio: 99.48% 100.28M
Feeds: 288.98k
L2 ARC Writes:
Writes Sent: 100.00% 127.19k
DMU Prefetch Efficiency: 2.31G
Hit Ratio: 0.05% 1.17M
Miss Ratio: 99.95% 2.31G
ZFS Tunables:
dbuf_cache_hiwater_pct 10
dbuf_cache_lowater_pct 10
dbuf_cache_max_bytes 104857600
dbuf_cache_max_shift 5
dmu_object_alloc_chunk_shift 7
ignore_hole_birth 1
l2arc_feed_again 1
l2arc_feed_min_ms 200
l2arc_feed_secs 1
l2arc_headroom 2
l2arc_headroom_boost 200
l2arc_noprefetch 1
l2arc_norw 0
l2arc_write_boost 8388608
l2arc_write_max 8388608
metaslab_aliquot 524288
metaslab_bias_enabled 1
metaslab_debug_load 0
metaslab_debug_unload 0
metaslab_fragmentation_factor_enabled 1
metaslab_lba_weighting_enabled 1
metaslab_preload_enabled 1
metaslabs_per_vdev 200
send_holes_without_birth_time 1
spa_asize_inflation 24
spa_config_path /etc/zfs/zpool.cache
spa_load_verify_data 1
spa_load_verify_maxinflight 10000
spa_load_verify_metadata 1
spa_slop_shift 5
zfetch_array_rd_sz 1048576
zfetch_max_distance 8388608
zfetch_max_streams 8
zfetch_min_sec_reap 2
zfs_abd_scatter_enabled 1
zfs_abd_scatter_max_order 10
zfs_admin_snapshot 1
zfs_arc_average_blocksize 8192
zfs_arc_dnode_limit 0
zfs_arc_dnode_limit_percent 10
zfs_arc_dnode_reduce_percent 10
zfs_arc_grow_retry 0
zfs_arc_lotsfree_percent 10
zfs_arc_max 0
zfs_arc_meta_adjust_restarts 4096
zfs_arc_meta_limit 0
zfs_arc_meta_limit_percent 75
zfs_arc_meta_min 0
zfs_arc_meta_prune 10000
zfs_arc_meta_strategy 1
zfs_arc_min 0
zfs_arc_min_prefetch_lifespan 0
zfs_arc_p_dampener_disable 1
zfs_arc_p_min_shift 0
zfs_arc_pc_percent 0
zfs_arc_shrink_shift 0
zfs_arc_sys_free 0
zfs_autoimport_disable 1
zfs_checksums_per_second 20
zfs_compressed_arc_enabled 1
zfs_dbgmsg_enable 0
zfs_dbgmsg_maxsize 4194304
zfs_dbuf_state_index 0
zfs_deadman_checktime_ms 5000
zfs_deadman_enabled 1
zfs_deadman_synctime_ms 1000000
zfs_dedup_prefetch 0
zfs_delay_min_dirty_percent 60
zfs_delay_scale 500000
zfs_delays_per_second 20
zfs_delete_blocks 20480
zfs_dirty_data_max 3361601536
zfs_dirty_data_max_max 4294967296
zfs_dirty_data_max_max_percent 25
zfs_dirty_data_max_percent 10
zfs_dirty_data_sync 67108864
zfs_dmu_offset_next_sync 0
zfs_expire_snapshot 300
zfs_flags 0
zfs_free_bpobj_enabled 1
zfs_free_leak_on_eio 0
zfs_free_max_blocks 100000
zfs_free_min_time_ms 1000
zfs_immediate_write_sz 32768
zfs_max_recordsize 1048576
zfs_mdcomp_disable 0
zfs_metaslab_fragmentation_threshold 70
zfs_metaslab_segment_weight_enabled 1
zfs_metaslab_switch_threshold 2
zfs_mg_fragmentation_threshold 85
zfs_mg_noalloc_threshold 0
zfs_multihost_fail_intervals 5
zfs_multihost_history 0
zfs_multihost_import_intervals 10
zfs_multihost_interval 1000
zfs_multilist_num_sublists 0
zfs_no_scrub_io 0
zfs_no_scrub_prefetch 0
zfs_nocacheflush 0
zfs_nopwrite_enabled 1
zfs_object_mutex_size 64
zfs_pd_bytes_max 52428800
zfs_per_txg_dirty_frees_percent 30
zfs_prefetch_disable 0
zfs_read_chunk_size 1048576
zfs_read_history 0
zfs_read_history_hits 0
zfs_recover 0
zfs_recv_queue_length 16777216
zfs_resilver_delay 2
zfs_resilver_min_time_ms 3000
zfs_scan_idle 50
zfs_scan_ignore_errors 0
zfs_scan_min_time_ms 1000
zfs_scrub_delay 4
zfs_send_corrupt_data 0
zfs_send_queue_length 16777216
zfs_sync_pass_deferred_free 2
zfs_sync_pass_dont_compress 5
zfs_sync_pass_rewrite 2
zfs_sync_taskq_batch_pct 75
zfs_top_maxinflight 32
zfs_txg_history 0
zfs_txg_timeout 5
zfs_vdev_aggregation_limit 131072
zfs_vdev_async_read_max_active 3
zfs_vdev_async_read_min_active 1
zfs_vdev_async_write_active_max_dirty_percent 60
zfs_vdev_async_write_active_min_dirty_percent 30
zfs_vdev_async_write_max_active 10
zfs_vdev_async_write_min_active 2
zfs_vdev_cache_bshift 16
zfs_vdev_cache_max 16384
zfs_vdev_cache_size 0
zfs_vdev_max_active 1000
zfs_vdev_mirror_non_rotating_inc 0
zfs_vdev_mirror_non_rotating_seek_inc 1
zfs_vdev_mirror_rotating_inc 0
zfs_vdev_mirror_rotating_seek_inc 5
zfs_vdev_mirror_rotating_seek_offset 1048576
zfs_vdev_queue_depth_pct 1000
zfs_vdev_raidz_impl [fastest] original
scalar sse2 ssse3 avx2
zfs_vdev_read_gap_limit 32768
zfs_vdev_scheduler noop
zfs_vdev_scrub_max_active 2
zfs_vdev_scrub_min_active 1
zfs_vdev_sync_read_max_active 10
zfs_vdev_sync_read_min_active 10
zfs_vdev_sync_write_max_active 10
zfs_vdev_sync_write_min_active 10
zfs_vdev_write_gap_limit 4096
zfs_zevent_cols 80
zfs_zevent_console 0
zfs_zevent_len_max 64
zfs_zil_clean_taskq_maxalloc 1048576
zfs_zil_clean_taskq_minalloc 1024
zfs_zil_clean_taskq_nthr_pct 100
zil_replay_disable 0
zil_slog_bulk 786432
zio_delay_max 30000
zio_dva_throttle_enabled 1
zio_requeue_io_start_cut_in_line 1
zio_taskq_batch_pct 75
zvol_inhibit_dev 0
zvol_major 230
zvol_max_discard_blocks 16384
zvol_prefetch_bytes 131072
zvol_request_sync 0
zvol_threads 32
zvol_volmode 1
# zpool status -v
pool: mybackup
state: ONLINE
scan: scrub repaired 0B in 7h51m with 0 errors on Mon Apr 1 15:35:47 2019
config:
NAME STATE READ
WRITE CKSUM
mybackup ONLINE 0
0 0
mirror-0 ONLINE 0
0 0
ata-SAMSUNG_HD204UI_S2H7J1BZB01231 ONLINE 0
0 0
ata-WDC_WD20EARX-00PASB0_WD-WCAZAE074784 ONLINE 0
0 0
logs
mirror-1 ONLINE 0
0 0
ata-INTEL_SSDSC2BX480G4K_BTHC7264088R480MGN-part4 ONLINE 0
0 0
ata-INTEL_SSDSC2BX480G4K_BTHC73040BK9480MGN-part4 ONLINE 0
0 0
errors: No known data errors
pool: mypool
state: ONLINE
scan: scrub repaired 0B in 12h57m with 0 errors on Mon Apr 1 20:41:20 2019
config:
NAME STATE READ
WRITE CKSUM
mypool ONLINE 0
0 0
mirror-0 ONLINE 0
0 0
ata-WDC_WD30EFRX-68EUZN0_WD-WMC4N2670271 ONLINE 0
0 0
ata-WDC_WD30EFRX-68EUZN0_WD-WCC4N7DA5DLU ONLINE 0
0 0
mirror-1 ONLINE 0
0 0
ata-WDC_WD30EFRX-68EUZN0_WD-WMC4N0839245 ONLINE 0
0 0
wwn-0x50014ee20f242475 ONLINE 0
0 0
logs
mirror-2 ONLINE 0
0 0
ata-INTEL_SSDSC2BX480G4K_BTHC7264088R480MGN-part5 ONLINE 0
0 0
ata-INTEL_SSDSC2BX480G4K_BTHC73040BK9480MGN-part5 ONLINE 0
0 0
cache
ata-INTEL_SSDSC2BX480G4K_BTHC7264088R480MGN-part6 ONLINE 0
0 0
ata-INTEL_SSDSC2BX480G4K_BTHC73040BK9480MGN-part6 ONLINE 0
0 0
errors: No known data errors
-- System Information:
Debian Release: buster/sid
APT prefers unstable
APT policy: (990, 'unstable'), (500, 'testing'), (500, 'stable')
Architecture: amd64 (x86_64)
Foreign Architectures: i386
Kernel: Linux 4.9.0-8-amd64 (SMP w/4 CPU cores)
Kernel taint flags: TAINT_PROPRIETARY_MODULE, TAINT_OOT_MODULE
Locale: LANG=en_IE:en, LC_CTYPE=en_IE:en (charmap=UTF-8) (ignored: LC_ALL set
to en_IE.UTF-8), LANGUAGE=en_IE:en (charmap=UTF-8) (ignored: LC_ALL set to
en_IE.UTF-8)
Shell: /bin/sh linked to /bin/dash
Init: systemd (via /run/systemd/system)
Versions of packages zfsutils-linux depends on:
ii libblkid1 2.33.1-0.1
ii libc6 2.28-8
ii libnvpair1linux 0.7.13-1
ii libuuid1 2.33.1-0.1
ii libuutil1linux 0.7.13-1
ii libzfs2linux 0.7.13-1
ii libzpool2linux 0.7.13-1
ii python3 3.7.3-1
ii zlib1g 1:1.2.11.dfsg-1
Versions of packages zfsutils-linux recommends:
ii lsb-base 10.2019031300
ii zfs-dkms [zfs-modules] 0.7.13-1
ii zfs-zed 0.7.13-1
Versions of packages zfsutils-linux suggests:
ii nfs-kernel-server 1:1.3.4-2.4
ii samba-common-bin 2:4.9.5+dfsg-2
ii zfs-initramfs 0.7.13-1
-- Configuration Files:
/etc/default/zfs changed:
ZFS_MOUNT='yes'
ZFS_UNMOUNT='yes'
ZFS_SHARE='yes'
ZFS_UNSHARE='yes'
ZPOOL_IMPORT_ALL_VISIBLE='no'
ZPOOL_IMPORT_PATH="/dev/disk/by-id"
ZFS_POOL_IMPORT="mypool;mybackup"
VERBOSE_MOUNT='no'
DO_OVERLAY_MOUNTS='no'
ZPOOL_IMPORT_OPTS=""
MOUNT_EXTRA_OPTIONS=""
ZFS_DKMS_ENABLE_DEBUG_DMU_TX='no'
ZFS_DKMS_ENABLE_DEBUG='no'
ZFS_DKMS_ENABLE_DEBUG_DMU_TX='no'
ZFS_DKMS_DISABLE_STRIP='no'
ZFS_INITRD_PRE_MOUNTROOT_SLEEP='0'
ZFS_INITRD_POST_MODPROBE_SLEEP='0'
-- no debconf information
