On Mon, Jun 14, 2021 at 08:56:00AM -0400, Brian Foster wrote: > On Mon, Jun 14, 2021 at 08:32:58AM -0400, Brian Foster wrote: > > On Sat, Jun 12, 2021 at 08:33:32AM +1000, Dave Chinner wrote: > > > On Fri, Jun 11, 2021 at 03:02:39PM -0400, Brian Foster wrote: > > > > On Thu, Jun 10, 2021 at 11:14:32AM -0400, Brian Foster wrote: > ... > > > > I've also now been hitting a deadlock issue more frequently with the > > same test. I'll provide more on that in a separate mail.. > > > > So I originally thought this one was shutdown related (there still may > be a shutdown hang, I was quickly working around other issues to give > priority to the corruption issue), but what I'm seeing actually looks > like a log reservation deadlock. More specifically, it looks like a > stuck CIL push and everything else backed up behind it. > > I suspect this is related to the same patch (it does show 4 concurrent > CIL push tasks, fwiw), but I'm not 100% certain atm. I'll repeat some > tests on the prior commit to try and confirm or rule that out. In the > meantime, dmesg with blocked task output is attached. > > [49989.354537] sysrq: Show Blocked State > [49989.362009] task:kworker/u161:4 state:D stack: 0 pid:105326 ppid: 2 flags:0x00004000 > [49989.370464] Workqueue: xfs-cil/dm-5 xlog_cil_push_work [xfs] > [49989.376278] Call Trace: > [49989.378744] __schedule+0x38b/0xc50 > [49989.382250] ? lock_release+0x1cd/0x2a0 > [49989.386097] schedule+0x5b/0xc0 > [49989.389251] xlog_wait_on_iclog+0xeb/0x100 [xfs] > [49989.393932] ? wake_up_q+0xa0/0xa0 > [49989.397353] xlog_cil_push_work+0x5cb/0x630 [xfs] > [49989.402123] ? sched_clock_cpu+0xc/0xb0 > [49989.405971] ? lock_acquire+0x15d/0x380 > [49989.409823] ? lock_release+0x1cd/0x2a0 > [49989.413662] ? lock_acquire+0x15d/0x380 > [49989.417502] ? lock_release+0x1cd/0x2a0 > [49989.421353] ? finish_task_switch.isra.0+0xa0/0x2c0 > [49989.426238] process_one_work+0x26e/0x560 > [49989.430271] worker_thread+0x52/0x3b0 > [49989.433942] ? process_one_work+0x560/0x560 > [49989.438138] kthread+0x12c/0x150 > [49989.441380] ? __kthread_bind_mask+0x60/0x60 Only way we can get stuck here is that the ctx->start_lsn != commit_lsn and the previous iclog is still in WANT_SYNC/SYNC state. This implies the iclog has an elevated reference count and so while it has been released, IO wasn't issued on it because refcount > 0. The only way I can see this happening is start_lsn != commit_lsn on the same iclog, or we have a bug in the iclog reference counting and it's never reaching zero on the previous iclog. Ok, I think I've reproduced this - took about 300 iterations of g/019, but I've got a system stuck like this but all the other CIL pushes in progress are stuck here: [ 2458.915655] INFO: task kworker/u8:4:31656 blocked for more than 123 seconds. [ 2458.917629] Not tainted 5.13.0-rc6-dgc+ #205 [ 2458.919011] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 2458.921205] task:kworker/u8:4 state:D stack:12160 pid:31656 ppid: 2 flags:0x00004000 [ 2458.923538] Workqueue: xfs-cil/vdb xlog_cil_push_work [ 2458.925000] Call Trace: [ 2458.925763] __schedule+0x30b/0x9f0 [ 2458.926811] schedule+0x68/0xe0 [ 2458.927757] xlog_state_get_iclog_space+0x1b8/0x2d0 [ 2458.929122] ? wake_up_q+0xa0/0xa0 [ 2458.930142] xlog_write+0x7b/0x650 [ 2458.931145] ? _raw_spin_unlock_irq+0xe/0x30 [ 2458.932405] ? __wait_for_common+0x133/0x160 [ 2458.933647] xlog_cil_push_work+0x5eb/0xa10 [ 2458.934854] ? wake_up_q+0xa0/0xa0 [ 2458.935881] ? xfs_swap_extents+0x920/0x920 [ 2458.937126] process_one_work+0x1ab/0x390 [ 2458.938284] worker_thread+0x56/0x3d0 [ 2458.939355] ? rescuer_thread+0x3c0/0x3c0 [ 2458.940557] kthread+0x14d/0x170 [ 2458.941530] ? __kthread_bind_mask+0x70/0x70 [ 2458.942779] ret_from_fork+0x1f/0x30 Which indicates that there are no iclogs in XLOG_STATE_ACTIVE (i.e. the "noiclogs" state, and that definitely correlates with an iclog stuck in an WANT_SYNC state.... Now I know I can reproduce it, I'll dig into it. Cheers, Dave. -- Dave Chinner david@xxxxxxxxxxxxx
