Received-SPF: pass (google.com: domain of linux-kernel+bounces-27685-linux.lists.archive=gmail.com@vger.kernel.org designates 147.75.199.223 as permitted sender) client-ip=147.75.199.223;
From: Leonardo Bras <leobras@redhat.com>
To: Ilpo =?iso-8859-1?Q?J=E4rvinen?= <ilpo.jarvinen@linux.intel.com>
Cc: Leonardo Bras <leobras@redhat.com>,
	Greg Kroah-Hartman <gregkh@linuxfoundation.org>,
	Jiri Slaby <jirislaby@kernel.org>,
	Thomas Gleixner <tglx@linutronix.de>,
	Andy Shevchenko <andriy.shevchenko@linux.intel.com>,
	Florian Fainelli <f.fainelli@gmail.com>,
	John Ogness <john.ogness@linutronix.de>,
	Tony Lindgren <tony@atomide.com>,
	Marcelo Tosatti <mtosatti@redhat.com>,
	LKML <linux-kernel@vger.kernel.org>,
	linux-serial <linux-serial@vger.kernel.org>
Subject: Re: [RESEND RFC PATCH v1 2/2] serial/8250: Avoid getting lock in RT atomic context
Date: Tue, 16 Jan 2024 15:21:13 -0300
Message-ID: <ZabJGefGkrs0SNzW@LeoBras>
In-Reply-To: <75a39f0a-8f79-eacf-4a35-5de512a3cbed@linux.intel.com>
References: <20240116073701.2356171-1-leobras@redhat.com> <20240116073701.2356171-3-leobras@redhat.com> <75a39f0a-8f79-eacf-4a35-5de512a3cbed@linux.intel.com>
Precedence: bulk
MIME-Version: 1.0
Content-Type: text/plain; charset=iso-8859-1
Content-Disposition: inline
Content-Transfer-Encoding: 8bit

On Tue, Jan 16, 2024 at 10:48:44AM +0200, Ilpo J?rvinen wrote:
> On Tue, 16 Jan 2024, Leonardo Bras wrote:
> 
> > With PREEMPT_RT enabled, a spin_lock_irqsave() becomes a possibly sleeping
> > spin_lock(), without preempt_disable() or irq_disable().
> > 
> > This allows a task T1 to get preempted or interrupted while holding the
> > port->lock. If the preempting task T2 need the lock, spin_lock() code
> > will schedule T1 back until it finishes using the lock, and then go back to
> > T2.
> > 
> > There is an issue if a T1 holding port->lock is interrupted by an
> > IRQ, and this IRQ handler needs to get port->lock for writting (printk):
> > spin_lock() code will try to reschedule the interrupt handler, which is in
> > atomic context, causing a BUG() for trying to reschedule/sleep in atomic
> > context.

Hello Ilpo, thanks for replying!

> 
> I thought that the printk side was supposed to be become aware when it's 
> not safe to write to serial side so the printing can be deferred... Has 
> that plan changed?
> 
> -- 
>  i.

I was not aware of this plan.

Well, at least in an PREEMPT_RT=y kernel I have found this same bug 
reproducing several times, and through the debugging that I went through I 
saw no mechanism for preventing it.

This is one example of the bug:
While writing to serial with serial8250_tx_chars in a irq_thread handler
there is an interruption, and __report_bad_irq() tries to printk 
stuff to the console, and when printk goes down to 
serial8250_console_write() and tried to get the port->lock, which causes 
the "BUG: scheduling while atomic":

[   42.485878] irq 4: nobody cared (try booting with the "irqpoll" option)
[   42.485886] BUG: scheduling while atomic: irq/4-ttyS0/751/0x00010002
[   42.485890] Modules linked in:
[   42.485892] Preemption disabled at:
[   42.485893] [<ffffffff8118ac80>] irq_enter_rcu+0x10/0x80
[   42.485919] CPU: 0 PID: 751 Comm: irq/4-ttyS0 Not tainted 6.7.0-rc6+ #6
[   42.485927] Hardware name: Red Hat KVM/RHEL, BIOS 1.16.3-1.el9 04/01/2014
[   42.485929] Call Trace:
[   42.485940]  <IRQ>
[   42.485944]  dump_stack_lvl+0x33/0x50
[   42.485976]  __schedule_bug+0x89/0xa0
[   42.485991]  schedule_debug.constprop.0+0xd1/0x120
[   42.485996]  __schedule+0x50/0x690
[   42.486026]  schedule_rtlock+0x1e/0x40
[   42.486029]  rtlock_slowlock_locked+0xe7/0x2b0
[   42.486047]  rt_spin_lock+0x41/0x60
[   42.486051]  serial8250_console_write+0x1be/0x460
[   42.486094]  console_flush_all+0x18d/0x3c0
[   42.486111]  console_unlock+0x6c/0xd0
[   42.486117]  vprintk_emit+0x1d6/0x290
[   42.486122]  _printk+0x58/0x80
[   42.486139]  __report_bad_irq+0x26/0xc0
[   42.486147]  note_interrupt+0x2a1/0x2f0
[   42.486155]  handle_irq_event+0x84/0x90
[   42.486161]  handle_edge_irq+0x9f/0x260
[   42.486168]  __common_interrupt+0x68/0x100
[   42.486178]  common_interrupt+0x9f/0xc0
[   42.486184]  </IRQ>


Thanks!
Leo

> 
> > So for the case (PREEMPT_RT && in_atomic()) try to get the lock, and if it
> > fails proceed anyway, just like it's done in oops_in_progress case.
> > 
> > Signed-off-by: Leonardo Bras <leobras@redhat.com>
> > ---
> >  drivers/tty/serial/8250/8250_port.c | 2 +-
> >  1 file changed, 1 insertion(+), 1 deletion(-)
> > 
> > diff --git a/drivers/tty/serial/8250/8250_port.c b/drivers/tty/serial/8250/8250_port.c
> > index 8ca061d3bbb92..8480832846319 100644
> > --- a/drivers/tty/serial/8250/8250_port.c
> > +++ b/drivers/tty/serial/8250/8250_port.c
> > @@ -3397,7 +3397,7 @@ void serial8250_console_write(struct uart_8250_port *up, const char *s,
> >  
> >  	touch_nmi_watchdog();
> >  
> > -	if (oops_in_progress)
> > +	if (oops_in_progress || (IS_ENABLED(CONFIG_PREEMPT_RT) && in_atomic())
> >  		locked = uart_port_trylock_irqsave(port, &flags);
> >  	else
> >  		uart_port_lock_irqsave(port, &flags);
> > 
>