linux-kernel - Re: [PATCH 09/16] tty: serial: 8250_dma: Add a TX trigger workaround for AM33xx

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]

Message-ID: <20140930084416.GB31111@ci00147.xsens-tech.local>
Date:	Tue, 30 Sep 2014 10:44:16 +0200
From:	Frans Klaver <frans.klaver@...ns.com>
To:	Sebastian Andrzej Siewior <bigeasy@...utronix.de>
CC:	Heikki Krogerus <heikki.krogerus@...ux.intel.com>,
	Peter Hurley <peter@...leysoftware.com>, <tony@...mide.com>,
	<gregkh@...uxfoundation.org>, <linux-kernel@...r.kernel.org>,
	<balbi@...com>, <linux-serial@...r.kernel.org>,
	<linux-omap@...r.kernel.org>,
	<linux-arm-kernel@...ts.infradead.org>,
	Alan Cox <alan@...ux.intel.com>
Subject: Re: [PATCH 09/16] tty: serial: 8250_dma: Add a TX trigger workaround
 for AM33xx

On Mon, Sep 29, 2014 at 12:30:43PM +0200, Frans Klaver wrote:
> On Mon, Sep 29, 2014 at 11:54:40AM +0200, Sebastian Andrzej Siewior wrote:
> > For your "too much work for irq" problem: Could you add trace_printk()
> > in tx/rx dma start/complete, and irq routine? The interresting part is
> > what is the irq routine doing once entered. It might be a condition that
> > is ignored at first and "acked" later while serving another event. Or it
> > is really doing something and this is more or less "legal".
> 

Here's some trace output I get. I hope branches become clear by the
calls they do.

       uart_test-482   [000] .ns.    17.860139: __dma_rx_do_complete: error: 0, uart_bug_dma: 32
       uart_test-482   [000] .ns.    17.860141: __dma_rx_do_complete: rx_dma(p, 0)
       uart_test-480   [000] ..s.    17.860260: __dma_rx_do_complete: error: 0, uart_bug_dma: 32
       uart_test-480   [000] ..s.    17.860263: __dma_rx_do_complete: rx_dma(p, 0)
       uart_test-478   [000] ..s.    17.860369: __dma_rx_do_complete: error: 0, uart_bug_dma: 32
       uart_test-478   [000] ..s.    17.860372: __dma_rx_do_complete: rx_dma(p, 0)
     kworker/0:1-10    [000] ..s.    17.860508: __dma_rx_do_complete: error: 0, uart_bug_dma: 32
     kworker/0:1-10    [000] ..s.    17.860512: __dma_rx_do_complete: rx_dma(p, 0)
       uart_test-477   [000] ..s.    17.860634: __dma_rx_do_complete: error: 0, uart_bug_dma: 32
       uart_test-477   [000] ..s.    17.860642: __dma_rx_do_complete: rx_dma(p, 0)
       uart_test-477   [000] ..s.    17.860768: __dma_rx_do_complete: error: 0, uart_bug_dma: 32
       uart_test-477   [000] ..s.    17.860772: __dma_rx_do_complete: rx_dma(p, 0)
     kworker/0:1-10    [000] ..s.    17.860900: __dma_rx_do_complete: error: 0, uart_bug_dma: 32
     kworker/0:1-10    [000] ..s.    17.860904: __dma_rx_do_complete: rx_dma(p, 0)
       uart_test-483   [000] dnh.    17.861018: serial8250_interrupt: irq 89
       uart_test-483   [000] dnh.    17.861026: serial8250_interrupt: 89 e
       uart_test-483   [000] .ns.    17.861045: __dma_rx_do_complete: error: 0, uart_bug_dma: 32
       uart_test-483   [000] .ns.    17.861047: __dma_rx_do_complete: rx_dma(p, 0)
       uart_test-479   [000] d.H.    17.861124: serial8250_interrupt: irq 89
       uart_test-479   [000] d.H.    17.861133: serial8250_handle_irq: l1 IIR cc LSR 61
       uart_test-479   [000] d.H.    17.861135: serial8250_handle_irq: rx_dma(up, iir)
       uart_test-479   [000] d.H.    17.861139: serial8250_rx_dma: l1, UART_IIR_RX_TIMEOUT
       uart_test-479   [000] d.H.    17.861147: __dma_rx_do_complete: error: 1, uart_bug_dma: 32
       uart_test-479   [000] d.H.    17.861150: serial8250_handle_irq: rx_chars(up, status)
       uart_test-479   [000] d.H.    17.861190: serial8250_handle_irq: rx_dma(up, 0)
       uart_test-479   [000] d.H.    17.861205: serial8250_interrupt: 89 e
     kworker/0:1-10    [000] dnH.    17.864949: serial8250_interrupt: irq 89

So far so good. We're just entered interrupt where stuff goes awry. The
following pattern repeats over 600 times:

     kworker/0:1-10    [000] dnH.    17.865198: serial8250_handle_irq: l1 IIR cc LSR 61
     kworker/0:1-10    [000] dnH.    17.865254: serial8250_handle_irq: rx_dma(up, iir)
     kworker/0:1-10    [000] dnH.    17.865333: serial8250_rx_dma: l1, UART_IIR_RX_TIMEOUT
     kworker/0:1-10    [000] dnH.    17.865626: __dma_rx_do_complete: error: 1, uart_bug_dma: 32
     kworker/0:1-10    [000] dnH.    17.865747: serial8250_handle_irq: rx_chars(up, status)
     kworker/0:1-10    [000] dnH.    17.868797: serial8250_handle_irq: rx_dma(up, 0)

ending with:

     kworker/0:1-10    [000] dnH.    20.027093: serial8250_interrupt: serial8250: too much work for irq89
     kworker/0:1-10    [000] dnH.    20.027181: serial8250_interrupt: 89 e

This clogs the entire system until I disconnect the communication lines.

So we get an RX timeout. The receiver fifo trigger level was not reached
and 8250_core is left to copy the remaining data. I would expect that if
the trigger level wasn't reached, we wouldn't need to be doing this that
often. On the other hand, could we be trapped reading data from rx
without dma helping us? And how could we resolve this?

Frans
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@...r.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/