[15315.252203] run fstests generic/464 at 2023-06-05 01:09:21
[15316.231215] BTRFS: device fsid 7ba6b25f-a9e7-4e45-8294-ba0fdde32b46 devid 1 transid 6 /dev/mapper/vg0-lv9 scanned by mkfs.btrfs (2129294)
[15316.254844] BTRFS info (device dm-9): using crc32c (crc32c-intel) checksum algorithm
[15316.254854] BTRFS info (device dm-9): turning on async discard
[15316.254857] BTRFS info (device dm-9): disk space caching is enabled
[15316.284165] BTRFS info (device dm-9): checking UUID tree
[15326.198902] BTRFS: device fsid 7ba6b25f-a9e7-4e45-8294-ba0fdde32b46 devid 1 transid 8 /dev/mapper/vg0-lv9 scanned by mount (2133615)
[15326.200419] BTRFS info (device dm-9): using crc32c (crc32c-intel) checksum algorithm
[15326.200428] BTRFS info (device dm-9): turning on async discard
[15326.200430] BTRFS info (device dm-9): disk space caching is enabled
[15334.695048] BTRFS: device fsid 7ba6b25f-a9e7-4e45-8294-ba0fdde32b46 devid 1 transid 10 /dev/mapper/vg0-lv9 scanned by mount (2138091)
[15334.695474] BTRFS info (device dm-9): using crc32c (crc32c-intel) checksum algorithm
[15334.695482] BTRFS info (device dm-9): turning on async discard
[15334.695484] BTRFS info (device dm-9): disk space caching is enabled
[15346.355640] BTRFS: device fsid 7ba6b25f-a9e7-4e45-8294-ba0fdde32b46 devid 1 transid 12 /dev/mapper/vg0-lv9 scanned by mount (2142302)
[15346.356960] BTRFS info (device dm-9): using crc32c (crc32c-intel) checksum algorithm
[15346.356968] BTRFS info (device dm-9): turning on async discard
[15346.356970] BTRFS info (device dm-9): disk space caching is enabled
[15359.265295] BTRFS: device fsid 7ba6b25f-a9e7-4e45-8294-ba0fdde32b46 devid 1 transid 14 /dev/mapper/vg0-lv9 scanned by mount (2146736)
[15359.266637] BTRFS info (device dm-9): using crc32c (crc32c-intel) checksum algorithm
[15359.266645] BTRFS info (device dm-9): turning on async discard
[15359.266647] BTRFS info (device dm-9): disk space caching is enabled
[15364.850404] ================================
[15364.850593] WARNING: inconsistent lock state
[15364.850756] 6.4.0-rc4+ #1200 Not tainted
[15364.850905] --------------------------------
[15364.851106] inconsistent {SOFTIRQ-ON-W} -> {IN-SOFTIRQ-W} usage.
[15364.851344] kworker/u4:0/2110072 [HC0[0]:SC1[1]:HE1:SE0] takes:
[15364.851589] ffff8eae83150d20 (&fs_info->delayed_iput_lock){+.?.}-{2:2}, at: btrfs_add_delayed_iput+0x67/0xd0
[15364.851943] {SOFTIRQ-ON-W} state was registered at:
[15364.852159] lock_acquire+0xc7/0x2b0
[15364.852316] _raw_spin_lock+0x2f/0x40
[15364.852464] btrfs_run_delayed_iputs+0x22/0x80
[15364.852630] close_ctree+0xcb/0x4e0
[15364.852763] generic_shutdown_super+0x7d/0x150
[15364.852931] kill_anon_super+0x14/0x30
[15364.853146] btrfs_kill_super+0x12/0x20
[15364.853307] deactivate_locked_super+0x2e/0xa0
[15364.853507] cleanup_mnt+0x100/0x160
[15364.853666] task_work_run+0x56/0xa0
[15364.853803] exit_to_user_mode_prepare+0x21e/0x240
[15364.854017] syscall_exit_to_user_mode+0x16/0x50
[15364.854190] do_syscall_64+0x48/0x90
[15364.854361] entry_SYSCALL_64_after_hwframe+0x72/0xdc
[15364.854585] irq event stamp: 567036
[15364.854714] hardirqs last enabled at (567036): [] mod_lruvec_page_state+0x47/0x60
[15364.855097] hardirqs last disabled at (567035): [] mod_lruvec_page_state+0x34/0x60
[15364.855454] softirqs last enabled at (565110): [] __irq_exit_rcu+0xeb/0x160
[15364.855760] softirqs last disabled at (565143): [] __irq_exit_rcu+0xeb/0x160
[15364.856117]
other info that might help us debug this:
[15364.856351] Possible unsafe locking scenario:
[15364.856562] CPU0
[15364.856656] ----
[15364.856750] lock(&fs_info->delayed_iput_lock);
[15364.856995]
[15364.857094] lock(&fs_info->delayed_iput_lock);
[15364.857268]
*** DEADLOCK ***
[15364.857479] 3 locks held by kworker/u4:0/2110072:
[15364.857649] #0: ffff8eae80328138 ((wq_completion)writeback){+.+.}-{0:0}, at: process_one_work+0x1f4/0x530
[15364.858092] #1: ffffa2390654be80 ((work_completion)(&(&wb->dwork)->work)){+.+.}-{0:0}, at: process_one_work+0x1f4/0x530
[15364.858518] #2: ffffffffa2d772c0 (rcu_read_lock){....}-{1:2}, at: folio_memcg_lock+0x5/0x240
[15364.858820]
stack backtrace:
[15364.858985] CPU: 0 PID: 2110072 Comm: kworker/u4:0 Not tainted 6.4.0-rc4+ #1200
[15364.859245] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 1.13.0-2.fc32 04/01/2014
[15364.859609] Workqueue: writeback wb_workfn (flush-btrfs-2942)
[15364.859821] Call Trace:
[15364.859918]
[15364.860029] dump_stack_lvl+0x58/0x90
[15364.860167] mark_lock.part.0+0x697/0x820
[15364.860314] ? print_irq_inversion_bug.part.0+0x137/0x250
[15364.860508] __lock_acquire+0x7b0/0x2220
[15364.860651] ? __mod_node_page_state+0x91/0x100
[15364.860820] lock_acquire+0xc7/0x2b0
[15364.860955] ? btrfs_add_delayed_iput+0x67/0xd0
[15364.861121] ? __folio_end_writeback+0x5e/0x3f0
[15364.861288] _raw_spin_lock+0x2f/0x40
[15364.861531] ? btrfs_add_delayed_iput+0x67/0xd0
[15364.861721] btrfs_add_delayed_iput+0x67/0xd0
[15364.861884] btrfs_put_ordered_extent+0xc9/0x170
[15364.862052] clone_endio+0x10a/0x1c0
[15364.862186] blk_update_request+0x112/0x4c0
[15364.862339] blk_mq_end_request+0x1c/0x110
[15364.862490] blk_complete_reqs+0x3d/0x50
[15364.862634] __do_softirq+0xe6/0x45e
[15364.862767] __irq_exit_rcu+0xeb/0x160
[15364.862908] irq_exit_rcu+0xa/0x30
[15364.863035] common_interrupt+0xb8/0xd0
[15364.863178]
[15364.863260]
[15364.863343] asm_common_interrupt+0x22/0x40
[15364.863606] RIP: 0010:_raw_spin_unlock_irqrestore+0x33/0x60
[15364.863806] Code: 48 83 c7 18 53 48 89 f3 48 8b 74 24 10 e8 d5 87 20 ff 48 89 ef e8 cd b1 20 ff 80 e7 02 74 0b e8 23 39 2f ff fb 0f 1f 44 00 00 01 00 00 00 e8 93 80 1b ff 65 8b 05 04 82 00 5e 85 c0 74 07 5b
[15364.864446] RSP: 0018:ffffa2390654b920 EFLAGS: 00000206
[15364.864696] RAX: 0000000000089f95 RBX: 0000000000000206 RCX: 0000000000000040
[15364.864953] RDX: 0000000000000000 RSI: ffffffffa2a4d9f9 RDI: ffffffffa29d4896
[15364.865203] RBP: ffff8eaed2c44cf0 R08: 0000000000000001 R09: 0000000000000001
[15364.865520] R10: 0000000000000000 R11: 0000000000481000 R12: 0000000000000001
[15364.865770] R13: ffff8eae84bbd000 R14: ffff8eaed2c44ce8 R15: ffff8eae83150000
[15364.866060] __folio_start_writeback+0x12d/0x2a0
[15364.866242] btrfs_set_range_writeback+0x77/0x120
[15364.866415] __extent_writepage_io+0x151/0x370
[15364.866579] ? writepage_delalloc+0xa8/0x130
[15364.866737] extent_write_cache_pages+0x5c4/0x7d0
[15364.866930] ? __lock_acquire+0x3c1/0x2220
[15364.867083] extent_writepages+0x7b/0x130
[15364.867230] ? __pfx_end_bio_extent_writepage+0x10/0x10
[15364.867418] do_writepages+0xbf/0x190
[15364.867555] ? lock_release+0x134/0x270
[15364.867697] __writeback_single_inode+0x58/0x420
[15364.867872] writeback_sb_inodes+0x1f0/0x4d0
[15364.868034] wb_writeback+0xb7/0x320
[15364.868168] wb_workfn+0xc8/0x510
[15364.868295] ? lock_acquire+0xd7/0x2b0
[15364.868433] ? lock_release+0x134/0x270
[15364.868575] process_one_work+0x271/0x530
[15364.868722] ? __pfx_worker_thread+0x10/0x10
[15364.868884] worker_thread+0x52/0x3b0
[15364.869020] ? __pfx_worker_thread+0x10/0x10
[15364.869177] kthread+0xfc/0x130
[15364.869296] ? __pfx_kthread+0x10/0x10
[15364.869435] ret_from_fork+0x29/0x50
[15364.869572]
[15370.495616] BTRFS: device fsid 7ba6b25f-a9e7-4e45-8294-ba0fdde32b46 devid 1 transid 16 /dev/mapper/vg0-lv9 scanned by mount (2151052)
[15370.497047] BTRFS info (device dm-9): using crc32c (crc32c-intel) checksum algorithm
[15370.497364] BTRFS info (device dm-9): turning on async discard
[15370.497569] BTRFS info (device dm-9): disk space caching is enabled
[15387.001713] BTRFS: device fsid 7ba6b25f-a9e7-4e45-8294-ba0fdde32b46 devid 1 transid 18 /dev/mapper/vg0-lv9 scanned by mount (2158529)
[15387.003593] BTRFS info (device dm-9): using crc32c (crc32c-intel) checksum algorithm
[15387.003992] BTRFS info (device dm-9): turning on async discard
[15387.004315] BTRFS info (device dm-9): disk space caching is enabled
[15401.924260] BTRFS: device fsid 7ba6b25f-a9e7-4e45-8294-ba0fdde32b46 devid 1 transid 20 /dev/mapper/vg0-lv9 scanned by mount (2165720)
[15401.925609] BTRFS info (device dm-9): using crc32c (crc32c-intel) checksum algorithm
[15401.925891] BTRFS info (device dm-9): turning on async discard
[15401.926119] BTRFS info (device dm-9): disk space caching is enabled
[15417.986105] BTRFS: device fsid 7ba6b25f-a9e7-4e45-8294-ba0fdde32b46 devid 1 transid 22 /dev/mapper/vg0-lv9 scanned by mount (2172557)
[15417.987378] BTRFS info (device dm-9): using crc32c (crc32c-intel) checksum algorithm
[15417.987700] BTRFS info (device dm-9): turning on async discard
[15417.987926] BTRFS info (device dm-9): disk space caching is enabled
[15433.742784] BTRFS: device fsid 7ba6b25f-a9e7-4e45-8294-ba0fdde32b46 devid 1 transid 24 /dev/mapper/vg0-lv9 scanned by mount (2179347)
[15433.743954] BTRFS info (device dm-9): using crc32c (crc32c-intel) checksum algorithm
[15433.744339] BTRFS info (device dm-9): turning on async discard
[15433.744616] BTRFS info (device dm-9): disk space caching is enabled
[15448.466071] BTRFS: device fsid 7ba6b25f-a9e7-4e45-8294-ba0fdde32b46 devid 1 transid 26 /dev/mapper/vg0-lv9 scanned by mount (2186492)
[15448.467412] BTRFS info (device dm-9): using crc32c (crc32c-intel) checksum algorithm
[15448.467720] BTRFS info (device dm-9): turning on async discard
[15448.467933] BTRFS info (device dm-9): disk space caching is enabled