[RESEND RFC PATCH v1 0/2] Fix serial console for PREEMPT_RT

[RESEND RFC PATCH v1 0/2] Fix serial console for PREEMPT_RT

[Leonardo Bras]

While dealing with a bug that breaks the serial console from qemu (8250)
after printing a lot of data, I found some issues on this driver on RT
as well as spurious IRQ behaviors that don't seem to be adeqate for RT.

Comments:
Patch #1:
I found out this driver get an IRQ request for every tx byte, but the
handler is able to deal with sending multiple bytes per "thread wake up". 

Since the irqs_unhandled keep growing, and theads_handled don't change
as often, after some intense load (tx ~300kBytes) the serial will 
disable the IRQ line for this driver, which ultimately breaks the console.

My fist solution kept track of how many requests given handler dealt with,
which got added to theads_handled. On note_interrupt I got the diff from
theads_handled_last and subtracted that diff from irqs_unhandled.

This solution required a change in the irqreturn_t typedef and a bunch of
helpers and defines, as well as adapting the 8250 driver. 
At the end seemed like a overcomplicated solution for the issue, but it
can be an alternative if the current solution is considered imprecise.

Mu cyrrent solution on patch #1 is much simpler, just keeping the
IRQ enabled as long as the irq_thread deal with any IRQ request before
irqs_unhandled hitting the limit value.

Patch #2:
In RT, the 8250 driver has an issue if it's interrupted while holding the
port->lock. If the interruption needs to printk() anything, it
will try to get the port->lock, which is busy, so spin_lock() will try
to reschedule the interruption, which is in atomic context, and will 
trigger a bug.

This bug reproduces quite often, like in 50% of tests I did. 

The only thing I could think of for fixing this is using in_atomic()
when PREEMPT_RT=y, so it makes use of the same mechanism as for
oops_in_progress to avoid getting the lock if it's busy. It's working
just fine.

Yeah, I got the warning in checkpath:
"ERROR: do not use in_atomic in drivers"

So I need some feedback on what to do to avoid this bug, if not 
by using in_atomic() at this driver.

Since this one is linked to the console, any printk will try to get
this drivers port->lock, and so it's kind of hard to avoid this accesses.

I though on doing an interface for spin_lock_only_if_can_sleep() but
it seemed overkill.

Please provide comments / feedback.

Thanks!
Leo


Leonardo Bras (2):
  irq/spurious: Reset irqs_unhandled if an irq_thread handles one IRQ
    request
  serial/8250: Avoid getting lock in RT atomic context

 drivers/tty/serial/8250/8250_port.c | 2 +-
 kernel/irq/spurious.c               | 8 ++++++++
 2 files changed, 9 insertions(+), 1 deletion(-)


base-commit: 052d534373b7ed33712a63d5e17b2b6cdbce84fd
-- 
2.43.0

[RESEND RFC PATCH v1 1/2] irq/spurious: Reset irqs_unhandled if an irq_thread handles one IRQ request

[Leonardo Bras]

When the IRQs are threaded, the part of the handler that runs in
interruption context can be pretty fast, as per design, while letting the
slow part to run into the thread handler.

In some cases, given IRQs can be triggered too fast, making it impossible
for the irq_thread to be able to keep up handling every request.

If two requests happen before any irq_thread handler is able to finish,
no increment to threads_handled happen, causing threads_handled and
threads_handled_last to be equal, which will ends up
causing irqs_unhandled to be incremented in note_interrupt().

Once irqs_unhandled gets to ~100k, the IRQ line gets disabled, disrupting
the device work.

As of today, the only way to reset irqs_unhandled before disabling the IRQ
line is to stay 100ms without having any increment to irqs_unhandled, which
can be pretty hard to happen if the IRQ is very busy.

On top of that, some irq_thread handlers can handle requests in batches,
effectively incrementing threads_handled only once despite dealing with a
lot of requests, which make the irqs_unhandled to reach 100k pretty fast
if the IRQ is getting a lot of requests.

This IRQ line disable bug can be easily reproduced with a serial8250
console on a PREEMPT_RT kernel: it only takes the user to print a lot
of text to the console (or to ttyS0): around 300k chars should be enough.

To fix this bug, reset irqs_unhandled whenever irq_thread handles at least
one IRQ request.

This fix makes possible to avoid disabling IRQs which irq_thread handlers
can take long (while on heavy usage of the IRQ line), without losing the
ability of disabling IRQs that actually get unhandled for too long.

Signed-off-by: Leonardo Bras <leobras@redhat.com>
---
 kernel/irq/spurious.c | 8 ++++++++
 1 file changed, 8 insertions(+)

diff --git a/kernel/irq/spurious.c b/kernel/irq/spurious.c
index 02b2daf074414..b60748f89738a 100644
--- a/kernel/irq/spurious.c
+++ b/kernel/irq/spurious.c
@@ -339,6 +339,14 @@ void note_interrupt(struct irq_desc *desc, irqreturn_t action_ret)
 			handled |= SPURIOUS_DEFERRED;
 			if (handled != desc->threads_handled_last) {
 				action_ret = IRQ_HANDLED;
+
+				/*
+				 * If the thread handlers handle
+				 * one IRQ reset the unhandled
+				 * IRQ counter.
+				 */
+				desc->irqs_unhandled = 0;
+
 				/*
 				 * Note: We keep the SPURIOUS_DEFERRED
 				 * bit set. We are handling the
-- 
2.43.0

Re: [RESEND RFC PATCH v1 1/2] irq/spurious: Reset irqs_unhandled if an irq_thread handles one IRQ request

[Thomas Gleixner]

On Tue, Jan 16 2024 at 04:36, Leonardo Bras wrote:
> This IRQ line disable bug can be easily reproduced with a serial8250
> console on a PREEMPT_RT kernel: it only takes the user to print a lot
> of text to the console (or to ttyS0): around 300k chars should be
> enough.

That has nothing to do with RT, it's a problem of force threaded
interrupts in combination with an edge type interrupt line and a
hardware which keeps firing interrupts forever.

> To fix this bug, reset irqs_unhandled whenever irq_thread handles at least
> one IRQ request.

This papers over the symptom and makes runaway detection way weaker for
all interrupts or breaks it completely.

The problem with edge type interrupts is that we cannot mask them like
we do with level type interrupts in the hard interrupt handler and
unmask them once the threaded handler finishes.

So yes, we need special rules here when:

   1) The interrupt handler is force threaded

   2) The interrupt line is edge type

   3) The accumulated unhandled interrupts are within a sane margin

Thanks,

        tglx

Re: [RESEND RFC PATCH v1 1/2] irq/spurious: Reset irqs_unhandled if an irq_thread handles one IRQ request

[Leonardo Bras]

On Wed, Jan 17, 2024 at 11:08:44PM +0100, Thomas Gleixner wrote:
> On Tue, Jan 16 2024 at 04:36, Leonardo Bras wrote:
> > This IRQ line disable bug can be easily reproduced with a serial8250
> > console on a PREEMPT_RT kernel: it only takes the user to print a lot
> > of text to the console (or to ttyS0): around 300k chars should be
> > enough.
> 
> That has nothing to do with RT, it's a problem of force threaded
> interrupts in combination with an edge type interrupt line and a
> hardware which keeps firing interrupts forever.

Hello Thomas, thanks for your feedback!

I agreed it has nothing to do with RT.
I just mentioned PREEMPT_RT as my test case scenario, since it enables 
force-threaded IRQs.

> 
> > To fix this bug, reset irqs_unhandled whenever irq_thread handles at least
> > one IRQ request.
> 
> This papers over the symptom and makes runaway detection way weaker for
> all interrupts or breaks it completely.

This change is supposed to only touch threaded interruptions, since it will
reach the included line only if (action_ret == IRQ_WAKE_THREAD) and if 
desc->threads_handled changes since the last IRQ request.

This incrementing also happens only on irq_forced_thread_fn() and 
irq_thread_fn(), which are called only from irq_thread_fn().

But I get the overall worry about having this making runaway detection way 
weaker for all threaded interrupts.

I have previously worked on a solution that can be more precise and be an 
opt-in for drivers instead of a general solution:

It required a change in IRQ interface that let the handlers inform how 
many IRQs were actually handled (batching). This number would then be 
added to desc->threads_handle (in irq_*thread_fn(), just changing the 
atomic_inc() to atomic_add()), and then subtracted from irqs_unhandled
at note_interrupt().

In the serial8250 case, the driver would be changed to use that interface, 
since it's already able to process multiple IRQs, and the bug just 
vanishes.

This also solved the serial driver issue, but required a deeper change in 
the code, which caused me to consider a simpler solution first.

This solution sure does give better runnaway detection. Do you think it 
would be better that the one I sent in this patch?

> 
> The problem with edge type interrupts is that we cannot mask them like
> we do with level type interrupts in the hard interrupt handler and
> unmask them once the threaded handler finishes.
> 
> So yes, we need special rules here when:
> 
>    1) The interrupt handler is force threaded
> 
>    2) The interrupt line is edge type
> 
>    3) The accumulated unhandled interrupts are within a sane margin
> 
> Thanks,
> 
>         tglx
> 

Completelly agree, that's why I am suggesting dealing with threaded 
interruptions in a different way: reseting the unhandled count when it 
handles a request. 

I am not sure how force threaded and just threaded are different in this 
scenario. Could you help me understand?

Thanks!
Leo

Re: [RESEND RFC PATCH v1 1/2] irq/spurious: Reset irqs_unhandled if an irq_thread handles one IRQ request

[Leonardo Bras]

On Wed, Jan 17, 2024 at 07:46:28PM -0300, Leonardo Bras wrote:
> On Wed, Jan 17, 2024 at 11:08:44PM +0100, Thomas Gleixner wrote:
> > On Tue, Jan 16 2024 at 04:36, Leonardo Bras wrote:
> > > This IRQ line disable bug can be easily reproduced with a serial8250
> > > console on a PREEMPT_RT kernel: it only takes the user to print a lot
> > > of text to the console (or to ttyS0): around 300k chars should be
> > > enough.
> > 
> > That has nothing to do with RT, it's a problem of force threaded
> > interrupts in combination with an edge type interrupt line and a
> > hardware which keeps firing interrupts forever.
> 
> Hello Thomas, thanks for your feedback!
> 
> I agreed it has nothing to do with RT.
> I just mentioned PREEMPT_RT as my test case scenario, since it enables 
> force-threaded IRQs.
> 
> > 
> > > To fix this bug, reset irqs_unhandled whenever irq_thread handles at least
> > > one IRQ request.
> > 
> > This papers over the symptom and makes runaway detection way weaker for
> > all interrupts or breaks it completely.
> 
> This change is supposed to only touch threaded interruptions, since it will
> reach the included line only if (action_ret == IRQ_WAKE_THREAD) and if 
> desc->threads_handled changes since the last IRQ request.
> 
> This incrementing also happens only on irq_forced_thread_fn() and 
> irq_thread_fn(), which are called only from irq_thread_fn().
> 
> But I get the overall worry about having this making runaway detection way 
> weaker for all threaded interrupts.
> 
> I have previously worked on a solution that can be more precise and be an 
> opt-in for drivers instead of a general solution:
> 
> It required a change in IRQ interface that let the handlers inform how 
> many IRQs were actually handled (batching). This number would then be 
> added to desc->threads_handle (in irq_*thread_fn(), just changing the 
> atomic_inc() to atomic_add()), and then subtracted from irqs_unhandled
> at note_interrupt().
> 
> In the serial8250 case, the driver would be changed to use that interface, 
> since it's already able to process multiple IRQs, and the bug just 
> vanishes.
> 
> This also solved the serial driver issue, but required a deeper change in 
> the code, which caused me to consider a simpler solution first.
> 
> This solution sure does give better runnaway detection. Do you think it 
> would be better that the one I sent in this patch?

For reference, this is the alternative:
https://gitlab.com/LeoBras/linux/-/commits/serial8250

Please let me know it you think this one is better.

Thanks!
Leo

> 
> > 
> > The problem with edge type interrupts is that we cannot mask them like
> > we do with level type interrupts in the hard interrupt handler and
> > unmask them once the threaded handler finishes.
> > 
> > So yes, we need special rules here when:
> > 
> >    1) The interrupt handler is force threaded
> > 
> >    2) The interrupt line is edge type
> > 
> >    3) The accumulated unhandled interrupts are within a sane margin
> > 
> > Thanks,
> > 
> >         tglx
> > 
> 
> Completelly agree, that's why I am suggesting dealing with threaded 
> interruptions in a different way: reseting the unhandled count when it 
> handles a request. 
> 
> I am not sure how force threaded and just threaded are different in this 
> scenario. Could you help me understand?
> 
> Thanks!
> Leo

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

[Leonardo Bras]

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.

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

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

[Ilpo Järvinen]

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.

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.

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

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

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

[John Ogness]

On 2024-01-16, Leonardo Bras <leobras@redhat.com> wrote:
> 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

This is 6.7.0-rc6+. How are you setting PREEMPT_RT?

> [   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

On PREEMPT_RT-patched kernel, serial8250_console_write() is not
compiled. So obviously you are not running a PREEMPT_RT-patched kernel.

> [   42.486094]  console_flush_all+0x18d/0x3c0
> [   42.486111]  console_unlock+0x6c/0xd0

Flushing on console_unlock() is the legacy method.

I assume you are using a mainline kernel with forced threading of
irqs. Mainline has many known problems with console printing, including
calling printk when the port->lock is held.

This has been discussed before [0].

> [   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>

If you want to fix any threaded irq problems relating to printk and
console drivers, please use the latest PREEMPT_RT patch series with
CONFIG_PREEMPT_RT enabled. This is the current work that is being
reviewed on LKML for mainline inclusion. Thanks!

John Ogness

[0] https://lore.kernel.org/lkml/87il5o32w9.fsf@jogness.linutronix.de

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

[Leonardo Bras]

On Thu, Jan 18, 2024 at 10:07:45AM +0106, John Ogness wrote:
> On 2024-01-16, Leonardo Bras <leobras@redhat.com> wrote:
> > 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
> 
> This is 6.7.0-rc6+. How are you setting PREEMPT_RT?

By setting ARCH_SUPPORTS_RT=y

> 
> > [   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
> 
> On PREEMPT_RT-patched kernel, serial8250_console_write() is not
> compiled. So obviously you are not running a PREEMPT_RT-patched kernel.

Yes, as mentioned to Thomas before, I am on Vanilla torvalds/linux.
I was not aware of any extra patches for PREEMPT_RT, could you please point 
the repo, or the patchset for that PREEMPT_RT-patched version?

> 
> > [   42.486094]  console_flush_all+0x18d/0x3c0
> > [   42.486111]  console_unlock+0x6c/0xd0
> 
> Flushing on console_unlock() is the legacy method.

Great! so this part is solved :)

> 
> I assume you are using a mainline kernel with forced threading of
> irqs. Mainline has many known problems with console printing, including
> calling printk when the port->lock is held.

I am using mainline (torvalds/linux) kernel, forcing ARCH_SUPPORTS_RT:

diff --git a/arch/Kconfig b/arch/Kconfig
index 5ca66aad0d08..879c34398cb7 100644
--- a/arch/Kconfig
+++ b/arch/Kconfig
@@ -1195,7 +1195,7 @@ config ARCH_NO_PREEMPT
        bool
 
 config ARCH_SUPPORTS_RT
-       bool
+       def_bool y

Since I was not aware of a PREEMPT_RT-patched tree, I did this so I could 
compile a PREEMPT_RT kernel.


> 
> This has been discussed before [0].
> 
> > [   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>
> 
> If you want to fix any threaded irq problems relating to printk and
> console drivers, please use the latest PREEMPT_RT patch series with
> CONFIG_PREEMPT_RT enabled. This is the current work that is being
> reviewed on LKML for mainline inclusion. Thanks!
> 

Sure, please let me know of where can I find the latest PREEMPT_RT patch 
series so I can re-test my bug. By what you comment, it's higly probable 
that patch 2/2 will not be necessary.

On the other hand, unless some extra work was done in preventing the 
scenario in patch 1/2, I think that can still be discussed. 

> John Ogness
> 
> [0] https://lore.kernel.org/lkml/87il5o32w9.fsf@jogness.linutronix.de
> 

Thanks!
Leo

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

[John Ogness]

On 2024-01-18, Leonardo Bras <leobras@redhat.com> wrote:
> Sure, please let me know of where can I find the latest PREEMPT_RT
> patch series so I can re-test my bug. By what you comment, it's higly
> probable that patch 2/2 will not be necessary.

Some links for you:


The Real-Time Wiki at the Linux Foundation:

https://wiki.linuxfoundation.org/realtime/


The latest development RT patch series for 6.7:

https://cdn.kernel.org/pub/linux/kernel/projects/rt/6.7/patches-6.7-rt6.tar.xz


RT git (branch linux-6.7.y-rt-rebase is probably what you want):

https://git.kernel.org/pub/scm/linux/kernel/git/rt/linux-rt-devel.git


> On the other hand, unless some extra work was done in preventing the
> scenario in patch 1/2, I think that can still be discussed.

I agree. Thanks for looking into this.

John

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

[Leonardo Bras]

On Thu, Jan 18, 2024 at 11:33:04AM +0106, John Ogness wrote:
> On 2024-01-18, Leonardo Bras <leobras@redhat.com> wrote:
> > Sure, please let me know of where can I find the latest PREEMPT_RT
> > patch series so I can re-test my bug. By what you comment, it's higly
> > probable that patch 2/2 will not be necessary.
> 
> Some links for you:
> 
> 
> The Real-Time Wiki at the Linux Foundation:
> 
> https://wiki.linuxfoundation.org/realtime/
> 
> 
> The latest development RT patch series for 6.7:
> 
> https://cdn.kernel.org/pub/linux/kernel/projects/rt/6.7/patches-6.7-rt6.tar.xz
> 
> 
> RT git (branch linux-6.7.y-rt-rebase is probably what you want):
> 
> https://git.kernel.org/pub/scm/linux/kernel/git/rt/linux-rt-devel.git
> 

Hello John, thank you for sharing the links!

> 
> > On the other hand, unless some extra work was done in preventing the
> > scenario in patch 1/2, I think that can still be discussed.
> 
> I agree. Thanks for looking into this.
> 
> John
> 

Thank you!
Leo

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

[Jiri Slaby]

On 18. 01. 24, 10:36, Leonardo Bras wrote:
> I am using mainline (torvalds/linux) kernel, forcing ARCH_SUPPORTS_RT:
> 
> diff --git a/arch/Kconfig b/arch/Kconfig
> index 5ca66aad0d08..879c34398cb7 100644
> --- a/arch/Kconfig
> +++ b/arch/Kconfig
> @@ -1195,7 +1195,7 @@ config ARCH_NO_PREEMPT
>          bool
>   
>   config ARCH_SUPPORTS_RT
> -       bool
> +       def_bool y
> 
> Since I was not aware of a PREEMPT_RT-patched tree, I did this so I could
> compile a PREEMPT_RT kernel.

Huh, when exactly did you intend to mention this?

-- 
js
suse labs

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

[Leonardo Bras]

On Thu, Jan 18, 2024 at 11:33:08AM +0100, Jiri Slaby wrote:
> On 18. 01. 24, 10:36, Leonardo Bras wrote:
> > I am using mainline (torvalds/linux) kernel, forcing ARCH_SUPPORTS_RT:
> > 
> > diff --git a/arch/Kconfig b/arch/Kconfig
> > index 5ca66aad0d08..879c34398cb7 100644
> > --- a/arch/Kconfig
> > +++ b/arch/Kconfig
> > @@ -1195,7 +1195,7 @@ config ARCH_NO_PREEMPT
> >          bool
> >   config ARCH_SUPPORTS_RT
> > -       bool
> > +       def_bool y
> > 
> > Since I was not aware of a PREEMPT_RT-patched tree, I did this so I could
> > compile a PREEMPT_RT kernel.
> 
> Huh, when exactly did you intend to mention this?

Since I was not aware of an PREEMPT_RT-patched tree, I thought that this 
was the vanilla way to get a PREEMPT_RT kernel running. 

TBH I did not even though that there were an external repo for PREEMPT_RT. 
I mean, I knew about non-mainline patches in the past, but I thought 
everything got already merged upstream, and any other patches would be WIP.

I understand this was a mistake on my part, and I feel sorry if this 
brought any pain to reviewers. For the future, I will be basing my RT 
work in this RT-devel tree shared by John.

Thanks!
Leo

> 
> -- 
> js
> suse labs
> 

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

[Thomas Gleixner]

On Tue, Jan 16 2024 at 04:37, 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.
>
> 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.

That's just blantantly wrong. The locks are really only to be ignored
for the oops case, but not for regular printk.

I assume that this is not against the latest RT kernel as that should
not have that problem at all.

Thanks,

        tglx

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

[Leonardo Bras]

On Wed, Jan 17, 2024 at 11:44:55PM +0100, Thomas Gleixner wrote:
> On Tue, Jan 16 2024 at 04:37, 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.
> >
> > 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.
> 
> That's just blantantly wrong. The locks are really only to be ignored
> for the oops case, but not for regular printk.

I agree, but the alternative was to have a BUG() due to scheduling in 
atomic context. This would only ignore the lock if it was already taken 
anyway.

That being said, I agree it is not the best solution for the issue, and 
just sent this in the RFC in order to get feedback on what could be done.

> 
> I assume that this is not against the latest RT kernel as that should
> not have that problem at all.

I am based on torvalds/linux at master branch, so maybe I am missing some 
RT-specific patches. Which tree do you recommend me testing?

> 
> Thanks,
> 
>         tglx
> 

Thank you!
Leo