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

Leonardo Bras
2024-01-16T18:21:21Z

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