[RT] Deadlock on filesystem operations v5.15+

[RT] Deadlock on filesystem operations v5.15+

[John Keeping]

Hi,

I'm seeing a deadlock in filesystem operations on v5.15.49-rt47-rebase;
after further testing this is reproducible in all v5.15 releases I
tested as well as v5.19-rc3-rt5-rebase.  I believe it is specific to
CONFIG_PREEMPT_RT.

With added logging, I've confirmed that the kworker here is plugged and
the buffer tar is waiting for is one of those held up by the plug.  The
vfat filesystem here is on a loop device.

Both tasks here are running at normal priority (SCHED_OTHER, nice 0).

This seems to be similar to the issue fixed by b0fdc01354f4
("sched/core: Schedule new worker even if PI-blocked") since the lock
being used here is msdos_sb_info::s_lock which is a normal struct mutex
and thus tsk_is_pi_blocked() will be false for non-RT but is returning
true on RT meaning that blk_schedule_flush_plug() is skipped in
sched_submit_work().  If I remove the tsk_is_pi_blocked() check then I
can't reproduce the hang any more.

Is some further refinement of the condition here needed?

-- >8 --
INFO: task kworker/u8:0:8 blocked for more than 491 seconds.
      Not tainted 5.15.49-rt46 #1
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:kworker/u8:0    state:D stack:    0 pid:    8 ppid:     2 flags:0x00000000
Workqueue: writeback wb_workfn (flush-7:0)
[<c08a3a10>] (__schedule) from [<c08a3d84>] (schedule+0xdc/0x134)
[<c08a3d84>] (schedule) from [<c08a65a0>] (rt_mutex_slowlock_block.constprop.0+0xb8/0x174)
[<c08a65a0>] (rt_mutex_slowlock_block.constprop.0) from [<c08a6708>] (rt_mutex_slowlock.constprop.0+0xac/0x174)
[<c08a6708>] (rt_mutex_slowlock.constprop.0) from [<c0374d60>] (fat_write_inode+0x34/0x54)
[<c0374d60>] (fat_write_inode) from [<c0297304>] (__writeback_single_inode+0x354/0x3ec)
[<c0297304>] (__writeback_single_inode) from [<c0297998>] (writeback_sb_inodes+0x250/0x45c)
[<c0297998>] (writeback_sb_inodes) from [<c0297c20>] (__writeback_inodes_wb+0x7c/0xb8)
[<c0297c20>] (__writeback_inodes_wb) from [<c0297f24>] (wb_writeback+0x2c8/0x2e4)
[<c0297f24>] (wb_writeback) from [<c0298c40>] (wb_workfn+0x1a4/0x3e4)
[<c0298c40>] (wb_workfn) from [<c0138ab8>] (process_one_work+0x1fc/0x32c)
[<c0138ab8>] (process_one_work) from [<c0139120>] (worker_thread+0x22c/0x2d8)
[<c0139120>] (worker_thread) from [<c013e6e0>] (kthread+0x16c/0x178)
[<c013e6e0>] (kthread) from [<c01000fc>] (ret_from_fork+0x14/0x38)
Exception stack(0xc10e3fb0 to 0xc10e3ff8)
3fa0:                                     00000000 00000000 00000000 00000000
3fc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
3fe0: 00000000 00000000 00000000 00000000 00000013 00000000

INFO: task tar:2083 blocked for more than 491 seconds.
      Not tainted 5.15.49-rt46 #1
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:tar             state:D stack:    0 pid: 2083 ppid:  2082 flags:0x00000000
[<c08a3a10>] (__schedule) from [<c08a3d84>] (schedule+0xdc/0x134)
[<c08a3d84>] (schedule) from [<c08a41b0>] (io_schedule+0x14/0x24)
[<c08a41b0>] (io_schedule) from [<c08a455c>] (bit_wait_io+0xc/0x30)
[<c08a455c>] (bit_wait_io) from [<c08a441c>] (__wait_on_bit_lock+0x54/0xa8)
[<c08a441c>] (__wait_on_bit_lock) from [<c08a44f4>] (out_of_line_wait_on_bit_lock+0x84/0xb0)
[<c08a44f4>] (out_of_line_wait_on_bit_lock) from [<c0371fb0>] (fat_mirror_bhs+0xa0/0x144)
[<c0371fb0>] (fat_mirror_bhs) from [<c0372a68>] (fat_alloc_clusters+0x138/0x2a4)
[<c0372a68>] (fat_alloc_clusters) from [<c0370b14>] (fat_alloc_new_dir+0x34/0x250)
[<c0370b14>] (fat_alloc_new_dir) from [<c03787c0>] (vfat_mkdir+0x58/0x148)
[<c03787c0>] (vfat_mkdir) from [<c0277b60>] (vfs_mkdir+0x68/0x98)
[<c0277b60>] (vfs_mkdir) from [<c027b484>] (do_mkdirat+0xb0/0xec)
[<c027b484>] (do_mkdirat) from [<c0100060>] (ret_fast_syscall+0x0/0x1c)
Exception stack(0xc2e1bfa8 to 0xc2e1bff0)
bfa0:                   01ee42f0 01ee4208 01ee42f0 000041ed 00000000 00004000
bfc0: 01ee42f0 01ee4208 00000000 00000027 01ee4302 00000004 000dcb00 01ee4190
bfe0: 000dc368 bed11924 0006d4b0 b6ebddfc
-- 8< --


Thanks,
John

Re: [RT] Deadlock on filesystem operations v5.15+

[John Keeping]

On Mon, Jul 04, 2022 at 03:17:39PM +0100, John Keeping wrote:
> I'm seeing a deadlock in filesystem operations on v5.15.49-rt47-rebase;
> after further testing this is reproducible in all v5.15 releases I
> tested as well as v5.19-rc3-rt5-rebase.  I believe it is specific to
> CONFIG_PREEMPT_RT.
> 
> With added logging, I've confirmed that the kworker here is plugged and
> the buffer tar is waiting for is one of those held up by the plug.  The
> vfat filesystem here is on a loop device.
> 
> Both tasks here are running at normal priority (SCHED_OTHER, nice 0).
> 
> This seems to be similar to the issue fixed by b0fdc01354f4
> ("sched/core: Schedule new worker even if PI-blocked") since the lock
> being used here is msdos_sb_info::s_lock which is a normal struct mutex
> and thus tsk_is_pi_blocked() will be false for non-RT but is returning
> true on RT meaning that blk_schedule_flush_plug() is skipped in
> sched_submit_work().  If I remove the tsk_is_pi_blocked() check then I
> can't reproduce the hang any more.
> 
> Is some further refinement of the condition here needed?

Having taken another look at why this wasn't happening in v5.10-rt
previously, the tsk_is_pi_blocked() check in sched_submit_work() was
removed by a patch [1] added in v5.9.1-rt20 but dropped in v5.13-rt1.

It looks like the rest of that patch was replaced by b4bfa3fcfe3b
("sched/core: Rework the __schedule() preempt argument") upstream but
the hunks dropping tsk_is_pi_blocked() have been totally lost.

So I've sent a patch to drop the check [2] as it seems this creates a
difference in the behaviour of always preemptible locks between RT and
!RT which this function isn't called at all by any of the locks that
become preemptible only with RT.

[1] https://git.kernel.org/pub/scm/linux/kernel/git/rt/linux-rt-devel.git/tree/patches/0022-locking-rtmutex-Use-custom-scheduling-function-for-s.patch?h=linux-5.10.y-rt-patches
[2] https://lore.kernel.org/lkml/20220707143902.529938-1-john@metanate.com/