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

[Boqun Feng <boqun.feng@gmail.com>]

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