[RFC] fs: Avoid to use lockdep information if it's turned off

[RFC] fs: Avoid to use lockdep information if it's turned off

[Boqun Feng]

Filipe Manana reported a warning followed by task hanging after attempts
to freeze a filesystem[1]. The problem happened in a LOCKDEP=y kernel,
and percpu_rwsem_is_held() provided incorrect results when
debug_locks == 0. Although the behavior is caused by commit 4d004099a668
("lockdep: Fix lockdep recursion"): after that lock_is_held() and its
friends always return true if debug_locks == 0. However, one could argue
that querying the lock holding information regardless if the lockdep
turn-off status is inappropriate in the first place. Therefore instead
of reverting lock_is_held() and its friends to the previous semantics,
add the explicit checking in fs code to avoid use the lock holding
information if lockdpe is turned off. And since the original problem
also happened with a silent lockdep turn-off, put a warning if
debug_locks is 0, which will help us spot the silent lockdep turn-offs.

[1]: https://lore.kernel.org/lkml/a5cf643b-842f-7a60-73c7-85d738a9276f@suse.com/

Reported-by: Filipe Manana <fdmanana@gmail.com>
Fixes: 4d004099a668 ("lockdep: Fix lockdep recursion")
Signed-off-by: Boqun Feng <boqun.feng@gmail.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Jan Kara <jack@suse.cz>
Cc: David Sterba <dsterba@suse.com>
Cc: Nikolay Borisov <nborisov@suse.com>
Cc: "Darrick J. Wong" <darrick.wong@oracle.com>
---
Hi Filipe,

I use the slightly different approach to fix this problem, and I think
it should have the similar effect with my previous fix[2], except that
you will hit a warning if the problem happens now. The warning is added
on purpose because I don't want to miss a silent lockdep turn-off.

Could you and other fs folks give this a try?

Regards,
Boqun

[2]: https://lore.kernel.org/lkml/20201103140828.GA2713762@boqun-archlinux/

 fs/super.c | 11 +++++++++++
 1 file changed, 11 insertions(+)

diff --git a/fs/super.c b/fs/super.c
index a51c2083cd6b..1803c8d999e9 100644
--- a/fs/super.c
+++ b/fs/super.c
@@ -1659,12 +1659,23 @@ int __sb_start_write(struct super_block *sb, int level, bool wait)
 	 * twice in some cases, which is OK only because we already hold a
 	 * freeze protection also on higher level. Due to these cases we have
 	 * to use wait == F (trylock mode) which must not fail.
+	 *
+	 * Note: lockdep can only prove correct information if debug_locks != 0
 	 */
 	if (wait) {
 		int i;
 
 		for (i = 0; i < level - 1; i++)
 			if (percpu_rwsem_is_held(sb->s_writers.rw_sem + i)) {
+				/*
+				 * XXX: the WARN_ON_ONCE() here is to help
+				 * track down silent lockdep turn-off, i.e.
+				 * this warning is triggered, but no lockdep
+				 * splat is reported.
+				 */
+				if (WARN_ON_ONCE(!debug_locks))
+					break;
+
 				force_trylock = true;
 				break;
 			}
-- 
2.29.2

Re: [RFC] fs: Avoid to use lockdep information if it's turned off

[Darrick J. Wong]

On Tue, Nov 10, 2020 at 09:37:37AM +0800, Boqun Feng wrote:
> Filipe Manana reported a warning followed by task hanging after attempts
> to freeze a filesystem[1]. The problem happened in a LOCKDEP=y kernel,
> and percpu_rwsem_is_held() provided incorrect results when
> debug_locks == 0. Although the behavior is caused by commit 4d004099a668
> ("lockdep: Fix lockdep recursion"): after that lock_is_held() and its
> friends always return true if debug_locks == 0. However, one could argue

...the silent trylock conversion with no checking of the return value is
completely broken.  I already sent a patch to tear all this out:

https://lore.kernel.org/linux-fsdevel/160494580419.772573.9286165021627298770.stgit@magnolia/T/#t

--D

> that querying the lock holding information regardless if the lockdep
> turn-off status is inappropriate in the first place. Therefore instead
> of reverting lock_is_held() and its friends to the previous semantics,
> add the explicit checking in fs code to avoid use the lock holding
> information if lockdpe is turned off. And since the original problem
> also happened with a silent lockdep turn-off, put a warning if
> debug_locks is 0, which will help us spot the silent lockdep turn-offs.
> 
> [1]: https://lore.kernel.org/lkml/a5cf643b-842f-7a60-73c7-85d738a9276f@suse.com/
> 
> Reported-by: Filipe Manana <fdmanana@gmail.com>
> Fixes: 4d004099a668 ("lockdep: Fix lockdep recursion")
> Signed-off-by: Boqun Feng <boqun.feng@gmail.com>
> Cc: Peter Zijlstra <peterz@infradead.org>
> Cc: Jan Kara <jack@suse.cz>
> Cc: David Sterba <dsterba@suse.com>
> Cc: Nikolay Borisov <nborisov@suse.com>
> Cc: "Darrick J. Wong" <darrick.wong@oracle.com>
> ---
> Hi Filipe,
> 
> I use the slightly different approach to fix this problem, and I think
> it should have the similar effect with my previous fix[2], except that
> you will hit a warning if the problem happens now. The warning is added
> on purpose because I don't want to miss a silent lockdep turn-off.
> 
> Could you and other fs folks give this a try?
> 
> Regards,
> Boqun
> 
> [2]: https://lore.kernel.org/lkml/20201103140828.GA2713762@boqun-archlinux/
> 
>  fs/super.c | 11 +++++++++++
>  1 file changed, 11 insertions(+)
> 
> diff --git a/fs/super.c b/fs/super.c
> index a51c2083cd6b..1803c8d999e9 100644
> --- a/fs/super.c
> +++ b/fs/super.c
> @@ -1659,12 +1659,23 @@ int __sb_start_write(struct super_block *sb, int level, bool wait)
>  	 * twice in some cases, which is OK only because we already hold a
>  	 * freeze protection also on higher level. Due to these cases we have
>  	 * to use wait == F (trylock mode) which must not fail.
> +	 *
> +	 * Note: lockdep can only prove correct information if debug_locks != 0
>  	 */
>  	if (wait) {
>  		int i;
>  
>  		for (i = 0; i < level - 1; i++)
>  			if (percpu_rwsem_is_held(sb->s_writers.rw_sem + i)) {
> +				/*
> +				 * XXX: the WARN_ON_ONCE() here is to help
> +				 * track down silent lockdep turn-off, i.e.
> +				 * this warning is triggered, but no lockdep
> +				 * splat is reported.
> +				 */
> +				if (WARN_ON_ONCE(!debug_locks))
> +					break;
> +
>  				force_trylock = true;
>  				break;
>  			}
> -- 
> 2.29.2
> 

Re: [RFC] fs: Avoid to use lockdep information if it's turned off

[Boqun Feng]

On Mon, Nov 09, 2020 at 05:49:25PM -0800, Darrick J. Wong wrote:
> On Tue, Nov 10, 2020 at 09:37:37AM +0800, Boqun Feng wrote:
> > Filipe Manana reported a warning followed by task hanging after attempts
> > to freeze a filesystem[1]. The problem happened in a LOCKDEP=y kernel,
> > and percpu_rwsem_is_held() provided incorrect results when
> > debug_locks == 0. Although the behavior is caused by commit 4d004099a668
> > ("lockdep: Fix lockdep recursion"): after that lock_is_held() and its
> > friends always return true if debug_locks == 0. However, one could argue
> 
> ...the silent trylock conversion with no checking of the return value is
> completely broken.  I already sent a patch to tear all this out:
> 
> https://lore.kernel.org/linux-fsdevel/160494580419.772573.9286165021627298770.stgit@magnolia/T/#t
> 

Thanks! That looks good to me. I'm all for removing that piece of code.

While we are at it, I have to ask, when you hit the original problem
(warning after trylock in __start_sb_write()), did you see any lockdep
splat happened previously? Or just like Filipe, you hit that without
seeing any lockdep splat happened before? Thanks! I'm trying to track
down the silent lockdep turn-off.

Regards,
Boqun

> --D
> 
> > that querying the lock holding information regardless if the lockdep
> > turn-off status is inappropriate in the first place. Therefore instead
> > of reverting lock_is_held() and its friends to the previous semantics,
> > add the explicit checking in fs code to avoid use the lock holding
> > information if lockdpe is turned off. And since the original problem
> > also happened with a silent lockdep turn-off, put a warning if
> > debug_locks is 0, which will help us spot the silent lockdep turn-offs.
> > 
> > [1]: https://lore.kernel.org/lkml/a5cf643b-842f-7a60-73c7-85d738a9276f@suse.com/
> > 
> > Reported-by: Filipe Manana <fdmanana@gmail.com>
> > Fixes: 4d004099a668 ("lockdep: Fix lockdep recursion")
> > Signed-off-by: Boqun Feng <boqun.feng@gmail.com>
> > Cc: Peter Zijlstra <peterz@infradead.org>
> > Cc: Jan Kara <jack@suse.cz>
> > Cc: David Sterba <dsterba@suse.com>
> > Cc: Nikolay Borisov <nborisov@suse.com>
> > Cc: "Darrick J. Wong" <darrick.wong@oracle.com>
> > ---
> > Hi Filipe,
> > 
> > I use the slightly different approach to fix this problem, and I think
> > it should have the similar effect with my previous fix[2], except that
> > you will hit a warning if the problem happens now. The warning is added
> > on purpose because I don't want to miss a silent lockdep turn-off.
> > 
> > Could you and other fs folks give this a try?
> > 
> > Regards,
> > Boqun
> > 
> > [2]: https://lore.kernel.org/lkml/20201103140828.GA2713762@boqun-archlinux/
> > 
> >  fs/super.c | 11 +++++++++++
> >  1 file changed, 11 insertions(+)
> > 
> > diff --git a/fs/super.c b/fs/super.c
> > index a51c2083cd6b..1803c8d999e9 100644
> > --- a/fs/super.c
> > +++ b/fs/super.c
> > @@ -1659,12 +1659,23 @@ int __sb_start_write(struct super_block *sb, int level, bool wait)
> >  	 * twice in some cases, which is OK only because we already hold a
> >  	 * freeze protection also on higher level. Due to these cases we have
> >  	 * to use wait == F (trylock mode) which must not fail.
> > +	 *
> > +	 * Note: lockdep can only prove correct information if debug_locks != 0
> >  	 */
> >  	if (wait) {
> >  		int i;
> >  
> >  		for (i = 0; i < level - 1; i++)
> >  			if (percpu_rwsem_is_held(sb->s_writers.rw_sem + i)) {
> > +				/*
> > +				 * XXX: the WARN_ON_ONCE() here is to help
> > +				 * track down silent lockdep turn-off, i.e.
> > +				 * this warning is triggered, but no lockdep
> > +				 * splat is reported.
> > +				 */
> > +				if (WARN_ON_ONCE(!debug_locks))
> > +					break;
> > +
> >  				force_trylock = true;
> >  				break;
> >  			}
> > -- 
> > 2.29.2
> > 

Re: [RFC] fs: Avoid to use lockdep information if it's turned off

[Darrick J. Wong]

On Tue, Nov 10, 2020 at 01:40:16PM +0800, Boqun Feng wrote:
> On Mon, Nov 09, 2020 at 05:49:25PM -0800, Darrick J. Wong wrote:
> > On Tue, Nov 10, 2020 at 09:37:37AM +0800, Boqun Feng wrote:
> > > Filipe Manana reported a warning followed by task hanging after attempts
> > > to freeze a filesystem[1]. The problem happened in a LOCKDEP=y kernel,
> > > and percpu_rwsem_is_held() provided incorrect results when
> > > debug_locks == 0. Although the behavior is caused by commit 4d004099a668
> > > ("lockdep: Fix lockdep recursion"): after that lock_is_held() and its
> > > friends always return true if debug_locks == 0. However, one could argue
> > 
> > ...the silent trylock conversion with no checking of the return value is
> > completely broken.  I already sent a patch to tear all this out:
> > 
> > https://lore.kernel.org/linux-fsdevel/160494580419.772573.9286165021627298770.stgit@magnolia/T/#t
> > 
> 
> Thanks! That looks good to me. I'm all for removing that piece of code.
> 
> While we are at it, I have to ask, when you hit the original problem
> (warning after trylock in __start_sb_write()), did you see any lockdep
> splat happened previously?

Yes.  Every time I hit this there had been a lockdep splat earlier in the
fstests run, along with lockdep declaring that it was going offline.

--D

> Or just like Filipe, you hit that without
> seeing any lockdep splat happened before? Thanks! I'm trying to track
> down the silent lockdep turn-off.
> 
> Regards,
> Boqun
> 
> > --D
> > 
> > > that querying the lock holding information regardless if the lockdep
> > > turn-off status is inappropriate in the first place. Therefore instead
> > > of reverting lock_is_held() and its friends to the previous semantics,
> > > add the explicit checking in fs code to avoid use the lock holding
> > > information if lockdpe is turned off. And since the original problem
> > > also happened with a silent lockdep turn-off, put a warning if
> > > debug_locks is 0, which will help us spot the silent lockdep turn-offs.
> > > 
> > > [1]: https://lore.kernel.org/lkml/a5cf643b-842f-7a60-73c7-85d738a9276f@suse.com/
> > > 
> > > Reported-by: Filipe Manana <fdmanana@gmail.com>
> > > Fixes: 4d004099a668 ("lockdep: Fix lockdep recursion")
> > > Signed-off-by: Boqun Feng <boqun.feng@gmail.com>
> > > Cc: Peter Zijlstra <peterz@infradead.org>
> > > Cc: Jan Kara <jack@suse.cz>
> > > Cc: David Sterba <dsterba@suse.com>
> > > Cc: Nikolay Borisov <nborisov@suse.com>
> > > Cc: "Darrick J. Wong" <darrick.wong@oracle.com>
> > > ---
> > > Hi Filipe,
> > > 
> > > I use the slightly different approach to fix this problem, and I think
> > > it should have the similar effect with my previous fix[2], except that
> > > you will hit a warning if the problem happens now. The warning is added
> > > on purpose because I don't want to miss a silent lockdep turn-off.
> > > 
> > > Could you and other fs folks give this a try?
> > > 
> > > Regards,
> > > Boqun
> > > 
> > > [2]: https://lore.kernel.org/lkml/20201103140828.GA2713762@boqun-archlinux/
> > > 
> > >  fs/super.c | 11 +++++++++++
> > >  1 file changed, 11 insertions(+)
> > > 
> > > diff --git a/fs/super.c b/fs/super.c
> > > index a51c2083cd6b..1803c8d999e9 100644
> > > --- a/fs/super.c
> > > +++ b/fs/super.c
> > > @@ -1659,12 +1659,23 @@ int __sb_start_write(struct super_block *sb, int level, bool wait)
> > >  	 * twice in some cases, which is OK only because we already hold a
> > >  	 * freeze protection also on higher level. Due to these cases we have
> > >  	 * to use wait == F (trylock mode) which must not fail.
> > > +	 *
> > > +	 * Note: lockdep can only prove correct information if debug_locks != 0
> > >  	 */
> > >  	if (wait) {
> > >  		int i;
> > >  
> > >  		for (i = 0; i < level - 1; i++)
> > >  			if (percpu_rwsem_is_held(sb->s_writers.rw_sem + i)) {
> > > +				/*
> > > +				 * XXX: the WARN_ON_ONCE() here is to help
> > > +				 * track down silent lockdep turn-off, i.e.
> > > +				 * this warning is triggered, but no lockdep
> > > +				 * splat is reported.
> > > +				 */
> > > +				if (WARN_ON_ONCE(!debug_locks))
> > > +					break;
> > > +
> > >  				force_trylock = true;
> > >  				break;
> > >  			}
> > > -- 
> > > 2.29.2
> > > 

Re: [RFC] fs: Avoid to use lockdep information if it's turned off

[David Sterba]

On Tue, Nov 10, 2020 at 09:37:37AM +0800, Boqun Feng wrote:
> Filipe Manana reported a warning followed by task hanging after attempts
> to freeze a filesystem[1]. The problem happened in a LOCKDEP=y kernel,
> and percpu_rwsem_is_held() provided incorrect results when
> debug_locks == 0. Although the behavior is caused by commit 4d004099a668
> ("lockdep: Fix lockdep recursion"): after that lock_is_held() and its
> friends always return true if debug_locks == 0. However, one could argue
> that querying the lock holding information regardless if the lockdep
> turn-off status is inappropriate in the first place. Therefore instead
> of reverting lock_is_held() and its friends to the previous semantics,
> add the explicit checking in fs code to avoid use the lock holding
> information if lockdpe is turned off. And since the original problem
> also happened with a silent lockdep turn-off, put a warning if
> debug_locks is 0, which will help us spot the silent lockdep turn-offs.
> 
> [1]: https://lore.kernel.org/lkml/a5cf643b-842f-7a60-73c7-85d738a9276f@suse.com/
> 
> Reported-by: Filipe Manana <fdmanana@gmail.com>
> Fixes: 4d004099a668 ("lockdep: Fix lockdep recursion")
> Signed-off-by: Boqun Feng <boqun.feng@gmail.com>
> Cc: Peter Zijlstra <peterz@infradead.org>
> Cc: Jan Kara <jack@suse.cz>
> Cc: David Sterba <dsterba@suse.com>
> Cc: Nikolay Borisov <nborisov@suse.com>
> Cc: "Darrick J. Wong" <darrick.wong@oracle.com>
> ---
> Hi Filipe,
> 
> I use the slightly different approach to fix this problem, and I think
> it should have the similar effect with my previous fix[2], except that
> you will hit a warning if the problem happens now. The warning is added
> on purpose because I don't want to miss a silent lockdep turn-off.

Applied on current master (407ab579637ce) it explodes in btrfs/078 and
then warning appears in folowup tests. The first report seems to be mix
of two so I'm pasting it as it got stored to the serial console, it
might give you some clues.

I'll run another test on top of the development branch in case there are
unrelated lockdep warning bugs that have been fixed meanwhile.

btrfs/078		[15:15:44][ 3963.635042] run fstests btrfs/078 at 2020-11-10 15:15:44
[ 3964.301547] BTRFS info (device vda): disk space caching is enabled
[ 3964.303698] BTRFS info (device vda): has skinny extents
[ 3964.595919] BTRFS: device fsid 6652279f-2c14-4db4-9622-77d2bc7ea516 devid 1 transid 5 /dev/vdb scanned by mkfs.btrfs (18614)
[ 3964.646896] BTRFS info (device vdb): turning on sync discard
[ 3964.648627] BTRFS info (device vdb): disk space caching is enabled
[ 3964.650483] BTRFS info (device vdb): has skinny extents
[ 3964.652107] BTRFS info (device vdb): flagging fs with big metadata feature
[ 3964.662211] BTRFS info (device vdb): checking UUID tree
[ 4173.535475] 
[ 4173.535670] ------------[ cut here ]------------
[ 4173.536750] ============================================
[ 4173.536754] WARNING: possible recursive locking detected
[ 4173.538755] WARNING: CPU: 2 PID: 18647 at fs/super.c:1676 __sb_start_write+0x113/0x2a0
[ 4173.541456] 5.10.0-rc3-default+ #1353 Not tainted
[ 4173.543478] Modules linked in:
[ 4173.546291] --------------------------------------------
[ 4173.547580]  dm_flakey
[ 4173.548722] btrfs/19276 is trying to acquire lock:
[ 4173.548725] ffffa19a7e420eb8
[ 4173.550243]  dm_mod xxhash_generic
[ 4173.551164]  (&eb->lock){++++}-{2:2}, at: btrfs_tree_read_lock_atomic+0x34/0x150 [btrfs]
[ 4173.551285] 
[ 4173.551285] but task is already holding lock:
[ 4173.552745]  btrfs
[ 4173.553789] ffffa19a7e4207b8 (
[ 4173.554894]  blake2b_generic
[ 4173.557288] &eb->lock){++++}-{2:2}
[ 4173.559162]  libcrc32c
[ 4173.559833] , at: btrfs_tree_read_lock_atomic+0x34/0x150 [btrfs]
[ 4173.559835] 
[ 4173.559835] other info that might help us debug this:
[ 4173.560803]  crc32c_intel
[ 4173.561735]  Possible unsafe locking scenario:
[ 4173.561735] 
[ 4173.561737]        CPU0
[ 4173.562815]  xor
[ 4173.563612]        ----
[ 4173.563615]   lock(
[ 4173.565378]  zstd_decompress
[ 4173.567138] &eb->lock);
[ 4173.567139]   lock(&eb->lock);
[ 4173.567140] 
[ 4173.567140]  *** DEADLOCK ***
[ 4173.567140] 
[ 4173.567141]  May be due to missing lock nesting notation
[ 4173.567141] 
[ 4173.567142] 4 locks held by btrfs/19276:
[ 4173.567142]  #0: ffffa19a704d4478 (sb_writers#10){.+.+}-{0:0}, at: mnt_want_write_file+0x22/0x70
[ 4173.567149]  #1: ffffa19a5901c570 (
[ 4173.567953]  zstd_compress
[ 4173.569465] &type->i_mutex_dir_key#7
[ 4173.570248]  xxhash
[ 4173.570784] /1){+.+.}-{3:3}, at: btrfs_mksubvol+0x56/0x1b0 [btrfs]
[ 4173.570810]  #2: 
[ 4173.571609]  lzo_compress
[ 4173.572203] ffffa19a62b0ccc0 (
[ 4173.573023]  lzo_decompress raid6_pq
[ 4173.573859] &fs_info->subvol_sem
[ 4173.574759]  loop
[ 4173.576320] ){++++}-{3:3}, at: btrfs_mksubvol+0xdd/0x1b0 [btrfs]
[ 4173.578167] 
[ 4173.579263]  #3: ffffa19a7e4207b8 (&eb->lock){++++}-{2:2}, at: btrfs_tree_read_lock_atomic+0x34/0x150 [btrfs]
[ 4173.579289] 
[ 4173.579289] stack backtrace:
[ 4173.581636] CPU: 2 PID: 18647 Comm: fsstress Not tainted 5.10.0-rc3-default+ #1353
[ 4173.582677] CPU: 1 PID: 19276 Comm: btrfs Not tainted 5.10.0-rc3-default+ #1353
[ 4173.582678] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.12.0-59-gc9ba527-rebuilt.opensuse.org 04/01/2014
[ 4173.582685] Call Trace:
[ 4173.582692]  dump_stack+0x77/0x97
[ 4173.583498] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.12.0-59-gc9ba527-rebuilt.opensuse.org 04/01/2014
[ 4173.584559]  validate_chain+0x367/0x780
[ 4173.585276] RIP: 0010:__sb_start_write+0x113/0x2a0
[ 4173.586929]  __lock_acquire+0x3fb/0x730
[ 4173.586931]  lock_acquire.part.0+0xac/0x1a0
[ 4173.586953]  ? btrfs_tree_read_lock_atomic+0x34/0x150 [btrfs]
[ 4173.586957]  ? rcu_read_lock_sched_held+0x3f/0x70
[ 4173.587610] Code: f3 f8 da 77 85 c0 0f 84 95 01 00 00 40 84 ed 0f 85 4c 01 00 00 45 84 e4 0f 85 75 01 00 00 5b 44 89 e8 5d 41 5c 41 5d 41 5e c3 <0f> 0b 48 89 e8 31 d2 be 31 00 00 00 48 c7 c7 7a 99 e4 88 48 c1 e0
[ 4173.588386]  ? lock_acquire+0xc4/0x150
[ 4173.589241] RSP: 0018:ffffb35a06cc7c10 EFLAGS: 00010246
[ 4173.590123]  ? btrfs_tree_read_lock_atomic+0x34/0x150 [btrfs]
[ 4173.590938] 
[ 4173.591473]  _raw_read_lock+0x40/0xa0
[ 4173.592825] RAX: 0000000000000001 RBX: ffffa19a704d4478 RCX: 0000000000000000
[ 4173.593343]  ? btrfs_tree_read_lock_atomic+0x34/0x150 [btrfs]
[ 4173.595900] RDX: 0000000000000001 RSI: 0000000000000000 RDI: ffffa19a704d4478
[ 4173.597072]  btrfs_tree_read_lock_atomic+0x34/0x150 [btrfs]
[ 4173.599104] RBP: 0000000000000003 R08: 00000000000001b8 R09: ffffa19a5c24f138
[ 4173.601184]  btrfs_search_slot+0x546/0x9f0 [btrfs]
[ 4173.603798] R10: 0000000000000001 R11: 0000000000000001 R12: 0000000000000001
[ 4173.604569]  btrfs_lookup_inode+0x3a/0xc0 [btrfs]
[ 4173.605462] R13: ffffa19a704d4398 R14: ffffa19a704d4698 R15: ffffa19a62b0c000
[ 4173.608583]  btrfs_read_locked_inode+0x519/0x640 [btrfs]
[ 4173.608599]  btrfs_iget_path+0x8d/0xd0 [btrfs]
[ 4173.609634] FS:  00007fd2627f4b80(0000) GS:ffffa19abda00000(0000) knlGS:0000000000000000
[ 4173.611006]  btrfs_lookup_dentry+0x13c/0x1f0 [btrfs]
[ 4173.611026]  create_snapshot+0x27e/0x2e0 [btrfs]
[ 4173.611925] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 4173.613129]  btrfs_mksubvol+0x111/0x1b0 [btrfs]
[ 4173.614480] CR2: 0000000000729e88 CR3: 0000000022ed5001 CR4: 0000000000170ea0
[ 4173.615823]  btrfs_mksnapshot+0x7b/0xb0 [btrfs]
[ 4173.615843]  __btrfs_ioctl_snap_create+0x16f/0x1a0 [btrfs]
[ 4173.620679] Call Trace:
[ 4173.621833]  btrfs_ioctl_snap_create_v2+0xb0/0xf0 [btrfs]
[ 4173.623251]  start_transaction+0x406/0x510 [btrfs]
[ 4173.624425]  btrfs_ioctl+0x6bd/0xb50 [btrfs]
[ 4173.624929]  btrfs_dirty_inode+0x44/0xd0 [btrfs]
[ 4173.625878]  __x64_sys_ioctl+0x83/0xa0
[ 4173.627746]  touch_atime+0xb2/0x100
[ 4173.629063]  do_syscall_64+0x2d/0x70
[ 4173.630537]  generic_file_buffered_read+0x778/0x8f0
[ 4173.631650]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 4173.631652] RIP: 0033:0x7f3e367da8a7
[ 4173.631654] Code: 3c 1c 48 f7 d8 49 39 c4 72 b9 e8 24 ff ff ff 85 c0 78 be 4c 89 e0 5b 5d 41 5c c3 0f 1f 84 00 00 00 00 00 b8 10 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d 99 b5 0c 00 f7 d8 64 89 01 48
[ 4173.631656] RSP: 002b:00007ffeeb887c58 EFLAGS: 00000202
[ 4173.633130]  generic_file_splice_read+0xf9/0x1b0
[ 4173.634113]  ORIG_RAX: 0000000000000010
[ 4173.635515]  do_splice+0x370/0x3c0
[ 4173.636517] RAX: ffffffffffffffda RBX: 0000000000000001 RCX: 00007f3e367da8a7
[ 4173.636519] RDX: 00007ffeeb887d30 RSI: 0000000050009417 RDI: 0000000000000003
[ 4173.637945]  __do_splice+0xde/0x160
[ 4173.639080] RBP: 00007f3e366e16a8 R08: 0000000000000010 R09: 0000000000000004
[ 4173.639081] R10: 000055969c45021c R11: 0000000000000202 R12: 00007ffeeb887d30
[ 4173.639081] R13: 000055969c5402a0 R14: 000055969c5402d0 R15: 0000000000000000
[ 4173.685866]  __x64_sys_splice+0x92/0x110
[ 4173.687427]  do_syscall_64+0x2d/0x70
[ 4173.688427]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 4173.690089] RIP: 0033:0x7fd2628f61c6
[ 4173.691699] Code: 48 c7 c0 ff ff ff ff eb b9 66 2e 0f 1f 84 00 00 00 00 00 90 49 89 ca 64 8b 04 25 18 00 00 00 85 c0 75 11 b8 13 01 00 00 0f 05 <48> 3d 00 f0 ff ff 77 72 c3 90 55 48 83 ec 30 44 89 4c 24 2c 4c 89
[ 4173.696840] RSP: 002b:00007ffe4fdf3748 EFLAGS: 00000246 ORIG_RAX: 0000000000000113
[ 4173.698781] RAX: ffffffffffffffda RBX: 0000000000473421 RCX: 00007fd2628f61c6
[ 4173.700341] RDX: 0000000000000006 RSI: 00007ffe4fdf3778 RDI: 0000000000000003
[ 4173.702153] RBP: 0000000000000004 R08: 000000000001b0fa R09: 0000000000000000
[ 4173.703879] R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000001779
[ 4173.705630] R13: 0000000000000003 R14: 000000000001b0fa R15: 0000000000000000
[ 4173.707398] CPU: 2 PID: 18647 Comm: fsstress Not tainted 5.10.0-rc3-default+ #1353
[ 4173.709347] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.12.0-59-gc9ba527-rebuilt.opensuse.org 04/01/2014
[ 4173.724526] Call Trace:
[ 4173.725284]  dump_stack+0x77/0x97
[ 4173.726189]  ? __sb_start_write+0x113/0x2a0
[ 4173.727327]  __warn.cold+0x24/0x83
[ 4173.728230]  ? __sb_start_write+0x113/0x2a0
[ 4173.729337]  report_bug+0x9a/0xc0
[ 4173.730255]  handle_bug+0x3c/0x60
[ 4173.731132]  exc_invalid_op+0x14/0x70
[ 4173.732057]  asm_exc_invalid_op+0x12/0x20
[ 4173.733107] RIP: 0010:__sb_start_write+0x113/0x2a0
[ 4173.734324] Code: f3 f8 da 77 85 c0 0f 84 95 01 00 00 40 84 ed 0f 85 4c 01 00 00 45 84 e4 0f 85 75 01 00 00 5b 44 89 e8 5d 41 5c 41 5d 41 5e c3 <0f> 0b 48 89 e8 31 d2 be 31 00 00 00 48 c7 c7 7a 99 e4 88 48 c1 e0
[ 4173.738687] RSP: 0018:ffffb35a06cc7c10 EFLAGS: 00010246
[ 4173.740042] RAX: 0000000000000001 RBX: ffffa19a704d4478 RCX: 0000000000000000
[ 4173.741919] RDX: 0000000000000001 RSI: 0000000000000000 RDI: ffffa19a704d4478
[ 4173.744107] RBP: 0000000000000003 R08: 00000000000001b8 R09: ffffa19a5c24f138
[ 4173.746113] R10: 0000000000000001 R11: 0000000000000001 R12: 0000000000000001
[ 4173.748296] R13: ffffa19a704d4398 R14: ffffa19a704d4698 R15: ffffa19a62b0c000
[ 4173.750518]  start_transaction+0x406/0x510 [btrfs]
[ 4173.751759]  btrfs_dirty_inode+0x44/0xd0 [btrfs]
[ 4173.752738]  touch_atime+0xb2/0x100
[ 4173.753752]  generic_file_buffered_read+0x778/0x8f0
[ 4173.754955]  generic_file_splice_read+0xf9/0x1b0
[ 4173.756098]  do_splice+0x370/0x3c0
[ 4173.757046]  __do_splice+0xde/0x160
[ 4173.757882]  __x64_sys_splice+0x92/0x110
[ 4173.758960]  do_syscall_64+0x2d/0x70
[ 4173.759885]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 4173.761016] RIP: 0033:0x7fd2628f61c6
[ 4173.761834] Code: 48 c7 c0 ff ff ff ff eb b9 66 2e 0f 1f 84 00 00 00 00 00 90 49 89 ca 64 8b 04 25 18 00 00 00 85 c0 75 11 b8 13 01 00 00 0f 05 <48> 3d 00 f0 ff ff 77 72 c3 90 55 48 83 ec 30 44 89 4c 24 2c 4c 89
[ 4173.766023] RSP: 002b:00007ffe4fdf3748 EFLAGS: 00000246 ORIG_RAX: 0000000000000113
[ 4173.767748] RAX: ffffffffffffffda RBX: 0000000000473421 RCX: 00007fd2628f61c6
[ 4173.769331] RDX: 0000000000000006 RSI: 00007ffe4fdf3778 RDI: 0000000000000003
[ 4173.770809] RBP: 0000000000000004 R08: 000000000001b0fa R09: 0000000000000000
[ 4173.772335] R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000001779
[ 4173.774046] R13: 0000000000000003 R14: 000000000001b0fa R15: 0000000000000000
[ 4173.775983] irq event stamp: 15494042
[ 4173.777099] hardirqs last  enabled at (15494041): [<ffffffff882498e2>] __slab_free+0x322/0x3e0
[ 4173.779317] hardirqs last disabled at (15494042): [<ffffffff8824b644>] __slab_alloc.constprop.0+0x94/0x170
[ 4173.781575] softirqs last  enabled at (15487856): [<ffffffff88a00333>] __do_softirq+0x333/0x5c2
[ 4173.783487] softirqs last disabled at (15487851): [<ffffffff88800dbf>] asm_call_irq_on_stack+0xf/0x20
[ 4173.785680] ---[ end trace 04c54d8226296c31 ]---
[ 4277.745950] BTRFS info (device vdb): turning on sync discard
[ 4277.749265] BTRFS info (device vdb): disk space caching is enabled
[ 4277.752718] BTRFS info (device vdb): has skinny extents
_check_dmesg: something found in dmesg (see /tmp/fstests/results//btrfs/078.dmesg)
 [15:20:59]
btrfs/079		[15:20:59][ 4278.696345] run fstests btrfs/079 at 2020-11-10 15:20:59
[ 4279.167520] BTRFS info (device vda): disk space caching is enabled
[ 4279.169666] BTRFS info (device vda): has skinny extents
[ 4279.347248] ------------[ cut here ]------------
[ 4279.349775] WARNING: CPU: 1 PID: 19750 at fs/super.c:1676 __sb_start_write+0x113/0x2a0
[ 4279.353817] Modules linked in: dm_flakey dm_mod xxhash_generic btrfs blake2b_generic libcrc32c crc32c_intel xor zstd_decompress zstd_compress xxhash lzo_compress lzo_decompress raid6_pq loop
[ 4279.357043] CPU: 1 PID: 19750 Comm: xfs_io Tainted: G        W         5.10.0-rc3-default+ #1353
[ 4279.359696] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.12.0-59-gc9ba527-rebuilt.opensuse.org 04/01/2014
[ 4279.363070] RIP: 0010:__sb_start_write+0x113/0x2a0
[ 4279.364568] Code: f3 f8 da 77 85 c0 0f 84 95 01 00 00 40 84 ed 0f 85 4c 01 00 00 45 84 e4 0f 85 75 01 00 00 5b 44 89 e8 5d 41 5c 41 5d 41 5e c3 <0f> 0b 48 89 e8 31 d2 be 31 00 00 00 48 c7 c7 7a 99 e4 88 48 c1 e0
[ 4279.370167] RSP: 0018:ffffb35a078c7b40 EFLAGS: 00010246
[ 4279.371710] RAX: 0000000000000001 RBX: ffffa19a4c764478 RCX: 0000000000000000
[ 4279.373768] RDX: 0000000000000001 RSI: 0000000000000000 RDI: ffffa19a4c764478
[ 4279.375769] RBP: 0000000000000003 R08: 00000000000001b8 R09: ffffa19a5c1a34a8
[ 4279.377871] R10: 0000000000000001 R11: 9494acff9096a08c R12: 0000000000000001
[ 4279.379960] R13: ffffa19a4c764398 R14: ffffa19a4c764698 R15: ffffa19a598e0000
[ 4279.382060] FS:  00007f5cdce3fe80(0000) GS:ffffa19abd800000(0000) knlGS:0000000000000000
[ 4279.384159] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 4279.385555] CR2: 00007f5cdcf57520 CR3: 0000000065e8f005 CR4: 0000000000170ea0
[ 4279.387201] Call Trace:
[ 4279.387867]  start_transaction+0x406/0x510 [btrfs]
[ 4279.389165]  btrfs_create+0x55/0x210 [btrfs]
[ 4279.390255]  lookup_open+0x24e/0x3f0
[ 4279.391151]  open_last_lookups+0xa5/0x360
[ 4279.392108]  path_openat+0x9c/0x1b0
[ 4279.392934]  ? getname_flags+0x29/0x180
[ 4279.393852]  do_filp_open+0x88/0x130
[ 4279.394706]  ? lock_release+0xb0/0x160
[ 4279.395553]  ? do_raw_spin_unlock+0x4b/0xa0
[ 4279.396515]  ? _raw_spin_unlock+0x29/0x40
[ 4279.397480]  ? __alloc_fd+0xfc/0x1e0
[ 4279.398309]  do_sys_openat2+0x97/0x150
[ 4279.399184]  __x64_sys_openat+0x54/0x90
[ 4279.400093]  do_syscall_64+0x2d/0x70
[ 4279.400953]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 4279.402062] RIP: 0033:0x7f5cdd08a047
[ 4279.402913] Code: 25 00 00 41 00 3d 00 00 41 00 74 47 64 8b 04 25 18 00 00 00 85 c0 75 6b 44 89 e2 48 89 ee bf 9c ff ff ff b8 01 01 00 00 0f 05 <48> 3d 00 f0 ff ff 0f 87 95 00 00 00 48 8b 4c 24 28 64 48 2b 0c 25
[ 4279.407507] RSP: 002b:00007ffc1c0e7650 EFLAGS: 00000246 ORIG_RAX: 0000000000000101
[ 4279.409434] RAX: ffffffffffffffda RBX: 0000000000000042 RCX: 00007f5cdd08a047
[ 4279.411235] RDX: 0000000000000042 RSI: 00007ffc1c0ea12b RDI: 00000000ffffff9c
[ 4279.413054] RBP: 00007ffc1c0ea12b R08: 0000000000000001 R09: 0000000000000000
[ 4279.414800] R10: 0000000000000180 R11: 0000000000000246 R12: 0000000000000042
[ 4279.416190] R13: 00007ffc1c0e7a40 R14: 0000000000000180 R15: 0000000000000020
[ 4279.417752] CPU: 1 PID: 19750 Comm: xfs_io Tainted: G        W         5.10.0-rc3-default+ #1353
[ 4279.419690] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.12.0-59-gc9ba527-rebuilt.opensuse.org 04/01/2014
[ 4279.422386] Call Trace:
[ 4279.423023]  dump_stack+0x77/0x97
[ 4279.423788]  ? __sb_start_write+0x113/0x2a0
[ 4279.424716]  __warn.cold+0x24/0x83
[ 4279.425666]  ? __sb_start_write+0x113/0x2a0
[ 4279.426882]  report_bug+0x9a/0xc0
[ 4279.427895]  handle_bug+0x3c/0x60
[ 4279.428914]  exc_invalid_op+0x14/0x70
[ 4279.430005]  asm_exc_invalid_op+0x12/0x20
[ 4279.431114] RIP: 0010:__sb_start_write+0x113/0x2a0
[ 4279.432210] Code: f3 f8 da 77 85 c0 0f 84 95 01 00 00 40 84 ed 0f 85 4c 01 00 00 45 84 e4 0f 85 75 01 00 00 5b 44 89 e8 5d 41 5c 41 5d 41 5e c3 <0f> 0b 48 89 e8 31 d2 be 31 00 00 00 48 c7 c7 7a 99 e4 88 48 c1 e0
[ 4279.436059] RSP: 0018:ffffb35a078c7b40 EFLAGS: 00010246
[ 4279.437512] RAX: 0000000000000001 RBX: ffffa19a4c764478 RCX: 0000000000000000
[ 4279.439467] RDX: 0000000000000001 RSI: 0000000000000000 RDI: ffffa19a4c764478
[ 4279.441477] RBP: 0000000000000003 R08: 00000000000001b8 R09: ffffa19a5c1a34a8
[ 4279.443437] R10: 0000000000000001 R11: 9494acff9096a08c R12: 0000000000000001
[ 4279.445451] R13: ffffa19a4c764398 R14: ffffa19a4c764698 R15: ffffa19a598e0000
[ 4279.447418]  start_transaction+0x406/0x510 [btrfs]
[ 4279.448808]  btrfs_create+0x55/0x210 [btrfs]
[ 4279.450031]  lookup_open+0x24e/0x3f0
[ 4279.450937]  open_last_lookups+0xa5/0x360
[ 4279.452060]  path_openat+0x9c/0x1b0
[ 4279.453066]  ? getname_flags+0x29/0x180
[ 4279.454158]  do_filp_open+0x88/0x130
[ 4279.455176]  ? lock_release+0xb0/0x160
[ 4279.456241]  ? do_raw_spin_unlock+0x4b/0xa0
[ 4279.457372]  ? _raw_spin_unlock+0x29/0x40
[ 4279.458255]  ? __alloc_fd+0xfc/0x1e0
[ 4279.459094]  do_sys_openat2+0x97/0x150
[ 4279.459990]  __x64_sys_openat+0x54/0x90
[ 4279.460866]  do_syscall_64+0x2d/0x70
[ 4279.461678]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 4279.462792] RIP: 0033:0x7f5cdd08a047
[ 4279.463576] Code: 25 00 00 41 00 3d 00 00 41 00 74 47 64 8b 04 25 18 00 00 00 85 c0 75 6b 44 89 e2 48 89 ee bf 9c ff ff ff b8 01 01 00 00 0f 05 <48> 3d 00 f0 ff ff 0f 87 95 00 00 00 48 8b 4c 24 28 64 48 2b 0c 25
[ 4279.468060] RSP: 002b:00007ffc1c0e7650 EFLAGS: 00000246 ORIG_RAX: 0000000000000101
[ 4279.470116] RAX: ffffffffffffffda RBX: 0000000000000042 RCX: 00007f5cdd08a047
[ 4279.471992] RDX: 0000000000000042 RSI: 00007ffc1c0ea12b RDI: 00000000ffffff9c
[ 4279.473856] RBP: 00007ffc1c0ea12b R08: 0000000000000001 R09: 0000000000000000
[ 4279.475705] R10: 0000000000000180 R11: 0000000000000246 R12: 0000000000000042
[ 4279.477572] R13: 00007ffc1c0e7a40 R14: 0000000000000180 R15: 0000000000000020
[ 4279.479449] irq event stamp: 0
[ 4279.480273] hardirqs last  enabled at (0): [<0000000000000000>] 0x0
[ 4279.481987] hardirqs last disabled at (0): [<ffffffff8807134b>] copy_process+0x3db/0x1440
[ 4279.484109] softirqs last  enabled at (0): [<ffffffff8807134b>] copy_process+0x3db/0x1440
[ 4279.485936] softirqs last disabled at (0): [<0000000000000000>] 0x0
[ 4279.487320] ---[ end trace 04c54d8226296c32 ]---
[ 4279.612947] BTRFS: device fsid a0190661-0fb3-4ea9-a258-3564f7237753 devid 1 transid 5 /dev/vdb scanned by mkfs.btrfs (19767)
[ 4279.643470] BTRFS info (device vdb): turning on sync discard
[ 4279.645293] BTRFS info (device vdb): disk space caching is enabled
[ 4279.647937] BTRFS info (device vdb): has skinny extents
[ 4279.650181] BTRFS info (device vdb): flagging fs with big metadata feature
[ 4279.657915] BTRFS info (device vdb): checking UUID tree
[ 4425.026967] BTRFS info (device vdb): turning on sync discard
[ 4425.028653] BTRFS info (device vdb): disk space caching is enabled
[ 4425.030472] BTRFS info (device vdb): has skinny extents
_check_dmesg: something found in dmesg (see /tmp/fstests/results//btrfs/079.dmesg)
 [15:23:26]
btrfs/080		[15:23:26][ 4426.585916] run fstests btrfs/080 at 2020-11-10 15:23:27
[ 4427.202665] BTRFS info (device vda): disk space caching is enabled
[ 4427.205475] BTRFS info (device vda): has skinny extents
[ 4427.538925] BTRFS: device fsid d4405e20-e03d-4d0a-a204-6b0ca9b3d543 devid 1 transid 5 /dev/vdb scanned by mkfs.btrfs (6752)
[ 4427.564820] BTRFS info (device vdb): turning on sync discard
[ 4427.577312] BTRFS info (device vdb): disk space caching is enabled
[ 4427.579100] BTRFS info (device vdb): has skinny extents
[ 4427.580478] BTRFS info (device vdb): flagging fs with big metadata feature
[ 4427.586893] BTRFS info (device vdb): checking UUID tree
[ 4427.588466] ------------[ cut here ]------------
[ 4427.589606] WARNING: CPU: 2 PID: 6782 at fs/super.c:1676 __sb_start_write+0x113/0x2a0
[ 4427.591647] Modules linked in: dm_flakey dm_mod xxhash_generic btrfs blake2b_generic libcrc32c crc32c_intel xor zstd_decompress zstd_compress xxhash lzo_compress lzo_decompress raid6_pq loop
[ 4427.595085] CPU: 2 PID: 6782 Comm: btrfs-uuid Tainted: G        W         5.10.0-rc3-default+ #1353
[ 4427.597077] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.12.0-59-gc9ba527-rebuilt.opensuse.org 04/01/2014
[ 4427.599547] RIP: 0010:__sb_start_write+0x113/0x2a0
[ 4427.600594] Code: f3 f8 da 77 85 c0 0f 84 95 01 00 00 40 84 ed 0f 85 4c 01 00 00 45 84 e4 0f 85 75 01 00 00 5b 44 89 e8 5d 41 5c 41 5d 41 5e c3 <0f> 0b 48 89 e8 31 d2 be 31 00 00 00 48 c7 c7 7a 99 e4 88 48 c1 e0
[ 4427.606614] RSP: 0018:ffffb35a0137fc80 EFLAGS: 00010246
[ 4427.608115] RAX: 0000000000000001 RBX: ffffa19a4c9ec478 RCX: 0000000000000000
[ 4427.610056] RDX: 0000000000000001 RSI: 0000000000000000 RDI: ffffa19a4c9ec478
[ 4427.611937] RBP: 0000000000000003 R08: 00000000000001b8 R09: ffffa19a5c1a3b88
[ 4427.613823] R10: 0000000000000001 R11: 0000000000000000 R12: 0000000000000001
[ 4427.626591] R13: ffffa19a4c9ec398 R14: ffffa19a4c9ec698 R15: ffffa19a4191c000
[ 4427.628387] FS:  0000000000000000(0000) GS:ffffa19abda00000(0000) knlGS:0000000000000000
[ 4427.630470] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 4427.631695] CR2: 000055d3f2f9108c CR3: 0000000002ffe003 CR4: 0000000000170ea0
[ 4427.633147] Call Trace:
[ 4427.633952]  start_transaction+0x406/0x510 [btrfs]
[ 4427.635308]  btrfs_uuid_scan_kthread+0x2d0/0x360 [btrfs]
[ 4427.636740]  ? btree_writepages+0x60/0x60 [btrfs]
[ 4427.638037]  kthread+0x151/0x170
[ 4427.650592]  ? __kthread_bind_mask+0x60/0x60
[ 4427.651775]  ret_from_fork+0x1f/0x30
[ 4427.652772] CPU: 2 PID: 6782 Comm: btrfs-uuid Tainted: G        W         5.10.0-rc3-default+ #1353
[ 4427.655090] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.12.0-59-gc9ba527-rebuilt.opensuse.org 04/01/2014
[ 4427.657860] Call Trace:
[ 4427.658485]  dump_stack+0x77/0x97
[ 4427.659266]  ? __sb_start_write+0x113/0x2a0
[ 4427.660188]  __warn.cold+0x24/0x83
[ 4427.661069]  ? __sb_start_write+0x113/0x2a0
[ 4427.662514]  report_bug+0x9a/0xc0
[ 4427.663574]  handle_bug+0x3c/0x60
[ 4427.664519]  exc_invalid_op+0x14/0x70
[ 4427.665547]  asm_exc_invalid_op+0x12/0x20
[ 4427.666632] RIP: 0010:__sb_start_write+0x113/0x2a0
[ 4427.667891] Code: f3 f8 da 77 85 c0 0f 84 95 01 00 00 40 84 ed 0f 85 4c 01 00 00 45 84 e4 0f 85 75 01 00 00 5b 44 89 e8 5d 41 5c 41 5d 41 5e c3 <0f> 0b 48 89 e8 31 d2 be 31 00 00 00 48 c7 c7 7a 99 e4 88 48 c1 e0
[ 4427.672250] RSP: 0018:ffffb35a0137fc80 EFLAGS: 00010246
[ 4427.673395] RAX: 0000000000000001 RBX: ffffa19a4c9ec478 RCX: 0000000000000000
[ 4427.675228] RDX: 0000000000000001 RSI: 0000000000000000 RDI: ffffa19a4c9ec478
[ 4427.677054] RBP: 0000000000000003 R08: 00000000000001b8 R09: ffffa19a5c1a3b88
[ 4427.678861] R10: 0000000000000001 R11: 0000000000000000 R12: 0000000000000001
[ 4427.680684] R13: ffffa19a4c9ec398 R14: ffffa19a4c9ec698 R15: ffffa19a4191c000
[ 4427.682565]  start_transaction+0x406/0x510 [btrfs]
[ 4427.683887]  btrfs_uuid_scan_kthread+0x2d0/0x360 [btrfs]
[ 4427.685357]  ? btree_writepages+0x60/0x60 [btrfs]
[ 4427.686643]  kthread+0x151/0x170
[ 4427.687595]  ? __kthread_bind_mask+0x60/0x60
[ 4427.688773]  ret_from_fork+0x1f/0x30
[ 4428.038587] irq event stamp: 0
[ 4428.039456] hardirqs last  enabled at (0): [<0000000000000000>] 0x0
[ 4428.040794] hardirqs last disabled at (0): [<ffffffff8807134b>] copy_process+0x3db/0x1440
[ 4428.042433] softirqs last  enabled at (0): [<ffffffff8807134b>] copy_process+0x3db/0x1440
[ 4428.150587] softirqs last disabled at (0): [<0000000000000000>] 0x0
[ 4428.152131] ---[ end trace 04c54d8226296c33 ]---
[ 4497.955015] BTRFS info (device vdb): turning on sync discard
[ 4497.957713] BTRFS info (device vdb): disk space caching is enabled
[ 4497.960776] BTRFS info (device vdb): has skinny extents
_check_dmesg: something found in dmesg (see /tmp/fstests/results//btrfs/080.dmesg)
 [15:24:41]

Re: [RFC] fs: Avoid to use lockdep information if it's turned off

[David Sterba]

On Tue, Nov 10, 2020 at 04:33:27PM +0100, David Sterba wrote:
> On Tue, Nov 10, 2020 at 09:37:37AM +0800, Boqun Feng wrote:
> 
> I'll run another test on top of the development branch in case there are
> unrelated lockdep warning bugs that have been fixed meanwhile.

Similar reports but earlier test and probably completely valid due to
"BUG: MAX_LOCKDEP_CHAIN_HLOCKS too low!"

btrfs/057		[16:01:29][ 1580.146087] run fstests btrfs/057 at 2020-11-10 16:01:29
[ 1580.787867] BTRFS info (device vda): disk space caching is enabled
[ 1580.789366] BTRFS info (device vda): has skinny extents
[ 1581.052542] BTRFS: device fsid 84018822-2e45-4341-80be-da6d2b4e033a devid 1 transid 5 /dev/vdb scanned by mkfs.btrfs (18739)
[ 1581.105177] BTRFS info (device vdb): turning on sync discard
[ 1581.106834] BTRFS info (device vdb): disk space caching is enabled
[ 1581.108423] BTRFS info (device vdb): has skinny extents
[ 1581.109799] BTRFS info (device vdb): flagging fs with big metadata feature
[ 1581.120343] BTRFS info (device vdb): checking UUID tree
[ 1586.942699] BUG: MAX_LOCKDEP_CHAIN_HLOCKS too low!
[ 1586.945725] turning off the locking correctness validator.
[ 1586.948823] Please attach the output of /proc/lock_stat to the bug report
[ 1586.952153] CPU: 0 PID: 18771 Comm: fsstress Not tainted 5.10.0-rc3-default+ #1355
[ 1586.954919] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.12.0-59-gc9ba527-rebuilt.opensuse.org 04/01/2014
[ 1586.958630] Call Trace:
[ 1586.959214]  dump_stack+0x77/0x97
[ 1586.960030]  add_chain_cache.cold+0x29/0x30
[ 1586.961028]  validate_chain+0x278/0x780
[ 1586.961979]  __lock_acquire+0x3fb/0x730
[ 1586.962880]  lock_acquire.part.0+0xac/0x1a0
[ 1586.963895]  ? try_to_wake_up+0x59/0x450
[ 1586.965153]  ? rcu_read_lock_sched_held+0x3f/0x70
[ 1586.966569]  ? lock_acquire+0xc4/0x150
[ 1586.967699]  ? try_to_wake_up+0x59/0x450
[ 1586.968882]  _raw_spin_lock_irqsave+0x43/0x90
[ 1586.970207]  ? try_to_wake_up+0x59/0x450
[ 1586.971404]  try_to_wake_up+0x59/0x450
[ 1586.973149]  wake_up_q+0x60/0xb0
[ 1586.974620]  __up_write+0x117/0x1d0
[ 1586.975080] ------------[ cut here ]------------
[ 1586.976039]  btrfs_release_path+0xc8/0x180 [btrfs]
[ 1586.977718] WARNING: CPU: 2 PID: 18772 at fs/super.c:1676 __sb_start_write+0x113/0x2a0
[ 1586.979478]  __btrfs_update_delayed_inode+0x1c1/0x2c0 [btrfs]
[ 1586.979506]  btrfs_commit_inode_delayed_inode+0x115/0x120 [btrfs]
[ 1586.982484] Modules linked in:
[ 1586.984080]  btrfs_evict_inode+0x1e2/0x370 [btrfs]
[ 1586.985557]  dm_flakey
[ 1586.986419]  ? evict+0xc3/0x220
[ 1586.986421]  evict+0xd5/0x220
[ 1586.986423]  vfs_rmdir.part.0+0x10c/0x180
[ 1586.986426]  do_rmdir+0x14b/0x1b0
[ 1586.987504]  dm_mod
[ 1586.988244]  do_syscall_64+0x2d/0x70
[ 1586.988947]  xxhash_generic btrfs
[ 1586.989779]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 1586.990906]  blake2b_generic
[ 1586.991808] RIP: 0033:0x7f0ad919b5d7
[ 1586.992451]  libcrc32c
[ 1586.993427] Code: 73 01 c3 48 8b 0d 99 f8 0c 00 f7 d8 64 89 01 48 83 c8 ff c3 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 b8 54 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d 69 f8 0c 00 f7 d8 64 89 01 48
[ 1586.994380]  crc32c_intel
[ 1586.995546] RSP: 002b:00007ffc152bf368 EFLAGS: 00000202 ORIG_RAX: 0000000000000054
[ 1586.996034]  xor
[ 1586.996613] RAX: ffffffffffffffda RBX: 00000000000001f4 RCX: 00007f0ad919b5d7
[ 1586.996615] RDX: 0000000000316264 RSI: 0000000000000000 RDI: 000000000045eff0
[ 1586.997033]  zstd_decompress
[ 1587.001060] RBP: 00007ffc152bf4b0 R08: 000000000045eff0 R09: 00007ffc152bf4a4
[ 1587.001061] R10: 00000000000000b1 R11: 0000000000000202 R12: 000000000000030e
[ 1587.001062] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000
[ 1587.013639]  zstd_compress xxhash lzo_compress lzo_decompress raid6_pq loop
[ 1587.015763] CPU: 2 PID: 18772 Comm: fsstress Not tainted 5.10.0-rc3-default+ #1355
[ 1587.017719] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.12.0-59-gc9ba527-rebuilt.opensuse.org 04/01/2014
[ 1587.020878] RIP: 0010:__sb_start_write+0x113/0x2a0
[ 1587.022233] Code: f3 f8 da 58 85 c0 0f 84 95 01 00 00 40 84 ed 0f 85 4c 01 00 00 45 84 e4 0f 85 75 01 00 00 5b 44 89 e8 5d 41 5c 41 5d 41 5e c3 <0f> 0b 48 89 e8 31 d2 be 31 00 00 00 48 c7 c7 ca 98 e4 a7 48 c1 e0
[ 1587.027309] RSP: 0018:ffffafbac3c2fdd0 EFLAGS: 00010246
[ 1587.028998] RAX: 0000000000000001 RBX: ffffa320cc6b4478 RCX: 0000000000000000
[ 1587.031038] RDX: 0000000000000001 RSI: 0000000000000000 RDI: ffffa320cc6b4478
[ 1587.032905] RBP: 0000000000000003 R08: 00000000000001b8 R09: ffffa320dbfa9b88
[ 1587.035782] R10: 0000000000000001 R11: ffffffffff9bcd99 R12: 0000000000000001
[ 1587.037974] R13: ffffa320cc6b4398 R14: ffffa320cc6b4698 R15: ffffa320e06f4000
[ 1587.040473] FS:  00007f0ad90a7b80(0000) GS:ffffa3213da00000(0000) knlGS:0000000000000000
[ 1587.043694] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 1587.045577] CR2: 00000000007b5ce8 CR3: 0000000004be6006 CR4: 0000000000170ea0
[ 1587.047744] Call Trace:
[ 1587.048689]  start_transaction+0x406/0x510 [btrfs]
[ 1587.050009]  btrfs_unlink+0x31/0xf0 [btrfs]
[ 1587.051313]  vfs_unlink+0xee/0x1d0
[ 1587.052435]  do_unlinkat+0x1a1/0x2e0
[ 1587.053676]  do_syscall_64+0x2d/0x70
[ 1587.054883]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 1587.056428] RIP: 0033:0x7f0ad919b577
[ 1587.057583] Code: f0 ff ff 73 01 c3 48 8b 0d f6 f8 0c 00 f7 d8 64 89 01 48 83 c8 ff c3 66 2e 0f 1f 84 00 00 00 00 00 66 90 b8 57 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d c9 f8 0c 00 f7 d8 64 89 01 48
[ 1587.061252] RSP: 002b:00007ffc152bf358 EFLAGS: 00000206 ORIG_RAX: 0000000000000057
[ 1587.063942] RAX: ffffffffffffffda RBX: 00000000000001f4 RCX: 00007f0ad919b577
[ 1587.065661] RDX: 0000000000643266 RSI: 0000000000000000 RDI: 0000000000418070
[ 1587.067478] RBP: 00007ffc152bf4b0 R08: 0000000000418070 R09: 00007ffc152bf49c
[ 1587.069024] R10: 000000000000002d R11: 0000000000000206 R12: 000000000000033e
[ 1587.071631] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000
[ 1587.074260] CPU: 2 PID: 18772 Comm: fsstress Not tainted 5.10.0-rc3-default+ #1355
[ 1587.076198] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.12.0-59-gc9ba527-rebuilt.opensuse.org 04/01/2014
[ 1587.078659] Call Trace:
[ 1587.079296]  dump_stack+0x77/0x97
[ 1587.080076]  ? __sb_start_write+0x113/0x2a0
[ 1587.081008]  __warn.cold+0x24/0x83
[ 1587.082506]  ? __sb_start_write+0x113/0x2a0
[ 1587.084716]  report_bug+0x9a/0xc0
[ 1587.086153]  handle_bug+0x3c/0x60
[ 1587.087103]  exc_invalid_op+0x14/0x70
[ 1587.087923]  asm_exc_invalid_op+0x12/0x20
[ 1587.088813] RIP: 0010:__sb_start_write+0x113/0x2a0
[ 1587.089962] Code: f3 f8 da 58 85 c0 0f 84 95 01 00 00 40 84 ed 0f 85 4c 01 00 00 45 84 e4 0f 85 75 01 00 00 5b 44 89 e8 5d 41 5c 41 5d 41 5e c3 <0f> 0b 48 89 e8 31 d2 be 31 00 00 00 48 c7 c7 ca 98 e4 a7 48 c1 e0
[ 1587.096163] RSP: 0018:ffffafbac3c2fdd0 EFLAGS: 00010246
[ 1587.098068] RAX: 0000000000000001 RBX: ffffa320cc6b4478 RCX: 0000000000000000
[ 1587.100489] RDX: 0000000000000001 RSI: 0000000000000000 RDI: ffffa320cc6b4478
[ 1587.102454] RBP: 0000000000000003 R08: 00000000000001b8 R09: ffffa320dbfa9b88
[ 1587.103974] R10: 0000000000000001 R11: ffffffffff9bcd99 R12: 0000000000000001
[ 1587.105366] R13: ffffa320cc6b4398 R14: ffffa320cc6b4698 R15: ffffa320e06f4000
[ 1587.106873]  start_transaction+0x406/0x510 [btrfs]
[ 1587.107859]  btrfs_unlink+0x31/0xf0 [btrfs]
[ 1587.108735]  vfs_unlink+0xee/0x1d0
[ 1587.109451]  do_unlinkat+0x1a1/0x2e0
[ 1587.110387]  do_syscall_64+0x2d/0x70
[ 1587.111318]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 1587.112588] RIP: 0033:0x7f0ad919b577
[ 1587.113543] Code: f0 ff ff 73 01 c3 48 8b 0d f6 f8 0c 00 f7 d8 64 89 01 48 83 c8 ff c3 66 2e 0f 1f 84 00 00 00 00 00 66 90 b8 57 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d c9 f8 0c 00 f7 d8 64 89 01 48
[ 1587.117977] RSP: 002b:00007ffc152bf358 EFLAGS: 00000206 ORIG_RAX: 0000000000000057
[ 1587.119801] RAX: ffffffffffffffda RBX: 00000000000001f4 RCX: 00007f0ad919b577
[ 1587.121488] RDX: 0000000000643266 RSI: 0000000000000000 RDI: 0000000000418070
[ 1587.123213] RBP: 00007ffc152bf4b0 R08: 0000000000418070 R09: 00007ffc152bf49c
[ 1587.124927] R10: 000000000000002d R11: 0000000000000206 R12: 000000000000033e
[ 1587.126121] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000
[ 1587.127122] irq event stamp: 1024932
[ 1587.128395] hardirqs last  enabled at (1024931): [<ffffffffa77fba04>] _raw_spin_unlock_irq+0x24/0x50
[ 1587.131643] hardirqs last disabled at (1024932): [<ffffffffa77f4188>] __schedule+0x3d8/0x8a0
[ 1587.135136] softirqs last  enabled at (1024750): [<ffffffffa7a00333>] __do_softirq+0x333/0x5c2
[ 1587.138237] softirqs last disabled at (1024741): [<ffffffffa7800dbf>] asm_call_irq_on_stack+0xf/0x20
[ 1587.140456] ---[ end trace 6b74e3ebe67d602c ]---
[ 1596.516828] BTRFS warning (device vdb): qgroup rescan is already in progress
[ 1596.788296] BTRFS info (device vdb): qgroup scan completed (inconsistency flag cleared)
[ 1597.641295] BTRFS info (device vdb): turning on sync discard
[ 1597.644117] BTRFS info (device vdb): disk space caching is enabled
[ 1597.646713] BTRFS info (device vdb): has skinny extents
_check_dmesg: something found in dmesg (see /tmp/fstests/results//btrfs/057.dmesg)
 [16:01:46]
btrfs/058		[16:01:46][ 1597.762062] run fstests btrfs/058 at 2020-11-10 16:01:46
[ 1598.091148] BTRFS info (device vda): disk space caching is enabled
[ 1598.093031] BTRFS info (device vda): has skinny extents
[ 1598.168010] ------------[ cut here ]------------
[ 1598.170209] WARNING: CPU: 1 PID: 19058 at fs/super.c:1676 __sb_start_write+0x113/0x2a0
[ 1598.173471] Modules linked in: dm_flakey dm_mod xxhash_generic btrfs blake2b_generic libcrc32c crc32c_intel xor zstd_decompress zstd_compress xxhash lzo_compress lzo_decompress raid6_pq loop
[ 1598.179110] CPU: 1 PID: 19058 Comm: xfs_io Tainted: G        W         5.10.0-rc3-default+ #1355
[ 1598.181745] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.12.0-59-gc9ba527-rebuilt.opensuse.org 04/01/2014
[ 1598.185018] RIP: 0010:__sb_start_write+0x113/0x2a0
[ 1598.186490] Code: f3 f8 da 58 85 c0 0f 84 95 01 00 00 40 84 ed 0f 85 4c 01 00 00 45 84 e4 0f 85 75 01 00 00 5b 44 89 e8 5d 41 5c 41 5d 41 5e c3 <0f> 0b 48 89 e8 31 d2 be 31 00 00 00 48 c7 c7 ca 98 e4 a7 48 c1 e0
[ 1598.191880] RSP: 0018:ffffafbac3ee7c38 EFLAGS: 00010246
[ 1598.193397] RAX: 0000000000000001 RBX: ffffa320cfcdc478 RCX: 0000000000000000
[ 1598.195124] RDX: 0000000000000001 RSI: 0000000000000000 RDI: ffffa320cfcdc478
[ 1598.197034] RBP: 0000000000000003 R08: 00000000000001b8 R09: ffffa320dbfa8378
[ 1598.198974] R10: 0000000000000001 R11: 4548530074736574 R12: 0000000000000001
[ 1598.200876] R13: ffffa320cfcdc398 R14: ffffa320cfcdc698 R15: ffffa320dade8000
[ 1598.202775] FS:  00007fb5ad735e80(0000) GS:ffffa3213d800000(0000) knlGS:0000000000000000
[ 1598.205041] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 1598.206551] CR2: 00007fb5ad84d520 CR3: 000000000fc4c004 CR4: 0000000000170ea0
[ 1598.208075] Call Trace:
[ 1598.208707]  start_transaction+0x406/0x510 [btrfs]
[ 1598.209821]  btrfs_tmpfile+0x49/0x1e0 [btrfs]
[ 1598.210881]  ? _raw_spin_unlock+0x29/0x40
[ 1598.211841]  vfs_tmpfile+0x63/0xe0
[ 1598.212617]  do_tmpfile+0x58/0xf0
[ 1598.213355]  path_openat+0x115/0x1b0
[ 1598.214205]  ? getname_flags+0x29/0x180
[ 1598.215050]  do_filp_open+0x88/0x130
[ 1598.215883]  ? lock_release+0xb0/0x160
[ 1598.216793]  ? do_raw_spin_unlock+0x4b/0xa0
[ 1598.217741]  ? _raw_spin_unlock+0x29/0x40
[ 1598.218660]  ? __alloc_fd+0xfc/0x1e0
[ 1598.219478]  do_sys_openat2+0x97/0x150
[ 1598.220342]  __x64_sys_openat+0x54/0x90
[ 1598.221240]  do_syscall_64+0x2d/0x70
[ 1598.222027]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 1598.223057] RIP: 0033:0x7fb5ad980047
[ 1598.223913] Code: 25 00 00 41 00 3d 00 00 41 00 74 47 64 8b 04 25 18 00 00 00 85 c0 75 6b 44 89 e2 48 89 ee bf 9c ff ff ff b8 01 01 00 00 0f 05 <48> 3d 00 f0 ff ff 0f 87 95 00 00 00 48 8b 4c 24 28 64 48 2b 0c 25
[ 1598.228002] RSP: 002b:00007ffd74683120 EFLAGS: 00000246 ORIG_RAX: 0000000000000101
[ 1598.230150] RAX: ffffffffffffffda RBX: 0000000000410002 RCX: 00007fb5ad980047
[ 1598.232082] RDX: 0000000000410002 RSI: 00007ffd74684138 RDI: 00000000ffffff9c
[ 1598.234054] RBP: 00007ffd74684138 R08: 0000000000000001 R09: 0000000000000000
[ 1598.236003] R10: 0000000000000180 R11: 0000000000000246 R12: 0000000000410002
[ 1598.237974] R13: 00007ffd74683510 R14: 0000000000000180 R15: 0000000000000200
[ 1598.239945] CPU: 1 PID: 19058 Comm: xfs_io Tainted: G        W         5.10.0-rc3-default+ #1355
[ 1598.242186] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.12.0-59-gc9ba527-rebuilt.opensuse.org 04/01/2014
[ 1598.244585] Call Trace:
[ 1598.245162]  dump_stack+0x77/0x97
[ 1598.245952]  ? __sb_start_write+0x113/0x2a0
[ 1598.246869]  __warn.cold+0x24/0x83
[ 1598.247614]  ? __sb_start_write+0x113/0x2a0
[ 1598.248561]  report_bug+0x9a/0xc0
[ 1598.249340]  handle_bug+0x3c/0x60
[ 1598.250112]  exc_invalid_op+0x14/0x70
[ 1598.250949]  asm_exc_invalid_op+0x12/0x20
[ 1598.251844] RIP: 0010:__sb_start_write+0x113/0x2a0
[ 1598.252862] Code: f3 f8 da 58 85 c0 0f 84 95 01 00 00 40 84 ed 0f 85 4c 01 00 00 45 84 e4 0f 85 75 01 00 00 5b 44 89 e8 5d 41 5c 41 5d 41 5e c3 <0f> 0b 48 89 e8 31 d2 be 31 00 00 00 48 c7 c7 ca 98 e4 a7 48 c1 e0
[ 1598.256674] RSP: 0018:ffffafbac3ee7c38 EFLAGS: 00010246
[ 1598.257786] RAX: 0000000000000001 RBX: ffffa320cfcdc478 RCX: 0000000000000000
[ 1598.259554] RDX: 0000000000000001 RSI: 0000000000000000 RDI: ffffa320cfcdc478
[ 1598.261376] RBP: 0000000000000003 R08: 00000000000001b8 R09: ffffa320dbfa8378
[ 1598.263173] R10: 0000000000000001 R11: 4548530074736574 R12: 0000000000000001
[ 1598.264966] R13: ffffa320cfcdc398 R14: ffffa320cfcdc698 R15: ffffa320dade8000
[ 1598.266774]  ? __sb_start_write+0x68/0x2a0
[ 1598.267888]  start_transaction+0x406/0x510 [btrfs]
[ 1598.269165]  btrfs_tmpfile+0x49/0x1e0 [btrfs]
[ 1598.270350]  ? _raw_spin_unlock+0x29/0x40
[ 1598.271421]  vfs_tmpfile+0x63/0xe0
[ 1598.272361]  do_tmpfile+0x58/0xf0
[ 1598.273281]  path_openat+0x115/0x1b0
[ 1598.274230]  ? getname_flags+0x29/0x180
[ 1598.275082]  do_filp_open+0x88/0x130
[ 1598.275879]  ? lock_release+0xb0/0x160
[ 1598.276706]  ? do_raw_spin_unlock+0x4b/0xa0
[ 1598.277923]  ? _raw_spin_unlock+0x29/0x40
[ 1598.279328]  ? __alloc_fd+0xfc/0x1e0
[ 1598.280596]  do_sys_openat2+0x97/0x150
[ 1598.281922]  __x64_sys_openat+0x54/0x90
[ 1598.283179]  do_syscall_64+0x2d/0x70
[ 1598.284373]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 1598.285973] RIP: 0033:0x7fb5ad980047
[ 1598.287187] Code: 25 00 00 41 00 3d 00 00 41 00 74 47 64 8b 04 25 18 00 00 00 85 c0 75 6b 44 89 e2 48 89 ee bf 9c ff ff ff b8 01 01 00 00 0f 05 <48> 3d 00 f0 ff ff 0f 87 95 00 00 00 48 8b 4c 24 28 64 48 2b 0c 25
[ 1598.292907] RSP: 002b:00007ffd74683120 EFLAGS: 00000246 ORIG_RAX: 0000000000000101
[ 1598.294685] RAX: ffffffffffffffda RBX: 0000000000410002 RCX: 00007fb5ad980047
[ 1598.296442] RDX: 0000000000410002 RSI: 00007ffd74684138 RDI: 00000000ffffff9c
[ 1598.298284] RBP: 00007ffd74684138 R08: 0000000000000001 R09: 0000000000000000
[ 1598.300103] R10: 0000000000000180 R11: 0000000000000246 R12: 0000000000410002
[ 1598.301922] R13: 00007ffd74683510 R14: 0000000000000180 R15: 0000000000000200
[ 1598.303754] irq event stamp: 0
[ 1598.304612] hardirqs last  enabled at (0): [<0000000000000000>] 0x0
[ 1598.306302] hardirqs last disabled at (0): [<ffffffffa707134b>] copy_process+0x3db/0x1440
[ 1598.308468] softirqs last  enabled at (0): [<ffffffffa707134b>] copy_process+0x3db/0x1440
[ 1598.310645] softirqs last disabled at (0): [<0000000000000000>] 0x0
[ 1598.312198] ---[ end trace 6b74e3ebe67d602d ]---
[ 1598.432274] BTRFS: device fsid 7c33f125-75b7-43f5-92a4-0fdbf15d7bef devid 1 transid 5 /dev/vdb scanned by mkfs.btrfs (19079)
[ 1598.459998] BTRFS info (device vdb): turning on sync discard
[ 1598.461401] BTRFS info (device vdb): disk space caching is enabled
[ 1598.462886] BTRFS info (device vdb): has skinny extents
[ 1598.464116] BTRFS info (device vdb): flagging fs with big metadata feature
[ 1598.470328] BTRFS info (device vdb): checking UUID tree
[ 1601.577163] BTRFS info (device vdb): turning on sync discard
[ 1601.579595] BTRFS info (device vdb): disk space caching is enabled
[ 1601.581907] BTRFS info (device vdb): has skinny extents
_check_dmesg: something found in dmesg (see /tmp/fstests/results//btrfs/058.dmesg)
 [16:01:50]

Re: [RFC] fs: Avoid to use lockdep information if it's turned off

[Boqun Feng]

Hi David,

On Wed, Nov 11, 2020 at 03:01:21PM +0100, David Sterba wrote:
> On Tue, Nov 10, 2020 at 04:33:27PM +0100, David Sterba wrote:
> > On Tue, Nov 10, 2020 at 09:37:37AM +0800, Boqun Feng wrote:
> > 
> > I'll run another test on top of the development branch in case there are
> > unrelated lockdep warning bugs that have been fixed meanwhile.
> 
> Similar reports but earlier test and probably completely valid due to
> "BUG: MAX_LOCKDEP_CHAIN_HLOCKS too low!"
> 

Thanks for trying this out. These results are as expected: first a
lockdep splat warning is hit, which could be either caused by the
detection of a deadlock case or caused by an internal lockdep issue
("BUG: MAX_LOCKDEP_CHAIN_HLOCKS too low!" in this case), the lockdep
get turned off afterwards, and then when __sb_start_write() wants to use
lock holding information, we find out, stop using that information and
do a WARN_ON_ONCE().

Without this patch, __sb_start_write() will get incorrect lock holding
information, and result in task hanging as reported by Filipe. Darrick's
patch:

	https://lore.kernel.org/linux-fsdevel/160494580419.772573.9286165021627298770.stgit@magnolia/T/#t

can also fix that by not relying the lock holding information at all in
__sb_start_write(). And I think that's a better fix.


For the "BUG: MAX_LOCKDEP_CHAIN_HLOCKS too low!" warning, do you see
that every time when you run xfstests and don't see other lockdep
splats? If so, that means we reach the limitation of number of lockdep
hlock chains, and we should fix that.

Regards,
Boqun

> btrfs/057		[16:01:29][ 1580.146087] run fstests btrfs/057 at 2020-11-10 16:01:29
> [ 1580.787867] BTRFS info (device vda): disk space caching is enabled
> [ 1580.789366] BTRFS info (device vda): has skinny extents
> [ 1581.052542] BTRFS: device fsid 84018822-2e45-4341-80be-da6d2b4e033a devid 1 transid 5 /dev/vdb scanned by mkfs.btrfs (18739)
> [ 1581.105177] BTRFS info (device vdb): turning on sync discard
> [ 1581.106834] BTRFS info (device vdb): disk space caching is enabled
> [ 1581.108423] BTRFS info (device vdb): has skinny extents
> [ 1581.109799] BTRFS info (device vdb): flagging fs with big metadata feature
> [ 1581.120343] BTRFS info (device vdb): checking UUID tree
> [ 1586.942699] BUG: MAX_LOCKDEP_CHAIN_HLOCKS too low!
> [ 1586.945725] turning off the locking correctness validator.
> [ 1586.948823] Please attach the output of /proc/lock_stat to the bug report
> [ 1586.952153] CPU: 0 PID: 18771 Comm: fsstress Not tainted 5.10.0-rc3-default+ #1355
> [ 1586.954919] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.12.0-59-gc9ba527-rebuilt.opensuse.org 04/01/2014
> [ 1586.958630] Call Trace:
> [ 1586.959214]  dump_stack+0x77/0x97
> [ 1586.960030]  add_chain_cache.cold+0x29/0x30
> [ 1586.961028]  validate_chain+0x278/0x780
> [ 1586.961979]  __lock_acquire+0x3fb/0x730
> [ 1586.962880]  lock_acquire.part.0+0xac/0x1a0
> [ 1586.963895]  ? try_to_wake_up+0x59/0x450
> [ 1586.965153]  ? rcu_read_lock_sched_held+0x3f/0x70
> [ 1586.966569]  ? lock_acquire+0xc4/0x150
> [ 1586.967699]  ? try_to_wake_up+0x59/0x450
> [ 1586.968882]  _raw_spin_lock_irqsave+0x43/0x90
> [ 1586.970207]  ? try_to_wake_up+0x59/0x450
> [ 1586.971404]  try_to_wake_up+0x59/0x450
> [ 1586.973149]  wake_up_q+0x60/0xb0
> [ 1586.974620]  __up_write+0x117/0x1d0
> [ 1586.975080] ------------[ cut here ]------------
> [ 1586.976039]  btrfs_release_path+0xc8/0x180 [btrfs]
> [ 1586.977718] WARNING: CPU: 2 PID: 18772 at fs/super.c:1676 __sb_start_write+0x113/0x2a0
> [ 1586.979478]  __btrfs_update_delayed_inode+0x1c1/0x2c0 [btrfs]
> [ 1586.979506]  btrfs_commit_inode_delayed_inode+0x115/0x120 [btrfs]
> [ 1586.982484] Modules linked in:
> [ 1586.984080]  btrfs_evict_inode+0x1e2/0x370 [btrfs]
> [ 1586.985557]  dm_flakey
> [ 1586.986419]  ? evict+0xc3/0x220
> [ 1586.986421]  evict+0xd5/0x220
> [ 1586.986423]  vfs_rmdir.part.0+0x10c/0x180
> [ 1586.986426]  do_rmdir+0x14b/0x1b0
> [ 1586.987504]  dm_mod
> [ 1586.988244]  do_syscall_64+0x2d/0x70
> [ 1586.988947]  xxhash_generic btrfs
> [ 1586.989779]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
> [ 1586.990906]  blake2b_generic
> [ 1586.991808] RIP: 0033:0x7f0ad919b5d7
> [ 1586.992451]  libcrc32c
> [ 1586.993427] Code: 73 01 c3 48 8b 0d 99 f8 0c 00 f7 d8 64 89 01 48 83 c8 ff c3 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 b8 54 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d 69 f8 0c 00 f7 d8 64 89 01 48
> [ 1586.994380]  crc32c_intel
> [ 1586.995546] RSP: 002b:00007ffc152bf368 EFLAGS: 00000202 ORIG_RAX: 0000000000000054
> [ 1586.996034]  xor
> [ 1586.996613] RAX: ffffffffffffffda RBX: 00000000000001f4 RCX: 00007f0ad919b5d7
> [ 1586.996615] RDX: 0000000000316264 RSI: 0000000000000000 RDI: 000000000045eff0
> [ 1586.997033]  zstd_decompress
> [ 1587.001060] RBP: 00007ffc152bf4b0 R08: 000000000045eff0 R09: 00007ffc152bf4a4
> [ 1587.001061] R10: 00000000000000b1 R11: 0000000000000202 R12: 000000000000030e
> [ 1587.001062] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000
> [ 1587.013639]  zstd_compress xxhash lzo_compress lzo_decompress raid6_pq loop
> [ 1587.015763] CPU: 2 PID: 18772 Comm: fsstress Not tainted 5.10.0-rc3-default+ #1355
> [ 1587.017719] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.12.0-59-gc9ba527-rebuilt.opensuse.org 04/01/2014
> [ 1587.020878] RIP: 0010:__sb_start_write+0x113/0x2a0
> [ 1587.022233] Code: f3 f8 da 58 85 c0 0f 84 95 01 00 00 40 84 ed 0f 85 4c 01 00 00 45 84 e4 0f 85 75 01 00 00 5b 44 89 e8 5d 41 5c 41 5d 41 5e c3 <0f> 0b 48 89 e8 31 d2 be 31 00 00 00 48 c7 c7 ca 98 e4 a7 48 c1 e0
> [ 1587.027309] RSP: 0018:ffffafbac3c2fdd0 EFLAGS: 00010246
> [ 1587.028998] RAX: 0000000000000001 RBX: ffffa320cc6b4478 RCX: 0000000000000000
> [ 1587.031038] RDX: 0000000000000001 RSI: 0000000000000000 RDI: ffffa320cc6b4478
> [ 1587.032905] RBP: 0000000000000003 R08: 00000000000001b8 R09: ffffa320dbfa9b88
> [ 1587.035782] R10: 0000000000000001 R11: ffffffffff9bcd99 R12: 0000000000000001
> [ 1587.037974] R13: ffffa320cc6b4398 R14: ffffa320cc6b4698 R15: ffffa320e06f4000
> [ 1587.040473] FS:  00007f0ad90a7b80(0000) GS:ffffa3213da00000(0000) knlGS:0000000000000000
> [ 1587.043694] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [ 1587.045577] CR2: 00000000007b5ce8 CR3: 0000000004be6006 CR4: 0000000000170ea0
> [ 1587.047744] Call Trace:
> [ 1587.048689]  start_transaction+0x406/0x510 [btrfs]
> [ 1587.050009]  btrfs_unlink+0x31/0xf0 [btrfs]
> [ 1587.051313]  vfs_unlink+0xee/0x1d0
> [ 1587.052435]  do_unlinkat+0x1a1/0x2e0
> [ 1587.053676]  do_syscall_64+0x2d/0x70
> [ 1587.054883]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
> [ 1587.056428] RIP: 0033:0x7f0ad919b577
> [ 1587.057583] Code: f0 ff ff 73 01 c3 48 8b 0d f6 f8 0c 00 f7 d8 64 89 01 48 83 c8 ff c3 66 2e 0f 1f 84 00 00 00 00 00 66 90 b8 57 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d c9 f8 0c 00 f7 d8 64 89 01 48
> [ 1587.061252] RSP: 002b:00007ffc152bf358 EFLAGS: 00000206 ORIG_RAX: 0000000000000057
> [ 1587.063942] RAX: ffffffffffffffda RBX: 00000000000001f4 RCX: 00007f0ad919b577
> [ 1587.065661] RDX: 0000000000643266 RSI: 0000000000000000 RDI: 0000000000418070
> [ 1587.067478] RBP: 00007ffc152bf4b0 R08: 0000000000418070 R09: 00007ffc152bf49c
> [ 1587.069024] R10: 000000000000002d R11: 0000000000000206 R12: 000000000000033e
> [ 1587.071631] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000
> [ 1587.074260] CPU: 2 PID: 18772 Comm: fsstress Not tainted 5.10.0-rc3-default+ #1355
> [ 1587.076198] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.12.0-59-gc9ba527-rebuilt.opensuse.org 04/01/2014
> [ 1587.078659] Call Trace:
> [ 1587.079296]  dump_stack+0x77/0x97
> [ 1587.080076]  ? __sb_start_write+0x113/0x2a0
> [ 1587.081008]  __warn.cold+0x24/0x83
> [ 1587.082506]  ? __sb_start_write+0x113/0x2a0
> [ 1587.084716]  report_bug+0x9a/0xc0
> [ 1587.086153]  handle_bug+0x3c/0x60
> [ 1587.087103]  exc_invalid_op+0x14/0x70
> [ 1587.087923]  asm_exc_invalid_op+0x12/0x20
> [ 1587.088813] RIP: 0010:__sb_start_write+0x113/0x2a0
> [ 1587.089962] Code: f3 f8 da 58 85 c0 0f 84 95 01 00 00 40 84 ed 0f 85 4c 01 00 00 45 84 e4 0f 85 75 01 00 00 5b 44 89 e8 5d 41 5c 41 5d 41 5e c3 <0f> 0b 48 89 e8 31 d2 be 31 00 00 00 48 c7 c7 ca 98 e4 a7 48 c1 e0
> [ 1587.096163] RSP: 0018:ffffafbac3c2fdd0 EFLAGS: 00010246
> [ 1587.098068] RAX: 0000000000000001 RBX: ffffa320cc6b4478 RCX: 0000000000000000
> [ 1587.100489] RDX: 0000000000000001 RSI: 0000000000000000 RDI: ffffa320cc6b4478
> [ 1587.102454] RBP: 0000000000000003 R08: 00000000000001b8 R09: ffffa320dbfa9b88
> [ 1587.103974] R10: 0000000000000001 R11: ffffffffff9bcd99 R12: 0000000000000001
> [ 1587.105366] R13: ffffa320cc6b4398 R14: ffffa320cc6b4698 R15: ffffa320e06f4000
> [ 1587.106873]  start_transaction+0x406/0x510 [btrfs]
> [ 1587.107859]  btrfs_unlink+0x31/0xf0 [btrfs]
> [ 1587.108735]  vfs_unlink+0xee/0x1d0
> [ 1587.109451]  do_unlinkat+0x1a1/0x2e0
> [ 1587.110387]  do_syscall_64+0x2d/0x70
> [ 1587.111318]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
> [ 1587.112588] RIP: 0033:0x7f0ad919b577
> [ 1587.113543] Code: f0 ff ff 73 01 c3 48 8b 0d f6 f8 0c 00 f7 d8 64 89 01 48 83 c8 ff c3 66 2e 0f 1f 84 00 00 00 00 00 66 90 b8 57 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d c9 f8 0c 00 f7 d8 64 89 01 48
> [ 1587.117977] RSP: 002b:00007ffc152bf358 EFLAGS: 00000206 ORIG_RAX: 0000000000000057
> [ 1587.119801] RAX: ffffffffffffffda RBX: 00000000000001f4 RCX: 00007f0ad919b577
> [ 1587.121488] RDX: 0000000000643266 RSI: 0000000000000000 RDI: 0000000000418070
> [ 1587.123213] RBP: 00007ffc152bf4b0 R08: 0000000000418070 R09: 00007ffc152bf49c
> [ 1587.124927] R10: 000000000000002d R11: 0000000000000206 R12: 000000000000033e
> [ 1587.126121] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000
> [ 1587.127122] irq event stamp: 1024932
> [ 1587.128395] hardirqs last  enabled at (1024931): [<ffffffffa77fba04>] _raw_spin_unlock_irq+0x24/0x50
> [ 1587.131643] hardirqs last disabled at (1024932): [<ffffffffa77f4188>] __schedule+0x3d8/0x8a0
> [ 1587.135136] softirqs last  enabled at (1024750): [<ffffffffa7a00333>] __do_softirq+0x333/0x5c2
> [ 1587.138237] softirqs last disabled at (1024741): [<ffffffffa7800dbf>] asm_call_irq_on_stack+0xf/0x20
> [ 1587.140456] ---[ end trace 6b74e3ebe67d602c ]---
> [ 1596.516828] BTRFS warning (device vdb): qgroup rescan is already in progress
> [ 1596.788296] BTRFS info (device vdb): qgroup scan completed (inconsistency flag cleared)
> [ 1597.641295] BTRFS info (device vdb): turning on sync discard
> [ 1597.644117] BTRFS info (device vdb): disk space caching is enabled
> [ 1597.646713] BTRFS info (device vdb): has skinny extents
> _check_dmesg: something found in dmesg (see /tmp/fstests/results//btrfs/057.dmesg)
>  [16:01:46]
> btrfs/058		[16:01:46][ 1597.762062] run fstests btrfs/058 at 2020-11-10 16:01:46
> [ 1598.091148] BTRFS info (device vda): disk space caching is enabled
> [ 1598.093031] BTRFS info (device vda): has skinny extents
> [ 1598.168010] ------------[ cut here ]------------
> [ 1598.170209] WARNING: CPU: 1 PID: 19058 at fs/super.c:1676 __sb_start_write+0x113/0x2a0
> [ 1598.173471] Modules linked in: dm_flakey dm_mod xxhash_generic btrfs blake2b_generic libcrc32c crc32c_intel xor zstd_decompress zstd_compress xxhash lzo_compress lzo_decompress raid6_pq loop
> [ 1598.179110] CPU: 1 PID: 19058 Comm: xfs_io Tainted: G        W         5.10.0-rc3-default+ #1355
> [ 1598.181745] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.12.0-59-gc9ba527-rebuilt.opensuse.org 04/01/2014
> [ 1598.185018] RIP: 0010:__sb_start_write+0x113/0x2a0
> [ 1598.186490] Code: f3 f8 da 58 85 c0 0f 84 95 01 00 00 40 84 ed 0f 85 4c 01 00 00 45 84 e4 0f 85 75 01 00 00 5b 44 89 e8 5d 41 5c 41 5d 41 5e c3 <0f> 0b 48 89 e8 31 d2 be 31 00 00 00 48 c7 c7 ca 98 e4 a7 48 c1 e0
> [ 1598.191880] RSP: 0018:ffffafbac3ee7c38 EFLAGS: 00010246
> [ 1598.193397] RAX: 0000000000000001 RBX: ffffa320cfcdc478 RCX: 0000000000000000
> [ 1598.195124] RDX: 0000000000000001 RSI: 0000000000000000 RDI: ffffa320cfcdc478
> [ 1598.197034] RBP: 0000000000000003 R08: 00000000000001b8 R09: ffffa320dbfa8378
> [ 1598.198974] R10: 0000000000000001 R11: 4548530074736574 R12: 0000000000000001
> [ 1598.200876] R13: ffffa320cfcdc398 R14: ffffa320cfcdc698 R15: ffffa320dade8000
> [ 1598.202775] FS:  00007fb5ad735e80(0000) GS:ffffa3213d800000(0000) knlGS:0000000000000000
> [ 1598.205041] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [ 1598.206551] CR2: 00007fb5ad84d520 CR3: 000000000fc4c004 CR4: 0000000000170ea0
> [ 1598.208075] Call Trace:
> [ 1598.208707]  start_transaction+0x406/0x510 [btrfs]
> [ 1598.209821]  btrfs_tmpfile+0x49/0x1e0 [btrfs]
> [ 1598.210881]  ? _raw_spin_unlock+0x29/0x40
> [ 1598.211841]  vfs_tmpfile+0x63/0xe0
> [ 1598.212617]  do_tmpfile+0x58/0xf0
> [ 1598.213355]  path_openat+0x115/0x1b0
> [ 1598.214205]  ? getname_flags+0x29/0x180
> [ 1598.215050]  do_filp_open+0x88/0x130
> [ 1598.215883]  ? lock_release+0xb0/0x160
> [ 1598.216793]  ? do_raw_spin_unlock+0x4b/0xa0
> [ 1598.217741]  ? _raw_spin_unlock+0x29/0x40
> [ 1598.218660]  ? __alloc_fd+0xfc/0x1e0
> [ 1598.219478]  do_sys_openat2+0x97/0x150
> [ 1598.220342]  __x64_sys_openat+0x54/0x90
> [ 1598.221240]  do_syscall_64+0x2d/0x70
> [ 1598.222027]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
> [ 1598.223057] RIP: 0033:0x7fb5ad980047
> [ 1598.223913] Code: 25 00 00 41 00 3d 00 00 41 00 74 47 64 8b 04 25 18 00 00 00 85 c0 75 6b 44 89 e2 48 89 ee bf 9c ff ff ff b8 01 01 00 00 0f 05 <48> 3d 00 f0 ff ff 0f 87 95 00 00 00 48 8b 4c 24 28 64 48 2b 0c 25
> [ 1598.228002] RSP: 002b:00007ffd74683120 EFLAGS: 00000246 ORIG_RAX: 0000000000000101
> [ 1598.230150] RAX: ffffffffffffffda RBX: 0000000000410002 RCX: 00007fb5ad980047
> [ 1598.232082] RDX: 0000000000410002 RSI: 00007ffd74684138 RDI: 00000000ffffff9c
> [ 1598.234054] RBP: 00007ffd74684138 R08: 0000000000000001 R09: 0000000000000000
> [ 1598.236003] R10: 0000000000000180 R11: 0000000000000246 R12: 0000000000410002
> [ 1598.237974] R13: 00007ffd74683510 R14: 0000000000000180 R15: 0000000000000200
> [ 1598.239945] CPU: 1 PID: 19058 Comm: xfs_io Tainted: G        W         5.10.0-rc3-default+ #1355
> [ 1598.242186] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.12.0-59-gc9ba527-rebuilt.opensuse.org 04/01/2014
> [ 1598.244585] Call Trace:
> [ 1598.245162]  dump_stack+0x77/0x97
> [ 1598.245952]  ? __sb_start_write+0x113/0x2a0
> [ 1598.246869]  __warn.cold+0x24/0x83
> [ 1598.247614]  ? __sb_start_write+0x113/0x2a0
> [ 1598.248561]  report_bug+0x9a/0xc0
> [ 1598.249340]  handle_bug+0x3c/0x60
> [ 1598.250112]  exc_invalid_op+0x14/0x70
> [ 1598.250949]  asm_exc_invalid_op+0x12/0x20
> [ 1598.251844] RIP: 0010:__sb_start_write+0x113/0x2a0
> [ 1598.252862] Code: f3 f8 da 58 85 c0 0f 84 95 01 00 00 40 84 ed 0f 85 4c 01 00 00 45 84 e4 0f 85 75 01 00 00 5b 44 89 e8 5d 41 5c 41 5d 41 5e c3 <0f> 0b 48 89 e8 31 d2 be 31 00 00 00 48 c7 c7 ca 98 e4 a7 48 c1 e0
> [ 1598.256674] RSP: 0018:ffffafbac3ee7c38 EFLAGS: 00010246
> [ 1598.257786] RAX: 0000000000000001 RBX: ffffa320cfcdc478 RCX: 0000000000000000
> [ 1598.259554] RDX: 0000000000000001 RSI: 0000000000000000 RDI: ffffa320cfcdc478
> [ 1598.261376] RBP: 0000000000000003 R08: 00000000000001b8 R09: ffffa320dbfa8378
> [ 1598.263173] R10: 0000000000000001 R11: 4548530074736574 R12: 0000000000000001
> [ 1598.264966] R13: ffffa320cfcdc398 R14: ffffa320cfcdc698 R15: ffffa320dade8000
> [ 1598.266774]  ? __sb_start_write+0x68/0x2a0
> [ 1598.267888]  start_transaction+0x406/0x510 [btrfs]
> [ 1598.269165]  btrfs_tmpfile+0x49/0x1e0 [btrfs]
> [ 1598.270350]  ? _raw_spin_unlock+0x29/0x40
> [ 1598.271421]  vfs_tmpfile+0x63/0xe0
> [ 1598.272361]  do_tmpfile+0x58/0xf0
> [ 1598.273281]  path_openat+0x115/0x1b0
> [ 1598.274230]  ? getname_flags+0x29/0x180
> [ 1598.275082]  do_filp_open+0x88/0x130
> [ 1598.275879]  ? lock_release+0xb0/0x160
> [ 1598.276706]  ? do_raw_spin_unlock+0x4b/0xa0
> [ 1598.277923]  ? _raw_spin_unlock+0x29/0x40
> [ 1598.279328]  ? __alloc_fd+0xfc/0x1e0
> [ 1598.280596]  do_sys_openat2+0x97/0x150
> [ 1598.281922]  __x64_sys_openat+0x54/0x90
> [ 1598.283179]  do_syscall_64+0x2d/0x70
> [ 1598.284373]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
> [ 1598.285973] RIP: 0033:0x7fb5ad980047
> [ 1598.287187] Code: 25 00 00 41 00 3d 00 00 41 00 74 47 64 8b 04 25 18 00 00 00 85 c0 75 6b 44 89 e2 48 89 ee bf 9c ff ff ff b8 01 01 00 00 0f 05 <48> 3d 00 f0 ff ff 0f 87 95 00 00 00 48 8b 4c 24 28 64 48 2b 0c 25
> [ 1598.292907] RSP: 002b:00007ffd74683120 EFLAGS: 00000246 ORIG_RAX: 0000000000000101
> [ 1598.294685] RAX: ffffffffffffffda RBX: 0000000000410002 RCX: 00007fb5ad980047
> [ 1598.296442] RDX: 0000000000410002 RSI: 00007ffd74684138 RDI: 00000000ffffff9c
> [ 1598.298284] RBP: 00007ffd74684138 R08: 0000000000000001 R09: 0000000000000000
> [ 1598.300103] R10: 0000000000000180 R11: 0000000000000246 R12: 0000000000410002
> [ 1598.301922] R13: 00007ffd74683510 R14: 0000000000000180 R15: 0000000000000200
> [ 1598.303754] irq event stamp: 0
> [ 1598.304612] hardirqs last  enabled at (0): [<0000000000000000>] 0x0
> [ 1598.306302] hardirqs last disabled at (0): [<ffffffffa707134b>] copy_process+0x3db/0x1440
> [ 1598.308468] softirqs last  enabled at (0): [<ffffffffa707134b>] copy_process+0x3db/0x1440
> [ 1598.310645] softirqs last disabled at (0): [<0000000000000000>] 0x0
> [ 1598.312198] ---[ end trace 6b74e3ebe67d602d ]---
> [ 1598.432274] BTRFS: device fsid 7c33f125-75b7-43f5-92a4-0fdbf15d7bef devid 1 transid 5 /dev/vdb scanned by mkfs.btrfs (19079)
> [ 1598.459998] BTRFS info (device vdb): turning on sync discard
> [ 1598.461401] BTRFS info (device vdb): disk space caching is enabled
> [ 1598.462886] BTRFS info (device vdb): has skinny extents
> [ 1598.464116] BTRFS info (device vdb): flagging fs with big metadata feature
> [ 1598.470328] BTRFS info (device vdb): checking UUID tree
> [ 1601.577163] BTRFS info (device vdb): turning on sync discard
> [ 1601.579595] BTRFS info (device vdb): disk space caching is enabled
> [ 1601.581907] BTRFS info (device vdb): has skinny extents
> _check_dmesg: something found in dmesg (see /tmp/fstests/results//btrfs/058.dmesg)
>  [16:01:50]

Re: [RFC] fs: Avoid to use lockdep information if it's turned off

[David Sterba]

On Thu, Nov 12, 2020 at 11:22:12AM +0800, Boqun Feng wrote:
> For the "BUG: MAX_LOCKDEP_CHAIN_HLOCKS too low!" warning, do you see
> that every time when you run xfstests and don't see other lockdep
> splats? If so, that means we reach the limitation of number of lockdep
> hlock chains, and we should fix that.

It's not every time and depends on the release, eg. I found no reports
in a sample log for 5.7..5.9, while there are many for 5.2..5.6 and
5.10, every 2nd or 3rd run.

[    0.185150] ... MAX_LOCKDEP_SUBCLASSES:  8
[    0.186202] ... MAX_LOCK_DEPTH:          48
[    0.187286] ... MAX_LOCKDEP_KEYS:        8192
[    0.188404] ... CLASSHASH_SIZE:          4096
[    0.189519] ... MAX_LOCKDEP_ENTRIES:     32768
[    0.190672] ... MAX_LOCKDEP_CHAINS:      65536
[    0.191814] ... CHAINHASH_SIZE:          32768