Deadlock on filesystem operations v5.15+

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

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/[email protected]/