lkml.org 
[lkml]   [2020]   [Apr]   [23]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
/
Date
From
SubjectRe: [PREEMPT_RT] 8250 IRQ lockup when flooding serial console (was Re: [ANNOUNCE] v5.4.28-rt19)
On Thu, 23 Apr 2020 21:48:20 +0200 (CEST)
Jiri Kosina <jikos@kernel.org> wrote:

> On Thu, 23 Apr 2020, Sebastian Andrzej Siewior wrote:
>
> > The IRQ4 is edge and in charge of ttyS0. It is handled by
> > handle_edge_irq() and after ->irq_ack(), the thread is woken up and then
> > we get another ->handle_edge_irq() for IRQ4. With larger PASS_LIMIT the
> > thread runs longer so note_interrupt() will make less IRQ_HANDLED based
> > on ->threads_handled_last. If it observes 100 handled within 100000
> > interrupts then the counters are reset again. On !RT it usually manages
> > to get >100 per 100000 interrupts so it appears good. On RT it gets less
> > and the interrupt gets disabled.
> >
> > So it is not RT related, but RT triggers it more reliably (also the
> > PASS_LIMIT change can vanish). I can't tell if this is a qemu bug in
> > emulating the HW or not. I can't reproduce it real HW. I see a second
> > edge interrupt only after the thread completed. I can't tell if this is
> > because it is a real UART and the data is flowing slower or because the
> > edge-IRQ is not triggered repeatedly.
>
> Yeah, it's all strange. In the hope of understanding the issue a little
> bit better, I tried to disable IRQs in serial8250_handle_irq() to mimic
> what !PREEMPT_RT spinlock would do; the idea was that this is some kind of
> strange race / memory ordering (missed ack?) between the threaded irq4
> handler and the do_IRQ() -> handle_edge_irq() -> ... path.
>
> So I did this:
>
> ---
> drivers/tty/serial/8250/8250_port.c | 4 +++-
> 1 file changed, 3 insertions(+), 1 deletion(-)
>
> diff --git a/drivers/tty/serial/8250/8250_port.c b/drivers/tty/serial/8250/8250_port.c
> index e31217e8dce6..1a577305e174 100644
> --- a/drivers/tty/serial/8250/8250_port.c
> +++ b/drivers/tty/serial/8250/8250_port.c
> @@ -1813,12 +1813,13 @@ static bool handle_rx_dma(struct uart_8250_port *up, unsigned int iir)
> int serial8250_handle_irq(struct uart_port *port, unsigned int iir)
> {
> unsigned char status;
> - unsigned long flags;
> + unsigned long flags, f;
> struct uart_8250_port *up = up_to_u8250p(port);
>
> if (iir & UART_IIR_NO_INT)
> return 0;
>
> + local_irq_save(f);
> spin_lock_irqsave(&port->lock, flags);

Note, this would break if there ever was a contention, as the spin lock is
a mutex and would sleep. And we don't want to do that with interrupts
disabled!

>
> status = serial_port_in(port, UART_LSR);
> @@ -1833,6 +1834,7 @@ int serial8250_handle_irq(struct uart_port *port, unsigned int iir)
> serial8250_tx_chars(up);
>
> uart_unlock_and_check_sysrq(port, flags);
> + local_irq_restore(f);
> return 1;
> }
>
> But curiously enough, that exploded in the oposite order (so first there
> was CPU stall, and only later the disabling of IRQ4 due to spurious
> storm):


Now what may be interesting to try is to enable tracing and
ftrace_dump_on_opps, and set panic_on_warning, as well as
traceoff_on_warning.


# echo 1 > /proc/sys/kernel/ftrace_dump_on_oops
# echo 1 > /proc/sys/kernel/panic_on_warn
# echo 1 > /proc/sys/kernel/traceoff_on_warning
# echo 1 > /sys/kernel/tracing/events/enable

Enabling all events will include interrupt events and wake ups, and perhaps
give you an idea what interrupts are happening after the uart thread is
woken.

-- Steve

\
 
 \ /
  Last update: 2020-04-23 22:16    [W:0.070 / U:0.132 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site