diff mbox

serial: 8250: Avoid "too much work" from bogus rx timeout interrupt

Message ID 1482110067-5591-1-git-send-email-dianders@chromium.org (mailing list archive)
State New, archived
Headers show

Commit Message

Doug Anderson Dec. 19, 2016, 1:14 a.m. UTC
On a Rockchip rk3399-based board during suspend/resume testing, we
found that we could get the console UART into a state where it would
print this to the console a lot:
  serial8250: too much work for irq42

Followed eventually by:
  NMI watchdog: BUG: soft lockup - CPU#0 stuck for 11s!

Upon debugging I found that we're in this state:
  iir = 0x000000cc
  lsr = 0x00000060

It appears that somehow we have a RX Timeout interrupt but there is no
actual data present to receive.  When we're in this state the UART
driver claims that it handled the interrupt but it actually doesn't
really do anything.  This means that we keep getting the interrupt
over and over again.

Normally we don't actually need to do anything special to handle a RX
Timeout interrupt.  We'll notice that there is some data ready and
we'll read it, which will end up clearing the RX Timeout.  In this
case we have a problem specifically because we got the RX TImeout
without any data.  Reading a bogus byte is confirmed to get us out of
this state.

It's unclear how exactly the UART got into this state, but it is known
that the UART lines are essentially undriven and unpowered during
suspend, so possibly during resume some garbage / half transmitted
bits are seen on the line and put the UART into this state.

The UART on the rk3399 is a DesignWare based 8250 UART but I have
placed this fix in the general 8250 code because it shouldn't hurt to
have this detection on all 8250 UARTs and it's plausible some other
UART could get into the same state.  If these two extra lines of code
are too much overhead, we can certainly move it into the DesignWare
driver or even only do it for Rockchip UARTs.

Signed-off-by: Douglas Anderson <dianders@chromium.org>
---
Testing and development done on a kernel-4.4 based tree, then picked
to ToT, where the code applied cleanly.

 drivers/tty/serial/8250/8250_port.c | 6 ++++++
 1 file changed, 6 insertions(+)

Comments

Andy Shevchenko Dec. 19, 2016, 12:59 p.m. UTC | #1
On Sun, 2016-12-18 at 17:14 -0800, Douglas Anderson wrote:
> On a Rockchip rk3399-based board during suspend/resume testing, we
> found that we could get the console UART into a state where it would
> print this to the console a lot:
>   serial8250: too much work for irq42

Have you read the following discussion
https://www.spinics.net/lists/kernel/msg2059543.html


> 
> Followed eventually by:
>   NMI watchdog: BUG: soft lockup - CPU#0 stuck for 11s!
> 
> Upon debugging I found that we're in this state:
>   iir = 0x000000cc
>   lsr = 0x00000060
> 
> It appears that somehow we have a RX Timeout interrupt but there is no
> actual data present to receive.  When we're in this state the UART
> driver claims that it handled the interrupt but it actually doesn't
> really do anything.  This means that we keep getting the interrupt
> over and over again.
> 
> Normally we don't actually need to do anything special to handle a RX
> Timeout interrupt.  We'll notice that there is some data ready and
> we'll read it, which will end up clearing the RX Timeout.  In this
> case we have a problem specifically because we got the RX TImeout
> without any data.  Reading a bogus byte is confirmed to get us out of
> this state.
> 
> It's unclear how exactly the UART got into this state, but it is known
> that the UART lines are essentially undriven and unpowered during
> suspend, so possibly during resume some garbage / half transmitted
> bits are seen on the line and put the UART into this state.
> 
> The UART on the rk3399 is a DesignWare based 8250 UART but I have
> placed this fix in the general 8250 code because it shouldn't hurt to
> have this detection on all 8250 UARTs and it's plausible some other
> UART could get into the same state.  If these two extra lines of code
> are too much overhead, we can certainly move it into the DesignWare
> driver or even only do it for Rockchip UARTs.
> 
> Signed-off-by: Douglas Anderson <dianders@chromium.org>
> ---
> Testing and development done on a kernel-4.4 based tree, then picked
> to ToT, where the code applied cleanly.
> 
>  drivers/tty/serial/8250/8250_port.c | 6 ++++++
>  1 file changed, 6 insertions(+)
> 
> diff --git a/drivers/tty/serial/8250/8250_port.c
> b/drivers/tty/serial/8250/8250_port.c
> index fe4399b41df6..8582c068c3d1 100644
> --- a/drivers/tty/serial/8250/8250_port.c
> +++ b/drivers/tty/serial/8250/8250_port.c
> @@ -1824,6 +1824,12 @@ int serial8250_handle_irq(struct uart_port
> *port, unsigned int iir)
>  	if (status & (UART_LSR_DR | UART_LSR_BI)) {
>  		if (!up->dma || handle_rx_dma(up, iir))
>  			status = serial8250_rx_chars(up, status);
> +	} else if ((iir & 0x3f) == UART_IIR_RX_TIMEOUT) {
> +		/*
> +		 * On some systems we saw the timeout interrupt even
> when
> +		 * there was no data ready.  Do a bogus read to clear
> it.
> +		 */
> +		(void) serial_port_in(port, UART_RX);
>  	}
>  	serial8250_modem_status(up);
>  	if ((!up->dma || up->dma->tx_err) && (status &
> UART_LSR_THRE))
Doug Anderson Dec. 19, 2016, 5:12 p.m. UTC | #2
Hi,

On Mon, Dec 19, 2016 at 4:59 AM, Andy Shevchenko
<andriy.shevchenko@linux.intel.com> wrote:
> On Sun, 2016-12-18 at 17:14 -0800, Douglas Anderson wrote:
>> On a Rockchip rk3399-based board during suspend/resume testing, we
>> found that we could get the console UART into a state where it would
>> print this to the console a lot:
>>   serial8250: too much work for irq42
>
> Have you read the following discussion
> https://www.spinics.net/lists/kernel/msg2059543.html

No, I wasn't aware of that discussion.  Yup, basically the exact same
thing is happening here.  Good to know I'm not alone.  Any idea if the
Baytrail UART is also based on DesignWare IP?

In that thread, Peter said:

> I think there is every likelihood of spurious RX timeout interrupts
> tripping this patch, sorry.
>
> Unfortunately, I think UART_BUG_ is the only viable possibility.
> Or perhaps fixing the port type as PORT_8250 (thus disabling the fifos).

My change is slightly different than California's in that I'm actually
throwing away the bogus byte and his patch was treating it as a valid
byte.  I don't know if that makes the patch more or less palatable.

I would hate to lose access to the FIFOs just due to this weird corner case.

Do we really think there's a case where there's an RX Timeout
interrupt w/ no "data ready" but that later the data ready will show
up?  Can you quantify how much later you think it will show up?  If we
can quantify how much longer the data will show up in then we should
probably just do a timeout loop right where I added my patch.

Specifically, here's what's happening today with RX Timeout interrupt
without "data ready":

1. We'll get the interrupt
2. We won't do _anything_ to service the interrupt.
3. We'll return back to serial8250_interrupt(), where we'll keep
looping until we get "too much work"
4. We'll break out, but the interrupt will still be active.
5. Go back to #1

...and since this interrupt will keep firing and firing and firing
with no delay in-between, we'll effectively lock the CPU up.

If there are some UARTs that eventually get themselves out of this
state by asserting "data ready" then the above won't be an "infinite"
loop but it will effectively be a tight loop where we won't let
userspace run and won't service other interrupts until we actually get
the data ready.  Since we're already blocking everything else, it
seems like it might be better to directly loop in
serial8250_handle_irq() with a timeout of some sort (how long?  100
us?  1 ms?).  Then we if we get the timeout then we can do the read
and safely work ourselves free.

What do others think about that?


-Doug
Andy Shevchenko Dec. 19, 2016, 5:33 p.m. UTC | #3
On Mon, 2016-12-19 at 09:12 -0800, Doug Anderson wrote:
> Hi,
> 
> On Mon, Dec 19, 2016 at 4:59 AM, Andy Shevchenko
> <andriy.shevchenko@linux.intel.com> wrote:
> > On Sun, 2016-12-18 at 17:14 -0800, Douglas Anderson wrote:
> > > On a Rockchip rk3399-based board during suspend/resume testing, we
> > > found that we could get the console UART into a state where it
> > > would
> > > print this to the console a lot:
> > >   serial8250: too much work for irq42
> > 
> > Have you read the following discussion
> > https://www.spinics.net/lists/kernel/msg2059543.html
> 
> No, I wasn't aware of that discussion.  Yup, basically the exact same
> thing is happening here.  Good to know I'm not alone.  Any idea if the
> Baytrail UART is also based on DesignWare IP?

Yes. Almost all Intel HW is using DesignWare IP for HS UARTs.

> In that thread, Peter said:
> 
> > I think there is every likelihood of spurious RX timeout interrupts
> > tripping this patch, sorry.
> > 
> > Unfortunately, I think UART_BUG_ is the only viable possibility.
> > Or perhaps fixing the port type as PORT_8250 (thus disabling the
> > fifos).
> 
> My change is slightly different than California's in that I'm actually
> throwing away the bogus byte and his patch was treating it as a valid
> byte.  I don't know if that makes the patch more or less palatable.

We need to test, especially in DMA case.

> I would hate to lose access to the FIFOs just due to this weird corner
> case.
> 
> Do we really think there's a case where there's an RX Timeout
> interrupt w/ no "data ready" but that later the data ready will show
> up?  Can you quantify how much later you think it will show up?  If we
> can quantify how much longer the data will show up in then we should
> probably just do a timeout loop right where I added my patch.
> 
> Specifically, here's what's happening today with RX Timeout interrupt
> without "data ready":
> 
> 1. We'll get the interrupt
> 2. We won't do _anything_ to service the interrupt.
> 3. We'll return back to serial8250_interrupt(), where we'll keep
> looping until we get "too much work"
> 4. We'll break out, but the interrupt will still be active.
> 5. Go back to #1
> 
> ...and since this interrupt will keep firing and firing and firing
> with no delay in-between, we'll effectively lock the CPU up.

And the root cause of that is... ?

> If there are some UARTs that eventually get themselves out of this
> state by asserting "data ready" then the above won't be an "infinite"
> loop but it will effectively be a tight loop where we won't let
> userspace run and won't service other interrupts until we actually get
> the data ready.  Since we're already blocking everything else, it
> seems like it might be better to directly loop in
> serial8250_handle_irq() with a timeout of some sort (how long?  100
> us?  1 ms?).  Then we if we get the timeout then we can do the read
> and safely work ourselves free.

What I think is that the root cause of this is still unknown and either
above looks like a hack.
Andy Shevchenko Dec. 19, 2016, 5:35 p.m. UTC | #4
On Mon, 2016-12-19 at 19:33 +0200, Andy Shevchenko wrote:
> On Mon, 2016-12-19 at 09:12 -0800, Doug Anderson wrote:

> What I think is that the root cause of this is still unknown and
> either
> above looks like a hack.

One more link:

http://www.spinics.net/lists/linux-serial/msg22316.html
Doug Anderson Dec. 19, 2016, 5:54 p.m. UTC | #5
Hi,

On Mon, Dec 19, 2016 at 9:33 AM, Andy Shevchenko
<andriy.shevchenko@linux.intel.com> wrote:
> On Mon, 2016-12-19 at 09:12 -0800, Doug Anderson wrote:
>> Hi,
>>
>> On Mon, Dec 19, 2016 at 4:59 AM, Andy Shevchenko
>> <andriy.shevchenko@linux.intel.com> wrote:
>> > On Sun, 2016-12-18 at 17:14 -0800, Douglas Anderson wrote:
>> > > On a Rockchip rk3399-based board during suspend/resume testing, we
>> > > found that we could get the console UART into a state where it
>> > > would
>> > > print this to the console a lot:
>> > >   serial8250: too much work for irq42
>> >
>> > Have you read the following discussion
>> > https://www.spinics.net/lists/kernel/msg2059543.html
>>
>> No, I wasn't aware of that discussion.  Yup, basically the exact same
>> thing is happening here.  Good to know I'm not alone.  Any idea if the
>> Baytrail UART is also based on DesignWare IP?
>
> Yes. Almost all Intel HW is using DesignWare IP for HS UARTs.

OK, so possibly we could add this workaround in just the DesignWare
code and then we could be more sure we're not breaking other UARTs?
That would work for me.  It seems like it would be easier to validate
that there are no unintended side effects if we put this just in the
DesignWare driver.


>> In that thread, Peter said:
>>
>> > I think there is every likelihood of spurious RX timeout interrupts
>> > tripping this patch, sorry.
>> >
>> > Unfortunately, I think UART_BUG_ is the only viable possibility.
>> > Or perhaps fixing the port type as PORT_8250 (thus disabling the
>> > fifos).
>>
>> My change is slightly different than California's in that I'm actually
>> throwing away the bogus byte and his patch was treating it as a valid
>> byte.  I don't know if that makes the patch more or less palatable.
>
> We need to test, especially in DMA case.

Yes, I could believe that in the DMA case that my patch might not be
the right thing to do.  I can easily just add a check for "!up->dma"
if it makes the patch better.


>> I would hate to lose access to the FIFOs just due to this weird corner
>> case.
>>
>> Do we really think there's a case where there's an RX Timeout
>> interrupt w/ no "data ready" but that later the data ready will show
>> up?  Can you quantify how much later you think it will show up?  If we
>> can quantify how much longer the data will show up in then we should
>> probably just do a timeout loop right where I added my patch.
>>
>> Specifically, here's what's happening today with RX Timeout interrupt
>> without "data ready":
>>
>> 1. We'll get the interrupt
>> 2. We won't do _anything_ to service the interrupt.
>> 3. We'll return back to serial8250_interrupt(), where we'll keep
>> looping until we get "too much work"
>> 4. We'll break out, but the interrupt will still be active.
>> 5. Go back to #1
>>
>> ...and since this interrupt will keep firing and firing and firing
>> with no delay in-between, we'll effectively lock the CPU up.
>
> And the root cause of that is... ?

I don't understand your question.  Basically what I'm saying is that
we got an interrupt and did absolutely nothing to handle it or clear
it.  Then we returned "handled".  Is it a mystery that the interrupt
will fire again and again and again?

Specifically:
* reading the LSR doesn't clear the interrupt
* The DR / BI bits aren't set.
* serial8250_modem_status() won't clear the interrupt (reads the MSR)
* nothing to transmit
* we'll return "handled" since the only time serial8250_handle_irq()
returns 0 is if we have UART_IIR_NO_INT.


>> If there are some UARTs that eventually get themselves out of this
>> state by asserting "data ready" then the above won't be an "infinite"
>> loop but it will effectively be a tight loop where we won't let
>> userspace run and won't service other interrupts until we actually get
>> the data ready.  Since we're already blocking everything else, it
>> seems like it might be better to directly loop in
>> serial8250_handle_irq() with a timeout of some sort (how long?  100
>> us?  1 ms?).  Then we if we get the timeout then we can do the read
>> and safely work ourselves free.
>
> What I think is that the root cause of this is still unknown and either
> above looks like a hack.

I postulated a root cause of receiving a partial character, but I'd
need to figure out how to twiddle bits in just the right way to
somehow try to do this in a programmatic way.  I can certainly
reproduce this in a black-box sort of way by just doing suspend/resume
testing long enough.

Even if the root cause isn't know, though, it seems like the current
behavior of locking up a CPU is non-ideal.  It seems like there ought
to be some sort of way to detect and handle this case.

-Doug
Andy Shevchenko Dec. 19, 2016, 8:18 p.m. UTC | #6
On Mon, 2016-12-19 at 09:54 -0800, Doug Anderson wrote:
> Hi,
> 
> Yes. Almost all Intel HW is using DesignWare IP for HS UARTs.
> 
> OK, so possibly we could add this workaround in just the DesignWare
> code and then we could be more sure we're not breaking other UARTs?
> That would work for me.  It seems like it would be easier to validate
> that there are no unintended side effects if we put this just in the
> DesignWare driver.

Yes, don't need to touch others.

> Yes, I could believe that in the DMA case that my patch might not be
> the right thing to do.  I can easily just add a check for "!up->dma"
> if it makes the patch better.

At least, yes.

> > > 1. We'll get the interrupt
> > > 2. We won't do _anything_ to service the interrupt.
> > > 3. We'll return back to serial8250_interrupt(), where we'll keep
> > > looping until we get "too much work"
> > > 4. We'll break out, but the interrupt will still be active.
> > > 5. Go back to #1
> > > 
> > > ...and since this interrupt will keep firing and firing and firing
> > > with no delay in-between, we'll effectively lock the CPU up.
> > 
> > And the root cause of that is... ?
> 
> I don't understand your question.  Basically what I'm saying is that
> we got an interrupt and did absolutely nothing to handle it or clear
> it.  Then we returned "handled".  Is it a mystery that the interrupt
> will fire again and again and again?

> Specifically:
> * reading the LSR doesn't clear the interrupt
> * The DR / BI bits aren't set.
> * serial8250_modem_status() won't clear the interrupt (reads the MSR)
> * nothing to transmit
> * we'll return "handled" since the only time serial8250_handle_irq()
> returns 0 is if we have UART_IIR_NO_INT.

My question here a bit rhetorical, we better understand root cause,
better fix would be.

> > What I think is that the root cause of this is still unknown and
> > either
> > above looks like a hack.
> 
> I postulated a root cause of receiving a partial character, but I'd
> need to figure out how to twiddle bits in just the right way to
> somehow try to do this in a programmatic way.  I can certainly
> reproduce this in a black-box sort of way by just doing suspend/resume
> testing long enough.

Have you tried to disable C-states or set PM QoS?
Do you have same issue with and without DMA?

> Even if the root cause isn't know, though, it seems like the current
> behavior of locking up a CPU is non-ideal.  It seems like there ought
> to be some sort of way to detect and handle this case.

Have you read links I sent? In one mail I mentioned Intel's
documentation that suggests not to use RDI interrupt when DMA. Which
sounds weird.
Doug Anderson Dec. 19, 2016, 9:13 p.m. UTC | #7
Hi,

On Mon, Dec 19, 2016 at 12:18 PM, Andy Shevchenko
<andriy.shevchenko@linux.intel.com> wrote:
> On Mon, 2016-12-19 at 09:54 -0800, Doug Anderson wrote:
>> Hi,
>>
>> Yes. Almost all Intel HW is using DesignWare IP for HS UARTs.
>>
>> OK, so possibly we could add this workaround in just the DesignWare
>> code and then we could be more sure we're not breaking other UARTs?
>> That would work for me.  It seems like it would be easier to validate
>> that there are no unintended side effects if we put this just in the
>> DesignWare driver.
>
> Yes, don't need to touch others.

OK, I will spin the patch with this.


>> Yes, I could believe that in the DMA case that my patch might not be
>> the right thing to do.  I can easily just add a check for "!up->dma"
>> if it makes the patch better.
>
> At least, yes.

OK, I'll include this.


>> > > 1. We'll get the interrupt
>> > > 2. We won't do _anything_ to service the interrupt.
>> > > 3. We'll return back to serial8250_interrupt(), where we'll keep
>> > > looping until we get "too much work"
>> > > 4. We'll break out, but the interrupt will still be active.
>> > > 5. Go back to #1
>> > >
>> > > ...and since this interrupt will keep firing and firing and firing
>> > > with no delay in-between, we'll effectively lock the CPU up.
>> >
>> > And the root cause of that is... ?
>>
>> I don't understand your question.  Basically what I'm saying is that
>> we got an interrupt and did absolutely nothing to handle it or clear
>> it.  Then we returned "handled".  Is it a mystery that the interrupt
>> will fire again and again and again?
>
>> Specifically:
>> * reading the LSR doesn't clear the interrupt
>> * The DR / BI bits aren't set.
>> * serial8250_modem_status() won't clear the interrupt (reads the MSR)
>> * nothing to transmit
>> * we'll return "handled" since the only time serial8250_handle_irq()
>> returns 0 is if we have UART_IIR_NO_INT.
>
> My question here a bit rhetorical, we better understand root cause,
> better fix would be.
>
>> > What I think is that the root cause of this is still unknown and
>> > either
>> > above looks like a hack.
>>
>> I postulated a root cause of receiving a partial character, but I'd
>> need to figure out how to twiddle bits in just the right way to
>> somehow try to do this in a programmatic way.  I can certainly
>> reproduce this in a black-box sort of way by just doing suspend/resume
>> testing long enough.
>
> Have you tried to disable C-states or set PM QoS?

C-states?  I think that is an Intel concept, isn't it?  I'm on a
Rockchip SoC and there is no official C-states.  I suppose I can check
to see if Linux Runtime PM is somehow involved, but it would be a bit
surprising.  As I said earlier in this thread I reproduce the problem
during suspend/resume testing when I'm entering into "suspend to ram"
(S3 in Intel speak, I believe) and then existing.

I've never dealt with PM QoS specifically.  Again, I would be
surprised if something like this was involved.


> Do you have same issue with and without DMA?

I have never tried with DMA, so probably the right thing to do is to
limit my patch to just the "no DMA" case and if/when someone finds
problems with DMA then they can adjust the patch accordingly.

Right now I don't believe DMA is enabled for the UART ports for any
Rockchip SoCs.  It should be theoretically possible to enable it, but
I'm not exactly in a rush to do so given that In my case I'm not using
the UARTs for any high performance activities and that enabling DMA
often causes some weird quirks to come up.


>> Even if the root cause isn't know, though, it seems like the current
>> behavior of locking up a CPU is non-ideal.  It seems like there ought
>> to be some sort of way to detect and handle this case.
>
> Have you read links I sent? In one mail I mentioned Intel's
> documentation that suggests not to use RDI interrupt when DMA. Which
> sounds weird.

I think I addressed the first link
(https://www.spinics.net/lists/kernel/msg2059543.html), which was a
proposed patch and a single response, right?

The 2nd link(http://www.spinics.net/lists/linux-serial/msg22316.html)
was all about DMA and right now I'm not using DMA (as per above).  I
will change my next patch to only run in the "no DMA" case.


-Doug
diff mbox

Patch

diff --git a/drivers/tty/serial/8250/8250_port.c b/drivers/tty/serial/8250/8250_port.c
index fe4399b41df6..8582c068c3d1 100644
--- a/drivers/tty/serial/8250/8250_port.c
+++ b/drivers/tty/serial/8250/8250_port.c
@@ -1824,6 +1824,12 @@  int serial8250_handle_irq(struct uart_port *port, unsigned int iir)
 	if (status & (UART_LSR_DR | UART_LSR_BI)) {
 		if (!up->dma || handle_rx_dma(up, iir))
 			status = serial8250_rx_chars(up, status);
+	} else if ((iir & 0x3f) == UART_IIR_RX_TIMEOUT) {
+		/*
+		 * On some systems we saw the timeout interrupt even when
+		 * there was no data ready.  Do a bogus read to clear it.
+		 */
+		(void) serial_port_in(port, UART_RX);
 	}
 	serial8250_modem_status(up);
 	if ((!up->dma || up->dma->tx_err) && (status & UART_LSR_THRE))