diff mbox

[09/16] tty: serial: 8250_dma: Add a TX trigger workaround for AM33xx

Message ID 20141002102723.GB23661@linutronix.de (mailing list archive)
State New, archived
Headers show

Commit Message

Sebastian Andrzej Siewior Oct. 2, 2014, 10:27 a.m. UTC 
* Frans Klaver | 2014-09-30 10:44:16 [+0200]:

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

these two happen outside the IRQ routine for every 48 bytes.
…
>       uart_test-483   [000] dnh.    17.861018: serial8250_interrupt: irq 89
>       uart_test-483   [000] dnh.    17.861026: serial8250_interrupt: 89 e
e? Did was the routine invoked 0xe times or this a register?

>       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)
another 48bytes

>       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)
timeout, manual purge. Do you have an idea how many bytes were manually
received?

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

So if I understand you correct, then you enter serial8250_interrupt()
and then you enter multiple times omap_8250_dma_handle_irq() and
you always get a TIMEOUT event and fetch byte(s) manualy via
serial8250_rx_chars(). And after one iteration UART_IIR_NO_INT is not
set and you do it again, right?

I have no idea when exactly the timeout-interrupt fires. The manual
says: "… the count is reset when there is activity on uarti_rx …" but it
does not say how often it increments before the level is reached.
It also might be that you have a small gap between two bytes and this
high baud rate the gap is considered as a timeout event.

Another thing could be that if the we enqueue a RX transfer from the
dma_completion callback then we have too many bytes in the FIFO already
becahse the callback is invoked from softirq. What happens if we cut the
middle man via



>
>Frans

Sebastian

Comments

Frans Klaver Oct. 13, 2014, 2:55 p.m. UTC | #1 
On Thu, Oct 02, 2014 at 12:27:23PM +0200, Sebastian Andrzej Siewior wrote:
> * Frans Klaver | 2014-09-30 10:44:16 [+0200]:
> 
> >       uart_test-483   [000] dnh.    17.861018: serial8250_interrupt: irq 89
> >       uart_test-483   [000] dnh.    17.861026: serial8250_interrupt: 89 e
> e? Did was the routine invoked 0xe times or this a register?

No, this marks the end of serial8250_interrupt().


> >       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)
> timeout, manual purge. Do you have an idea how many bytes were manually
> received?

Here's an excerpt from a new trial using v10
(previous was v10_pre3). We manually read 10 bytes before we start
trying to get all bytes without dma. 

       uart_test-483   [000] dnH.    18.182647: serial8250_interrupt: irq 89
       uart_test-483   [000] dnH.    18.182653: omap_8250_dma_handle_irq: rx_dma(up, iir)
       uart_test-483   [000] dnH.    18.182655: omap_8250_rx_dma: UART_IIR_RX_TIMEOUT
       uart_test-483   [000] dnH.    18.182657: omap_8250_rx_dma: rx was running
       uart_test-483   [000] dnH.    18.182662: __dma_rx_do_complete: count = 0
       uart_test-483   [000] dnH.    18.182666: omap_8250_dma_handle_irq: rx_chars(up, status)
       uart_test-483   [000] dnH.    18.182683: serial8250_rx_chars: bytes read = 10
       uart_test-483   [000] dnH.    18.182685: omap_8250_dma_handle_irq: rx_dma(up, 0)
       uart_test-483   [000] dnH.    18.182698: omap_8250_dma_handle_irq: rpm_put(up)
       uart_test-483   [000] dnH.    18.182701: serial8250_interrupt: 89 end
       uart_test-488   [000] ..s.    18.185353: __dma_rx_do_complete: count = 48
       uart_test-488   [000] ..s.    18.185366: __dma_rx_do_complete: rx_dma(p, 0)
     kworker/0:1-10    [000] d.H.    18.185486: serial8250_interrupt: irq 89
     kworker/0:1-10    [000] d.H.    18.185496: omap_8250_dma_handle_irq: rpm_put(up)
     kworker/0:1-10    [000] d.H.    18.185501: serial8250_interrupt: 89 end
     kworker/0:1-10    [000] ..s.    18.185520: __dma_rx_do_complete: count = 48
     kworker/0:1-10    [000] ..s.    18.185526: __dma_rx_do_complete: rx_dma(p, 0)

Below things go downhill again.

     kworker/0:1-10    [000] ..s.    18.227273: __dma_rx_do_complete: rx_dma(p, 0)
       uart_test-483   [000] ..s.    18.227396: __dma_rx_do_complete: count = 48
       uart_test-483   [000] ..s.    18.227404: __dma_rx_do_complete: rx_dma(p, 0)
       uart_test-485   [000] .ns.    18.227540: __dma_rx_do_complete: count = 48
       uart_test-485   [000] .ns.    18.227547: __dma_rx_do_complete: rx_dma(p, 0)
     kworker/0:2-65    [000] ..s.    18.227660: __dma_rx_do_complete: count = 48
     kworker/0:2-65    [000] ..s.    18.227667: __dma_rx_do_complete: rx_dma(p, 0)
     kworker/0:1-10    [000] .ns.    18.227786: __dma_rx_do_complete: count = 48
     kworker/0:1-10    [000] .ns.    18.227793: __dma_rx_do_complete: rx_dma(p, 0)
       uart_test-477   [000] ..s.    18.227921: __dma_rx_do_complete: count = 48
       uart_test-477   [000] ..s.    18.227928: __dma_rx_do_complete: rx_dma(p, 0)
       uart_test-481   [000] ..s.    18.228051: __dma_rx_do_complete: count = 48
       uart_test-481   [000] ..s.    18.228057: __dma_rx_do_complete: rx_dma(p, 0)
     kworker/0:1-10    [000] ..s.    18.228185: __dma_rx_do_complete: count = 48
     kworker/0:1-10    [000] ..s.    18.228191: __dma_rx_do_complete: rx_dma(p, 0)
       uart_test-485   [000] ..s.    18.228318: __dma_rx_do_complete: count = 48
       uart_test-485   [000] ..s.    18.228324: __dma_rx_do_complete: rx_dma(p, 0)
       uart_test-488   [000] d.h.    18.228445: serial8250_interrupt: irq 89
       uart_test-488   [000] d.h.    18.228454: omap_8250_dma_handle_irq: rpm_put(up)
       uart_test-488   [000] d.h.    18.228459: serial8250_interrupt: 89 end
       uart_test-488   [000] d.H.    18.228472: serial8250_interrupt: irq 89
       uart_test-488   [000] d.H.    18.228477: omap_8250_dma_handle_irq: rx_dma(up, iir)
       uart_test-488   [000] d.H.    18.228479: omap_8250_rx_dma: UART_IIR_RX_TIMEOUT
       uart_test-488   [000] d.H.    18.228480: omap_8250_rx_dma: rx was running
       uart_test-488   [000] d.H.    18.228487: __dma_rx_do_complete: count = 48
       uart_test-488   [000] d.H.    18.228500: omap_8250_dma_handle_irq: rx_chars(up, status)
       uart_test-488   [000] d.H.    18.228517: serial8250_rx_chars: bytes read = 10
       uart_test-488   [000] d.H.    18.228519: omap_8250_dma_handle_irq: rx_dma(up, 0)
       uart_test-488   [000] d.H.    18.228534: omap_8250_dma_handle_irq: rpm_put(up)
       uart_test-488   [000] d.H.    18.228540: serial8250_interrupt: 89 end
     kworker/0:1-10    [000] dnh.    18.234930: serial8250_interrupt: irq 89
     kworker/0:1-10    [000] dnh.    18.235074: omap_8250_dma_handle_irq: rx_dma(up, iir)
     kworker/0:1-10    [000] dnh.    18.235123: omap_8250_rx_dma: UART_IIR_RX_TIMEOUT
     kworker/0:1-10    [000] dnh.    18.235159: omap_8250_rx_dma: rx was running
     kworker/0:1-10    [000] dnh.    18.235334: __dma_rx_do_complete: count = 48
     kworker/0:1-10    [000] dnh.    18.235455: omap_8250_dma_handle_irq: rx_chars(up, status)
     kworker/0:1-10    [000] dnh.    18.238523: serial8250_rx_chars: bytes read = 256
     kworker/0:1-10    [000] dnh.    18.238566: omap_8250_dma_handle_irq: rx_dma(up, 0)
     kworker/0:1-10    [000] dnh.    18.239169: omap_8250_dma_handle_irq: rx_dma(up, iir)
     kworker/0:1-10    [000] dnh.    18.239223: omap_8250_rx_dma: UART_IIR_RX_TIMEOUT
     kworker/0:1-10    [000] dnh.    18.239256: omap_8250_rx_dma: rx was running
     kworker/0:1-10    [000] dnh.    18.239377: __dma_rx_do_complete: count = 0
     kworker/0:1-10    [000] dnh.    18.239449: omap_8250_dma_handle_irq: rx_chars(up, status)
     kworker/0:1-10    [000] dnh.    18.242576: serial8250_rx_chars: bytes read = 256
     kworker/0:1-10    [000] dnh.    18.242620: omap_8250_dma_handle_irq: rx_dma(up, 0)
     kworker/0:1-10    [000] dnh.    18.242878: omap_8250_dma_handle_irq: rx_dma(up, iir)
     kworker/0:1-10    [000] dnh.    18.242921: omap_8250_rx_dma: UART_IIR_RX_TIMEOUT
     kworker/0:1-10    [000] dnh.    18.242954: omap_8250_rx_dma: rx was running
     kworker/0:1-10    [000] dnh.    18.243064: __dma_rx_do_complete: count = 0
     kworker/0:1-10    [000] dnh.    18.243127: omap_8250_dma_handle_irq: rx_chars(up, status)
     kworker/0:1-10    [000] dnh.    18.246238: serial8250_rx_chars: bytes read = 256
     kworker/0:1-10    [000] dnh.    18.246283: omap_8250_dma_handle_irq: rx_dma(up, 0)
     kworker/0:1-10    [000] dnh.    18.246524: omap_8250_dma_handle_irq: rx_dma(up, iir)
     kworker/0:1-10    [000] dnh.    18.246563: omap_8250_rx_dma: UART_IIR_RX_TIMEOUT
     kworker/0:1-10    [000] dnh.    18.246599: omap_8250_rx_dma: rx was running
     kworker/0:1-10    [000] dnh.    18.246702: __dma_rx_do_complete: count = 0

> >     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?
> 
> So if I understand you correct, then you enter serial8250_interrupt()
> and then you enter multiple times omap_8250_dma_handle_irq() and
> you always get a TIMEOUT event and fetch byte(s) manualy via
> serial8250_rx_chars(). And after one iteration UART_IIR_NO_INT is not
> set and you do it again, right?

That's what it looks like, yes.


> I have no idea when exactly the timeout-interrupt fires. The manual
> says: "… the count is reset when there is activity on uarti_rx …" but it
> does not say how often it increments before the level is reached.
> It also might be that you have a small gap between two bytes and this
> high baud rate the gap is considered as a timeout event.
> 
> Another thing could be that if the we enqueue a RX transfer from the
> dma_completion callback then we have too many bytes in the FIFO already
> becahse the callback is invoked from softirq. What happens if we cut the
> middle man via
> 
> 
> diff --git a/drivers/dma/virt-dma.c b/drivers/dma/virt-dma.c
> index 6f80432..21b04bd 100644
> --- a/drivers/dma/virt-dma.c
> +++ b/drivers/dma/virt-dma.c
> @@ -63,8 +63,9 @@ static void vchan_complete(unsigned long arg)
>  	dma_async_tx_callback cb = NULL;
>  	void *cb_data = NULL;
>  	LIST_HEAD(head);
> +	unsigned long flags;
>  
> -	spin_lock_irq(&vc->lock);
> +	spin_lock_irqsave(&vc->lock, flags);
>  	list_splice_tail_init(&vc->desc_completed, &head);
>  	vd = vc->cyclic;
>  	if (vd) {
> @@ -72,7 +73,7 @@ static void vchan_complete(unsigned long arg)
>  		cb = vd->tx.callback;
>  		cb_data = vd->tx.callback_param;
>  	}
> -	spin_unlock_irq(&vc->lock);
> +	spin_unlock_irqrestore(&vc->lock, flags);
>  
>  	if (cb)
>  		cb(cb_data);
> diff --git a/drivers/dma/virt-dma.h b/drivers/dma/virt-dma.h
> index 181b952..7632338 100644
> --- a/drivers/dma/virt-dma.h
> +++ b/drivers/dma/virt-dma.h
> @@ -92,7 +92,10 @@ static inline void vchan_cookie_complete(struct virt_dma_desc *vd)
>  		 vd, cookie);
>  	list_add_tail(&vd->node, &vc->desc_completed);
>  
> -	tasklet_schedule(&vc->task);
> +	if (vd->tx.my_uart)
> +		vc->task.func(vc);
> +	else
> +		tasklet_schedule(&vc->task);
>  }
>  
>  /**
> diff --git a/drivers/tty/serial/8250/8250_omap.c b/drivers/tty/serial/8250/8250_omap.c
> index 57a8b12..5d7ee92 100644
> --- a/drivers/tty/serial/8250/8250_omap.c
> +++ b/drivers/tty/serial/8250/8250_omap.c
> @@ -728,6 +728,7 @@ static int omap_8250_rx_dma(struct uart_8250_port *p, unsigned int iir)
>  	dma->rx_running = 1;
>  	desc->callback = __dma_rx_complete;
>  	desc->callback_param = p;
> +	desc->my_uart = 1;
>  
>  	dma->rx_cookie = dmaengine_submit(desc);
>  
> diff --git a/include/linux/dmaengine.h b/include/linux/dmaengine.h
> index 1f9e642..0f5fbe1 100644
> --- a/include/linux/dmaengine.h
> +++ b/include/linux/dmaengine.h
> @@ -459,6 +459,7 @@ struct dmaengine_unmap_data {
>  struct dma_async_tx_descriptor {
>  	dma_cookie_t cookie;
>  	enum dma_ctrl_flags flags; /* not a 'long' to pack with cookie */
> +	u32 my_uart;
>  	dma_addr_t phys;
>  	struct dma_chan *chan;
>  	dma_cookie_t (*tx_submit)(struct dma_async_tx_descriptor *tx);
> 

[  251.363111] BUG: spinlock recursion on CPU#0, swapper/0
[  251.368394]  lock: 0xcf151dc4, .magic: dead4ead, .owner: swapper/0, .owner_cpu: 0
[  251.375920] CPU: 0 PID: 0 Comm: swapper Not tainted 3.17.0-rc5-00141-geccc467-dirty #35
[  251.384012] [<c0013454>] (unwind_backtrace) from [<c00113b0>] (show_stack+0x10/0x14)
[  251.391811] [<c00113b0>] (show_stack) from [<c0055cdc>] (do_raw_spin_lock+0x48/0x110)
[  251.399703] [<c0055cdc>] (do_raw_spin_lock) from [<c04dbef0>] (_raw_spin_lock_irqsave+0x10/0x18)
[  251.408544] [<c04dbef0>] (_raw_spin_lock_irqsave) from [<c0221f74>] (vchan_complete+0x1c/0xe8)
[  251.417207] [<c0221f74>] (vchan_complete) from [<c0222f54>] (edma_callback+0x138/0x274)
[  251.425259] [<c0222f54>] (edma_callback) from [<c001a844>] (dma_irq_handler+0x154/0x190)
[  251.433406] [<c001a844>] (dma_irq_handler) from [<c005b2dc>] (handle_irq_event_percpu+0x2c/0x130)
[  251.442331] [<c005b2dc>] (handle_irq_event_percpu) from [<c005b41c>] (handle_irq_event+0x3c/0x5c)
[  251.451254] [<c005b41c>] (handle_irq_event) from [<c005d940>] (handle_level_irq+0xd0/0x108)
[  251.459655] [<c005d940>] (handle_level_irq) from [<c005acc0>] (generic_handle_irq+0x20/0x30)
[  251.468144] [<c005acc0>] (generic_handle_irq) from [<c000ee2c>] (handle_IRQ+0x60/0x80)
[  251.476109] [<c000ee2c>] (handle_IRQ) from [<c0008654>] (omap3_intc_handle_irq+0x64/0x8c)
[  251.484337] [<c0008654>] (omap3_intc_handle_irq) from [<c0011dc0>] (__irq_svc+0x40/0x54)
[  251.492466] Exception stack(0xc0725f68 to 0xc0725fb0)
[  251.497549] 5f60:                   00000000 c0757160 00000000 c0018fc0 c0724000 c0724038
[  251.505772] 5f80: c078de40 c072c040 c0714124 cfefc4c0 00000000 00000000 c0757160 c0725fb0
[  251.513989] 5fa0: c000ef40 c000ef44 60000013 ffffffff
[  251.519077] [<c0011dc0>] (__irq_svc) from [<c000ef44>] (arch_cpu_idle+0x2c/0x38)
[  251.526517] [<c000ef44>] (arch_cpu_idle) from [<c005255c>] (cpu_startup_entry+0x9c/0xf0)
[  251.534664] [<c005255c>] (cpu_startup_entry) from [<c06e5b34>] (start_kernel+0x308/0x360)

I should probably take out the spin_lock calls if vd->tx.my_uart is 1?

Thanks,
Frans
diff mbox

Patch

diff --git a/drivers/dma/virt-dma.c b/drivers/dma/virt-dma.c
index 6f80432..21b04bd 100644
--- a/drivers/dma/virt-dma.c
+++ b/drivers/dma/virt-dma.c
@@ -63,8 +63,9 @@  static void vchan_complete(unsigned long arg)
 	dma_async_tx_callback cb = NULL;
 	void *cb_data = NULL;
 	LIST_HEAD(head);
+	unsigned long flags;
 
-	spin_lock_irq(&vc->lock);
+	spin_lock_irqsave(&vc->lock, flags);
 	list_splice_tail_init(&vc->desc_completed, &head);
 	vd = vc->cyclic;
 	if (vd) {
@@ -72,7 +73,7 @@  static void vchan_complete(unsigned long arg)
 		cb = vd->tx.callback;
 		cb_data = vd->tx.callback_param;
 	}
-	spin_unlock_irq(&vc->lock);
+	spin_unlock_irqrestore(&vc->lock, flags);
 
 	if (cb)
 		cb(cb_data);
diff --git a/drivers/dma/virt-dma.h b/drivers/dma/virt-dma.h
index 181b952..7632338 100644
--- a/drivers/dma/virt-dma.h
+++ b/drivers/dma/virt-dma.h
@@ -92,7 +92,10 @@  static inline void vchan_cookie_complete(struct virt_dma_desc *vd)
 		 vd, cookie);
 	list_add_tail(&vd->node, &vc->desc_completed);
 
-	tasklet_schedule(&vc->task);
+	if (vd->tx.my_uart)
+		vc->task.func(vc);
+	else
+		tasklet_schedule(&vc->task);
 }
 
 /**
diff --git a/drivers/tty/serial/8250/8250_omap.c b/drivers/tty/serial/8250/8250_omap.c
index 57a8b12..5d7ee92 100644
--- a/drivers/tty/serial/8250/8250_omap.c
+++ b/drivers/tty/serial/8250/8250_omap.c
@@ -728,6 +728,7 @@  static int omap_8250_rx_dma(struct uart_8250_port *p, unsigned int iir)
 	dma->rx_running = 1;
 	desc->callback = __dma_rx_complete;
 	desc->callback_param = p;
+	desc->my_uart = 1;
 
 	dma->rx_cookie = dmaengine_submit(desc);
 
diff --git a/include/linux/dmaengine.h b/include/linux/dmaengine.h
index 1f9e642..0f5fbe1 100644
--- a/include/linux/dmaengine.h
+++ b/include/linux/dmaengine.h
@@ -459,6 +459,7 @@  struct dmaengine_unmap_data {
 struct dma_async_tx_descriptor {
 	dma_cookie_t cookie;
 	enum dma_ctrl_flags flags; /* not a 'long' to pack with cookie */
+	u32 my_uart;
 	dma_addr_t phys;
 	struct dma_chan *chan;
 	dma_cookie_t (*tx_submit)(struct dma_async_tx_descriptor *tx);