watchdog: BUG: soft lockup - CPU#2 stuck for 45s! [kworker/2:1:3036

[b-r-o-w-n]

[ 2488.235847] watchdog: BUG: soft lockup - CPU#2 stuck for 45s! [kworker/2:1:3036] [ 2488.243461] Kernel panic - not syncing: softlockup: hung tasks [ 2488.249350] CPU: 2 PID: 3036 Comm: kworker/2:1 Tainted: G L 5.15.0-g01b9c0b2147b+ #19 [ 2488.258568] Hardware name: System manufacturer System Product Name/P9X79 LE, BIOS 4801 07/24/2014 [ 2488.267520] Workqueue: events_long bch2_subvolume_wait_for_pagecache_and_delete [ 2488.274936] Call Trace: [ 2488.277456] <IRQ> [ 2488.279533] dump_stack_lvl+0x34/0x44 [ 2488.283272] panic+0xe8/0x2ae [ 2488.286306] ? ret_from_fork+0x2d/0x30 [ 2488.290120] watchdog_timer_fn.cold+0xc/0x16 [ 2488.294479] ? lockup_detector_update_enable+0x50/0x50 [ 2488.299716] __hrtimer_run_queues+0x125/0x270 [ 2488.304135] hrtimer_interrupt+0xf7/0x210 [ 2488.308226] __sysvec_apic_timer_interrupt+0x57/0xd0 [ 2488.313280] sysvec_apic_timer_interrupt+0x65/0x90 [ 2488.318185] </IRQ> [ 2488.320347] asm_sysvec_apic_timer_interrupt+0x12/0x20 [ 2488.325576] RIP: 0010:queued_spin_lock_slowpath+0x3b/0x190 [ 2488.331149] Code: 5a f0 0f ba 2a 08 0f 92 c1 8b 02 0f b6 c9 c1 e1 08 30 e4 09 c8 a9 00 01 ff ff 0f 85 ed 00 00 00 85 c0 74 0e 8b 02 84 c0 74 08 90 8b 02 84 c0 75 f8 b8 01 00 00 00 66 89 02 c3 8b 37 b8 00 02 [ 2488.350082] RSP: 0018:ffff9f034fa1bc30 EFLAGS: 00000202 [ 2488.355390] RAX: 0000000000000101 RBX: ffff8e0d9387f700 RCX: 0000000000000000 [ 2488.362613] RDX: ffff8e0dde384d00 RSI: 0000000000000000 RDI: ffff8e0dde384d00 [ 2488.369840] RBP: ffff8e0d9387f5f0 R08: ffff8e0d80054ab0 R09: ffff8e0d81cf4afc [ 2488.377085] R10: 0000000000000018 R11: 0000000000000018 R12: ffffffffafc75000 [ 2488.384341] R13: ffff8e0e310e3e40 R14: ffff9f034fa1bd30 R15: ffff8e0dde384d08 [ 2488.391580] evict+0x6e/0x160 [ 2488.394604] __dentry_kill+0xcc/0x160 [ 2488.398348] d_prune_aliases+0x80/0xb0 [ 2488.402179] bch2_evict_subvolume_inodes+0x96/0x260 [ 2488.407123] ? __closure_wake_up+0x15/0x250 [ 2488.411384] ? btree_node_write_work+0x18e/0x300 [ 2488.416076] bch2_subvolume_wait_for_pagecache_and_delete+0x84/0x1c0 [ 2488.422543] ? btree_node_write_work+0x1a5/0x300 [ 2488.427220] ? newidle_balance.constprop.0+0xf7/0x370 [ 2488.432360] ? update_load_avg+0x59/0x4f0 [ 2488.436440] ? __switch_to+0x132/0x430 [ 2488.440263] process_one_work+0x1d4/0x370 [ 2488.444344] worker_thread+0x48/0x3d0 [ 2488.448061] ? rescuer_thread+0x380/0x380 [ 2488.452134] kthread+0x122/0x140 [ 2488.455428] ? set_kthread_struct+0x40/0x40 [ 2488.459677] ret_from_fork+0x22/0x30 [ 2488.463347] Kernel Offset: 0x2de00000 from 0xffffffff81000000 (relocation range: 0xffffffff80000000-0xffffffffbfffffff) [ 2488.474252] ---[ end Kernel panic - not syncing: softlockup: hung tasks ]---

kernel: 5.15.0-g01b9c0b2147b+ tools: v0.1-478-gbf7924f+

I was doing this before panic

/usr/src/bcachefs-tools/bcachefs subvolume delete /mnt/bcachefs/t/test /mnt/bcachefs/t/.snap/*

[b-r-o-w-n]

More info. I'm doing this:

copy in some files: copy file: time rsync -a -c /mnt/data_disk/linux-5.15.1/ /mnt/bcachefs/t/test/linux --delete --stats

While this is in progress take lots of snapshpts for count in {1..100} do time /usr/src/bcachefs-tools/bcachefs subvolume snapshot -r /mnt/bcachefs/t/test /mnt/bcachefs/t/.snap/$count sleep 1 done

I got 81 snapshots..... No faults.

Then delete the snapshots /usr/src/bcachefs-tools/bcachefs subvolume delete /mnt/bcachefs/t/test /mnt/bcachefs/t/.snap/*

and we get....

[ 1289.988507] rcu: INFO: rcu_sched self-detected stall on CPU [ 1289.988516] rcu: 7-....: (20999 ticks this GP) idle=05f/1/0x4000000000000000 softirq=13388/13388 fqs=5249 [ 1289.988526] (t=21000 jiffies g=45397 q=217) [ 1289.988530] NMI backtrace for cpu 7 [ 1289.988532] CPU: 7 PID: 103 Comm: kworker/7:1 Not tainted 5.15.0-g01b9c0b2147b+ #19 [ 1289.988537] Hardware name: System manufacturer System Product Name/P9X79 LE, BIOS 4801 07/24/2014 [ 1289.988540] Workqueue: events_long bch2_subvolume_wait_for_pagecache_and_delete [ 1289.988552] Call Trace: [ 1289.988557] <IRQ> [ 1289.988560] dump_stack_lvl+0x34/0x44 [ 1289.988567] nmi_cpu_backtrace.cold+0x30/0x70 [ 1289.988571] ? lapic_can_unplug_cpu+0x70/0x70 [ 1289.988579] nmi_trigger_cpumask_backtrace+0x80/0x90 [ 1289.988586] rcu_dump_cpu_stacks+0xb1/0xdf [ 1289.988593] rcu_sched_clock_irq.cold+0xe8/0x220 [ 1289.988598] ? timekeeping_advance+0x373/0x550 [ 1289.988607] update_process_times+0x87/0xc0 [ 1289.988612] tick_sched_handle+0x1d/0x50 [ 1289.988620] tick_sched_timer+0x75/0xa0 [ 1289.988626] ? can_stop_idle_tick+0x90/0x90 [ 1289.988633] __hrtimer_run_queues+0x125/0x270 [ 1289.988639] hrtimer_interrupt+0xf7/0x210 [ 1289.988644] __sysvec_apic_timer_interrupt+0x57/0xd0 [ 1289.988650] sysvec_apic_timer_interrupt+0x65/0x90 [ 1289.988658] </IRQ> [ 1289.988660] asm_sysvec_apic_timer_interrupt+0x12/0x20 [ 1289.988668] RIP: 0010:queued_spin_lock_slowpath+0x3b/0x190 [ 1289.988678] Code: 5a f0 0f ba 2a 08 0f 92 c1 8b 02 0f b6 c9 c1 e1 08 30 e4 09 c8 a9 00 01 ff ff 0f 85 ed 00 00 00 85 c0 74 0e 8b 02 84 c0 74 08 90 8b 02 84 c0 75 f8 b8 01 00 00 00 66 89 02 c3 8b 37 b8 00 02 [ 1289.988682] RSP: 0018:ffffa9a8844f3c30 EFLAGS: 00000202 [ 1289.988686] RAX: 0000000000000101 RBX: ffff9a180e68d450 RCX: 0000000000000000 [ 1289.988689] RDX: ffff9a174839ad00 RSI: 0000000000000000 RDI: ffff9a174839ad00 [ 1289.988691] RBP: ffff9a180e68d340 R08: ffff9a1740054ab0 R09: ffff9a1740da707c [ 1289.988694] R10: 0000000000000018 R11: 0000000000000018 R12: ffffffffa4675000 [ 1289.988696] R13: ffff9a182021af00 R14: ffffa9a8844f3d30 R15: ffff9a174839ad08 [ 1289.988700] evict+0x6e/0x160 [ 1289.988707] __dentry_kill+0xcc/0x160 [ 1289.988712] d_prune_aliases+0x80/0xb0 [ 1289.988716] bch2_evict_subvolume_inodes+0x96/0x260 [ 1289.988722] ? load_balance+0x173/0xb40 [ 1289.988730] bch2_subvolume_wait_for_pagecache_and_delete+0x84/0x1c0 [ 1289.988737] ? __cond_resched+0x11/0x40 [ 1289.988741] ? refresh_cpu_vm_stats+0x200/0x240 [ 1289.988749] ? update_load_avg+0x59/0x4f0 [ 1289.988754] ? set_next_entity+0x97/0x160 [ 1289.988760] ? __switch_to+0x132/0x430 [ 1289.988767] process_one_work+0x1d4/0x370 [ 1289.988774] worker_thread+0x48/0x3d0 [ 1289.988780] ? rescuer_thread+0x380/0x380 [ 1289.988785] kthread+0x122/0x140 [ 1289.988790] ? set_kthread_struct+0x40/0x40 [ 1289.988795] ret_from_fork+0x22/0x30 test1 ~ # [ 1316.240506] watchdog: BUG: soft lockup - CPU#7 stuck for 44s! [kworker/7:1:103] [ 1316.248059] Kernel panic - not syncing: softlockup: hung tasks [ 1316.253952] CPU: 7 PID: 103 Comm: kworker/7:1 Tainted: G L 5.15.0-g01b9c0b2147b+ #19 [ 1316.263066] Hardware name: System manufacturer System Product Name/P9X79 LE, BIOS 4801 07/24/2014 [ 1316.272009] Workqueue: events_long bch2_subvolume_wait_for_pagecache_and_delete [ 1316.279416] Call Trace: [ 1316.281929] <IRQ> [ 1316.284006] dump_stack_lvl+0x34/0x44 [ 1316.287726] panic+0xe8/0x2ae [ 1316.290769] ? ret_from_fork+0x2d/0x30 [ 1316.294582] watchdog_timer_fn.cold+0xc/0x16 [ 1316.298918] ? lockup_detector_update_enable+0x50/0x50 [ 1316.304134] __hrtimer_run_queues+0x125/0x270 [ 1316.308563] hrtimer_interrupt+0xf7/0x210 [ 1316.312645] __sysvec_apic_timer_interrupt+0x57/0xd0 [ 1316.317706] sysvec_apic_timer_interrupt+0x65/0x90 [ 1316.322568] </IRQ> [ 1316.324739] asm_sysvec_apic_timer_interrupt+0x12/0x20 [ 1316.329963] RIP: 0010:queued_spin_lock_slowpath+0x3f/0x190 [ 1316.335526] Code: 2a 08 0f 92 c1 8b 02 0f b6 c9 c1 e1 08 30 e4 09 c8 a9 00 01 ff ff 0f 85 ed 00 00 00 85 c0 74 0e 8b 02 84 c0 74 08 f3 90 8b 02 <84> c0 75 f8 b8 01 00 00 00 66 89 02 c3 8b 37 b8 00 02 00 00 81 fe [ 1316.354451] RSP: 0018:ffffa9a8844f3c30 EFLAGS: 00000202 [ 1316.359748] RAX: 0000000000000101 RBX: ffff9a180e68d450 RCX: 0000000000000000 [ 1316.366978] RDX: ffff9a174839ad00 RSI: 0000000000000000 RDI: ffff9a174839ad00 [ 1316.374173] RBP: ffff9a180e68d340 R08: ffff9a1740054ab0 R09: ffff9a1740da707c [ 1316.381384] R10: 0000000000000018 R11: 0000000000000018 R12: ffffffffa4675000 [ 1316.388604] R13: ffff9a182021af00 R14: ffffa9a8844f3d30 R15: ffff9a174839ad08 [ 1316.395825] evict+0x6e/0x160 [ 1316.398857] __dentry_kill+0xcc/0x160 [ 1316.402596] d_prune_aliases+0x80/0xb0 [ 1316.406408] bch2_evict_subvolume_inodes+0x96/0x260 [ 1316.411359] ? load_balance+0x173/0xb40 [ 1316.415285] bch2_subvolume_wait_for_pagecache_and_delete+0x84/0x1c0 [ 1316.421702] ? __cond_resched+0x11/0x40 [ 1316.425597] ? refresh_cpu_vm_stats+0x200/0x240 [ 1316.430208] ? update_load_avg+0x59/0x4f0 [ 1316.434272] ? set_next_entity+0x97/0x160 [ 1316.438372] ? __switch_to+0x132/0x430 [ 1316.442209] process_one_work+0x1d4/0x370 [ 1316.446292] worker_thread+0x48/0x3d0 [ 1316.450011] ? rescuer_thread+0x380/0x380 [ 1316.454075] kthread+0x122/0x140 [ 1316.457377] ? set_kthread_struct+0x40/0x40 [ 1316.461634] ret_from_fork+0x22/0x30 [ 1316.465313] Kernel Offset: 0x22800000 from 0xffffffff81000000 (relocation range: 0xffffffff80000000-0xffffffffbfffffff) [ 1316.476201] ---[ end Kernel panic - not syncing: softlockup: hung tasks ]---

[b-r-o-w-n]

One big comment.... I just reviewed the kernel configurations settings as detailed in the new testing doc (bug_report.md

I have been testing with : Voluntary Kernel Preemption (Desktop)" instead of Preemptible Kernel (Low-Latency Desktop)

This means that CONFIG_PREEMPT was not set in the past. This may account some of the issues I had.

[YellowOnion]

PREEMPT should help with debugging a soft-lock, since you can still run userspace apps to inspect the kernel stack etc.

It shouldn't fix any issues though, as most people will be using voluntary once this is upstreamed.

[b-r-o-w-n]

Still present on: 5.16.0-g020a223efab9+ bcachefs tool version v0.1-495-g59abea5+

[Wed Mar 30 15:21:35 2022] rcu: INFO: rcu_preempt self-detected stall on CPU [Wed Mar 30 15:21:35 2022] rcu: 1-....: (20999 ticks this GP) idle=33b/1/0x4000000000000000 softirq=26583/26583 fqs=5249 [Wed Mar 30 15:21:35 2022] (t=21000 jiffies g=170081 q=171) [Wed Mar 30 15:21:35 2022] NMI backtrace for cpu 1 [Wed Mar 30 15:21:35 2022] CPU: 1 PID: 86 Comm: kworker/1:1 Not tainted 5.16.0-g020a223efab9+ #28 [Wed Mar 30 15:21:35 2022] Hardware name: System manufacturer System Product Name/P9X79 LE, BIOS 4801 07/24/2014 [Wed Mar 30 15:21:35 2022] Workqueue: events_long bch2_subvolume_wait_for_pagecache_and_delete [Wed Mar 30 15:21:35 2022] Call Trace: [Wed Mar 30 15:21:35 2022] <IRQ> [Wed Mar 30 15:21:35 2022] dump_stack_lvl+0x34/0x44 [Wed Mar 30 15:21:35 2022] nmi_cpu_backtrace.cold+0x30/0x70 [Wed Mar 30 15:21:35 2022] ? lapic_can_unplug_cpu+0x80/0x80 [Wed Mar 30 15:21:35 2022] nmi_trigger_cpumask_backtrace+0xcb/0xe0 [Wed Mar 30 15:21:35 2022] rcu_dump_cpu_stacks+0xc8/0xf0 [Wed Mar 30 15:21:35 2022] rcu_sched_clock_irq.cold+0x60/0x2f2 [Wed Mar 30 15:21:35 2022] ? update_load_avg+0x5f/0x550 [Wed Mar 30 15:21:35 2022] ? timekeeping_update+0xab/0x280 [Wed Mar 30 15:21:35 2022] ? _raw_spin_unlock_irqrestore+0x16/0x30 [Wed Mar 30 15:21:35 2022] update_process_times+0x8e/0xc0 [Wed Mar 30 15:21:35 2022] tick_sched_handle+0x1d/0x50 [Wed Mar 30 15:21:35 2022] tick_sched_timer+0x7f/0xa0 [Wed Mar 30 15:21:35 2022] ? can_stop_idle_tick+0xd0/0xd0 [Wed Mar 30 15:21:35 2022] __hrtimer_run_queues+0x125/0x2c0 [Wed Mar 30 15:21:35 2022] hrtimer_interrupt+0x101/0x210 [Wed Mar 30 15:21:35 2022] __sysvec_apic_timer_interrupt+0x7a/0x160 [Wed Mar 30 15:21:35 2022] sysvec_apic_timer_interrupt+0x89/0xc0 [Wed Mar 30 15:21:35 2022] </IRQ> [Wed Mar 30 15:21:35 2022] <TASK> [Wed Mar 30 15:21:35 2022] asm_sysvec_apic_timer_interrupt+0x12/0x20 [Wed Mar 30 15:21:35 2022] RIP: 0010:queued_spin_lock_slowpath+0x43/0x1d0 [Wed Mar 30 15:21:35 2022] Code: 2b 08 0f 92 c2 8b 03 0f b6 d2 c1 e2 08 30 e4 09 d0 a9 00 01 ff ff 0f 85 fc 00 00 00 85 c0 74 0e 8b 03 84 c0 74 08 f3 90 8b 03 <84> c0 75 f8 b8 01 00 00 00 66 89 03 5b 5d 41 5c c3 8b 37 b8 00 02 [Wed Mar 30 15:21:35 2022] RSP: 0018:ffffa1ae8446bc00 EFLAGS: 00000202 [Wed Mar 30 15:21:35 2022] RAX: 0000000000000101 RBX: ffff99a240a5b500 RCX: 0000000000000000 [Wed Mar 30 15:21:35 2022] RDX: 0000000000000000 RSI: 0000000000000000 RDI: ffff99a240a5b500 [Wed Mar 30 15:21:35 2022] RBP: ffff99a27b18f278 R08: ffff99a240054ab0 R09: ffff99a240a2d13c [Wed Mar 30 15:21:35 2022] R10: 0000000000000018 R11: 0000000000000018 R12: ffffffff81e7d280 [Wed Mar 30 15:21:35 2022] R13: ffff99a27b18f300 R14: ffff99a27bb95540 R15: ffff99a27bb95598 [Wed Mar 30 15:21:35 2022] evict+0x6e/0x160 [Wed Mar 30 15:21:35 2022] __dentry_kill+0xd1/0x170 [Wed Mar 30 15:21:35 2022] d_prune_aliases+0x46/0x110 [Wed Mar 30 15:21:35 2022] bch2_evict_subvolume_inodes+0x97/0x270 [Wed Mar 30 15:21:35 2022] ? load_balance+0x177/0xbb0 [Wed Mar 30 15:21:35 2022] bch2_subvolume_wait_for_pagecache_and_delete+0x84/0x1c0 [Wed Mar 30 15:21:35 2022] ? refresh_cpu_vm_stats+0x249/0x290 [Wed Mar 30 15:21:35 2022] ? update_load_avg+0x5f/0x550 [Wed Mar 30 15:21:35 2022] ? update_load_avg+0x5f/0x550 [Wed Mar 30 15:21:35 2022] ? cpuacct_charge+0x56/0x90 [Wed Mar 30 15:21:35 2022] ? xfd_validate_state+0x19/0x70 [Wed Mar 30 15:21:35 2022] ? _raw_spin_unlock+0xd/0x20 [Wed Mar 30 15:21:35 2022] ? finish_task_switch.isra.0+0xb2/0x260 [Wed Mar 30 15:21:35 2022] process_one_work+0x1d6/0x3a0 [Wed Mar 30 15:21:35 2022] worker_thread+0x48/0x3d0 [Wed Mar 30 15:21:35 2022] ? rescuer_thread+0x390/0x390 [Wed Mar 30 15:21:35 2022] kthread+0x166/0x190 [Wed Mar 30 15:21:35 2022] ? set_kthread_struct+0x40/0x40 [Wed Mar 30 15:21:35 2022] ret_from_fork+0x22/0x30 [Wed Mar 30 15:21:35 2022] </TASK> test1 ~ # [ 1716.210112] watchdog: BUG: soft lockup - CPU#1 stuck for 45s! [kworker/1:1:86] [ 1716.217517] Kernel panic - not syncing: softlockup: hung tasks [ 1716.223388] CPU: 1 PID: 86 Comm: kworker/1:1 Tainted: G L 5.16.0-g020a223efab9+ #28 [ 1716.232388] Hardware name: System manufacturer System Product Name/P9X79 LE, BIOS 4801 07/24/2014 [ 1716.241297] Workqueue: events_long bch2_subvolume_wait_for_pagecache_and_delete [ 1716.248668] Call Trace: [ 1716.251165] <IRQ> [ 1716.253235] dump_stack_lvl+0x34/0x44 [ 1716.256954] panic+0xef/0x2b5 [ 1716.259980] watchdog_timer_fn.cold+0xc/0x16 [ 1716.264305] ? softlockup_fn+0x60/0x60 [ 1716.268107] __hrtimer_run_queues+0x125/0x2c0 [ 1716.272520] hrtimer_interrupt+0x101/0x210 [ 1716.276672] __sysvec_apic_timer_interrupt+0x7a/0x160 [ 1716.281793] sysvec_apic_timer_interrupt+0x89/0xc0 [ 1716.286650] </IRQ> [ 1716.288802] <TASK> [ 1716.290952] asm_sysvec_apic_timer_interrupt+0x12/0x20 [ 1716.296146] RIP: 0010:queued_spin_lock_slowpath+0x41/0x1d0 [ 1716.301686] Code: 0f ba 2b 08 0f 92 c2 8b 03 0f b6 d2 c1 e2 08 30 e4 09 d0 a9 00 01 ff ff 0f 85 fc 00 00 00 85 c0 74 0e 8b 03 84 c0 74 08 f3 90 <8b> 03 84 c0 75 f8 b8 01 00 00 00 66 89 03 5b 5d 41 5c c3 8b 37 b8 [ 1716.320528] RSP: 0018:ffffa1ae8446bc00 EFLAGS: 00000202 [ 1716.325813] RAX: 0000000000000101 RBX: ffff99a240a5b500 RCX: 0000000000000000 [ 1716.333002] RDX: 0000000000000000 RSI: 0000000000000000 RDI: ffff99a240a5b500 [ 1716.340186] RBP: ffff99a27b18f278 R08: ffff99a240054ab0 R09: ffff99a240a2d13c [ 1716.347370] R10: 0000000000000018 R11: 0000000000000018 R12: ffffffff81e7d280 [ 1716.354555] R13: ffff99a27b18f300 R14: ffff99a27bb95540 R15: ffff99a27bb95598 [ 1716.361743] evict+0x6e/0x160 [ 1716.364768] __dentry_kill+0xd1/0x170 [ 1716.368488] d_prune_aliases+0x46/0x110 [ 1716.372379] bch2_evict_subvolume_inodes+0x97/0x270 [ 1716.377311] ? load_balance+0x177/0xbb0 [ 1716.381201] bch2_subvolume_wait_for_pagecache_and_delete+0x84/0x1c0 [ 1716.387610] ? refresh_cpu_vm_stats+0x249/0x290 [ 1716.392200] ? update_load_avg+0x5f/0x550 [ 1716.396264] ? update_load_avg+0x5f/0x550 [ 1716.400328] ? cpuacct_charge+0x56/0x90 [ 1716.404220] ? xfd_validate_state+0x19/0x70 [ 1716.408459] ? _raw_spin_unlock+0xd/0x20 [ 1716.412435] ? finish_task_switch.isra.0+0xb2/0x260 [ 1716.417378] process_one_work+0x1d6/0x3a0 [ 1716.421441] worker_thread+0x48/0x3d0 [ 1716.425157] ? rescuer_thread+0x390/0x390 [ 1716.429222] kthread+0x166/0x190 [ 1716.432514] ? set_kthread_struct+0x40/0x40 [ 1716.436754] ret_from_fork+0x22/0x30 [ 1716.440394] </TASK> [ 1716.442644] Kernel Offset: 0x0 from 0xffffffff81000000 (relocation range: 0xffffffff80000000-0xffffffffbfffffff) [ 1716.452881] ---[ end Kernel panic - not syncing: softlockup: hung tasks ]---

[koverstreet]

Yeah this is a known bug - I'm not going to be able to get to snapshots-related bugs for the next month or so, focusing on getting backpointers done right now