Message-ID: <CANDhNCo8NRm4meR7vHqvP8vVZ-_GXVPuUKSO1wUQkKdfjvy20w@mail.gmail.com>
Date: Mon, 28 Oct 2024 12:30:20 -0700
From: John Stultz <jstultz@...gle.com>
To: John Ogness <john.ogness@...utronix.de>, Petr Mladek <pmladek@...e.com>, 
	Greg Kroah-Hartman <gregkh@...uxfoundation.org>, jirislaby@...nel.org
Cc: LKML <linux-kernel@...r.kernel.org>, kernel-team@...roid.com
Subject: Deadlock?: console_waiter/serial8250_ports/low_water_lock with 6.12-rc

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@...ry=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@...ry=0) at kernel/exit.c:982

* One thread is in virt_spin_lock (lock=lock@...ry=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@...ry=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@...ry=0xffffffff8418fa50 <list_entries+5712>,
depth=depth@...ry=5,
    check_src=check_src@...ry=0xffff888100360b58,
check_tgt=check_tgt@...ry=0xffff888100360b30) at
kernel/locking/lockdep.c:1968
#4  0xffffffff811213dc in print_circular_bug
(this=this@...ry=0xffffc90000017b10, target=0xffffffff8418fa50
<list_entries+5712>,
    check_src=check_src@...ry=0xffff888100360b58,
check_tgt=check_tgt@...ry=0xffff888100360b30) at
kernel/locking/lockdep.c:2057
#5  0xffffffff811217fe in check_noncircular
(src=src@...ry=0xffff888100360b58,
target=target@...ry=0xffff888100360b30,
trace=trace@...ry=0xffffc90000017c10)
    at kernel/locking/lockdep.c:2206
#6  0xffffffff81122a6b in check_prev_add
(curr=curr@...ry=0xffff888100360000,
prev=prev@...ry=0xffff888100360b30,
next=next@...ry=0xffff888100360b58, distance=1,
    trace=trace@...ry=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@...ry=0xffff88810b4a2970,
subclass=subclass@...ry=0, trylock=trylock@...ry=0, read=read@...ry=0,
check=<optimized out>, check@...ry=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@...ry=0xffff88810b4a2970,
subclass=subclass@...ry=0, trylock=trylock@...ry=0, read=read@...ry=0,
check=check@...ry=1,
    nest_lock=nest_lock@...ry=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@...ry=0xffff88810b4a2958) at
kernel/locking/spinlock.c:162
#14 0xffffffff81a4295e in __pm_runtime_resume
(dev=dev@...ry=0xffff88810b4a2800, rpmflags=rpmflags@...ry=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@...ry=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@...ry=0xffff888108154000,
buf=buf@...ry=0x55b9dbbffa60 "Loading, please wait...\n",
count=count@...ry=24, pos=pos@...ry=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 ?? ()

Powered by blists - more mailing lists