[10139.530532] run fstests generic/166 at 2022-08-18 23:40:38
[10140.103516] BTRFS info (device dm-0): using crc32c (crc32c-intel) checksum algorithm
[10140.103526] BTRFS info (device dm-0): using free space tree
[10140.380786] BTRFS: device fsid 088dc985-8e4d-4608-b235-b70decc20e15 devid 1 transid 6 /dev/mapper/vg0-lv9 scanned by mkfs.btrfs (1383430)
[10140.420712] BTRFS info (device dm-9): using crc32c (crc32c-intel) checksum algorithm
[10140.420721] BTRFS info (device dm-9): disk space caching is enabled
[10140.449065] BTRFS info (device dm-9): checking UUID tree
[10140.915771] BTRFS: device fsid b7627c40-b36d-4da4-8bc9-f3bc91286c75 devid 1 transid 6 /dev/mapper/vg0-lv9 scanned by mkfs.btrfs (1383474)
[10140.959268] BTRFS info (device dm-9): using crc32c (crc32c-intel) checksum algorithm
[10140.959277] BTRFS info (device dm-9): disk space caching is enabled
[10140.962763] BTRFS info (device dm-9): checking UUID tree
[10141.955317] BTRFS info (device dm-9): using crc32c (crc32c-intel) checksum algorithm
[10141.955325] BTRFS info (device dm-9): disk space caching is enabled
[10285.264423] BTRFS info (device dm-9): using crc32c (crc32c-intel) checksum algorithm
[10285.264432] BTRFS info (device dm-9): disk space caching is enabled
[10285.291730] ------------[ cut here ]------------
[10285.291815] WARNING: CPU: 1 PID: 1339843 at kernel/sched/core.c:8366 __cond_resched_lock+0x6c/0x70
[10285.291828] Modules linked in: dm_thin_pool dm_persistent_data dm_bio_prison dm_log_writes dm_dust dm_flakey nft_fib_inet nft_fib_ipv4 nft_fib_ipv6 nft_fib nft_reject_inet nf_reject_ipv4 nf_reject_ipv6 nft_reject nft_ct nft_chain_nat nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 ip6_tables nft_compat ip_set rfkill nf_tables nfnetlink intel_rapl_msr iTCO_wdt iTCO_vendor_support intel_rapl_common snd_hda_codec_generic i2c_i801 snd_hda_intel snd_intel_dspcfg i2c_smbus joydev snd_hda_codec snd_hwdep snd_hda_core snd_pcm lpc_ich virtio_balloon snd_timer snd soundcore zram ip_tables xfs crct10dif_pclmul crc32_pclmul crc32c_intel ghash_clmulni_intel serio_raw qemu_fw_cfg
[10285.291958] CPU: 1 PID: 1339843 Comm: kworker/u4:1 Tainted: G W 6.0.0-rc1+ #801
[10285.291962] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 1.13.0-2.fc32 04/01/2014
[10285.291966] Workqueue: btrfs-cache btrfs_work_helper
[10285.291974] RIP: 0010:__cond_resched_lock+0x6c/0x70
[10285.291978] Code: 75 02 f3 90 48 89 ef e8 02 7c d1 00 b8 01 00 00 00 5b 5d c3 cc cc cc cc 48 8d 7f 18 be ff ff ff ff e8 b8 52 d0 00 85 c0 75 af <0f> 0b eb ab 0f 1f 44 00 00 8b 05 51 97 e1 01 55 48 89 fd 53 65 8b
[10285.291982] RSP: 0018:ffffa87d454f3ab8 EFLAGS: 00010246
[10285.291987] RAX: 0000000000000000 RBX: 0000000080000001 RCX: 0000000000000001
[10285.291990] RDX: 0000000000000000 RSI: ffffffffb480fceb RDI: ffffffffb48b4a2e
[10285.291993] RBP: ffffa87d454f3bf8 R08: ffffa87d454f3c40 R09: 0000000000000001
[10285.291997] R10: 000000000000bf97 R11: 0000000000000001 R12: ffffa87d454f3c38
[10285.292000] R13: ffff8a3e43b331b8 R14: ffffa87d454f3c40 R15: ffff8a3d4d42e930
[10285.292003] FS: 0000000000000000(0000) GS:ffff8a3ebbd00000(0000) knlGS:0000000000000000
[10285.292007] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[10285.292010] CR2: 00005556b170e700 CR3: 00000001029fe004 CR4: 0000000000370ee0
[10285.292016] Call Trace:
[10285.292019]
[10285.292027] __btrfs_remove_free_space_cache+0x43/0xe0
[10285.292037] load_free_space_cache+0xacc/0xaf0
[10285.292127] caching_thread+0x417/0x5c0
[10285.292142] ? lock_release+0x137/0x2d0
[10285.292156] btrfs_work_helper+0xf2/0x3e0
[10285.292161] ? lock_is_held_type+0xe2/0x140
[10285.292176] process_one_work+0x271/0x590
[10285.292218] ? process_one_work+0x590/0x590
[10285.292225] worker_thread+0x52/0x3b0
[10285.292235] ? process_one_work+0x590/0x590
[10285.292240] kthread+0xf0/0x120
[10285.292244] ? kthread_complete_and_exit+0x20/0x20
[10285.292253] ret_from_fork+0x1f/0x30
[10285.292281]
[10285.292284] irq event stamp: 4944223
[10285.292287] hardirqs last enabled at (4944229): [] __up_console_sem+0x5e/0x70
[10285.292297] hardirqs last disabled at (4944234): [] __up_console_sem+0x43/0x70
[10285.292302] softirqs last enabled at (4943592): [] __irq_exit_rcu+0xfd/0x150
[10285.292308] softirqs last disabled at (4943587): [] __irq_exit_rcu+0xfd/0x150
[10285.292313] ---[ end trace 0000000000000000 ]---
[10285.292325] ------------[ cut here ]------------
[10285.292328] WARNING: CPU: 1 PID: 1339843 at kernel/sched/core.c:8366 __cond_resched_lock+0x6c/0x70
[10285.292334] Modules linked in: dm_thin_pool dm_persistent_data dm_bio_prison dm_log_writes dm_dust dm_flakey nft_fib_inet nft_fib_ipv4 nft_fib_ipv6 nft_fib nft_reject_inet nf_reject_ipv4 nf_reject_ipv6 nft_reject nft_ct nft_chain_nat nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 ip6_tables nft_compat ip_set rfkill nf_tables nfnetlink intel_rapl_msr iTCO_wdt iTCO_vendor_support intel_rapl_common snd_hda_codec_generic i2c_i801 snd_hda_intel snd_intel_dspcfg i2c_smbus joydev snd_hda_codec snd_hwdep snd_hda_core snd_pcm lpc_ich virtio_balloon snd_timer snd soundcore zram ip_tables xfs crct10dif_pclmul crc32_pclmul crc32c_intel ghash_clmulni_intel serio_raw qemu_fw_cfg
[10285.292464] CPU: 1 PID: 1339843 Comm: kworker/u4:1 Tainted: G W 6.0.0-rc1+ #801
[10285.292469] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 1.13.0-2.fc32 04/01/2014
[10285.292472] Workqueue: btrfs-cache btrfs_work_helper
[10285.292478] RIP: 0010:__cond_resched_lock+0x6c/0x70
[10285.292483] Code: 75 02 f3 90 48 89 ef e8 02 7c d1 00 b8 01 00 00 00 5b 5d c3 cc cc cc cc 48 8d 7f 18 be ff ff ff ff e8 b8 52 d0 00 85 c0 75 af <0f> 0b eb ab 0f 1f 44 00 00 8b 05 51 97 e1 01 55 48 89 fd 53 65 8b
[10285.292486] RSP: 0018:ffffa87d454f3ab8 EFLAGS: 00010246
[10285.292492] RAX: 0000000000000000 RBX: 0000000080000001 RCX: 0000000000000001
[10285.292495] RDX: 0000000000000000 RSI: ffffffffb480fceb RDI: ffffffffb48b4a2e
[10285.292498] RBP: ffffa87d454f3bf8 R08: ffffa87d454f3c40 R09: 0000000000000001
[10285.292502] R10: 000000000000bf97 R11: 0000000000000001 R12: ffffa87d454f3c38
[10285.292505] R13: ffff8a3e43b33490 R14: ffffa87d454f3c40 R15: ffff8a3d4d42e930
[10285.292508] FS: 0000000000000000(0000) GS:ffff8a3ebbd00000(0000) knlGS:0000000000000000
[10285.292512] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[10285.292516] CR2: 00005556b170e700 CR3: 00000001029fe004 CR4: 0000000000370ee0
[10285.292522] Call Trace:
[10285.292525]
[10285.292530] __btrfs_remove_free_space_cache+0x43/0xe0
[10285.292541] load_free_space_cache+0xacc/0xaf0
[10285.292633] caching_thread+0x417/0x5c0
[10285.292654] ? lock_release+0x137/0x2d0
[10285.292669] btrfs_work_helper+0xf2/0x3e0
[10285.292673] ? lock_is_held_type+0xe2/0x140
[10285.292687] process_one_work+0x271/0x590
[10285.292705] ? process_one_work+0x590/0x590
[10285.292711] worker_thread+0x52/0x3b0
[10285.292721] ? process_one_work+0x590/0x590
[10285.292727] kthread+0xf0/0x120
[10285.292731] ? kthread_complete_and_exit+0x20/0x20
[10285.292741] ret_from_fork+0x1f/0x30
[10285.292770]
[10285.292772] irq event stamp: 4944799
[10285.292775] hardirqs last enabled at (4944805): [] __up_console_sem+0x5e/0x70
[10285.292781] hardirqs last disabled at (4944810): [] __up_console_sem+0x43/0x70
[10285.292786] softirqs last enabled at (4943592): [] __irq_exit_rcu+0xfd/0x150
[10285.292791] softirqs last disabled at (4943587): [] __irq_exit_rcu+0xfd/0x150
[10285.292796] ---[ end trace 0000000000000000 ]---
[10285.292805] ------------[ cut here ]------------
[10285.292808] WARNING: CPU: 1 PID: 1339843 at kernel/sched/core.c:8366 __cond_resched_lock+0x6c/0x70
[10285.292813] Modules linked in: dm_thin_pool dm_persistent_data dm_bio_prison dm_log_writes dm_dust dm_flakey nft_fib_inet nft_fib_ipv4 nft_fib_ipv6 nft_fib nft_reject_inet nf_reject_ipv4 nf_reject_ipv6 nft_reject nft_ct nft_chain_nat nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 ip6_tables nft_compat ip_set rfkill nf_tables nfnetlink intel_rapl_msr iTCO_wdt iTCO_vendor_support intel_rapl_common snd_hda_codec_generic i2c_i801 snd_hda_intel snd_intel_dspcfg i2c_smbus joydev snd_hda_codec snd_hwdep snd_hda_core snd_pcm lpc_ich virtio_balloon snd_timer snd soundcore zram ip_tables xfs crct10dif_pclmul crc32_pclmul crc32c_intel ghash_clmulni_intel serio_raw qemu_fw_cfg
[10285.292940] CPU: 1 PID: 1339843 Comm: kworker/u4:1 Tainted: G W 6.0.0-rc1+ #801
[10285.292944] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 1.13.0-2.fc32 04/01/2014
[10285.292947] Workqueue: btrfs-cache btrfs_work_helper
[10285.292954] RIP: 0010:__cond_resched_lock+0x6c/0x70
[10285.292958] Code: 75 02 f3 90 48 89 ef e8 02 7c d1 00 b8 01 00 00 00 5b 5d c3 cc cc cc cc 48 8d 7f 18 be ff ff ff ff e8 b8 52 d0 00 85 c0 75 af <0f> 0b eb ab 0f 1f 44 00 00 8b 05 51 97 e1 01 55 48 89 fd 53 65 8b
[10285.292962] RSP: 0018:ffffa87d454f3ab8 EFLAGS: 00010246
[10285.292968] RAX: 0000000000000000 RBX: 0000000080000001 RCX: 0000000000000001
[10285.292971] RDX: 0000000000000000 RSI: ffffffffb480fceb RDI: ffffffffb48b4a2e
[10285.292974] RBP: ffffa87d454f3bf8 R08: ffffa87d454f3c40 R09: 0000000000000001
[10285.292978] R10: 000000000000bf97 R11: 0000000000000001 R12: ffffa87d454f3c38
[10285.292981] R13: ffff8a3e43b33e50 R14: ffffa87d454f3c40 R15: ffff8a3d4d42e930
[10285.292984] FS: 0000000000000000(0000) GS:ffff8a3ebbd00000(0000) knlGS:0000000000000000
[10285.292987] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[10285.292991] CR2: 00005556b170e700 CR3: 00000001029fe004 CR4: 0000000000370ee0
[10285.292996] Call Trace:
[10285.292999]
[10285.293004] __btrfs_remove_free_space_cache+0x43/0xe0
[10285.293014] load_free_space_cache+0xacc/0xaf0
[10285.293105] caching_thread+0x417/0x5c0
[10285.293120] ? lock_release+0x137/0x2d0
[10285.293134] btrfs_work_helper+0xf2/0x3e0
[10285.293138] ? lock_is_held_type+0xe2/0x140
[10285.293152] process_one_work+0x271/0x590
[10285.293170] ? process_one_work+0x590/0x590
[10285.293176] worker_thread+0x52/0x3b0
[10285.293215] ? process_one_work+0x590/0x590
[10285.293222] kthread+0xf0/0x120
[10285.293226] ? kthread_complete_and_exit+0x20/0x20
[10285.293237] ret_from_fork+0x1f/0x30
[10285.293261]
[10285.293263] irq event stamp: 4945389
[10285.293266] hardirqs last enabled at (4945395): [] __up_console_sem+0x5e/0x70
[10285.293272] hardirqs last disabled at (4945400): [] __up_console_sem+0x43/0x70
[10285.293276] softirqs last enabled at (4945358): [] __irq_exit_rcu+0xfd/0x150
[10285.293281] softirqs last disabled at (4945347): [] __irq_exit_rcu+0xfd/0x150
[10285.293286] ---[ end trace 0000000000000000 ]---
[10285.293296] ------------[ cut here ]------------
[10285.293298] WARNING: CPU: 1 PID: 1339843 at kernel/sched/core.c:8366 __cond_resched_lock+0x6c/0x70
[10285.293304] Modules linked in: dm_thin_pool dm_persistent_data dm_bio_prison dm_log_writes dm_dust dm_flakey nft_fib_inet nft_fib_ipv4 nft_fib_ipv6 nft_fib nft_reject_inet nf_reject_ipv4 nf_reject_ipv6 nft_reject nft_ct nft_chain_nat nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 ip6_tables nft_compat ip_set rfkill nf_tables nfnetlink intel_rapl_msr iTCO_wdt iTCO_vendor_support intel_rapl_common snd_hda_codec_generic i2c_i801 snd_hda_intel snd_intel_dspcfg i2c_smbus joydev snd_hda_codec snd_hwdep snd_hda_core snd_pcm lpc_ich virtio_balloon snd_timer snd soundcore zram ip_tables xfs crct10dif_pclmul crc32_pclmul crc32c_intel ghash_clmulni_intel serio_raw qemu_fw_cfg
[10285.293432] CPU: 1 PID: 1339843 Comm: kworker/u4:1 Tainted: G W 6.0.0-rc1+ #801
[10285.293436] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 1.13.0-2.fc32 04/01/2014
[10285.293439] Workqueue: btrfs-cache btrfs_work_helper
[10285.293446] RIP: 0010:__cond_resched_lock+0x6c/0x70
[10285.293450] Code: 75 02 f3 90 48 89 ef e8 02 7c d1 00 b8 01 00 00 00 5b 5d c3 cc cc cc cc 48 8d 7f 18 be ff ff ff ff e8 b8 52 d0 00 85 c0 75 af <0f> 0b eb ab 0f 1f 44 00 00 8b 05 51 97 e1 01 55 48 89 fd 53 65 8b
[10285.293454] RSP: 0018:ffffa87d454f3ab8 EFLAGS: 00010246
[10285.293460] RAX: 0000000000000000 RBX: 0000000000000001 RCX: 0000000000000001
[10285.293463] RDX: 0000000000000000 RSI: ffffffffb480fceb RDI: ffffffffb48b4a2e
[10285.293466] RBP: ffffa87d454f3bf8 R08: ffffa87d454f3c40 R09: 0000000000000001
[10285.293470] R10: 000000000000bf97 R11: 0000000000000001 R12: ffffa87d454f3c38
[10285.293473] R13: ffff8a3e43b335c8 R14: ffffa87d454f3c40 R15: ffff8a3d4d42e930
[10285.293477] FS: 0000000000000000(0000) GS:ffff8a3ebbd00000(0000) knlGS:0000000000000000
[10285.293481] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[10285.293484] CR2: 00005556b170e700 CR3: 00000001029fe004 CR4: 0000000000370ee0
[10285.293490] Call Trace:
[10285.293493]
[10285.293498] __btrfs_remove_free_space_cache+0x43/0xe0
[10285.293508] load_free_space_cache+0xacc/0xaf0
[10285.293599] caching_thread+0x417/0x5c0
[10285.293614] ? lock_release+0x137/0x2d0
[10285.293629] btrfs_work_helper+0xf2/0x3e0
[10285.293633] ? lock_is_held_type+0xe2/0x140
[10285.293652] process_one_work+0x271/0x590
[10285.293670] ? process_one_work+0x590/0x590
[10285.293675] worker_thread+0x52/0x3b0
[10285.293686] ? process_one_work+0x590/0x590
[10285.293691] kthread+0xf0/0x120
[10285.293696] ? kthread_complete_and_exit+0x20/0x20
[10285.293706] ret_from_fork+0x1f/0x30
[10285.293734]
[10285.293737] irq event stamp: 4945965
[10285.293739] hardirqs last enabled at (4945971): [] __up_console_sem+0x5e/0x70
[10285.293745] hardirqs last disabled at (4945976): [] __up_console_sem+0x43/0x70
[10285.293749] softirqs last enabled at (4945358): [] __irq_exit_rcu+0xfd/0x150
[10285.293754] softirqs last disabled at (4945347): [] __irq_exit_rcu+0xfd/0x150
[10285.293759] ---[ end trace 0000000000000000 ]---
[10285.293908] =====================================
[10285.294175] WARNING: bad unlock balance detected!
[10285.294447] 6.0.0-rc1+ #801 Tainted: G W
[10285.294750] -------------------------------------
[10285.295020] kworker/u4:1/1339843 is trying to release lock (&ctl->tree_lock) at:
[10285.295432] [] __cond_resched_lock+0x3b/0x70
[10285.295837] but there are no more locks to release!
[10285.296114]
other info that might help us debug this:
[10285.296476] 5 locks held by kworker/u4:1/1339843:
[10285.296751] #0: ffff8a3e428f5d38 ((wq_completion)btrfs-cache){+.+.}-{0:0}, at: process_one_work+0x1f4/0x590
[10285.297300] #1: ffffa87d454f3e80 ((work_completion)(&work->normal_work)){+.+.}-{0:0}, at: process_one_work+0x1f4/0x590
[10285.297898] #2: ffff8a3e54bf5878 (&caching_ctl->mutex){+.+.}-{3:3}, at: caching_thread+0x46/0x5c0
[10285.298398] #3: ffff8a3ea6668ac8 (&fs_info->commit_root_sem){++++}-{3:3}, at: caching_thread+0x5b/0x5c0
[10285.298929] #4: ffff8a3e43181218 (&ctl->tree_lock){+.+.}-{2:2}, at: load_free_space_cache+0xabf/0xaf0
[10285.299443]
stack backtrace:
[10285.299697] CPU: 1 PID: 1339843 Comm: kworker/u4:1 Tainted: G W 6.0.0-rc1+ #801
[10285.300178] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 1.13.0-2.fc32 04/01/2014
[10285.300653] Workqueue: btrfs-cache btrfs_work_helper
[10285.300937] Call Trace:
[10285.301086]
[10285.301217] dump_stack_lvl+0x56/0x73
[10285.301433] lock_release.cold+0x45/0x4a
[10285.301669] _raw_spin_unlock+0x17/0x50
[10285.301893] __cond_resched_lock+0x3b/0x70
[10285.302129] __btrfs_remove_free_space_cache+0x43/0xe0
[10285.302425] load_free_space_cache+0xacc/0xaf0
[10285.302694] caching_thread+0x417/0x5c0
[10285.302860] ? lock_release+0x137/0x2d0
[10285.303023] btrfs_work_helper+0xf2/0x3e0
[10285.303190] ? lock_is_held_type+0xe2/0x140
[10285.303362] process_one_work+0x271/0x590
[10285.303534] ? process_one_work+0x590/0x590
[10285.303710] worker_thread+0x52/0x3b0
[10285.303865] ? process_one_work+0x590/0x590
[10285.304039] kthread+0xf0/0x120
[10285.304173] ? kthread_complete_and_exit+0x20/0x20
[10285.304372] ret_from_fork+0x1f/0x30
[10285.304526]
[10285.304732] BTRFS warning (device dm-9): block group 30408704 has wrong amount of free space
[10285.305075] BTRFS warning (device dm-9): failed to load free space cache for block group 30408704, rebuilding it now
[10285.322979] BTRFS warning (device dm-9): block group 1372585984 has wrong amount of free space
[10285.323359] BTRFS warning (device dm-9): failed to load free space cache for block group 1372585984, rebuilding it now