Re: possible lockdep regression introduced by 4d004099a668 ("lockdep: Fix lockdep recursion")

[Boqun Feng]

On Wed, Nov 04, 2020 at 10:22:36AM +0800, Boqun Feng wrote:
> On Tue, Nov 03, 2020 at 07:44:29PM +0000, Filipe Manana wrote:
> > 
> > 
> > On 03/11/20 14:08, Boqun Feng wrote:
> > > Hi Filipe,
> > > 
> > > On Mon, Oct 26, 2020 at 11:26:49AM +0000, Filipe Manana wrote:
> > >> Hello,
> > >>
> > >> I've recently started to hit a warning followed by tasks hanging after
> > >> attempts to freeze a filesystem. A git bisection pointed to the
> > >> following commit:
> > >>
> > >> commit 4d004099a668c41522242aa146a38cc4eb59cb1e
> > >> Author: Peter Zijlstra <peterz@xxxxxxxxxxxxx>
> > >> Date:   Fri Oct 2 11:04:21 2020 +0200
> > >>
> > >>     lockdep: Fix lockdep recursion
> > >>
> > >> This happens very reliably when running all xfstests with lockdep
> > >> enabled, and the tested filesystem is btrfs (haven't tried other
> > >> filesystems, but it shouldn't matter). The warning and task hangs always
> > >> happen at either test generic/068 or test generic/390, and (oddly)
> > >> always have to run all tests for it to trigger, running those tests
> > >> individually on an infinite loop doesn't seem to trigger it (at least
> > >> for a couple hours).
> > >>
> > >> The warning triggered is at fs/super.c:__sb_start_write() which always
> > >> results later in several tasks hanging on a percpu rw_sem:
> > >>
> > >> https://pastebin.com/qnLvf94E
> > >>
> > > 
> > > In your dmesg, I see line:
> > > 
> > > 	[ 9304.920151] INFO: lockdep is turned off.
> > > 
> > > , that means debug_locks is 0, that usually happens when lockdep find a
> > > problem (i.e. a deadlock) and it turns itself off, because a problem is
> > > found and it's pointless for lockdep to continue to run.
> > > 
> > > And I haven't found a lockdep splat in your dmesg, do you have a full
> > > dmesg so that I can have a look?
> > > 
> > > This may be relevant because in commit 4d004099a66, we have
> > > 
> > > 	@@ -5056,13 +5081,13 @@ noinstr int lock_is_held_type(const struct lockdep_map *lock, int read)
> > > 		unsigned long flags;
> > > 		int ret = 0;
> > > 
> > > 	-       if (unlikely(current->lockdep_recursion))
> > > 	+       if (unlikely(!lockdep_enabled()))
> > > 			return 1; /* avoid false negative lockdep_assert_held() */
> > > 
> > > before this commit lock_is_held_type() and its friends may return false
> > > if debug_locks==0, after this commit lock_is_held_type() and its friends
> > > will always return true if debug_locks == 0. That could cause the
> > > behavior here.
> > > 
> > > In case I'm correct, the following "fix" may be helpful. 
> > > 
> > > Regards,
> > > Boqun
> > > 
> > > ----------8
> > > diff --git a/kernel/locking/lockdep.c b/kernel/locking/lockdep.c
> > > index 3e99dfef8408..c0e27fb949ff 100644
> > > --- a/kernel/locking/lockdep.c
> > > +++ b/kernel/locking/lockdep.c
> > > @@ -5471,7 +5464,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);
> > 
> > Boqun, the patch fixes the problem for me!
> > You can have Tested-by: Filipe Manana <fdmanana@xxxxxxxx>
> > 
> 
> Thanks. Although I think it still means that we have a lock issue when
> running xfstests (because we don't know why debug_locks gets cleared),

I might find a place where we could turn lockdep off silently:

in print_circular_bug(), we turn off lockdep via
debug_locks_off_graph_unlock(), and then we try to save the trace for
lockdep splat, however, if we use up the stack_trace buffer (i.e.
nr_stack_trace_entries), save_trace() will return NULL and we return
silently.

Filipe, in order to check whethter that happens, could you share me your
/proc/lockdep_stats after the full set of xfstests is finished?

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.
> > >