Messages in this thread Patch in this message | | | Date | Thu, 5 Nov 2020 09:10:12 +0800 | From | Boqun Feng <> | Subject | Re: possible lockdep regression introduced by 4d004099a668 ("lockdep: Fix lockdep recursion") |
| |
On Wed, Nov 04, 2020 at 07:54:40PM +0000, Filipe Manana wrote: [...] > > Ok, so I ran 5.10-rc2 plus your two patches (the fix and the debug one): > > diff --git a/kernel/locking/lockdep.c b/kernel/locking/lockdep.c > index b71ad8d9f1c9..b31d4ad482c7 100644 > --- a/kernel/locking/lockdep.c > +++ b/kernel/locking/lockdep.c > @@ -539,8 +539,10 @@ static struct lock_trace *save_trace(void) > LOCK_TRACE_SIZE_IN_LONGS; > > if (max_entries <= 0) { > - if (!debug_locks_off_graph_unlock()) > + if (!debug_locks_off_graph_unlock()) { > + WARN_ON_ONCE(1); > return NULL; > + } > > print_lockdep_off("BUG: MAX_STACK_TRACE_ENTRIES too low!"); > dump_stack(); > @@ -5465,7 +5467,7 @@ noinstr int lock_is_held_type(const struct > lockdep_map *lock, int read) > unsigned long flags; > int ret = 0; > > - if (unlikely(!lockdep_enabled())) > + if (unlikely(debug_locks && !lockdep_enabled())) > return 1; /* avoid false negative lockdep_assert_held() */ > > raw_local_irq_save(flags); > > With 3 runs of all fstests, the WARN_ON_ONCE(1) wasn't triggered. > Unexpected, right? >
Kinda, that means we still don't know why lockdep was turned off.
> Should I try something else? >
Thanks for trying this. Let me set up the reproducer on my side, and see if I could get more information.
Regards, Boqun
> Thanks. > > > > > > Thanks! > > > >> > >> Alternatively, it's also helpful if you can try the following debug > >> diff, with teh full set of xfstests: > >> > >> Thanks! Just trying to understand the real problem. > >> > >> Regards, > >> Boqun > >> > >> -------------->8 > >> diff --git a/kernel/locking/lockdep.c b/kernel/locking/lockdep.c > >> index b71ad8d9f1c9..9ae3e089e5c0 100644 > >> --- a/kernel/locking/lockdep.c > >> +++ b/kernel/locking/lockdep.c > >> @@ -539,8 +539,10 @@ static struct lock_trace *save_trace(void) > >> LOCK_TRACE_SIZE_IN_LONGS; > >> > >> if (max_entries <= 0) { > >> - if (!debug_locks_off_graph_unlock()) > >> + if (!debug_locks_off_graph_unlock()) { > >> + WARN_ON_ONCE(1); > >> return NULL; > >> + } > >> > >> print_lockdep_off("BUG: MAX_STACK_TRACE_ENTRIES too low!"); > >> dump_stack(); > >> > >>> I guess I will have to reproduce this myself for further analysis, could > >>> you share you .config? > >>> > >>> Anyway, I think this fix still makes a bit sense, I will send a proper > >>> patch so that the problem won't block fs folks. > >>> > >>> Regards, > >>> Boqun > >>> > >>>> Thanks! > >>>> > >>>>> > >>>>> > >>>>> > >>>>>> What happens is percpu_rwsem_is_held() is apparently returning a false > >>>>>> positive, so this makes __sb_start_write() do a > >>>>>> percpu_down_read_trylock() on a percpu_rw_sem at a higher level, which > >>>>>> is expected to always succeed, because if the calling task is holding a > >>>>>> freeze percpu_rw_sem at level 1, it's supposed to be able to try_lock > >>>>>> the semaphore at level 2, since the freeze semaphores are always > >>>>>> acquired by increasing level order. > >>>>>> > >>>>>> But the try_lock fails, it triggers the warning at __sb_start_write(), > >>>>>> then its caller sb_start_pagefault() ignores the return value and > >>>>>> callers such as btrfs_page_mkwrite() make the assumption the freeze > >>>>>> semaphore was taken, proceed to do their stuff, and later call > >>>>>> sb_end_pagefault(), which which will do an up_read() on the percpu_rwsem > >>>>>> at level 2 despite not having not been able to down_read() the > >>>>>> semaphore. This obviously corrupts the semaphore's read_count state, and > >>>>>> later causes any task trying to down_write() it to hang forever. > >>>>>> > >>>>>> After such a hang I ran a drgn script to confirm it: > >>>>>> > >>>>>> $ cat dump_freeze_sems.py > >>>>>> import sys > >>>>>> import drgn > >>>>>> from drgn import NULL, Object, cast, container_of, execscript, \ > >>>>>> reinterpret, sizeof > >>>>>> from drgn.helpers.linux import * > >>>>>> > >>>>>> mnt_path = b'/home/fdmanana/btrfs-tests/scratch_1' > >>>>>> > >>>>>> mnt = None > >>>>>> for mnt in for_each_mount(prog, dst = mnt_path): > >>>>>> pass > >>>>>> > >>>>>> if mnt is None: > >>>>>> sys.stderr.write(f'Error: mount point {mnt_path} not found\n') > >>>>>> sys.exit(1) > >>>>>> > >>>>>> def dump_sem(level_enum): > >>>>>> level = level_enum.value_() > >>>>>> sem = mnt.mnt.mnt_sb.s_writers.rw_sem[level - 1] > >>>>>> print(f'freeze semaphore at level {level}, {str(level_enum)}') > >>>>>> print(f' block {sem.block.counter.value_()}') > >>>>>> for i in for_each_possible_cpu(prog): > >>>>>> read_count = per_cpu_ptr(sem.read_count, i) > >>>>>> print(f' read_count at cpu {i} = {read_count}') > >>>>>> print() > >>>>>> > >>>>>> # dump semaphore read counts for all freeze levels (fs.h) > >>>>>> dump_sem(prog['SB_FREEZE_WRITE']) > >>>>>> dump_sem(prog['SB_FREEZE_PAGEFAULT']) > >>>>>> dump_sem(prog['SB_FREEZE_FS']) > >>>>>> > >>>>>> > >>>>>> $ drgn dump_freeze_sems.py > >>>>>> freeze semaphore at level 1, (enum <anonymous>)SB_FREEZE_WRITE > >>>>>> block 1 > >>>>>> read_count at cpu 0 = *(unsigned int *)0xffffc2ec3ee00c74 = 3 > >>>>>> read_count at cpu 1 = *(unsigned int *)0xffffc2ec3f200c74 = 4294967293 > >>>>>> read_count at cpu 2 = *(unsigned int *)0xffffc2ec3f600c74 = 3 > >>>>>> read_count at cpu 3 = *(unsigned int *)0xffffc2ec3fa00c74 = 4294967293 > >>>>>> > >>>>>> freeze semaphore at level 2, (enum <anonymous>)SB_FREEZE_PAGEFAULT > >>>>>> block 1 > >>>>>> read_count at cpu 0 = *(unsigned int *)0xffffc2ec3ee00c78 = 0 > >>>>>> read_count at cpu 1 = *(unsigned int *)0xffffc2ec3f200c78 = 4294967295 > >>>>>> read_count at cpu 2 = *(unsigned int *)0xffffc2ec3f600c78 = 0 > >>>>>> read_count at cpu 3 = *(unsigned int *)0xffffc2ec3fa00c78 = 0 > >>>>>> > >>>>>> freeze semaphore at level 3, (enum <anonymous>)SB_FREEZE_FS > >>>>>> block 0 > >>>>>> read_count at cpu 0 = *(unsigned int *)0xffffc2ec3ee00c7c = 0 > >>>>>> read_count at cpu 1 = *(unsigned int *)0xffffc2ec3f200c7c = 0 > >>>>>> read_count at cpu 2 = *(unsigned int *)0xffffc2ec3f600c7c = 0 > >>>>>> read_count at cpu 3 = *(unsigned int *)0xffffc2ec3fa00c7c = 0 > >>>>>> > >>>>>> At levels 1 and 3, read_count sums to 0, so it's fine, but at level 2 it > >>>>>> sums to -1. The system remains like that for hours at least, with no > >>>>>> progress at all. > >>>>>> > >>>>>> Is there a known regression with that lockdep commit? > >>>>>> Anything I can do to help debug it in case it's not obvious? > >>>>>> > >>>>>> Thanks. > >>>>> > >>
| |