Linux-Serial Archive mirror
 help / color / mirror / Atom feed
* [RFC PATCH] serial: core: Use pm_runtime_get_sync() in uart_start()
@ 2023-11-24 12:22 Xuewen Yan
  2023-11-25  7:47 ` Tony Lindgren
                   ` (2 more replies)
  0 siblings, 3 replies; 6+ messages in thread
From: Xuewen Yan @ 2023-11-24 12:22 UTC (permalink / raw)
  To: gregkh, jirislaby, ilpo.jarvinen, tony, john.ogness
  Cc: tglx, andriy.shevchenko, linux-kernel, linux-serial, ke.wang,
	xuewen.yan94

The commit 84a9582fd203("serial: core: Start managing serial controllers to enable runtime PM")
use the pm_runtime_get() after uart_port_lock() which would close the irq and disable preement.
At this time,  pm_runtime_get may cause the following two problems:

(1) deadlock in try_to_wake_up:

uart_write()
uart_port_lock() <<< get lock
__uart_start
__pm_runtime_resume
rpm_resume
queue_work_on
try_to_wake_up
_printk
uart_console_write
...
uart_port_lock() <<< wait forever

(2) scheduling while atomic:
uart_write()
uart_port_lock() <<< get lock
__uart_start
__pm_runtime_resume
rpm_resume
chedule() << sleep

So let us use pm_runtime_get_sync() to prevent these.

Fixes: 84a9582fd203 ("serial: core: Start managing serial controllers to enable runtime PM")
Signed-off-by: Xuewen Yan <xuewen.yan@unisoc.com>
---
 drivers/tty/serial/serial_core.c | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/drivers/tty/serial/serial_core.c b/drivers/tty/serial/serial_core.c
index f1348a509552..902f7ed35f4d 100644
--- a/drivers/tty/serial/serial_core.c
+++ b/drivers/tty/serial/serial_core.c
@@ -145,7 +145,7 @@ static void __uart_start(struct uart_state *state)
 	port_dev = port->port_dev;
 
 	/* Increment the runtime PM usage count for the active check below */
-	err = pm_runtime_get(&port_dev->dev);
+	err = pm_runtime_get_sync(&port_dev->dev);
 	if (err < 0 && err != -EINPROGRESS) {
 		pm_runtime_put_noidle(&port_dev->dev);
 		return;
@@ -159,7 +159,7 @@ static void __uart_start(struct uart_state *state)
 	if (!pm_runtime_enabled(port->dev) || pm_runtime_active(port->dev))
 		port->ops->start_tx(port);
 	pm_runtime_mark_last_busy(&port_dev->dev);
-	pm_runtime_put_autosuspend(&port_dev->dev);
+	pm_runtime_put_sync_autosuspend(&port_dev->dev);
 }
 
 static void uart_start(struct tty_struct *tty)
-- 
2.25.1


^ permalink raw reply related	[flat|nested] 6+ messages in thread

* Re: [RFC PATCH] serial: core: Use pm_runtime_get_sync() in uart_start()
  2023-11-24 12:22 [RFC PATCH] serial: core: Use pm_runtime_get_sync() in uart_start() Xuewen Yan
@ 2023-11-25  7:47 ` Tony Lindgren
  2023-11-27  1:54   ` Xuewen Yan
  2023-11-26 16:17 ` John Ogness
  2023-11-28 15:11 ` kernel test robot
  2 siblings, 1 reply; 6+ messages in thread
From: Tony Lindgren @ 2023-11-25  7:47 UTC (permalink / raw)
  To: Xuewen Yan
  Cc: gregkh, jirislaby, ilpo.jarvinen, john.ogness, tglx,
	andriy.shevchenko, linux-kernel, linux-serial, ke.wang,
	xuewen.yan94

* Xuewen Yan <xuewen.yan@unisoc.com> [231124 12:25]:
> The commit 84a9582fd203("serial: core: Start managing serial controllers to enable runtime PM")
> use the pm_runtime_get() after uart_port_lock() which would close the irq and disable preement.
> At this time,  pm_runtime_get may cause the following two problems:
> 
> (1) deadlock in try_to_wake_up:
> 
> uart_write()
> uart_port_lock() <<< get lock
> __uart_start
> __pm_runtime_resume
> rpm_resume
> queue_work_on
> try_to_wake_up
> _printk
> uart_console_write
> ...
> uart_port_lock() <<< wait forever
> 
> (2) scheduling while atomic:
> uart_write()
> uart_port_lock() <<< get lock
> __uart_start
> __pm_runtime_resume
> rpm_resume
> chedule() << sleep

Are these spinlock vs raw spinlock nesting warnings from lockdep? If so
can you please post the full warnings somewhere? Or if some extra steps
are needed to reproduce please describe that too.

Chances are very high that your serial port is already runtime active at
this point unless you manually idle it so that's why I'm wondering as
all that likely is happening here is a check on the runtime PM usage count.

> So let us use pm_runtime_get_sync() to prevent these.

We need to fix this some other way as we can't use pm_runtime_get_sync()
here. The sync call variants require setting pm_runtime_irq_safe() for the
device. And this is what we really want to avoid as it takes a permanent
usage count on the parent device.

What we want to do here is to get runtime PM to wake-up the device if idle
and try tx again after runtime PM resume as needed.

Just guessing at this point.. To me it sounds like the fix might be to
use a raw spinlock for uart_port_lock() and uart_port_unlock()?

Regards,

Tony


> Fixes: 84a9582fd203 ("serial: core: Start managing serial controllers to enable runtime PM")
> Signed-off-by: Xuewen Yan <xuewen.yan@unisoc.com>
> ---
>  drivers/tty/serial/serial_core.c | 4 ++--
>  1 file changed, 2 insertions(+), 2 deletions(-)
> 
> diff --git a/drivers/tty/serial/serial_core.c b/drivers/tty/serial/serial_core.c
> index f1348a509552..902f7ed35f4d 100644
> --- a/drivers/tty/serial/serial_core.c
> +++ b/drivers/tty/serial/serial_core.c
> @@ -145,7 +145,7 @@ static void __uart_start(struct uart_state *state)
>  	port_dev = port->port_dev;
>  
>  	/* Increment the runtime PM usage count for the active check below */
> -	err = pm_runtime_get(&port_dev->dev);
> +	err = pm_runtime_get_sync(&port_dev->dev);
>  	if (err < 0 && err != -EINPROGRESS) {
>  		pm_runtime_put_noidle(&port_dev->dev);
>  		return;
> @@ -159,7 +159,7 @@ static void __uart_start(struct uart_state *state)
>  	if (!pm_runtime_enabled(port->dev) || pm_runtime_active(port->dev))
>  		port->ops->start_tx(port);
>  	pm_runtime_mark_last_busy(&port_dev->dev);
> -	pm_runtime_put_autosuspend(&port_dev->dev);
> +	pm_runtime_put_sync_autosuspend(&port_dev->dev);
>  }
>  
>  static void uart_start(struct tty_struct *tty)
> -- 
> 2.25.1
> 

^ permalink raw reply	[flat|nested] 6+ messages in thread

* Re: [RFC PATCH] serial: core: Use pm_runtime_get_sync() in uart_start()
  2023-11-24 12:22 [RFC PATCH] serial: core: Use pm_runtime_get_sync() in uart_start() Xuewen Yan
  2023-11-25  7:47 ` Tony Lindgren
@ 2023-11-26 16:17 ` John Ogness
  2023-11-27  2:06   ` Xuewen Yan
  2023-11-28 15:11 ` kernel test robot
  2 siblings, 1 reply; 6+ messages in thread
From: John Ogness @ 2023-11-26 16:17 UTC (permalink / raw)
  To: Xuewen Yan, gregkh, jirislaby, ilpo.jarvinen, tony
  Cc: tglx, andriy.shevchenko, linux-kernel, linux-serial, ke.wang,
	xuewen.yan94, Petr Mladek, Sergey Senozhatsky, Steven Rostedt

[Added printk maintainers CC.]

On 2023-11-24, Xuewen Yan <xuewen.yan@unisoc.com> wrote:
> The commit 84a9582fd203("serial: core: Start managing serial
> controllers to enable runtime PM") use the pm_runtime_get() after
> uart_port_lock() which would close the irq and disable preement.  At
> this time, pm_runtime_get may cause the following two problems:
>
> (1) deadlock in try_to_wake_up:
>
> uart_write()
> uart_port_lock() <<< get lock
> __uart_start
> __pm_runtime_resume
> rpm_resume
> queue_work_on
> try_to_wake_up
> _printk
> uart_console_write
> ...
> uart_port_lock() <<< wait forever

I suppose you got this because of the lockdep message generated by
#2. It probably would make sense to call __printk_safe_enter() inside
uart_port_lock(). This would allow printk() to automatically defer the
printing for that CPU until the port lock is released.

> (2) scheduling while atomic:
> uart_write()
> uart_port_lock() <<< get lock
> __uart_start
> __pm_runtime_resume
> rpm_resume
> schedule() << sleep

rpm_resume() is a fascinating function. It requires the caller to hold a
spin_lock (dev->power.lock) with interrupts disabled. But it seems to
believe that this is the *only* spin_lock held so that it can
temporarily spin_unlock and call might_sleep() functions. In the case of
uart_write(), it certainly is not the only spin_lock held.

I do not know enough about the internals of RPM to suggest a proper
solution. But it looks like rpm_resume() cannot assume dev->power.lock
is the only spin_lock held by the caller.

John Ogness

^ permalink raw reply	[flat|nested] 6+ messages in thread

* Re: [RFC PATCH] serial: core: Use pm_runtime_get_sync() in uart_start()
  2023-11-25  7:47 ` Tony Lindgren
@ 2023-11-27  1:54   ` Xuewen Yan
  0 siblings, 0 replies; 6+ messages in thread
From: Xuewen Yan @ 2023-11-27  1:54 UTC (permalink / raw)
  To: Tony Lindgren
  Cc: Xuewen Yan, gregkh, jirislaby, ilpo.jarvinen, john.ogness, tglx,
	andriy.shevchenko, linux-kernel, linux-serial, ke.wang

Hi Tony

On Sat, Nov 25, 2023 at 3:48 PM Tony Lindgren <tony@atomide.com> wrote:
>
> * Xuewen Yan <xuewen.yan@unisoc.com> [231124 12:25]:
> > The commit 84a9582fd203("serial: core: Start managing serial controllers to enable runtime PM")
> > use the pm_runtime_get() after uart_port_lock() which would close the irq and disable preement.
> > At this time,  pm_runtime_get may cause the following two problems:
> >
> > (1) deadlock in try_to_wake_up:
> >
> > uart_write()
> > uart_port_lock() <<< get lock
> > __uart_start
> > __pm_runtime_resume
> > rpm_resume
> > queue_work_on
> > try_to_wake_up
> > _printk
> > uart_console_write
> > ...
> > uart_port_lock() <<< wait forever
> >
> > (2) scheduling while atomic:
> > uart_write()
> > uart_port_lock() <<< get lock
> > __uart_start
> > __pm_runtime_resume
> > rpm_resume
> > chedule() << sleep
>
> Are these spinlock vs raw spinlock nesting warnings from lockdep? If so
> can you please post the full warnings somewhere? Or if some extra steps
> are needed to reproduce please describe that too.

Indeed, we use pr_info in scheduler in our own kernel tree, and this
deadlock happended.
I would try to use printk_deferred and re-test.
And I also notice the warning was reported by syzbot:

https://lore.kernel.org/all/0000000000006f01f00608a16cea@google.com/
https://lore.kernel.org/all/000000000000e7765006072e9591@google.com/

These are also because the pm_runtime_put().

Thanks!

>
> Chances are very high that your serial port is already runtime active at
> this point unless you manually idle it so that's why I'm wondering as
> all that likely is happening here is a check on the runtime PM usage count.
>
> > So let us use pm_runtime_get_sync() to prevent these.
>
> We need to fix this some other way as we can't use pm_runtime_get_sync()
> here. The sync call variants require setting pm_runtime_irq_safe() for the
> device. And this is what we really want to avoid as it takes a permanent
> usage count on the parent device.
>
> What we want to do here is to get runtime PM to wake-up the device if idle
> and try tx again after runtime PM resume as needed.
>
> Just guessing at this point.. To me it sounds like the fix might be to
> use a raw spinlock for uart_port_lock() and uart_port_unlock()?
>
> Regards,
>
> Tony
>
>
> > Fixes: 84a9582fd203 ("serial: core: Start managing serial controllers to enable runtime PM")
> > Signed-off-by: Xuewen Yan <xuewen.yan@unisoc.com>
> > ---
> >  drivers/tty/serial/serial_core.c | 4 ++--
> >  1 file changed, 2 insertions(+), 2 deletions(-)
> >
> > diff --git a/drivers/tty/serial/serial_core.c b/drivers/tty/serial/serial_core.c
> > index f1348a509552..902f7ed35f4d 100644
> > --- a/drivers/tty/serial/serial_core.c
> > +++ b/drivers/tty/serial/serial_core.c
> > @@ -145,7 +145,7 @@ static void __uart_start(struct uart_state *state)
> >       port_dev = port->port_dev;
> >
> >       /* Increment the runtime PM usage count for the active check below */
> > -     err = pm_runtime_get(&port_dev->dev);
> > +     err = pm_runtime_get_sync(&port_dev->dev);
> >       if (err < 0 && err != -EINPROGRESS) {
> >               pm_runtime_put_noidle(&port_dev->dev);
> >               return;
> > @@ -159,7 +159,7 @@ static void __uart_start(struct uart_state *state)
> >       if (!pm_runtime_enabled(port->dev) || pm_runtime_active(port->dev))
> >               port->ops->start_tx(port);
> >       pm_runtime_mark_last_busy(&port_dev->dev);
> > -     pm_runtime_put_autosuspend(&port_dev->dev);
> > +     pm_runtime_put_sync_autosuspend(&port_dev->dev);
> >  }
> >
> >  static void uart_start(struct tty_struct *tty)
> > --
> > 2.25.1
> >

^ permalink raw reply	[flat|nested] 6+ messages in thread

* Re: [RFC PATCH] serial: core: Use pm_runtime_get_sync() in uart_start()
  2023-11-26 16:17 ` John Ogness
@ 2023-11-27  2:06   ` Xuewen Yan
  0 siblings, 0 replies; 6+ messages in thread
From: Xuewen Yan @ 2023-11-27  2:06 UTC (permalink / raw)
  To: John Ogness
  Cc: Xuewen Yan, gregkh, jirislaby, ilpo.jarvinen, tony, tglx,
	andriy.shevchenko, linux-kernel, linux-serial, ke.wang,
	Petr Mladek, Sergey Senozhatsky, Steven Rostedt

Hi John

On Mon, Nov 27, 2023 at 12:17 AM John Ogness <john.ogness@linutronix.de> wrote:
>
> [Added printk maintainers CC.]
>
> On 2023-11-24, Xuewen Yan <xuewen.yan@unisoc.com> wrote:
> > The commit 84a9582fd203("serial: core: Start managing serial
> > controllers to enable runtime PM") use the pm_runtime_get() after
> > uart_port_lock() which would close the irq and disable preement.  At
> > this time, pm_runtime_get may cause the following two problems:
> >
> > (1) deadlock in try_to_wake_up:
> >
> > uart_write()
> > uart_port_lock() <<< get lock
> > __uart_start
> > __pm_runtime_resume
> > rpm_resume
> > queue_work_on
> > try_to_wake_up
> > _printk
> > uart_console_write
> > ...
> > uart_port_lock() <<< wait forever
>
> I suppose you got this because of the lockdep message generated by
> #2. It probably would make sense to call __printk_safe_enter() inside
> uart_port_lock(). This would allow printk() to automatically defer the
> printing for that CPU until the port lock is released.

Thanks for the suggestion, I would use printk_deferred in our tree to
retest the case.

And I also notice the warning was reported by syzbot:
https://lore.kernel.org/all/0000000000006f01f00608a16cea@google.com/
https://lore.kernel.org/all/000000000000e7765006072e9591@google.com/

>
> > (2) scheduling while atomic:
> > uart_write()
> > uart_port_lock() <<< get lock
> > __uart_start
> > __pm_runtime_resume
> > rpm_resume
> > schedule() << sleep
>
> rpm_resume() is a fascinating function. It requires the caller to hold a
> spin_lock (dev->power.lock) with interrupts disabled. But it seems to
> believe that this is the *only* spin_lock held so that it can
> temporarily spin_unlock and call might_sleep() functions. In the case of
> uart_write(), it certainly is not the only spin_lock held.
>
> I do not know enough about the internals of RPM to suggest a proper
> solution. But it looks like rpm_resume() cannot assume dev->power.lock
> is the only spin_lock held by the caller.

I would also be very grateful if could give us more suggestions.

Thanks!

BR
---
xuewen
>
> John Ogness

^ permalink raw reply	[flat|nested] 6+ messages in thread

* Re: [RFC PATCH] serial: core: Use pm_runtime_get_sync() in uart_start()
  2023-11-24 12:22 [RFC PATCH] serial: core: Use pm_runtime_get_sync() in uart_start() Xuewen Yan
  2023-11-25  7:47 ` Tony Lindgren
  2023-11-26 16:17 ` John Ogness
@ 2023-11-28 15:11 ` kernel test robot
  2 siblings, 0 replies; 6+ messages in thread
From: kernel test robot @ 2023-11-28 15:11 UTC (permalink / raw)
  To: Xuewen Yan
  Cc: oe-lkp, lkp, linux-kernel, linux-serial, gregkh, jirislaby,
	ilpo.jarvinen, tony, john.ogness, tglx, andriy.shevchenko,
	ke.wang, xuewen.yan94, oliver.sang



Hello,

kernel test robot noticed "BUG:sleeping_function_called_from_invalid_context_at_drivers/base/power/runtime.c" on:

commit: 81a787668db066cb86873bd4f8fbf7c36ac8dd5a ("[RFC PATCH] serial: core: Use pm_runtime_get_sync() in uart_start()")
url: https://github.com/intel-lab-lkp/linux/commits/Xuewen-Yan/serial-core-Use-pm_runtime_get_sync-in-uart_start/20231124-202425
base: https://git.kernel.org/cgit/linux/kernel/git/gregkh/tty.git tty-next
patch link: https://lore.kernel.org/all/20231124122258.1050-1-xuewen.yan@unisoc.com/
patch subject: [RFC PATCH] serial: core: Use pm_runtime_get_sync() in uart_start()

in testcase: boot

compiler: gcc-12
test machine: qemu-system-x86_64 -enable-kvm -cpu SandyBridge -smp 2 -m 16G

(please refer to attached dmesg/kmsg for entire log/backtrace)



If you fix the issue in a separate patch/commit (i.e. not just a new version of
the same patch/commit), kindly add following tags
| Reported-by: kernel test robot <oliver.sang@intel.com>
| Closes: https://lore.kernel.org/oe-lkp/202311282251.b5351d99-oliver.sang@intel.com


[  678.716002][    T1] BUG: sleeping function called from invalid context at drivers/base/power/runtime.c:1163
[  678.716028][    T1]
[  678.716029][    T1] ======================================================
[  678.716030][    T1] WARNING: possible circular locking dependency detected
[  678.716031][    T1] 6.7.0-rc2-00001-g81a787668db0 #3 Tainted: G                 N
[  678.716033][    T1] ------------------------------------------------------
[  678.716033][    T1] init/1 is trying to acquire lock:
[ 678.716035][ T1] c249c82c (console_owner){-.-.}-{0:0}, at: console_flush_all (kernel/printk/printk.c:2894 kernel/printk/printk.c:2967) 
[  678.716047][    T1]
[  678.716047][    T1] but task is already holding lock:
[ 678.716048][ T1] c3356e90 (&port_lock_key){-.-.}-{2:2}, at: uart_write (drivers/tty/serial/serial_core.c:598) 
[  678.716057][    T1]
[  678.716057][    T1] which lock already depends on the new lock.
[  678.716057][    T1]
[  678.716057][    T1] the existing dependency chain (in reverse order) is:
[  678.716058][    T1]
[  678.716058][    T1] -> #1 (&port_lock_key){-.-.}-{2:2}:
[ 678.716062][ T1] __lock_acquire (kernel/locking/lockdep.c:5136) 
[ 678.716066][ T1] lock_acquire (kernel/locking/lockdep.c:467 kernel/locking/lockdep.c:5755) 
[ 678.716069][ T1] _raw_spin_lock_irqsave (include/linux/spinlock_api_smp.h:111 kernel/locking/spinlock.c:162) 
[ 678.716073][ T1] serial8250_console_write (drivers/tty/serial/8250/8250_port.c:3396) 
[ 678.716076][ T1] univ8250_console_write (drivers/tty/serial/8250/8250_core.c:601) 
[ 678.716079][ T1] console_flush_all (kernel/printk/printk.c:2905 kernel/printk/printk.c:2967) 
[ 678.716081][ T1] console_unlock (kernel/printk/printk.c:3037) 
[ 678.716084][ T1] vprintk_emit (arch/x86/include/asm/preempt.h:85 kernel/printk/printk.c:2304) 
[ 678.716086][ T1] vprintk_default (kernel/printk/printk.c:2319) 
[ 678.716089][ T1] vprintk (kernel/printk/printk_safe.c:46) 
[ 678.716091][ T1] _printk (kernel/printk/printk.c:2332) 
[ 678.716093][ T1] register_console (kernel/printk/printk.c:3543) 
[ 678.716096][ T1] univ8250_console_init (drivers/tty/serial/8250/8250_core.c:718) 
[ 678.716102][ T1] console_init (arch/x86/include/asm/atomic.h:23 include/linux/atomic/atomic-arch-fallback.h:457 include/linux/jump_label.h:260 include/linux/jump_label.h:270 include/trace/events/initcall.h:48 kernel/printk/printk.c:3689) 
[ 678.716104][ T1] start_kernel (init/main.c:1009 (discriminator 3)) 
[ 678.716108][ T1] i386_start_kernel (??:?) 
[ 678.716112][ T1] startup_32_smp (arch/x86/kernel/head_32.S:295) 
[  678.716115][    T1]
[  678.716115][    T1] -> #0 (console_owner){-.-.}-{0:0}:
[ 678.716118][ T1] check_prev_add (kernel/locking/lockdep.c:3135) 
[ 678.716121][ T1] validate_chain (kernel/locking/lockdep.c:3254 kernel/locking/lockdep.c:3868) 
[ 678.716124][ T1] __lock_acquire (kernel/locking/lockdep.c:5136) 
[ 678.716126][ T1] lock_acquire (kernel/locking/lockdep.c:467 kernel/locking/lockdep.c:5755) 
[ 678.716129][ T1] console_flush_all (kernel/printk/printk.c:2901 kernel/printk/printk.c:2967) 
[ 678.716131][ T1] console_unlock (kernel/printk/printk.c:3037) 
[ 678.716134][ T1] vprintk_emit (arch/x86/include/asm/preempt.h:85 kernel/printk/printk.c:2304) 
[ 678.716136][ T1] vprintk_default (kernel/printk/printk.c:2319) 
[ 678.716138][ T1] vprintk (kernel/printk/printk_safe.c:46) 
[ 678.716140][ T1] _printk (kernel/printk/printk.c:2332) 
[ 678.716142][ T1] __might_resched (kernel/sched/core.c:10130) 
[ 678.716145][ T1] __might_sleep (kernel/sched/core.c:10081 (discriminator 17)) 
[ 678.716147][ T1] __pm_runtime_resume (drivers/base/power/runtime.c:1163 (discriminator 5)) 
[ 678.716152][ T1] __uart_start (drivers/tty/serial/serial_core.c:149) 
[ 678.716156][ T1] uart_write (include/linux/spinlock.h:406 include/linux/serial_core.h:667 drivers/tty/serial/serial_core.c:617) 
[ 678.716159][ T1] process_output_block (drivers/tty/n_tty.c:574) 
[ 678.716163][ T1] n_tty_write (drivers/tty/n_tty.c:2380) 
[ 678.716166][ T1] iterate_tty_write (drivers/tty/tty_io.c:1022) 
[ 678.716169][ T1] file_tty_write+0x80/0x10c 
[ 678.716172][ T1] redirected_tty_write (drivers/tty/tty_io.c:1137) 
[ 678.716175][ T1] vfs_write (fs/read_write.c:492 fs/read_write.c:584) 
[ 678.716179][ T1] ksys_write (fs/read_write.c:638) 
[ 678.716180][ T1] __ia32_sys_write (fs/read_write.c:646) 
[ 678.716182][ T1] do_int80_syscall_32 (arch/x86/entry/common.c:164 arch/x86/entry/common.c:184) 
[ 678.716185][ T1] restore_all_switch_stack (arch/x86/entry/entry_32.S:947) 
[  678.716190][    T1]
[  678.716190][    T1] other info that might help us debug this:
[  678.716190][    T1]
[  678.716191][    T1]  Possible unsafe locking scenario:
[  678.716191][    T1]
[  678.716192][    T1]        CPU0                    CPU1
[  678.716193][    T1]        ----                    ----
[  678.716193][    T1]   lock(&port_lock_key);
[  678.716195][    T1]                                lock(console_owner);
[  678.716196][    T1]                                lock(&port_lock_key);
[  678.716198][    T1]   lock(console_owner);
[  678.716199][    T1]
[  678.716199][    T1]  *** DEADLOCK ***
[  678.716199][    T1]
[  678.716200][    T1] 7 locks held by init/1:
[ 678.716202][ T1] #0: c3fc5060 (&tty->ldisc_sem){++++}-{0:0}, at: ldsem_down_read (drivers/tty/tty_ldsem.c:341) 
[ 678.716211][ T1] #1: c3fc50b8 (&tty->atomic_write_lock){+.+.}-{3:3}, at: iterate_tty_write (drivers/tty/tty_io.c:954 drivers/tty/tty_io.c:973) 
[ 678.716217][ T1] #2: c3fc51c4 (&tty->termios_rwsem){++++}-{3:3}, at: n_tty_write (drivers/tty/n_tty.c:2365) 
[ 678.716223][ T1] #3: ef4112f0 (&ldata->output_lock){+.+.}-{3:3}, at: process_output_block (drivers/tty/n_tty.c:531) 
[ 678.716229][ T1] #4: c3356e90 (&port_lock_key){-.-.}-{2:2}, at: uart_write (drivers/tty/serial/serial_core.c:598) 
[ 678.716236][ T1] #5: c27bc9a8 (console_lock){+.+.}-{0:0}, at: vprintk_default (kernel/printk/printk.c:2319) 
[ 678.716241][ T1] #6: c27bca58 (console_srcu){....}-{0:0}, at: console_flush_all (include/linux/srcutiny.h:67 include/linux/srcu.h:70 include/linux/srcu.h:231 kernel/printk/printk.c:286 kernel/printk/printk.c:2959) 
[  678.716247][    T1]
[  678.716247][    T1] stack backtrace:
[  678.716248][    T1] CPU: 0 PID: 1 Comm: init Tainted: G                 N 6.7.0-rc2-00001-g81a787668db0 #3 457007a7b9fe78ab16bc9131e3cdb3e013769988
[  678.716253][    T1] Call Trace:
[ 678.716254][ T1] dump_stack_lvl (lib/dump_stack.c:108) 
[ 678.716259][ T1] dump_stack (lib/dump_stack.c:114) 
[ 678.716262][ T1] print_circular_bug (kernel/locking/lockdep.c:2061) 
[ 678.716266][ T1] check_noncircular (kernel/locking/lockdep.c:2190) 
[ 678.716271][ T1] check_prev_add (kernel/locking/lockdep.c:3135) 
[ 678.716275][ T1] validate_chain (kernel/locking/lockdep.c:3254 kernel/locking/lockdep.c:3868) 
[ 678.716279][ T1] __lock_acquire (kernel/locking/lockdep.c:5136) 
[ 678.716282][ T1] ? sched_clock_noinstr (arch/x86/kernel/tsc.c:267) 
[ 678.716285][ T1] ? local_clock_noinstr (kernel/sched/clock.c:301) 
[ 678.716290][ T1] lock_acquire (kernel/locking/lockdep.c:467 kernel/locking/lockdep.c:5755) 
[ 678.716293][ T1] ? console_flush_all (kernel/printk/printk.c:2894 kernel/printk/printk.c:2967) 
[ 678.716296][ T1] ? console_flush_all (kernel/printk/printk.c:1854 kernel/printk/printk.c:2895 kernel/printk/printk.c:2967) 
[ 678.716299][ T1] ? lock_release (kernel/locking/lockdep.c:467 kernel/locking/lockdep.c:5775) 
[ 678.716303][ T1] console_flush_all (kernel/printk/printk.c:2901 kernel/printk/printk.c:2967) 
[ 678.716306][ T1] ? console_flush_all (kernel/printk/printk.c:2894 kernel/printk/printk.c:2967) 
[ 678.716310][ T1] console_unlock (kernel/printk/printk.c:3037) 
[ 678.716313][ T1] vprintk_emit (arch/x86/include/asm/preempt.h:85 kernel/printk/printk.c:2304) 
[ 678.716316][ T1] vprintk_default (kernel/printk/printk.c:2319) 
[ 678.716319][ T1] vprintk (kernel/printk/printk_safe.c:46) 
[ 678.716322][ T1] _printk (kernel/printk/printk.c:2332) 
[ 678.716324][ T1] __might_resched (kernel/sched/core.c:10130) 
[ 678.716328][ T1] __might_sleep (kernel/sched/core.c:10081 (discriminator 17)) 
[ 678.716331][ T1] ? uart_write (drivers/tty/serial/serial_core.c:598) 
[ 678.716335][ T1] ? lock_acquired (kernel/locking/lockdep.c:467 kernel/locking/lockdep.c:6035) 
[ 678.716337][ T1] __pm_runtime_resume (drivers/base/power/runtime.c:1163 (discriminator 5)) 
[ 678.716341][ T1] ? _raw_spin_lock_irqsave (kernel/locking/spinlock.c:163) 
[ 678.716344][ T1] __uart_start (drivers/tty/serial/serial_core.c:149) 
[ 678.716348][ T1] uart_write (include/linux/spinlock.h:406 include/linux/serial_core.h:667 drivers/tty/serial/serial_core.c:617) 
[ 678.716352][ T1] ? uart_write_room (drivers/tty/serial/serial_core.c:74 drivers/tty/serial/serial_core.c:630) 
[ 678.716356][ T1] process_output_block (drivers/tty/n_tty.c:574) 
[ 678.716361][ T1] n_tty_write (drivers/tty/n_tty.c:2380) 
[ 678.716365][ T1] ? autoremove_wake_function (kernel/sched/wait.c:439) 
[ 678.716370][ T1] iterate_tty_write (drivers/tty/tty_io.c:1022) 
[ 678.716375][ T1] file_tty_write+0x80/0x10c 
[ 678.716378][ T1] ? lock_release (kernel/locking/lockdep.c:467 kernel/locking/lockdep.c:5775) 
[ 678.716382][ T1] redirected_tty_write (drivers/tty/tty_io.c:1137) 
[ 678.716385][ T1] vfs_write (fs/read_write.c:492 fs/read_write.c:584) 
[ 678.716389][ T1] ? exit_to_user_mode_prepare (kernel/entry/common.c:212 (discriminator 43)) 
[ 678.716395][ T1] ksys_write (fs/read_write.c:638) 
[ 678.716398][ T1] __ia32_sys_write (fs/read_write.c:646) 
[ 678.716400][ T1] do_int80_syscall_32 (arch/x86/entry/common.c:164 arch/x86/entry/common.c:184) 
[ 678.716403][ T1] ? syscall_exit_to_user_mode (kernel/entry/common.c:299) 
[ 678.716406][ T1] ? do_int80_syscall_32 (arch/x86/entry/common.c:188) 
[ 678.716408][ T1] ? irqentry_exit_to_user_mode (kernel/entry/common.c:312) 
[ 678.716412][ T1] ? irqentry_exit (kernel/entry/common.c:445) 
[ 678.716415][ T1] ? exc_page_fault (arch/x86/mm/fault.c:1565) 
[ 678.716417][ T1] ? rest_init (init/main.c:1433) 
[ 678.716420][ T1] entry_INT80_32 (arch/x86/entry/entry_32.S:947) 
[  678.716424][    T1] EIP: 0xb7e9b6c2
[ 678.716427][ T1] Code: 90 66 90 66 90 66 90 90 56 53 83 ec 14 8b 5c 24 20 8b 4c 24 24 8b 54 24 28 65 a1 0c 00 00 00 85 c0 75 15 b8 04 00 00 00 cd 80 <3d> 00 f0 ff ff 77 47 83 c4 14 5b 5e c3 90 89 54 24 0c 89 4c 24 08
All code
========
   0:	90                   	nop
   1:	66 90                	xchg   %ax,%ax
   3:	66 90                	xchg   %ax,%ax
   5:	66 90                	xchg   %ax,%ax
   7:	90                   	nop
   8:	56                   	push   %rsi
   9:	53                   	push   %rbx
   a:	83 ec 14             	sub    $0x14,%esp
   d:	8b 5c 24 20          	mov    0x20(%rsp),%ebx
  11:	8b 4c 24 24          	mov    0x24(%rsp),%ecx
  15:	8b 54 24 28          	mov    0x28(%rsp),%edx
  19:	65 a1 0c 00 00 00 85 	movabs %gs:0x1575c0850000000c,%eax
  20:	c0 75 15 
  23:	b8 04 00 00 00       	mov    $0x4,%eax
  28:	cd 80                	int    $0x80


The kernel config and materials to reproduce are available at:
https://download.01.org/0day-ci/archive/20231128/202311282251.b5351d99-oliver.sang@intel.com



-- 
0-DAY CI Kernel Test Service
https://github.com/intel/lkp-tests/wiki


^ permalink raw reply	[flat|nested] 6+ messages in thread

end of thread, other threads:[~2023-11-28 15:12 UTC | newest]

Thread overview: 6+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2023-11-24 12:22 [RFC PATCH] serial: core: Use pm_runtime_get_sync() in uart_start() Xuewen Yan
2023-11-25  7:47 ` Tony Lindgren
2023-11-27  1:54   ` Xuewen Yan
2023-11-26 16:17 ` John Ogness
2023-11-27  2:06   ` Xuewen Yan
2023-11-28 15:11 ` kernel test robot

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for read-only IMAP folder(s) and NNTP newsgroup(s).