lkml.org 
[lkml]   [2020]   [Nov]   [4]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
Patch in this message
/
Date
From
SubjectRe: 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.
> >>>>>
> >>

\
 
 \ /
  Last update: 2020-11-05 02:11    [W:0.082 / U:0.136 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site