Re: [RESEND RFC PATCH v1 2/2] serial/8250: Avoid getting lock in RT atomic context

[Leonardo Bras]

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@xxxxxxxxxx>
> > ---
> >  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);
> > 
>