[PATCH] serial: 8250: Fix PM usage_count for console handover

[PATCH] serial: 8250: Fix PM usage_count for console handover

[Ilpo Järvinen]

When console is enabled, univ8250_console_setup() calls
serial8250_console_setup() before .dev is set to uart_port. Therefore,
it will not call pm_runtime_get_sync(). Later, when the actual driver
is going to take over univ8250_console_exit() is called. As .dev is
already set, serial8250_console_exit() makes pm_runtime_put_sync() call
with usage count being zero triggering PM usage count warning
(extra debug for univ8250_console_setup(), univ8250_console_exit(), and
serial8250_register_ports()):

[    0.068987] univ8250_console_setup ttyS0 nodev
[    0.499670] printk: console [ttyS0] enabled
[    0.717955] printk: console [ttyS0] printing thread started
[    1.960163] serial8250_register_ports assigned dev for ttyS0
[    1.976830] printk: console [ttyS0] disabled
[    1.976888] printk: console [ttyS0] printing thread stopped
[    1.977073] univ8250_console_exit ttyS0 usage:0
[    1.977075] serial8250 serial8250: Runtime PM usage count underflow!
[    1.977429] dw-apb-uart.6: ttyS0 at MMIO 0x4010006000 (irq = 33, base_baud = 115200) is a 16550A
[    1.977812] univ8250_console_setup ttyS0 usage:2
[    1.978167] printk: console [ttyS0] printing thread started
[    1.978203] printk: console [ttyS0] enabled

To fix the issue, call pm_runtime_get_sync() in
serial8250_register_ports() as soon as .dev is set for an uart_port
if it has console enabled.

This problem became apparent only recently because 82586a721595 ("PM:
runtime: Avoid device usage count underflows") added the warning
printout. I confirmed this problem also occurs with v5.18 (w/o the
warning printout, obviously) so the recent printk kthreads are not the
cause for this.

Fixes: bedb404e91bb ("serial: 8250_port: Don't use power management for kernel console")
Signed-off-by: Ilpo Järvinen <ilpo.jarvinen@linux.intel.com>

---
 drivers/tty/serial/8250/8250_core.c | 4 ++++
 drivers/tty/serial/serial_core.c    | 5 -----
 include/linux/serial_core.h         | 5 +++++
 3 files changed, 9 insertions(+), 5 deletions(-)

diff --git a/drivers/tty/serial/8250/8250_core.c b/drivers/tty/serial/8250/8250_core.c
index 57e86133af4f..2e83e7367441 100644
--- a/drivers/tty/serial/8250/8250_core.c
+++ b/drivers/tty/serial/8250/8250_core.c
@@ -23,6 +23,7 @@
 #include <linux/sysrq.h>
 #include <linux/delay.h>
 #include <linux/platform_device.h>
+#include <linux/pm_runtime.h>
 #include <linux/tty.h>
 #include <linux/ratelimit.h>
 #include <linux/tty_flip.h>
@@ -558,6 +559,9 @@ serial8250_register_ports(struct uart_driver *drv, struct device *dev)
 
 		up->port.dev = dev;
 
+		if (uart_console_enabled(&up->port))
+			pm_runtime_get_sync(up->port.dev);
+
 		serial8250_apply_quirks(up);
 		uart_add_one_port(drv, &up->port);
 	}
diff --git a/drivers/tty/serial/serial_core.c b/drivers/tty/serial/serial_core.c
index 85ef7ef00b82..3161445504bc 100644
--- a/drivers/tty/serial/serial_core.c
+++ b/drivers/tty/serial/serial_core.c
@@ -2024,11 +2024,6 @@ static int uart_proc_show(struct seq_file *m, void *v)
 }
 #endif
 
-static inline bool uart_console_enabled(struct uart_port *port)
-{
-	return uart_console(port) && (port->cons->flags & CON_ENABLED);
-}
-
 static void uart_port_spin_lock_init(struct uart_port *port)
 {
 	spin_lock_init(&port->lock);
diff --git a/include/linux/serial_core.h b/include/linux/serial_core.h
index b7b86ee3cb12..9d8aa139b175 100644
--- a/include/linux/serial_core.h
+++ b/include/linux/serial_core.h
@@ -404,6 +404,11 @@ static const bool earlycon_acpi_spcr_enable EARLYCON_USED_OR_UNUSED;
 static inline int setup_earlycon(char *buf) { return 0; }
 #endif
 
+static inline bool uart_console_enabled(struct uart_port *port)
+{
+	return uart_console(port) && (port->cons->flags & CON_ENABLED);
+}
+
 struct uart_port *uart_get_console(struct uart_port *ports, int nr,
 				   struct console *c);
 int uart_parse_earlycon(char *p, unsigned char *iotype, resource_size_t *addr,

-- 
tg: (f287f971e256..) fix/console-usage_count (depends on: tty-next)

Re: [PATCH] serial: 8250: Fix PM usage_count for console handover

[Andy Shevchenko]

On Tue, Jun 28, 2022 at 07:58:34PM +0300, Ilpo Järvinen wrote:
> When console is enabled, univ8250_console_setup() calls
> serial8250_console_setup() before .dev is set to uart_port. Therefore,
> it will not call pm_runtime_get_sync(). Later, when the actual driver
> is going to take over univ8250_console_exit() is called. As .dev is
> already set, serial8250_console_exit() makes pm_runtime_put_sync() call
> with usage count being zero triggering PM usage count warning
> (extra debug for univ8250_console_setup(), univ8250_console_exit(), and
> serial8250_register_ports()):
> 
> [    0.068987] univ8250_console_setup ttyS0 nodev
> [    0.499670] printk: console [ttyS0] enabled
> [    0.717955] printk: console [ttyS0] printing thread started
> [    1.960163] serial8250_register_ports assigned dev for ttyS0
> [    1.976830] printk: console [ttyS0] disabled
> [    1.976888] printk: console [ttyS0] printing thread stopped
> [    1.977073] univ8250_console_exit ttyS0 usage:0
> [    1.977075] serial8250 serial8250: Runtime PM usage count underflow!
> [    1.977429] dw-apb-uart.6: ttyS0 at MMIO 0x4010006000 (irq = 33, base_baud = 115200) is a 16550A
> [    1.977812] univ8250_console_setup ttyS0 usage:2
> [    1.978167] printk: console [ttyS0] printing thread started
> [    1.978203] printk: console [ttyS0] enabled
> 
> To fix the issue, call pm_runtime_get_sync() in
> serial8250_register_ports() as soon as .dev is set for an uart_port
> if it has console enabled.
> 
> This problem became apparent only recently because 82586a721595 ("PM:
> runtime: Avoid device usage count underflows") added the warning
> printout. I confirmed this problem also occurs with v5.18 (w/o the
> warning printout, obviously) so the recent printk kthreads are not the
> cause for this.

Since printk kthread was reverted, you may drop its mention here completely.

In any case, good catch!
Reviewed-by: Andy Shevchenko <andriy.shevchenko@linux.intel.com>

But it would be good to be tested by Tony.

> Fixes: bedb404e91bb ("serial: 8250_port: Don't use power management for kernel console")
> Signed-off-by: Ilpo Järvinen <ilpo.jarvinen@linux.intel.com>
> 
> ---
>  drivers/tty/serial/8250/8250_core.c | 4 ++++
>  drivers/tty/serial/serial_core.c    | 5 -----
>  include/linux/serial_core.h         | 5 +++++
>  3 files changed, 9 insertions(+), 5 deletions(-)
> 
> diff --git a/drivers/tty/serial/8250/8250_core.c b/drivers/tty/serial/8250/8250_core.c
> index 57e86133af4f..2e83e7367441 100644
> --- a/drivers/tty/serial/8250/8250_core.c
> +++ b/drivers/tty/serial/8250/8250_core.c
> @@ -23,6 +23,7 @@
>  #include <linux/sysrq.h>
>  #include <linux/delay.h>
>  #include <linux/platform_device.h>
> +#include <linux/pm_runtime.h>
>  #include <linux/tty.h>
>  #include <linux/ratelimit.h>
>  #include <linux/tty_flip.h>
> @@ -558,6 +559,9 @@ serial8250_register_ports(struct uart_driver *drv, struct device *dev)
>  
>  		up->port.dev = dev;
>  
> +		if (uart_console_enabled(&up->port))
> +			pm_runtime_get_sync(up->port.dev);
> +
>  		serial8250_apply_quirks(up);
>  		uart_add_one_port(drv, &up->port);
>  	}
> diff --git a/drivers/tty/serial/serial_core.c b/drivers/tty/serial/serial_core.c
> index 85ef7ef00b82..3161445504bc 100644
> --- a/drivers/tty/serial/serial_core.c
> +++ b/drivers/tty/serial/serial_core.c
> @@ -2024,11 +2024,6 @@ static int uart_proc_show(struct seq_file *m, void *v)
>  }
>  #endif
>  
> -static inline bool uart_console_enabled(struct uart_port *port)
> -{
> -	return uart_console(port) && (port->cons->flags & CON_ENABLED);
> -}
> -
>  static void uart_port_spin_lock_init(struct uart_port *port)
>  {
>  	spin_lock_init(&port->lock);
> diff --git a/include/linux/serial_core.h b/include/linux/serial_core.h
> index b7b86ee3cb12..9d8aa139b175 100644
> --- a/include/linux/serial_core.h
> +++ b/include/linux/serial_core.h
> @@ -404,6 +404,11 @@ static const bool earlycon_acpi_spcr_enable EARLYCON_USED_OR_UNUSED;
>  static inline int setup_earlycon(char *buf) { return 0; }
>  #endif
>  
> +static inline bool uart_console_enabled(struct uart_port *port)
> +{
> +	return uart_console(port) && (port->cons->flags & CON_ENABLED);
> +}
> +
>  struct uart_port *uart_get_console(struct uart_port *ports, int nr,
>  				   struct console *c);
>  int uart_parse_earlycon(char *p, unsigned char *iotype, resource_size_t *addr,
> 
> -- 
> tg: (f287f971e256..) fix/console-usage_count (depends on: tty-next)

-- 
With Best Regards,
Andy Shevchenko

Re: [PATCH] serial: 8250: Fix PM usage_count for console handover

[Tony Lindgren]

* Andy Shevchenko <andriy.shevchenko@linux.intel.com> [220628 21:09]:
> On Tue, Jun 28, 2022 at 07:58:34PM +0300, Ilpo Järvinen wrote:
> > When console is enabled, univ8250_console_setup() calls
> > serial8250_console_setup() before .dev is set to uart_port. Therefore,
> > it will not call pm_runtime_get_sync(). Later, when the actual driver
> > is going to take over univ8250_console_exit() is called. As .dev is
> > already set, serial8250_console_exit() makes pm_runtime_put_sync() call
> > with usage count being zero triggering PM usage count warning
> > (extra debug for univ8250_console_setup(), univ8250_console_exit(), and
> > serial8250_register_ports()):

Hmm so serial8250_console_setup() calls pm_runtime_get_sync() if dev
exists..

> > diff --git a/drivers/tty/serial/8250/8250_core.c b/drivers/tty/serial/8250/8250_core.c
> > index 57e86133af4f..2e83e7367441 100644
> > --- a/drivers/tty/serial/8250/8250_core.c
> > +++ b/drivers/tty/serial/8250/8250_core.c
> > @@ -23,6 +23,7 @@
> >  #include <linux/sysrq.h>
> >  #include <linux/delay.h>
> >  #include <linux/platform_device.h>
> > +#include <linux/pm_runtime.h>
> >  #include <linux/tty.h>
> >  #include <linux/ratelimit.h>
> >  #include <linux/tty_flip.h>
> > @@ -558,6 +559,9 @@ serial8250_register_ports(struct uart_driver *drv, struct device *dev)
> >  
> >  		up->port.dev = dev;
> >  
> > +		if (uart_console_enabled(&up->port))
> > +			pm_runtime_get_sync(up->port.dev);
> > +
> >  		serial8250_apply_quirks(up);
> >  		uart_add_one_port(drv, &up->port);
> >  	}

..and now we also call it here. Are there now cases where pm_runtime_get_sync()
gets called twice potentially or does uart_console_enabled() ensure that is
not the case already?

Regards,

Tony

Re: [PATCH] serial: 8250: Fix PM usage_count for console handover

[Ilpo Järvinen]

[-- Attachment #1: Type: text/plain, Size: 2108 bytes --]

On Wed, 29 Jun 2022, Tony Lindgren wrote:

> * Andy Shevchenko <andriy.shevchenko@linux.intel.com> [220628 21:09]:
> > On Tue, Jun 28, 2022 at 07:58:34PM +0300, Ilpo Järvinen wrote:
> > > When console is enabled, univ8250_console_setup() calls
> > > serial8250_console_setup() before .dev is set to uart_port. Therefore,
> > > it will not call pm_runtime_get_sync(). Later, when the actual driver
> > > is going to take over univ8250_console_exit() is called. As .dev is
> > > already set, serial8250_console_exit() makes pm_runtime_put_sync() call
> > > with usage count being zero triggering PM usage count warning
> > > (extra debug for univ8250_console_setup(), univ8250_console_exit(), and
> > > serial8250_register_ports()):
> 
> Hmm so serial8250_console_setup() calls pm_runtime_get_sync() if dev
> exists..
> 
> > > diff --git a/drivers/tty/serial/8250/8250_core.c b/drivers/tty/serial/8250/8250_core.c
> > > index 57e86133af4f..2e83e7367441 100644
> > > --- a/drivers/tty/serial/8250/8250_core.c
> > > +++ b/drivers/tty/serial/8250/8250_core.c
> > > @@ -23,6 +23,7 @@
> > >  #include <linux/sysrq.h>
> > >  #include <linux/delay.h>
> > >  #include <linux/platform_device.h>
> > > +#include <linux/pm_runtime.h>
> > >  #include <linux/tty.h>
> > >  #include <linux/ratelimit.h>
> > >  #include <linux/tty_flip.h>
> > > @@ -558,6 +559,9 @@ serial8250_register_ports(struct uart_driver *drv, struct device *dev)
> > >  
> > >  		up->port.dev = dev;
> > >  
> > > +		if (uart_console_enabled(&up->port))
> > > +			pm_runtime_get_sync(up->port.dev);
> > > +
> > >  		serial8250_apply_quirks(up);
> > >  		uart_add_one_port(drv, &up->port);
> > >  	}
> 
> ..and now we also call it here. Are there now cases where pm_runtime_get_sync()
> gets called twice potentially or does uart_console_enabled() ensure that is
> not the case already?

The code in serial8250_register_ports() right before that context block is 
this:

		if (up->port.dev)
			continue;

If serial8250_console_setup() already saw .dev != NULL, we take that 
continue and pm_runtime_get_sync() will not get called again here.


-- 
 i.

Re: [PATCH] serial: 8250: Fix PM usage_count for console handover

[Tony Lindgren]

* Ilpo Järvinen <ilpo.jarvinen@linux.intel.com> [220629 09:26]:
> On Wed, 29 Jun 2022, Tony Lindgren wrote:
> 
> > * Andy Shevchenko <andriy.shevchenko@linux.intel.com> [220628 21:09]:
> > > On Tue, Jun 28, 2022 at 07:58:34PM +0300, Ilpo Järvinen wrote:
> > > > When console is enabled, univ8250_console_setup() calls
> > > > serial8250_console_setup() before .dev is set to uart_port. Therefore,
> > > > it will not call pm_runtime_get_sync(). Later, when the actual driver
> > > > is going to take over univ8250_console_exit() is called. As .dev is
> > > > already set, serial8250_console_exit() makes pm_runtime_put_sync() call
> > > > with usage count being zero triggering PM usage count warning
> > > > (extra debug for univ8250_console_setup(), univ8250_console_exit(), and
> > > > serial8250_register_ports()):
> > 
> > Hmm so serial8250_console_setup() calls pm_runtime_get_sync() if dev
> > exists..
> > 
> > > > diff --git a/drivers/tty/serial/8250/8250_core.c b/drivers/tty/serial/8250/8250_core.c
> > > > index 57e86133af4f..2e83e7367441 100644
> > > > --- a/drivers/tty/serial/8250/8250_core.c
> > > > +++ b/drivers/tty/serial/8250/8250_core.c
> > > > @@ -23,6 +23,7 @@
> > > >  #include <linux/sysrq.h>
> > > >  #include <linux/delay.h>
> > > >  #include <linux/platform_device.h>
> > > > +#include <linux/pm_runtime.h>
> > > >  #include <linux/tty.h>
> > > >  #include <linux/ratelimit.h>
> > > >  #include <linux/tty_flip.h>
> > > > @@ -558,6 +559,9 @@ serial8250_register_ports(struct uart_driver *drv, struct device *dev)
> > > >  
> > > >  		up->port.dev = dev;
> > > >  
> > > > +		if (uart_console_enabled(&up->port))
> > > > +			pm_runtime_get_sync(up->port.dev);
> > > > +
> > > >  		serial8250_apply_quirks(up);
> > > >  		uart_add_one_port(drv, &up->port);
> > > >  	}
> > 
> > ..and now we also call it here. Are there now cases where pm_runtime_get_sync()
> > gets called twice potentially or does uart_console_enabled() ensure that is
> > not the case already?
> 
> The code in serial8250_register_ports() right before that context block is 
> this:
> 
> 		if (up->port.dev)
> 			continue;
> 
> If serial8250_console_setup() already saw .dev != NULL, we take that 
> continue and pm_runtime_get_sync() will not get called again here.

OK thanks. Looks good to me:

Reviewed-by: Tony Lindgren <tony@atomide.com>
Tested-by: Tony Lindgren <tony@atomide.com>