Linux md raid-10 freezes during resync
Affects | Status | Importance | Assigned to | Milestone | |
---|---|---|---|---|---|
linux (Ubuntu) |
Confirmed
|
Undecided
|
Unassigned | ||
Bionic |
Fix Released
|
Medium
|
Connor Kuehl |
Bug Description
[Impact]
* If regular and resync IO happen at the same time during a regular IO
split, the split bio will wait until resync IO finishes while at the
same time the resync IO is waiting for regular IO to finish. This
results in deadlock.
* I believe this only impacts Bionic as Disco+ already contains this
commit. Xenial doesn't contain the commit that this one fixes.
[Test Case]
The test kernel containing this commit received positive feedback in the
launchpad bug.
From the launchpad bug comment #10:
"For reproduce on 4.15.0-50-generic: Make new raid-10, add some io fio/dd,
unpack anaconda archives, after minute or two deadlocked"
[Regression Potential]
* This fix has been in mainline since December 2018 and I don't see any
fixup commits upstream referencing this one. The small number of
changes in this commit seem reasonable for managing the `nr_pending`
adjustments which preclude either regular or resync IO.
Original bug description follows:
-------
I'm trying to setup a few nodes with software raid-10.
When array is created and resync is running i'm trying to install a few packages and frequently system stops responding, resync process stops, and I'm getting following errors in the kernel log.
This looks like a deadlock for me.
I had this problem in both 18.04 and 16.04. Reboot is the only way to fix the node.
[ 2659.317256] INFO: task kworker/u24:13:343 blocked for more than 120 seconds.
[ 2659.317313] Not tainted 4.15.0-20-generic #21-Ubuntu
[ 2659.317350] "echo 0 > /proc/sys/
[ 2659.317401] kworker/u24:13 D 0 343 2 0x80000000
[ 2659.317414] Workqueue: writeback wb_workfn (flush-9:1)
[ 2659.317417] Call Trace:
[ 2659.317430] __schedule+
[ 2659.317435] schedule+0x2c/0x80
[ 2659.317443] wait_barrier+
[ 2659.317449] ? wait_woken+
[ 2659.317454] raid10_
[ 2659.317459] ? r10bio_
[ 2659.317465] ? mempool_
[ 2659.317469] ? ___slab_
[ 2659.317475] ? md_write_
[ 2659.317480] ? mempool_
[ 2659.317484] raid10_
[ 2659.317489] md_handle_
[ 2659.317494] md_make_
[ 2659.317501] generic_
[ 2659.317506] submit_
[ 2659.317510] ? submit_
[ 2659.317579] xfs_submit_
[ 2659.317626] xfs_do_
[ 2659.317632] write_cache_
[ 2659.317674] ? xfs_vm_
[ 2659.317682] ? intel_pstate_
[ 2659.317687] ? update_
[ 2659.317727] xfs_vm_
[ 2659.317732] do_writepages+
[ 2659.317738] ? check_preempt_
[ 2659.317742] ? ttwu_do_
[ 2659.317746] __writeback_
[ 2659.317749] ? __writeback_
[ 2659.317752] writeback_
[ 2659.317756] __writeback_
[ 2659.317759] wb_writeback+
[ 2659.317764] wb_workfn+
[ 2659.317766] ? wb_workfn+
[ 2659.317773] process_
[ 2659.317776] worker_
[ 2659.317781] kthread+0x121/0x140
[ 2659.317784] ? process_
[ 2659.317788] ? kthread_
[ 2659.317793] ? do_syscall_
[ 2659.317797] ? SyS_exit_
[ 2659.317801] ret_from_
[ 2659.317806] INFO: task md1_resync:429 blocked for more than 120 seconds.
[ 2659.317853] Not tainted 4.15.0-20-generic #21-Ubuntu
[ 2659.317889] "echo 0 > /proc/sys/
[ 2659.317940] md1_resync D 0 429 2 0x80000000
[ 2659.317943] Call Trace:
[ 2659.317949] __schedule+
[ 2659.317954] schedule+0x2c/0x80
[ 2659.317959] raise_barrier+
[ 2659.317963] ? wait_woken+
[ 2659.317968] raid10_
[ 2659.317975] ? find_next_
[ 2659.317980] ? cpumask_
[ 2659.317985] ? is_mddev_
[ 2659.317990] md_do_sync+
[ 2659.317994] ? wait_woken+
[ 2659.318000] md_thread+
[ 2659.318004] ? mddev_put+
[ 2659.318007] ? md_thread+
[ 2659.318012] kthread+0x121/0x140
[ 2659.318015] ? find_pers+0x70/0x70
[ 2659.318019] ? kthread_
[ 2659.318023] ret_from_
[ 2659.318031] INFO: task xfsaild/md1p1:701 blocked for more than 120 seconds.
[ 2659.318077] Not tainted 4.15.0-20-generic #21-Ubuntu
[ 2659.318113] "echo 0 > /proc/sys/
[ 2659.318164] xfsaild/md1p1 D 0 701 2 0x80000000
[ 2659.318167] Call Trace:
[ 2659.318172] __schedule+
[ 2659.318177] ? mempool_
[ 2659.318181] schedule+0x2c/0x80
[ 2659.318186] wait_barrier+
[ 2659.318189] ? wait_woken+
[ 2659.318194] raid10_
[ 2659.318198] ? r10bio_
[ 2659.318202] ? mempool_
[ 2659.318206] ? md_write_
[ 2659.318211] raid10_
[ 2659.318215] md_handle_
[ 2659.318220] md_make_
[ 2659.318225] generic_
[ 2659.318230] submit_
[ 2659.318234] ? submit_
[ 2659.318283] _xfs_buf_
[ 2659.318330] ? xfs_buf_
[ 2659.318372] xfs_buf_
[ 2659.318412] ? xfs_buf_
[ 2659.318451] xfs_buf_
[ 2659.318492] ? xfs_buf_
[ 2659.318534] xfs_buf_
[ 2659.318573] ? xfs_buf_
[ 2659.318628] xfsaild+0x378/0x7b0 [xfs]
[ 2659.318633] ? __schedule+
[ 2659.318638] kthread+0x121/0x140
[ 2659.318691] ? xfs_trans_
[ 2659.318695] ? kthread+0x121/0x140
[ 2659.318744] ? xfs_trans_
[ 2659.318749] ? kthread_
[ 2659.318753] ret_from_
[ 2659.318758] INFO: task journal-
[ 2659.318806] Not tainted 4.15.0-20-generic #21-Ubuntu
[ 2659.318843] "echo 0 > /proc/sys/
[ 2659.318893] journal-offline D 0 17690 1 0x00000100
[ 2659.318897] Call Trace:
[ 2659.318902] __schedule+
[ 2659.318907] schedule+0x2c/0x80
[ 2659.318911] wait_barrier+
[ 2659.318915] ? wait_woken+
[ 2659.318920] raid10_
[ 2659.318924] ? r10bio_
[ 2659.318928] ? mempool_
[ 2659.318933] ? md_write_
[ 2659.318938] ? flush_tlb_
[ 2659.318942] raid10_
[ 2659.318947] md_handle_
[ 2659.318951] md_make_
[ 2659.318957] generic_
[ 2659.318962] submit_
[ 2659.318966] ? submit_
[ 2659.319015] xfs_submit_
[ 2659.319057] xfs_do_
[ 2659.319063] write_cache_
[ 2659.319104] ? xfs_vm_
[ 2659.319144] xfs_vm_
[ 2659.319149] do_writepages+
[ 2659.319154] __filemap_
[ 2659.319158] ? __filemap_
[ 2659.319163] file_write_
[ 2659.319210] xfs_file_
[ 2659.319215] vfs_fsync_
[ 2659.319218] do_fsync+0x3d/0x70
[ 2659.319222] SyS_fsync+0x10/0x20
[ 2659.319226] do_syscall_
[ 2659.319230] entry_SYSCALL_
[ 2659.319234] RIP: 0033:0x7f3efab64237
[ 2659.319236] RSP: 002b:00007f3ef6
[ 2659.319240] RAX: ffffffffffffffda RBX: 0000000000000017 RCX: 00007f3efab64237
[ 2659.319241] RDX: 0000000000000000 RSI: 00007f3efa771e9a RDI: 0000000000000017
[ 2659.319243] RBP: 00007f3efa773660 R08: 00007f3ef6268700 R09: 00007f3ef6268700
[ 2659.319245] R10: 0000000000000e9a R11: 0000000000000293 R12: 0000000000000002
[ 2659.319247] R13: 0000000000000000 R14: 00005556663a10b0 R15: 00007ffdce2bd200
[ 2659.319256] INFO: task kworker/1:0:2163 blocked for more than 120 seconds.
[ 2659.319302] Not tainted 4.15.0-20-generic #21-Ubuntu
[ 2659.319339] "echo 0 > /proc/sys/
[ 2659.319389] kworker/1:0 D 0 2163 2 0x80000000
[ 2659.319397] Workqueue: md md_submit_
[ 2659.319399] Call Trace:
[ 2659.319405] __schedule+
[ 2659.319409] ? enqueue_
[ 2659.319414] schedule+0x2c/0x80
[ 2659.319418] wait_barrier+
[ 2659.319422] ? wait_woken+
[ 2659.319427] raid10_
[ 2659.319431] ? r10bio_
[ 2659.319435] ? mempool_
[ 2659.319439] ? md_write_
[ 2659.319444] raid10_
[ 2659.319448] md_handle_
[ 2659.319453] md_make_
[ 2659.319458] generic_
[ 2659.319463] raid10_
[ 2659.319467] ? raid10_
[ 2659.319471] ? r10bio_
[ 2659.319474] ? mempool_
[ 2659.319478] ? md_write_
[ 2659.319483] raid10_
[ 2659.319487] md_handle_
[ 2659.319492] md_submit_
[ 2659.319495] process_
[ 2659.319498] worker_
[ 2659.319503] kthread+0x121/0x140
[ 2659.319506] ? process_
[ 2659.319510] ? kthread_
[ 2659.319513] ret_from_
[ 2659.319522] INFO: task kworker/2:4:9775 blocked for more than 120 seconds.
[ 2659.319568] Not tainted 4.15.0-20-generic #21-Ubuntu
[ 2659.319604] "echo 0 > /proc/sys/
[ 2659.319655] kworker/2:4 D 0 9775 2 0x80000000
[ 2659.319661] Workqueue: md md_submit_
[ 2659.319663] Call Trace:
[ 2659.319668] __schedule+
[ 2659.319673] schedule+0x2c/0x80
[ 2659.319677] wait_barrier+
[ 2659.319681] ? wait_woken+
[ 2659.319685] raid10_
[ 2659.319689] ? r10bio_
[ 2659.319693] ? mempool_
[ 2659.319697] ? md_write_
[ 2659.319702] raid10_
[ 2659.319706] md_handle_
[ 2659.319711] md_submit_
[ 2659.319714] process_
[ 2659.319717] worker_
[ 2659.319721] kthread+0x121/0x140
[ 2659.319724] ? process_
[ 2659.319728] ? kthread_
[ 2659.319732] ? do_syscall_
[ 2659.319735] ? SyS_exit_
[ 2659.319738] ret_from_
[ 2659.319750] INFO: task dpkg:17453 blocked for more than 120 seconds.
[ 2659.319792] Not tainted 4.15.0-20-generic #21-Ubuntu
[ 2659.319829] "echo 0 > /proc/sys/
[ 2659.319879] dpkg D 0 17453 17180 0x00000000
[ 2659.319882] Call Trace:
[ 2659.319887] __schedule+
[ 2659.319944] ? xlog_sync+
[ 2659.319949] schedule+0x2c/0x80
[ 2659.319999] _xfs_log_
[ 2659.320003] ? file_check_
[ 2659.320008] ? wake_up_q+0x80/0x80
[ 2659.320056] xfs_file_
[ 2659.320061] vfs_fsync_
[ 2659.320064] do_fsync+0x3d/0x70
[ 2659.320067] SyS_fsync+0x10/0x20
[ 2659.320071] do_syscall_
[ 2659.320076] entry_SYSCALL_
[ 2659.320078] RIP: 0033:0x7f97758f9214
[ 2659.320080] RSP: 002b:00007ffe2c
[ 2659.320083] RAX: ffffffffffffffda RBX: 00005622a49c6300 RCX: 00007f97758f9214
[ 2659.320085] RDX: 0000000000000001 RSI: 00005622a49ce340 RDI: 000000000000000b
[ 2659.320086] RBP: 00005622a3a35174 R08: 00005622a49c6373 R09: 0000000000000000
[ 2659.320088] R10: 0000000000000000 R11: 0000000000000246 R12: 00005622a49c6210
[ 2659.320090] R13: 00005622a3a35173 R14: 000000000000000b R15: 00005622a49ce340
[ 2659.320094] INFO: task kworker/4:2:17583 blocked for more than 120 seconds.
[ 2659.320140] Not tainted 4.15.0-20-generic #21-Ubuntu
[ 2659.320176] "echo 0 > /proc/sys/
[ 2659.320226] kworker/4:2 D 0 17583 2 0x80000000
[ 2659.320281] Workqueue: xfs-sync/md1p1 xfs_log_worker [xfs]
[ 2659.320283] Call Trace:
[ 2659.320289] __schedule+
[ 2659.320293] schedule+0x2c/0x80
[ 2659.320298] md_flush_
[ 2659.320302] ? wait_woken+
[ 2659.320307] raid10_
[ 2659.320311] md_handle_
[ 2659.320316] md_make_
[ 2659.320322] generic_
[ 2659.320326] submit_
[ 2659.320330] ? submit_
[ 2659.320378] _xfs_buf_
[ 2659.320385] ? kernel_
[ 2659.320433] ? xlog_bdstrat+
[ 2659.320479] xfs_buf_
[ 2659.320520] ? xfs_buf_
[ 2659.320567] xlog_bdstrat+
[ 2659.320611] xlog_sync+
[ 2659.320654] xlog_state_
[ 2659.320696] _xfs_log_
[ 2659.320702] ? __switch_
[ 2659.320744] ? xfs_log_
[ 2659.320784] xfs_log_
[ 2659.320824] xfs_log_
[ 2659.320828] process_
[ 2659.320832] worker_
[ 2659.320836] kthread+0x121/0x140
[ 2659.320839] ? process_
[ 2659.320843] ? kthread_
[ 2659.320847] ? do_syscall_
[ 2659.320850] ? SyS_exit_
[ 2659.320854] ret_from_
[ 2659.320858] INFO: task bash:17617 blocked for more than 120 seconds.
[ 2659.320901] Not tainted 4.15.0-20-generic #21-Ubuntu
[ 2659.320938] "echo 0 > /proc/sys/
[ 2659.320988] bash D 0 17617 5271 0x80000000
[ 2659.320991] Call Trace:
[ 2659.320997] __schedule+
[ 2659.321002] schedule+0x2c/0x80
[ 2659.321006] wait_barrier+
[ 2659.321010] ? wait_woken+
[ 2659.321015] raid10_
[ 2659.321019] ? r10bio_
[ 2659.321023] ? mempool_
[ 2659.321027] ? mempool_
[ 2659.321030] ? kmem_cache_
[ 2659.321036] ? radix_tree_
[ 2659.321040] raid10_
[ 2659.321045] md_handle_
[ 2659.321050] md_make_
[ 2659.321055] generic_
[ 2659.321060] submit_
[ 2659.321064] ? submit_
[ 2659.321070] ? guard_bio_
[ 2659.321073] mpage_readpages
[ 2659.321123] ? xfs_map_
[ 2659.321168] xfs_vm_
[ 2659.321173] __do_page_
[ 2659.321178] ondemand_
[ 2659.321204] ? find_get_
[ 2659.321207] ? ondemand_
[ 2659.321212] page_cache_
[ 2659.321215] generic_
[ 2659.321221] ? _cond_resched+
[ 2659.321224] ? down_read+0x12/0x40
[ 2659.321273] xfs_file_
[ 2659.321322] xfs_file_
[ 2659.321334] new_sync_
[ 2659.321344] __vfs_read+
[ 2659.321355] vfs_read+0x8e/0x130
[ 2659.321365] kernel_
[ 2659.321372] prepare_
[ 2659.321376] do_execveat_
[ 2659.321382] SyS_execve+
[ 2659.321391] do_syscall_
[ 2659.321401] entry_SYSCALL_
[ 2659.321409] RIP: 0033:0x7fb415617e37
[ 2659.321414] RSP: 002b:00007fffde
[ 2659.321428] RAX: ffffffffffffffda RBX: 0000560263024ab0 RCX: 00007fb415617e37
[ 2659.321432] RDX: 0000560262ffb1c0 RSI: 0000560263024b10 RDI: 0000560263024ab0
[ 2659.321438] RBP: 0000560263024ab0 R08: 00007fffde7393b0 R09: 0000000000000000
[ 2659.321445] R10: 0000000000000008 R11: 0000000000000246 R12: 0000000000000001
[ 2659.321451] R13: 0000560263024b10 R14: 0000560262ffb1c0 R15: 0000000000000000
description: | updated |
affects: | ubuntu → linux (Ubuntu) |
Changed in linux (Ubuntu Bionic): | |
status: | New → In Progress |
importance: | Undecided → Medium |
assignee: | nobody → Connor Kuehl (connork) |
Changed in linux (Ubuntu Bionic): | |
status: | In Progress → Fix Committed |
tags: | added: cscc |
Same here, md raid10 (not sure if its important but xfs, hung 3 times in last 2 days). 42.46~16. 04.1-generic 4.10.17 (yes, I know it's a wide range, but everything started happening after we rebooted this machine, which upgraded us from Ubuntu 4.10.0- 42.46~16. 04.1-generic 4.10.17 to Ubuntu 4.13.0- 43.48~16. 04.1-generic 4.13.16, the check was scheduled some time later, so we didn't catch it immediately).
It seems that a combination of md raid10 check + I/O (maybe XFS-specific, I dunno, but both original poster and us seem to use XFS) frequently hangs on kernels that are newer than Ubuntu 4.10.0-
The logs look very similar: kernel/ hung_task_ timeout_ secs" disables this message. 0x3d6/0x8b0 0xd2/0x1a0 [raid10] 0x80/0x80 sync_request+ 0x9bd/0x1b10 [raid10] task_fair+ 0x449/0x570 to+0xb2/ 0x540 bit+0xb/ 0x10 idle+0xa1/ 0x101 0xb81/0xfb0 0x80/0x80 0x133/0x180 0x133/0x180 0x320/0x320 create_ on_node+ 0x70/0x70 fork+0x35/ 0x40 kernel/ hung_task_ timeout_ secs" disables this message. 0x3d6/0x8b0 timeout+ 0x1f3/0x360
Jun 13 19:15:42 pisces kernel: [27430.370899] INFO: task md7_resync:12982 blocked for more than 120 seconds.
Jun 13 19:15:42 pisces kernel: [27430.370940] Not tainted 4.13.0-43-generic #48~16.04.1-Ubuntu
Jun 13 19:15:42 pisces kernel: [27430.370966] "echo 0 > /proc/sys/
Jun 13 19:15:42 pisces kernel: [27430.370997] md7_resync D 0 12982 2 0x80000000
Jun 13 19:15:42 pisces kernel: [27430.371000] Call Trace:
Jun 13 19:15:42 pisces kernel: [27430.371012] __schedule+
Jun 13 19:15:42 pisces kernel: [27430.371014] schedule+0x36/0x80
Jun 13 19:15:42 pisces kernel: [27430.371020] raise_barrier+
Jun 13 19:15:42 pisces kernel: [27430.371024] ? wait_woken+
Jun 13 19:15:42 pisces kernel: [27430.371027] raid10_
Jun 13 19:15:42 pisces kernel: [27430.371031] ? pick_next_
Jun 13 19:15:42 pisces kernel: [27430.371035] ? __switch_
Jun 13 19:15:42 pisces kernel: [27430.371041] ? find_next_
Jun 13 19:15:42 pisces kernel: [27430.371046] ? is_mddev_
Jun 13 19:15:42 pisces kernel: [27430.371048] md_do_sync+
Jun 13 19:15:42 pisces kernel: [27430.371050] ? wait_woken+
Jun 13 19:15:42 pisces kernel: [27430.371054] md_thread+
Jun 13 19:15:42 pisces kernel: [27430.371055] ? md_thread+
Jun 13 19:15:42 pisces kernel: [27430.371060] kthread+0x10c/0x140
Jun 13 19:15:42 pisces kernel: [27430.371062] ? state_show+
Jun 13 19:15:42 pisces kernel: [27430.371064] ? kthread_
Jun 13 19:15:42 pisces kernel: [27430.371067] ret_from_
Jun 13 19:15:42 pisces kernel: [27430.371181] INFO: task kworker/20:1:27873 blocked for more than 120 seconds.
Jun 13 19:15:42 pisces kernel: [27430.371210] Not tainted 4.13.0-43-generic #48~16.04.1-Ubuntu
Jun 13 19:15:42 pisces kernel: [27430.371235] "echo 0 > /proc/sys/
Jun 13 19:15:42 pisces kernel: [27430.371267] kworker/20:1 D 0 27873 2 0x80000000
Jun 13 19:15:42 pisces kernel: [27430.371333] Workqueue: xfs-sync/md7 xfs_log_worker [xfs]
Jun 13 19:15:42 pisces kernel: [27430.371334] Call Trace:
Jun 13 19:15:42 pisces kernel: [27430.371338] __schedule+
Jun 13 19:15:42 pisces kernel: [27430.371340] schedule+0x36/0x80
Jun 13 19:15:42 pisces kernel: [27430.371342] schedule_
Jun 13 19:15:42 pisces kernel: [27430.371347] ? scsi_ini...