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 <pet...@infradead.org> > >> 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 <fdman...@suse.com> >
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 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. > >