buddy softlockup detector: was: Re: BUG: soft lockup in kernel_init

[Petr Mladek]

Adding Douglas into Cc.

On Mon 2026-06-29 14:47:09, Petr Mladek wrote:
> On Fri 2026-06-26 14:26:40, sanan.hasanou@xxxxxxxxx wrote:
> > Good day, dear maintainers,
> > 
> > We found a bug using a modified version of syzkaller.
> > 
> > Kernel Branch: 7.0-rc1
> > Kernel Config: <https://drive.google.com/open?id=1mAp3gxor4yGtL0ZArdrc1E7ufSn4T841>
> > Unfortunately, we don't have any reproducer for this bug yet.
> > Thank you!
> > 
> > Best regards,
> > Sanan Hasanov
> > 
> > watchdog: BUG: soft lockup - CPU#0 stuck for 142s! [swapper/0:1]
> > Modules linked in:
> > irq event stamp: 1640392
> > hardirqs last  enabled at (1640391): [<ffffffff819f6073>] console_trylock_spinning kernel/printk/printk.c:2032 [inline]
> > hardirqs last  enabled at (1640391): [<ffffffff819f6073>] vprintk_emit+0x3b3/0x550 kernel/printk/printk.c:2478
> > hardirqs last disabled at (1640392): [<ffffffff8b54d19e>] sysvec_apic_timer_interrupt+0xe/0xb0 arch/x86/kernel/apic/apic.c:1056
> > softirqs last  enabled at (1640360): [<ffffffff81842680>] __do_softirq kernel/softirq.c:656 [inline]
> > softirqs last  enabled at (1640360): [<ffffffff81842680>] invoke_softirq kernel/softirq.c:496 [inline]
> > softirqs last  enabled at (1640360): [<ffffffff81842680>] __irq_exit_rcu+0x60/0x150 kernel/softirq.c:723
> > softirqs last disabled at (1640327): [<ffffffff81842680>] __do_softirq kernel/softirq.c:656 [inline]
> > softirqs last disabled at (1640327): [<ffffffff81842680>] invoke_softirq kernel/softirq.c:496 [inline]
> > softirqs last disabled at (1640327): [<ffffffff81842680>] __irq_exit_rcu+0x60/0x150 kernel/softirq.c:723
> > CPU: 0 UID: 0 PID: 1 Comm: swapper/0 Not tainted 7.0.0-rc1 #1 PREEMPT(full) 
> > Hardware name: QEMU Ubuntu 24.04 PC v2 (i440FX + PIIX, arch_caps fix, 1996), BIOS 1.16.3-debian-1.16.3-2 04/01/2014
> > RIP: 0010:console_trylock_spinning kernel/printk/printk.c:2039 [inline]
> 
> This code is from kernel/printk/printk.c (7.0-rc1):
> 
> 1080	static int console_trylock_spinning(void)
> 1081	{
> [...]
> 2025		/* We spin waiting for the owner to release us */
> 2026		spin_acquire(&console_owner_dep_map, 0, 0, _THIS_IP_);
> 2027		/* Owner will clear console_waiter on hand off */
> 2028		while (READ_ONCE(console_waiter))
> 2029			cpu_relax();
> 2030		spin_release(&console_owner_dep_map, _THIS_IP_);
> 2031
> 2032		printk_safe_exit_irqrestore(flags);
> 2033		/*
> 2034		 * The owner passed the console lock to us.
> 2035		 * Since we did not spin on console lock, annotate
> 2036		 * this as a trylock. Otherwise lockdep will
> 2037		 * complain.
> 2038		 */
> 2039		mutex_acquire(&console_lock_dep_map, 0, 1, _THIS_IP_);
> 
> The softlockup has been reported right after console_trylock_spinning()
> has got the ownership and enabled interrupts again. It allowed to
> process timers, including the watchdog_timer_fn().
> 
> It means that console_trylock_spinning() has been called in
> task context, the interrupts were disabled inside this
> function and it has been busy waiting for a long time
> (~140s).
> 
> The shows that the caller has been blocked.
> Unfortunately, the log does not show who blocked it.

It is pity that the softlockup could be reported only after
the given CPU gets unstuck. It might be very helpful when
the lockup might get detected and reported by another CPU
which is not blocked at the moment, using a similar
trick like the buddy hardlockup detector.

Then we would be able to trigger backtraces from all
CPUs earlier and catch the task blocking the progress.

Douglas, have you ever thought about this, please?

Best Regards,
Petr

> Some hint might give a full log with with timestamps.
> Could you please provide it, please?
> 
> > RIP: 0010:vprintk_emit+0x453/0x550 kernel/printk/printk.c:2478
> > Code: 0f 84 44 ff ff ff e8 5c d7 1f 00 fb eb 44 e8 54 d7 1f 00 e8 af 78 b5 09 4d 85 f6 74 94 e8 45 d7 1f 00 fb 48 c7 c7 20 e0 d4 8d <31> f6 ba 01 00 00 00 31 c9 41 b8 01 00 00 00 45 31 c9 53 e8 a5 35
> > RSP: 0018:ffffc9000012f220 EFLAGS: 00000293
> > RAX: ffffffff819f610b RBX: ffffffff819f5f85 RCX: ffff88801a6f5700
> > RDX: 0000000000000000 RSI: 0000000000000000 RDI: ffffffff8dd4e020
> > RBP: ffffc9000012f2d0 R08: ffffffff8f722db7 R09: 1ffffffff1ee45b6
> > R10: dffffc0000000000 R11: fffffbfff1ee45b7 R12: 0000000000000045
> > R13: 0000000000000000 R14: 0000000000000200 R15: 0000000000000000
> > FS:  0000000000000000(0000) GS:ffff88809ab94000(0000) knlGS:0000000000000000
> > CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> > CR2: ffff8880186b4000 CR3: 000000000db4a000 CR4: 00000000000006f0
> > Call Trace:
> >  <TASK>
> >  dev_vprintk_emit+0x337/0x3f0 drivers/base/core.c:4913
> >  dev_printk_emit+0xe0/0x120 drivers/base/core.c:4924
> >  _dev_info+0x10a/0x150 drivers/base/core.c:4982
> >  cmos_do_probe+0xca4/0x1020 drivers/rtc/rtc-cmos.c:1121
> >  pnp_device_probe+0x305/0x4b0 drivers/pnp/driver.c:111
> >  call_driver_probe drivers/base/dd.c:-1 [inline]
> >  really_probe+0x258/0xae0 drivers/base/dd.c:661
> >  __driver_probe_device+0x18c/0x320 drivers/base/dd.c:803
> >  driver_probe_device+0x4f/0x230 drivers/base/dd.c:833
> >  __driver_attach+0x3e1/0x710 drivers/base/dd.c:1227
> >  bus_for_each_dev+0x22c/0x2a0 drivers/base/bus.c:383
> >  bus_add_driver+0x340/0x670 drivers/base/bus.c:715
> >  driver_register+0x23a/0x310 drivers/base/driver.c:249
> >  cmos_init+0x11/0x80 drivers/rtc/rtc-cmos.c:1546
> >  do_one_initcall+0x1eb/0x870 init/main.c:1382
> >  do_initcall_level+0x104/0x190 init/main.c:1444
> >  do_initcalls+0x59/0xa0 init/main.c:1460
> >  kernel_init_freeable+0x2a0/0x3e0 init/main.c:1692
> >  kernel_init+0x1d/0x1c0 init/main.c:1582
> >  ret_from_fork+0x507/0xb90 arch/x86/kernel/process.c:158
> >  ret_from_fork_asm+0x11/0x20 arch/x86/entry/entry_64.S:245
> >  </TASK>
> > 
> > <<<<<<<<<<<<<<< tail report >>>>>>>>>>>>>>>