Re: 1 lock held by xfs_repair/276634
From: Dave Chinner <david@fromorbit.com>
Date: 2021-07-02 00:06:02
Also in:
linux-fsdevel
On Thu, Jul 01, 2021 at 12:44:30PM +0200, Bruno Goncalves wrote:
Hello, We have hit this lock problem during xfstest [1] on aarch64. The whole console.log is available on [2].
fstests is not the place to report test failures. They should be directed to the list for the subsystem that failed. In this case, probably linux-xfs@vger.kernel.org. I haven't cc'd that list because....
10847.013727] run fstests generic/023 at 2021-05-15 17:21:46
[10863.635560] XFS (sda4): Unmounting Filesystem
[10865.095328] BUG: sleeping function called from invalid context at (null):3550
[10865.102695] in_atomic(): 0, irqs_disabled(): 128, non_block: 0,
pid: 276634, name: xfs_repair
[10865.111223] 1 lock held by xfs_repair/276634:
[10865.115579] #0: ffff000168f654d0
(&tsk->futex_exit_mutex){+.+.}-{3:3}, at: futex_exit_release+0x40/0xe4
[10865.125091] irq event stamp: 150
[10865.128314] hardirqs last enabled at (149): [<ffff8000101a2778>]
uaccess_ttbr0_enable+0xa8/0xc0
[10865.137096] hardirqs last disabled at (150): [<ffff8000101a2838>]
uaccess_ttbr0_disable+0xa8/0xb4
[10865.145964] softirqs last enabled at (132): [<ffff800010016490>]
put_cpu_fpsimd_context+0x30/0x70
[10865.154921] softirqs last disabled at (130): [<ffff800010016408>]
get_cpu_fpsimd_context+0x8/0x60
[10865.163792] CPU: 31 PID: 276634 Comm: xfs_repair Not tainted 5.13.0-rc1 #1
[10865.170663] Hardware name: GIGABYTE R120-T34-00/MT30-GS2-00, BIOS
F02 08/06/2019
[10865.178054] Call trace:
[10865.180496] dump_backtrace+0x0/0x1c0
[10865.184156] show_stack+0x24/0x30
[10865.187467] dump_stack+0xf8/0x164
[10865.190867] ___might_sleep+0x174/0x250
[10865.194700] __might_sleep+0x60/0xa0
[10865.198272] __might_fault+0x3c/0x90
[10865.201847] exit_robust_list+0xac/0x36c
[10865.205767] exit_robust_list+0x9c/0x36c
[10865.209686] futex_exit_release+0xa8/0xe4
[10865.213692] exit_mm_release+0x28/0x44
[10865.217438] exit_mm+0x2c/0x27c
[10865.220579] do_exit+0x1f0/0x454
[10865.223804] __arm64_sys_exit+0x24/0x2c
[10865.227638] invoke_syscall+0x50/0x120
[10865.231384] el0_svc_common.constprop.0+0x68/0x104
[10865.236172] do_el0_svc+0x30/0x9c
[10865.239483] el0_svc+0x2c/0x54
[10865.242538] el0_sync_handler+0x1a4/0x1b0
[10865.246544] el0_sync+0x19c/0x1c0... this is likely a futex bug or some other platform kernel bug. xfs_repair is just the userspace application that is tripping over it.
We don't reproduce this often, but the first time I've seen it was with 'Commit: f36edc5533b2 - Merge tag 'arc-5.13-rc2' of git://git.kernel.org/pub/scm/linux/kernel/git/vgupta/arc' [1] https://gitlab.com/cki-project/kernel-tests/-/tree/main/filesystems/xfs/xfstests [2] https://arr-cki-prod-datawarehouse-public.s3.amazonaws.com/datawarehouse-public/2021/05/15/303402899/build_aarch64_redhat%3A1264727321/tests/9991652_aarch64_2_console.log
Yup, there's a second occurrence of this same "sleeping in invalid context" bug from something called "stress-ng" on a rwsem: [ 2277.799926] BUG: sleeping function called from invalid context at kernel/locking/rwsem.c:1352 [ 2277.808464] in_atomic(): 0, irqs_disabled(): 128, non_block: 0, pid: 125191, name: stress-ng [ 2277.816908] no locks held by stress-ng/125191. [ 2277.821356] irq event stamp: 2482 [ 2277.824682] hardirqs last enabled at (2481): [<ffff800010341e0c>] __uaccess_ttbr0_enable+0x7c/0x90 [ 2277.833742] hardirqs last disabled at (2482): [<ffff800010342130>] __do_sys_mincore+0x310/0x354 [ 2277.842448] softirqs last enabled at (30): [<ffff800010016490>] put_cpu_fpsimd_context+0x30/0x70 [ 2277.851329] softirqs last disabled at (28): [<ffff800010016408>] get_cpu_fpsimd_context+0x8/0x60 [ 2277.860125] CPU: 11 PID: 125191 Comm: stress-ng Not tainted 5.13.0-rc1 #1 [ 2277.866919] Hardware name: GIGABYTE R120-T34-00/MT30-GS2-00, BIOS F02 08/06/2019 [ 2277.874319] Call trace: [ 2277.876772] dump_backtrace+0x0/0x1c0 [ 2277.880443] show_stack+0x24/0x30 [ 2277.883765] dump_stack+0xf8/0x164 [ 2277.887170] ___might_sleep+0x174/0x250 [ 2277.891003] __might_sleep+0x60/0xa0 [ 2277.894575] down_read+0x38/0xa0 [ 2277.897802] __do_sys_mincore+0xe0/0x354 [ 2277.901723] __arm64_sys_mincore+0x28/0x8c [ 2277.905816] invoke_syscall+0x50/0x120 [ 2277.909563] el0_svc_common.constprop.0+0x68/0x104 [ 2277.914350] do_el0_svc+0x30/0x9c [ 2277.917661] el0_svc+0x2c/0x54 [ 2277.920716] el0_sync_handler+0x1a4/0x1b0 [ 2277.924722] el0_sync+0x19c/0x1c0 There are also RCU lock warnings immediately after this: "kernel/sched/core.c:8304 Illegal context switch in RCU-sched read-side critical section!" occuring in core memory allocation code, followed by other interleaved warning mess. So, really, this looks like a platform bug or unbalanced irq enable/disable somewhere in the kernel and has nothing to do with the xfs_repair process that triggered it... Cheers, Dave. -- Dave Chinner david@fromorbit.com