linux-btrfs.vger.kernel.org archive mirror
 help / color / mirror / Atom feed
* BUG: MAX_LOCKDEP_CHAIN_HLOCKS too low!
@ 2022-07-26 12:32 Mikhail Gavrilov
  2022-07-26 16:42 ` David Sterba
  0 siblings, 1 reply; 34+ messages in thread
From: Mikhail Gavrilov @ 2022-07-26 12:32 UTC (permalink / raw)
  To: Btrfs BTRFS, Linux List Kernel Mailing

Hi guys.
Always with intensive writing on a btrfs volume, the message "BUG:
MAX_LOCKDEP_CHAIN_HLOCKS too low!" appears in the kernel logs.

[46729.134549] BUG: MAX_LOCKDEP_CHAIN_HLOCKS too low!
[46729.134557] turning off the locking correctness validator.
[46729.134559] Please attach the output of /proc/lock_stat to the bug report
[46729.134561] CPU: 22 PID: 166516 Comm: ThreadPoolForeg Tainted: G
    W    L   --------  ---
5.19.0-0.rc7.20220722git68e77ffbfd06.56.fc37.x86_64 #1
[46729.134566] Hardware name: System manufacturer System Product
Name/ROG STRIX X570-I GAMING, BIOS 4403 04/27/2022
[46729.134569] Call Trace:
[46729.134572]  <TASK>
[46729.134576]  dump_stack_lvl+0x5b/0x77
[46729.134583]  __lock_acquire.cold+0x167/0x29e
[46729.134594]  lock_acquire+0xce/0x2d0
[46729.134599]  ? btrfs_reserve_extent+0xbd/0x250
[46729.134606]  ? btrfs_get_alloc_profile+0x17e/0x240
[46729.134611]  btrfs_get_alloc_profile+0x19c/0x240
[46729.134614]  ? btrfs_reserve_extent+0xbd/0x250
[46729.134618]  btrfs_reserve_extent+0xbd/0x250
[46729.134629]  btrfs_alloc_tree_block+0xa3/0x510
[46729.134635]  ? release_extent_buffer+0xa7/0xe0
[46729.134643]  split_node+0x131/0x3d0
[46729.134652]  btrfs_search_slot+0x2f3/0xc30
[46729.134659]  ? btrfs_insert_inode_ref+0x50/0x3b0
[46729.134664]  btrfs_insert_empty_items+0x31/0x70
[46729.134669]  btrfs_insert_inode_ref+0x99/0x3b0
[46729.134678]  btrfs_rename2+0x317/0x1510
[46729.134690]  ? vfs_rename+0x49d/0xd20
[46729.134693]  ? btrfs_symlink+0x460/0x460
[46729.134696]  vfs_rename+0x49d/0xd20
[46729.134705]  ? do_renameat2+0x4a0/0x510
[46729.134709]  do_renameat2+0x4a0/0x510
[46729.134720]  __x64_sys_rename+0x3f/0x50
[46729.134724]  do_syscall_64+0x5b/0x80
[46729.134729]  ? memcg_slab_free_hook+0x1fd/0x2e0
[46729.134735]  ? do_faccessat+0x111/0x260
[46729.134739]  ? kmem_cache_free+0x379/0x3d0
[46729.134744]  ? lock_is_held_type+0xe8/0x140
[46729.134749]  ? do_syscall_64+0x67/0x80
[46729.134752]  ? lockdep_hardirqs_on+0x7d/0x100
[46729.134757]  ? do_syscall_64+0x67/0x80
[46729.134760]  ? asm_exc_page_fault+0x22/0x30
[46729.134764]  ? lockdep_hardirqs_on+0x7d/0x100
[46729.134768]  entry_SYSCALL_64_after_hwframe+0x63/0xcd
[46729.134773] RIP: 0033:0x7fd2a29b5afb
[46729.134798] Code: e8 7a 27 0a 00 f7 d8 19 c0 5b c3 0f 1f 40 00 b8
ff ff ff ff 5b c3 66 0f 1f 84 00 00 00 00 00 f3 0f 1e fa b8 52 00 00
00 0f 05 <48> 3d 00 f0 ff ff 77 05 c3 0f 1f 40 00 48 8b 15 f1 82 17 00
f7 d8
[46729.134801] RSP: 002b:00007fd25b70a5a8 EFLAGS: 00000282 ORIG_RAX:
0000000000000052
[46729.134805] RAX: ffffffffffffffda RBX: 00007fd25b70a5e0 RCX: 00007fd2a29b5afb
[46729.134808] RDX: 0000000000000000 RSI: 00003ba01ef60820 RDI: 00003ba00e4b2da0
[46729.134810] RBP: 00007fd25b70a660 R08: 0000000000000000 R09: 00007fd25b70a570
[46729.134812] R10: 00007ffd36b1f080 R11: 0000000000000282 R12: 00007fd25b70a5b8
[46729.134815] R13: 00003ba00e4b2da0 R14: 00007fd25b70a6c4 R15: 00003ba01ef60820
[46729.134823]  </TASK>

In this regard, I want to ask, is this really a bug?
The kernel version is 5.19-rc7.

Here's the full kernel log: https://pastebin.com/hYWH7RHu
Here's /proc/lock_stat: https://pastebin.com/ex5w0QW9

-- 
Best Regards,
Mike Gavrilov.

^ permalink raw reply	[flat|nested] 34+ messages in thread
* BUG: MAX_LOCKDEP_CHAIN_HLOCKS too low!
@ 2021-03-02 10:27 Johannes Thumshirn
  2021-03-04 13:52 ` David Sterba
  0 siblings, 1 reply; 34+ messages in thread
From: Johannes Thumshirn @ 2021-03-02 10:27 UTC (permalink / raw)
  To: linux-btrfs @ vger . kernel . org

I've just tripped over this lockdep splat on v5.12-rc1 (Linus' tree not misc-next),
while investigating a different bug report.


[ 1250.721882] BUG: MAX_LOCKDEP_CHAIN_HLOCKS too low!
[ 1250.722641] turning off the locking correctness validator.
[ 1250.723486] CPU: 0 PID: 468 Comm: fsstress Not tainted 5.12.0-rc1 #950
[ 1250.724483] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.14.0-0-g155821a-rebuilt.opensuse.org 04/01/2014
[ 1250.726180] Call Trace:
[ 1250.726551]  dump_stack+0x6d/0x89
[ 1250.727052]  __lock_acquire.cold+0x2dd/0x2e2
[ 1250.727676]  lock_acquire+0xab/0x350
[ 1250.728204]  ? btrfs_add_delayed_tree_ref+0x1ae/0x4a0 [btrfs]
[ 1250.729215]  ? debug_mutex_init+0x33/0x40
[ 1250.729822]  _raw_spin_lock+0x2c/0x40
[ 1250.730340]  ? btrfs_add_delayed_tree_ref+0x1ae/0x4a0 [btrfs]
[ 1250.731208]  btrfs_add_delayed_tree_ref+0x1ae/0x4a0 [btrfs]
[ 1250.732047]  ? kmem_cache_alloc+0x17a/0x300
[ 1250.732635]  btrfs_alloc_tree_block+0x292/0x320 [btrfs]
[ 1250.733417]  alloc_tree_block_no_bg_flush+0x4f/0x60 [btrfs]
[ 1250.734253]  __btrfs_cow_block+0x13b/0x5e0 [btrfs]
[ 1250.734964]  btrfs_cow_block+0x117/0x240 [btrfs]
[ 1250.735662]  btrfs_search_slot+0x688/0xc60 [btrfs]
[ 1250.736378]  ? mark_held_locks+0x49/0x70
[ 1250.736927]  btrfs_insert_empty_items+0x58/0xa0 [btrfs]
[ 1250.737706]  btrfs_insert_file_extent+0x8d/0x1c0 [btrfs]
[ 1250.738494]  btrfs_cont_expand+0x359/0x4c0 [btrfs]
[ 1250.739226]  btrfs_setattr+0x380/0x660 [btrfs]
[ 1250.739900]  ? ktime_get_coarse_real_ts64+0xcb/0xe0
[ 1250.740578]  ? current_time+0x1b/0xd0
[ 1250.741088]  notify_change+0x27b/0x490
[ 1250.741613]  ? do_truncate+0x6d/0xb0
[ 1250.742122]  do_truncate+0x6d/0xb0
[ 1250.742604]  vfs_truncate+0x108/0x140
[ 1250.743122]  do_sys_truncate.part.0+0x6a/0x80
[ 1250.743738]  do_syscall_64+0x33/0x40
[ 1250.744250]  entry_SYSCALL_64_after_hwframe+0x44/0xae
[ 1250.744946] RIP: 0033:0x7f38d7819b8b
[ 1250.745453] Code: 48 8b 4c 24 28 64 48 2b 0c 25 28 00 00 00 75 05 48 83 c4 38 c3 e8 c5 69 01 00 0f 1f 44 00 00 f3 0f 1e fa b8 4c 00 00 00 0f 05 <48> 3d 00 f0 ff ff 77 05 c3 0f 1f 40 00 48 8b 15 b1 92 0c 00 f7 d8
[ 1250.748044] RSP: 002b:00007ffdf2983ed8 EFLAGS: 00000202 ORIG_RAX: 000000000000004c
[ 1250.749096] RAX: ffffffffffffffda RBX: 00007ffdf2984030 RCX: 00007f38d7819b8b
[ 1250.750081] RDX: 00000000001b92a2 RSI: 00000000001b92a2 RDI: 0000000000bdb380
[ 1250.751061] RBP: 00000000001b92a2 R08: 0000000000000029 R09: 00007ffdf298402c
[ 1250.752052] R10: 0000000000000002 R11: 0000000000000202 R12: 0000000000000010
[ 1250.753040] R13: 00000000001b92a2 R14: 0000000000000000 R15: 0000000000000001
[ 1260.719289] BTRFS info (device md0): scrub: started on devid 1
[ 1262.030768] BTRFS info (device md0): scrub: finished on devid 1 with status: 0

To trigger the bug I did several (4-5 I think) runs of this script:

rapido1:/home/johannes/src/xfstests-dev# cat test.sh 
#!/bin/sh

SCRATCH_DIR=/mnt/scratch

echo "running fsstress"
./ltp/fsstress -w -f unlink=1 -f rmdir=1 -f symlink=1 -f sync=1 -f link=1 \
        -f rename=1 -f fdatasync=1 -f removefattr=1 -f fsync=1 -f setfattr=1 \
        -f setxattr=1 -f unresvsp=1 -f mkdir=1 -f mknod=1 -f chown=1 -f fiemap=1 \
        -f freesp=1 -f snapshot=1 -f rnoreplace=1 -f rexchange=1 -f rwhiteout=1 \
        -f allocsp=1 -f subvol_create=1 -f subvol_delete=1 -f awrite=1 \
        -f writev=1 -f write=1 -f splice=1 -f mread=1 -f deduperange=1 \
        -f mwrite=1 -f dwrite=1 -f clonerange=1 -f copyrange=1 -f truncate=1 \
        -f fallocate=1 -f punch=1 -f zero=1 -f collapse=1 -f insert=1 -p 30 \
        -n 1000 -S t -d $SCRATCH_DIR

echo "scrubbing"
btrfs scrub start -Bd $SCRATCH_DIR || exit 1

echo "cleaning up"
rm -rf $SCRATCH_DIR/*


$SCRATCH_DIR is mounted on top of a md-raid1 array: 

rapido1:/home/johannes/src/xfstests-dev# mdadm --detail /dev/md0
/dev/md0:
           Version : 1.2
     Creation Time : Tue Mar  2 09:38:17 2021
        Raid Level : raid1
        Array Size : 3142656 (3.00 GiB 3.22 GB)
     Used Dev Size : 3142656 (3.00 GiB 3.22 GB)
      Raid Devices : 4
     Total Devices : 4
       Persistence : Superblock is persistent

       Update Time : Tue Mar  2 09:58:57 2021
             State : clean 
    Active Devices : 4
   Working Devices : 4
    Failed Devices : 0
     Spare Devices : 0

Consistency Policy : resync

              Name : rapido1:0  (local to host rapido1)
              UUID : 10a4866b:6da1ccdc:e069e6da:79196fb1
            Events : 19

    Number   Major   Minor   RaidDevice State
       0     251        1        0      active sync   /dev/zram1
       1     251        4        1      active sync   /dev/zram4
       2     251        2        2      active sync   /dev/zram2
       3     251        3        3      active sync   /dev/zram3



johannes@redsun60:linux(master)$ ./scripts/faddr2line fs/btrfs/btrfs.ko btrfs_add_delayed_tree_ref+0x1ae
btrfs_add_delayed_tree_ref+0x1ae/0x4a0:
btrfs_add_delayed_tree_ref at /home/johannes/src/linux/fs/btrfs/delayed-ref.c:999
johannes@redsun60:linux(master)$ cat -n fs/btrfs/delayed-ref.c | grep -C 10 999
   989                                is_system);
   990          head_ref->extent_op = extent_op;
   991
   992          delayed_refs = &trans->transaction->delayed_refs;
   993          spin_lock(&delayed_refs->lock);
   994
   995          /*
   996           * insert both the head node and the new ref without dropping
   997           * the spin lock
   998           */
   999          head_ref = add_delayed_ref_head(trans, head_ref, record,
  1000                                          action, &qrecord_inserted);
  1001
  1002          ret = insert_delayed_ref(trans, delayed_refs, head_ref, &ref->node);
  1003          spin_unlock(&delayed_refs->lock);
  1004
  1005          /*
  1006           * Need to update the delayed_refs_rsv with any changes we may have
  1007           * made.
  1008           */
  1009          btrfs_update_delayed_refs_rsv(trans);

Has anyone seen this before?

^ permalink raw reply	[flat|nested] 34+ messages in thread

end of thread, other threads:[~2025-09-23  7:03 UTC | newest]

Thread overview: 34+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2022-07-26 12:32 BUG: MAX_LOCKDEP_CHAIN_HLOCKS too low! Mikhail Gavrilov
2022-07-26 16:42 ` David Sterba
2022-07-26 19:19   ` Chris Murphy
2022-07-26 19:21     ` Chris Murphy
2022-07-26 20:42       ` David Sterba
2022-08-03 19:28   ` Mikhail Gavrilov
2022-08-03 20:00     ` Chris Murphy
2022-08-04  7:35       ` Mikhail Gavrilov
2022-08-04 11:23         ` Tetsuo Handa
2023-01-24 20:27   ` Mikhail Gavrilov
2023-01-25 17:15     ` David Sterba
2023-01-26  9:47       ` Mikhail Gavrilov
2023-01-26 17:38         ` Boqun Feng
2023-01-26 18:30           ` Waiman Long
2023-01-26 18:59             ` Boqun Feng
2023-01-26 19:07               ` Waiman Long
2023-01-26 22:42           ` Mikhail Gavrilov
2023-01-26 22:51             ` Boqun Feng
2023-01-26 23:49             ` Boqun Feng
2023-01-27  0:20             ` Waiman Long
2023-01-27  3:37               ` Chris Murphy
2023-01-27  4:07                 ` Boqun Feng
2023-01-27  5:35                   ` Mikhail Gavrilov
2023-01-27 14:26                   ` Waiman Long
2023-01-27 15:33                     ` Chris Murphy
2025-03-09 22:51                       ` Mikhail Gavrilov
2025-03-10 11:23                         ` Peter Zijlstra
2025-03-10  9:08                 ` Peter Zijlstra
2025-03-10 13:01                   ` Peter Zijlstra
2025-03-10 11:21           ` Peter Zijlstra
2025-03-10 16:37             ` Boqun Feng
2025-09-23  7:03               ` Mikhail Gavrilov
  -- strict thread matches above, loose matches on Subject: below --
2021-03-02 10:27 Johannes Thumshirn
2021-03-04 13:52 ` David Sterba

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).