Deadlock?: console_waiter/serial8250_ports/low_water_lock with 6.12-rc

Deadlock?: console_waiter/serial8250_ports/low_water_lock with 6.12-rc

[John Stultz]

In stress testing my own patches over the weekend, I ran across a hang
that looks unrelated to my changes, so I wanted to raise it with folks
to see if they have seen anything.

I basically left a shell script looping rebooting a qemu system (which
uses a number of in-kernel torture/selftest drivers) over and over,
and on boot the hang happened right as init was starting. On the
serial console I saw:

[   69.661820] Freeing unused kernel image (initmem) memory: 3788K
[   69.669203] Write protecting the kernel read-only data: 28672k
[   69.680557] Freeing unused kernel image (rodata/data gap) memory: 1436K
[   69.758577] x86/mm: Checked W+X mappings: passed, no W+X pages found.
[   69.763876] x86/mm: Checking user space page tables
[   69.826932] x86/mm: Checked W+X mappings: passed, no W+X pages found.
[   69.832656] Run /init as init process
[   69.841940] mkdir (833) used greatest stack depth: 14272 bytes left
[   69.847347] mkdir (834) used greatest stack depth: 13856 bytes left
[   69.852756] mount (837) used greatest stack depth: 12960 bytes left

Attaching gdb to qemu, I see:
* Most of the non-idle/halted cpus are stuck in:
virt_spin_lock (lock=lock@entry=0xffffffff82c6d3a0 <low_water_lock>)
at ./arch/x86/include/asm/qspinlock.h:106. The backtrace shows they
are being call from  check_stack_usage () at kernel/exit.c:849  from
do_exit (code=code@entry=0) at kernel/exit.c:982

* One thread is in virt_spin_lock (lock=lock@entry=0xffffffff843d19a0
<serial8250_ports>) at ./arch/x86/include/asm/qspinlock.h:106.  The
backtrace there, is similarly going through
do_exit()->check_stack_usage()->printk (I suspect blocking all the
other cpus), where it hits: serial8250_console_write
(up=0xffffffff843d19a0 <serial8250_ports>, s=0xffffffff8434f7e0
<printk_shared_pbufs> "[   69.857641] \n", count=<optimized out>) at
drivers/tty/serial/8250/8250_port.c:3352,  then into the spinlock
code.

* Another thread is stuck in:
console_trylock_spinning () at kernel/printk/printk.c:2031

This one has the most interesting backtrace, as it is going from
ksys_write() -> uart_write() [which takes the uart port_lock] ->
__pm_runtime_resume() -> trying to grab the dev->power.lock, which
trips lockdep, which tries to then printk lockdep details which gets
stuck on console_trylock_spinning.

Full gdb backtrace trace below.

I wanted to raise this in case anyone else has already hit something
similar, or had any ideas as to the root cause.

#0  console_trylock_spinning () at kernel/printk/printk.c:2031
#1  vprintk_emit (facility=0, level=<optimized out>, dev_info=0x0
<fixed_percpu_data>, fmt=0xffffffff82980860 "\0014\nwhich lock already
depends on the new lock.\n\n",
    args=0xffffc90000017a28) at kernel/printk/printk.c:2406
#2  0xffffffff8113b9d4 in _printk (fmt=fmt@entry=0xffffffff82980860
"\0014\nwhich lock already depends on the new lock.\n\n") at
kernel/printk/printk.c:2432
#3  0xffffffff81121319 in print_circular_bug_header
(entry=entry@entry=0xffffffff8418fa50 <list_entries+5712>,
depth=depth@entry=5,
    check_src=check_src@entry=0xffff888100360b58,
check_tgt=check_tgt@entry=0xffff888100360b30) at
kernel/locking/lockdep.c:1968
#4  0xffffffff811213dc in print_circular_bug
(this=this@entry=0xffffc90000017b10, target=0xffffffff8418fa50
<list_entries+5712>,
    check_src=check_src@entry=0xffff888100360b58,
check_tgt=check_tgt@entry=0xffff888100360b30) at
kernel/locking/lockdep.c:2057
#5  0xffffffff811217fe in check_noncircular
(src=src@entry=0xffff888100360b58,
target=target@entry=0xffff888100360b30,
trace=trace@entry=0xffffc90000017c10)
    at kernel/locking/lockdep.c:2206
#6  0xffffffff81122a6b in check_prev_add
(curr=curr@entry=0xffff888100360000,
prev=prev@entry=0xffff888100360b30,
next=next@entry=0xffff888100360b58, distance=1,
    trace=trace@entry=0xffffc90000017c10) at kernel/locking/lockdep.c:3161
#7  0xffffffff81125b0c in check_prevs_add (next=0xffff888100360b58,
curr=0xffff888100360000) at kernel/locking/lockdep.c:3280
#8  validate_chain (chain_key=<optimized out>, chain_head=<optimized
out>, hlock=0xffff888100360b58, curr=0xffff888100360000) at
kernel/locking/lockdep.c:3904
#9  __lock_acquire (lock=lock@entry=0xffff88810b4a2970,
subclass=subclass@entry=0, trylock=trylock@entry=0, read=read@entry=0,
check=<optimized out>, check@entry=1,
    hardirqs_off=<optimized out>, nest_lock=<optimized out>,
ip=<optimized out>, references=<optimized out>, pin_count=<optimized
out>, sync=<optimized out>)
    at kernel/locking/lockdep.c:5202
#10 0xffffffff8112686e in lock_acquire (ip=<optimized out>,
nest_lock=0x0 <fixed_percpu_data>, check=1, read=0, trylock=0,
subclass=0, lock=0xffff88810b4a2970)
    at kernel/locking/lockdep.c:5825
#11 lock_acquire (lock=lock@entry=0xffff88810b4a2970,
subclass=subclass@entry=0, trylock=trylock@entry=0, read=read@entry=0,
check=check@entry=1,
    nest_lock=nest_lock@entry=0x0 <fixed_percpu_data>, ip=<optimized
out>) at kernel/locking/lockdep.c:5790
#12 0xffffffff82177e5f in __raw_spin_lock_irqsave
(lock=0xffff88810b4a2958) at ./include/linux/spinlock_api_smp.h:110
#13 _raw_spin_lock_irqsave (lock=lock@entry=0xffff88810b4a2958) at
kernel/locking/spinlock.c:162
#14 0xffffffff81a4295e in __pm_runtime_resume
(dev=dev@entry=0xffff88810b4a2800, rpmflags=rpmflags@entry=5) at
drivers/base/power/runtime.c:1171
#15 0xffffffff81760715 in pm_runtime_get (dev=0xffff88810b4a2800) at
./include/linux/pm_runtime.h:396
#16 __uart_start (state=state@entry=0xffff8881172b8000) at
drivers/tty/serial/serial_core.c:148
#17 0xffffffff817655c6 in uart_write (tty=<optimized out>,
buf=0xffff888108010800 "Loading, please wait...\n\020",
count=<optimized out>)
    at drivers/tty/serial/serial_core.c:635
#18 0xffffffff81742e1e in process_output_block (nr=24,
buf=0xffff888108010800 "Loading, please wait...\n\020",
tty=0xffff8881080d7000) at drivers/tty/n_tty.c:574
#19 n_tty_write (tty=0xffff8881080d7000, file=<optimized out>,
buf=0xffff888108010800 "Loading, please wait...\n\020", nr=24) at
drivers/tty/n_tty.c:2389
#20 0xffffffff8173dfbe in iterate_tty_write (from=0xffffc90000017e60,
file=0xffff888108154000, tty=0xffff8881080d7000,
ld=0xffff8881080cf060) at drivers/tty/tty_io.c:1015
#21 file_tty_write (file=0xffff888108154000, from=0xffffc90000017e60,
iocb=<optimized out>) at drivers/tty/tty_io.c:1090
#22 0xffffffff8132e756 in new_sync_write (ppos=0xffffc90000017ef0,
len=24, buf=0x55b9dbbffa60 "Loading, please wait...\n",
filp=0xffff888108154000) at fs/read_write.c:590
#23 vfs_write (file=file@entry=0xffff888108154000,
buf=buf@entry=0x55b9dbbffa60 "Loading, please wait...\n",
count=count@entry=24, pos=pos@entry=0xffffc90000017ef0)
    at fs/read_write.c:683
#24 0xffffffff8132ec05 in ksys_write (fd=<optimized out>,
buf=0x55b9dbbffa60 "Loading, please wait...\n", count=24) at
fs/read_write.c:736
#25 0xffffffff8216267b in do_syscall_x64 (nr=1,
regs=0xffffc90000017f58) at arch/x86/entry/common.c:52
#26 do_syscall_64 (regs=0xffffc90000017f58, nr=1) at arch/x86/entry/common.c:83
#27 0xffffffff82200130 in entry_SYSCALL_64 () at arch/x86/entry/entry_64.S:121
#28 0x00007ffd2cd643c0 in ?? ()

Re: Deadlock?: console_waiter/serial8250_ports/low_water_lock with 6.12-rc

[John Stultz]

On Mon, Oct 28, 2024 at 12:30 PM John Stultz <jstultz@google.com> wrote:
> * One thread is in virt_spin_lock (lock=lock@entry=0xffffffff843d19a0
> <serial8250_ports>) at ./arch/x86/include/asm/qspinlock.h:106.  The
> backtrace there, is similarly going through
> do_exit()->check_stack_usage()->printk (I suspect blocking all the
> other cpus), where it hits: serial8250_console_write
> (up=0xffffffff843d19a0 <serial8250_ports>, s=0xffffffff8434f7e0
> <printk_shared_pbufs> "[   69.857641] \n", count=<optimized out>) at
> drivers/tty/serial/8250/8250_port.c:3352,  then into the spinlock
> code.
>

I got a question on IRC about the backtrace for this cpu, so I wanted
to also share it here as well.

#0  virt_spin_lock (lock=lock@entry=0xffffffff843d19a0
<serial8250_ports>) at ./arch/x86/include/asm/qspinlock.h:106
#1  queued_spin_lock_slowpath (lock=lock@entry=0xffffffff843d19a0
<serial8250_ports>, val=1) at kernel/locking/qspinlock.c:324
#2  0xffffffff8112954e in queued_spin_lock (lock=0xffffffff843d19a0
<serial8250_ports>) at ./include/asm-generic/qspinlock.h:114
#3  do_raw_spin_lock (lock=lock@entry=0xffffffff843d19a0
<serial8250_ports>) at kernel/locking/spinlock_debug.c:116
#4  0xffffffff82177e67 in __raw_spin_lock_irqsave
(lock=0xffffffff843d19a0 <serial8250_ports>) at
./include/linux/spinlock_api_smp.h:111
#5  _raw_spin_lock_irqsave (lock=lock@entry=0xffffffff843d19a0
<serial8250_ports>) at kernel/locking/spinlock.c:162
#6  0xffffffff817723d0 in uart_port_lock_irqsave (flags=<synthetic
pointer>, up=0xffffffff843d19a0 <serial8250_ports>) at
./include/linux/serial_core.h:711
#7  serial8250_console_write (up=0xffffffff843d19a0
<serial8250_ports>, s=0xffffffff8434f7e0 <printk_shared_pbufs> "[
69.857641] \n", count=<optimized out>)
    at drivers/tty/serial/8250/8250_port.c:3352
#8  0xffffffff8113ef11 in console_emit_next_record (cookie=<optimized
out>, handover=<optimized out>, con=0xffffffff82e11e40
<univ8250_console>)
    at kernel/printk/printk.c:3092
#9  console_flush_all (do_cond_resched=do_cond_resched@entry=false,
next_seq=next_seq@entry=0xffffc9000274fdb8,
handover=handover@entry=0xffffc9000274fdb3)
    at kernel/printk/printk.c:3180
#10 0xffffffff8113f1a3 in __console_flush_and_unlock () at
kernel/printk/printk.c:3239
#11 console_unlock () at kernel/printk/printk.c:3279
#12 0xffffffff8113f745 in vprintk_emit (facility=0, level=<optimized
out>, dev_info=0x0 <fixed_percpu_data>,
    fmt=0xffffffff8297cc28 "\0016%s (%d) used greatest stack depth:
%lu bytes left\n", args=0xffffc9000274fe30) at
kernel/printk/printk.c:2407
#13 0xffffffff8113b9d4 in _printk (fmt=fmt@entry=0xffffffff8297cc28
"\0016%s (%d) used greatest stack depth: %lu bytes left\n") at
kernel/printk/printk.c:2432
#14 0xffffffff810994d0 in check_stack_usage () at ./include/linux/pid.h:232
#15 do_exit (code=code@entry=0) at kernel/exit.c:982
#16 0xffffffff81099876 in do_group_exit (exit_code=0) at kernel/exit.c:1088
#17 0xffffffff81099908 in __do_sys_exit_group (error_code=<optimized
out>) at kernel/exit.c:1099
#18 __se_sys_exit_group (error_code=<optimized out>) at kernel/exit.c:1097
#19 __x64_sys_exit_group (regs=<optimized out>) at kernel/exit.c:1097
#20 0xffffffff81003ab3 in x64_sys_call (regs=<optimized out>,
nr=<optimized out>) at
./arch/x86/include/generated/asm/syscalls_64.h:232
#21 0xffffffff8216267b in do_syscall_x64 (nr=231,
regs=0xffffc9000274ff58) at arch/x86/entry/common.c:52
#22 do_syscall_64 (regs=0xffffc9000274ff58, nr=231) at
arch/x86/entry/common.c:83
#23 0xffffffff82200130 in entry_SYSCALL_64 () at arch/x86/entry/entry_64.S:121
#24 0x0000000000000000 in ?? ()


thanks
-john

Re: Deadlock?: console_waiter/serial8250_ports/low_water_lock with 6.12-rc

[Boqun Feng]

On Mon, Oct 28, 2024 at 12:54:35PM -0700, John Stultz wrote:
> On Mon, Oct 28, 2024 at 12:30 PM John Stultz <jstultz@google.com> wrote:
> > * One thread is in virt_spin_lock (lock=lock@entry=0xffffffff843d19a0
> > <serial8250_ports>) at ./arch/x86/include/asm/qspinlock.h:106.  The
> > backtrace there, is similarly going through
> > do_exit()->check_stack_usage()->printk (I suspect blocking all the
> > other cpus), where it hits: serial8250_console_write
> > (up=0xffffffff843d19a0 <serial8250_ports>, s=0xffffffff8434f7e0
> > <printk_shared_pbufs> "[   69.857641] \n", count=<optimized out>) at
> > drivers/tty/serial/8250/8250_port.c:3352,  then into the spinlock
> > code.
> >
> 
> I got a question on IRC about the backtrace for this cpu, so I wanted
> to also share it here as well.
> 

I think the cause of the issue is:

	CPU X					CPU Y
	=====					=====
	uart_write():				console_unlock(): // console lock is held by Y.
	  uart_port_lock();			  __console_flush_and_unlock():
	  __uart_start():			    __console_flush_all():
	    pm_runtime_get():			      console_emit_next_record():
	      __pm_runtime_resume():		        con->write(); <- serial8250_console_write() // will try to acquire uart_port_lock();
	        spin_lock_irqsave(&dev->power.lock, flags):
		  <this triggers the lockdep splats, probably because
		   PM has done some print under "&dev->power.lock">
		  lock_acquire():
		    printk():
		      vprintk_emit():
		        // Because NBCON_PRIO_EMERGENCY is used, and 
		        console_trylock_spinning();

So CPU X has the uart_port_lock() but need the console lock, and CPU Y
has the console lock but need the uart_port_lock().

Regards,
Boqun

> #0  virt_spin_lock (lock=lock@entry=0xffffffff843d19a0
> <serial8250_ports>) at ./arch/x86/include/asm/qspinlock.h:106
> #1  queued_spin_lock_slowpath (lock=lock@entry=0xffffffff843d19a0
> <serial8250_ports>, val=1) at kernel/locking/qspinlock.c:324
> #2  0xffffffff8112954e in queued_spin_lock (lock=0xffffffff843d19a0
> <serial8250_ports>) at ./include/asm-generic/qspinlock.h:114
> #3  do_raw_spin_lock (lock=lock@entry=0xffffffff843d19a0
> <serial8250_ports>) at kernel/locking/spinlock_debug.c:116
> #4  0xffffffff82177e67 in __raw_spin_lock_irqsave
> (lock=0xffffffff843d19a0 <serial8250_ports>) at
> ./include/linux/spinlock_api_smp.h:111
> #5  _raw_spin_lock_irqsave (lock=lock@entry=0xffffffff843d19a0
> <serial8250_ports>) at kernel/locking/spinlock.c:162
> #6  0xffffffff817723d0 in uart_port_lock_irqsave (flags=<synthetic
> pointer>, up=0xffffffff843d19a0 <serial8250_ports>) at
> ./include/linux/serial_core.h:711
> #7  serial8250_console_write (up=0xffffffff843d19a0
> <serial8250_ports>, s=0xffffffff8434f7e0 <printk_shared_pbufs> "[
> 69.857641] \n", count=<optimized out>)
>     at drivers/tty/serial/8250/8250_port.c:3352
> #8  0xffffffff8113ef11 in console_emit_next_record (cookie=<optimized
> out>, handover=<optimized out>, con=0xffffffff82e11e40
> <univ8250_console>)
>     at kernel/printk/printk.c:3092
> #9  console_flush_all (do_cond_resched=do_cond_resched@entry=false,
> next_seq=next_seq@entry=0xffffc9000274fdb8,
> handover=handover@entry=0xffffc9000274fdb3)
>     at kernel/printk/printk.c:3180
> #10 0xffffffff8113f1a3 in __console_flush_and_unlock () at
> kernel/printk/printk.c:3239
> #11 console_unlock () at kernel/printk/printk.c:3279
> #12 0xffffffff8113f745 in vprintk_emit (facility=0, level=<optimized
> out>, dev_info=0x0 <fixed_percpu_data>,
>     fmt=0xffffffff8297cc28 "\0016%s (%d) used greatest stack depth:
> %lu bytes left\n", args=0xffffc9000274fe30) at
> kernel/printk/printk.c:2407
> #13 0xffffffff8113b9d4 in _printk (fmt=fmt@entry=0xffffffff8297cc28
> "\0016%s (%d) used greatest stack depth: %lu bytes left\n") at
> kernel/printk/printk.c:2432
> #14 0xffffffff810994d0 in check_stack_usage () at ./include/linux/pid.h:232
> #15 do_exit (code=code@entry=0) at kernel/exit.c:982
> #16 0xffffffff81099876 in do_group_exit (exit_code=0) at kernel/exit.c:1088
> #17 0xffffffff81099908 in __do_sys_exit_group (error_code=<optimized
> out>) at kernel/exit.c:1099
> #18 __se_sys_exit_group (error_code=<optimized out>) at kernel/exit.c:1097
> #19 __x64_sys_exit_group (regs=<optimized out>) at kernel/exit.c:1097
> #20 0xffffffff81003ab3 in x64_sys_call (regs=<optimized out>,
> nr=<optimized out>) at
> ./arch/x86/include/generated/asm/syscalls_64.h:232
> #21 0xffffffff8216267b in do_syscall_x64 (nr=231,
> regs=0xffffc9000274ff58) at arch/x86/entry/common.c:52
> #22 do_syscall_64 (regs=0xffffc9000274ff58, nr=231) at
> arch/x86/entry/common.c:83
> #23 0xffffffff82200130 in entry_SYSCALL_64 () at arch/x86/entry/entry_64.S:121
> #24 0x0000000000000000 in ?? ()
> 
> 
> thanks
> -john

Re: Deadlock?: console_waiter/serial8250_ports/low_water_lock with 6.12-rc

[John Ogness]

On 2024-10-28, Boqun Feng <boqun.feng@gmail.com> wrote:
> I think the cause of the issue is:
>
> 	CPU X					CPU Y
> 	=====					=====
> 	uart_write():				console_unlock(): // console lock is held by Y.
> 	  uart_port_lock();			  __console_flush_and_unlock():
> 	  __uart_start():			    __console_flush_all():
> 	    pm_runtime_get():			      console_emit_next_record():
> 	      __pm_runtime_resume():		        con->write(); <- serial8250_console_write() // will try to acquire uart_port_lock();
> 	        spin_lock_irqsave(&dev->power.lock, flags):
> 		  <this triggers the lockdep splats, probably because
> 		   PM has done some print under "&dev->power.lock">
> 		  lock_acquire():
> 		    printk():

It is a known problem that calling printk() while holding the
uart_port_lock for non-printing purposes (such as pm) will deadlock the
system. You don't even need CPU-Y to be involved. CPU-X will deadlock
itself after acquiring the console_lock.

One possible solution would be to enable deferred_printk if the
uart_port_lock of a console is taken for non-printing purposes. The
correct solution is to convert the console driver to the new nbcon
model.

The reasons why nbcon avoids this issue:

1. It does not use the BKL-like console lock.

2. It is aware that something else is using the driver and will instead
just write to the lockless ringbuffer rather than endlessly spinning on
the lock (that it itself is already holding).

@jstultz: Is it possible that you could run your tests using the latest
version [0] of the proposed nbcon-based 8250 driver? This will not have
the issue and should cleanly apply to any recent kernel.

John Ogness

[0] https://lore.kernel.org/lkml/20241025105728.602310-1-john.ogness@linutronix.de