[BUG] dmaengine: pxa_dma: + mmc: pxamci: race condition with DMA error on tx channel

All of lore.kernel.org
 help / color / mirror / Atom feed

* [BUG] dmaengine: pxa_dma: + mmc: pxamci: race condition with DMA error on tx channel
@ 2017-03-08  6:57 ` Petr Cvek
  0 siblings, 0 replies; 12+ messages in thread
From: Petr Cvek @ 2017-03-08  6:57 UTC (permalink / raw)
  To: Robert Jarzmik, vinod.koul, Ulf Hansson, Daniel Mack, Haojian Zhuang
  Cc: dmaengine, linux-mmc, linux-arm-kernel

Hello,

PXA27x DMA changes between:

	v4.7
	d52bd54db8be8999df6df5a776f38c4f8b5e9cea
and
	v4.10-rc5
	a4685d2f58e2230d4e27fb2ee581d7ea35e5d046

seems to expose a race condition while using PXA MMC driver on a PXA27x (magician.c machine).

The failure causes one line in the kernel log, after which the filesystem on SD card is inaccessible (and machine too).

	mmc0: DMA error on tx channel

I wasn't able to track the problem to a single patch as the problem occurs at random time (from the boot to like a half an hour) and it's maybe dependent on a level of a battery charge (maybe because of kernel log writes of charging messages).

It seems that most occurrency is during writes on an SD card. Using an SDHC card decreases the time to fail. After failure the OS is unavailable (rootfs in on the card).

>From my poking in the kernel source code it seems there is a probability that pxamci_irq() takes longer to call and its subsequent call pxamci_data_done() isn't fast enough to set [1]
	host->data = NULL;
>From the DMA side, the DMA done interrupt is generated:
	pxad_chan_handler() -> vchan_cookie_complete()
...where a tasklet for vchan_complete() is scheduled, where finally with interrupts enabled (can pxamci_irq() be called here?) the callback pxamci_dma_irq() is called.

>From my tests it seems at this point [2] the host->data is always NULL and rest of the callback is never called. It is called once with a nonempty host->data only just before the failure.

During the testing I put udelay(100) at the start of pxamci_dma_irq() and fail occurred after like 2 hours (when I for the first time tapped the touchscreen - higher CPU usage and interrupts).

[1] http://elixir.free-electrons.com/source/drivers/mmc/host/pxamci.c?v=4.10#L385
[2] http://elixir.free-electrons.com/source/drivers/mmc/host/pxamci.c?v=4.10#L561

Best regards,
Petr

^ permalink raw reply	[flat|nested] 12+ messages in thread

* [BUG] dmaengine: pxa_dma: + mmc: pxamci: race condition with DMA error on tx channel
@ 2017-03-08  6:57 ` Petr Cvek
  0 siblings, 0 replies; 12+ messages in thread
From: Petr Cvek @ 2017-03-08  6:57 UTC (permalink / raw)
  To: linux-arm-kernel

Hello,

PXA27x DMA changes between:

	v4.7
	d52bd54db8be8999df6df5a776f38c4f8b5e9cea
and
	v4.10-rc5
	a4685d2f58e2230d4e27fb2ee581d7ea35e5d046

seems to expose a race condition while using PXA MMC driver on a PXA27x (magician.c machine).

The failure causes one line in the kernel log, after which the filesystem on SD card is inaccessible (and machine too).

	mmc0: DMA error on tx channel

I wasn't able to track the problem to a single patch as the problem occurs at random time (from the boot to like a half an hour) and it's maybe dependent on a level of a battery charge (maybe because of kernel log writes of charging messages).

It seems that most occurrency is during writes on an SD card. Using an SDHC card decreases the time to fail. After failure the OS is unavailable (rootfs in on the card).

>From my poking in the kernel source code it seems there is a probability that pxamci_irq() takes longer to call and its subsequent call pxamci_data_done() isn't fast enough to set [1]
	host->data = NULL;
>From the DMA side, the DMA done interrupt is generated:
	pxad_chan_handler() -> vchan_cookie_complete()
...where a tasklet for vchan_complete() is scheduled, where finally with interrupts enabled (can pxamci_irq() be called here?) the callback pxamci_dma_irq() is called.

>From my tests it seems at this point [2] the host->data is always NULL and rest of the callback is never called. It is called once with a nonempty host->data only just before the failure.

During the testing I put udelay(100) at the start of pxamci_dma_irq() and fail occurred after like 2 hours (when I for the first time tapped the touchscreen - higher CPU usage and interrupts).

[1] http://elixir.free-electrons.com/source/drivers/mmc/host/pxamci.c?v=4.10#L385
[2] http://elixir.free-electrons.com/source/drivers/mmc/host/pxamci.c?v=4.10#L561

Best regards,
Petr

^ permalink raw reply	[flat|nested] 12+ messages in thread

* Re: [BUG] dmaengine: pxa_dma: + mmc: pxamci: race condition with DMA error on tx channel
  2017-03-08  6:57 ` Petr Cvek
@ 2017-03-08 16:43   ` Robert Jarzmik
  -1 siblings, 0 replies; 12+ messages in thread
From: Robert Jarzmik @ 2017-03-08 16:43 UTC (permalink / raw)
  To: Petr Cvek
  Cc: vinod.koul, Ulf Hansson, Daniel Mack, Haojian Zhuang, linux-mmc,
	linux-arm-kernel, dmaengine

Petr Cvek <petr.cvek@tul.cz> writes:

Hi Petr,
> I wasn't able to track the problem to a single patch as the problem occurs at
> random time (from the boot to like a half an hour) and it's maybe dependent on a
> level of a battery charge (maybe because of kernel log writes of charging
> messages).
Mmmh, long reproduction time, that will be bad.

> It seems that most occurrency is during writes on an SD card. Using an SDHC
> card decreases the time to fail. After failure the OS is unavailable (rootfs
> in on the card).
Okay, let me try to make write loop on my SD card to see if I manage to
reproduce this.

> From my poking in the kernel source code it seems there is a probability that pxamci_irq() takes longer to call and its subsequent call pxamci_data_done() isn't fast enough to set [1]
> 	host->data = NULL;

> From the DMA side, the DMA done interrupt is generated:
> 	pxad_chan_handler() -> vchan_cookie_complete()
> ...where a tasklet for vchan_complete() is scheduled
At least that seems to hint the DMA part is sound so for.
The bothering part is the log error "mmc0: DMA error on tx channel". I would
need a bit of guidance here, with the same log with [1] applied.

> , where finally with interrupts enabled (can pxamci_irq() be called here?) the
> callback pxamci_dma_irq() is called.
When DMA completes, there is a tiny window, before pxamci_dma_irq() is called,
when pxamci_irq() can be called, yes. As soon as the spinlock is taken in
pxamci_dma_irq() is taken, no more races.

> From my tests it seems at this point [2] the host->data is always NULL and rest
> of the callback is never called. It is called once with a nonempty host->data
> only just before the failure.
>
> During the testing I put udelay(100) at the start of pxamci_dma_irq() and fail
> occurred after like 2 hours (when I for the first time tapped the touchscreen -
> higher CPU usage and interrupts).
Mmm I would need more data here.

The biggest help I could get would be the pxa dma traces here :
echo -n 'file pxa_dma.c +p' > /sys/kernel/debug/dynamic_debug/control
echo -n 'file virt-dma.c +p' > /sys/kernel/debug/dynamic_debug/control

And then capture the last traces and send them to me.

Cheers.

-- 
Robert

[1] Small debug patch
---8>---
diff --git a/drivers/mmc/host/pxamci.c b/drivers/mmc/host/pxamci.c
index c763b404510f..ed3812b2a34d 100644
--- a/drivers/mmc/host/pxamci.c
+++ b/drivers/mmc/host/pxamci.c
@@ -571,8 +571,9 @@ static void pxamci_dma_irq(void *param)
 	if (likely(status == DMA_COMPLETE)) {
 		writel(BUF_PART_FULL, host->base + MMC_PRTBUF);
 	} else {
-		pr_err("%s: DMA error on %s channel\n", mmc_hostname(host->mmc),
-			host->data->flags & MMC_DATA_READ ? "rx" : "tx");
+		pr_err("%s: DMA error on %s channel: %d\n",
+		       mmc_hostname(host->mmc),
+		       host->data->flags & MMC_DATA_READ ? "rx" : "tx", status);
 		host->data->error = -EIO;
 		pxamci_data_done(host, 0);
 	}

^ permalink raw reply related	[flat|nested] 12+ messages in thread

* [BUG] dmaengine: pxa_dma: + mmc: pxamci: race condition with DMA error on tx channel
@ 2017-03-08 16:43   ` Robert Jarzmik
  0 siblings, 0 replies; 12+ messages in thread
From: Robert Jarzmik @ 2017-03-08 16:43 UTC (permalink / raw)
  To: linux-arm-kernel

Petr Cvek <petr.cvek@tul.cz> writes:

Hi Petr,
> I wasn't able to track the problem to a single patch as the problem occurs at
> random time (from the boot to like a half an hour) and it's maybe dependent on a
> level of a battery charge (maybe because of kernel log writes of charging
> messages).
Mmmh, long reproduction time, that will be bad.

> It seems that most occurrency is during writes on an SD card. Using an SDHC
> card decreases the time to fail. After failure the OS is unavailable (rootfs
> in on the card).
Okay, let me try to make write loop on my SD card to see if I manage to
reproduce this.

> From my poking in the kernel source code it seems there is a probability that pxamci_irq() takes longer to call and its subsequent call pxamci_data_done() isn't fast enough to set [1]
> 	host->data = NULL;

> From the DMA side, the DMA done interrupt is generated:
> 	pxad_chan_handler() -> vchan_cookie_complete()
> ...where a tasklet for vchan_complete() is scheduled
At least that seems to hint the DMA part is sound so for.
The bothering part is the log error "mmc0: DMA error on tx channel". I would
need a bit of guidance here, with the same log with [1] applied.

> , where finally with interrupts enabled (can pxamci_irq() be called here?) the
> callback pxamci_dma_irq() is called.
When DMA completes, there is a tiny window, before pxamci_dma_irq() is called,
when pxamci_irq() can be called, yes. As soon as the spinlock is taken in
pxamci_dma_irq() is taken, no more races.

> From my tests it seems at this point [2] the host->data is always NULL and rest
> of the callback is never called. It is called once with a nonempty host->data
> only just before the failure.
>
> During the testing I put udelay(100) at the start of pxamci_dma_irq() and fail
> occurred after like 2 hours (when I for the first time tapped the touchscreen -
> higher CPU usage and interrupts).
Mmm I would need more data here.

The biggest help I could get would be the pxa dma traces here :
echo -n 'file pxa_dma.c +p' > /sys/kernel/debug/dynamic_debug/control
echo -n 'file virt-dma.c +p' > /sys/kernel/debug/dynamic_debug/control

And then capture the last traces and send them to me.

Cheers.

-- 
Robert

[1] Small debug patch
---8>---
diff --git a/drivers/mmc/host/pxamci.c b/drivers/mmc/host/pxamci.c
index c763b404510f..ed3812b2a34d 100644
--- a/drivers/mmc/host/pxamci.c
+++ b/drivers/mmc/host/pxamci.c
@@ -571,8 +571,9 @@ static void pxamci_dma_irq(void *param)
 	if (likely(status == DMA_COMPLETE)) {
 		writel(BUF_PART_FULL, host->base + MMC_PRTBUF);
 	} else {
-		pr_err("%s: DMA error on %s channel\n", mmc_hostname(host->mmc),
-			host->data->flags & MMC_DATA_READ ? "rx" : "tx");
+		pr_err("%s: DMA error on %s channel: %d\n",
+		       mmc_hostname(host->mmc),
+		       host->data->flags & MMC_DATA_READ ? "rx" : "tx", status);
 		host->data->error = -EIO;
 		pxamci_data_done(host, 0);
 	}

^ permalink raw reply related	[flat|nested] 12+ messages in thread

* Re: [BUG] dmaengine: pxa_dma: + mmc: pxamci: race condition with DMA error on tx channel
  2017-03-08 16:43   ` Robert Jarzmik
@ 2017-03-10  0:49     ` Petr Cvek
  -1 siblings, 0 replies; 12+ messages in thread
From: Petr Cvek @ 2017-03-10  0:49 UTC (permalink / raw)
  To: Robert Jarzmik
  Cc: Ulf Hansson, vinod.koul, linux-mmc, Haojian Zhuang,
	linux-arm-kernel, dmaengine, Daniel Mack

[-- Attachment #1: Type: text/plain, Size: 3595 bytes --]

Dne 8.3.2017 v 17:43 Robert Jarzmik napsal(a):
> Petr Cvek <petr.cvek@tul.cz> writes:
> 
> Hi Petr,
>> I wasn't able to track the problem to a single patch as the problem occurs at
>> random time (from the boot to like a half an hour) and it's maybe dependent on a
>> level of a battery charge (maybe because of kernel log writes of charging
>> messages).
> Mmmh, long reproduction time, that will be bad.

Sent log is for a machine which finally died when I tried to start an X server. These debug printks slow it down.

>> It seems that most occurrency is during writes on an SD card. Using an SDHC
>> card decreases the time to fail. After failure the OS is unavailable (rootfs
>> in on the card).
> Okay, let me try to make write loop on my SD card to see if I manage to
> reproduce this.
> 

I tried to enable and disable soundcard (other part which is using DMA), but it does not have any effect. Concurrent interrupts may have.

>> From my poking in the kernel source code it seems there is a probability that pxamci_irq() takes longer to call and its subsequent call pxamci_data_done() isn't fast enough to set [1]
>> 	host->data = NULL;
> 
>> From the DMA side, the DMA done interrupt is generated:
>> 	pxad_chan_handler() -> vchan_cookie_complete()
>> ...where a tasklet for vchan_complete() is scheduled
> At least that seems to hint the DMA part is sound so for.
> The bothering part is the log error "mmc0: DMA error on tx channel". I would
> need a bit of guidance here, with the same log with [1] applied.
> 

Probably some cooperation of the DMA engine and the PXA MMC (like that other mail I've sent to you with UDC and g_webcam). I made another version of debug kernel with my own asserts:

In pxamci_dma_irq() before dmaengine_tx_status() call I've put:

pr_info("!!!cookie=%x complete=%x used=%x\n", 
	host->dma_cookie,chan->completed_cookie,chan->cookie);

It gets called only ONCE, just before failure, which values like this:
	cookie=372 complete=371 used=372

vchan_cyclic_callback() is called only with the soundcard in my machine IMO. I first thought there is regression with vd_completed in pxad_chan_handler() being changed during vchan_cyclic_callback() but it seems not.

pxad_tx_status() returns DMA_IN_PROGRESS before the failure.

>> , where finally with interrupts enabled (can pxamci_irq() be called here?) the
>> callback pxamci_dma_irq() is called.
> When DMA completes, there is a tiny window, before pxamci_dma_irq() is called,
> when pxamci_irq() can be called, yes. As soon as the spinlock is taken in
> pxamci_dma_irq() is taken, no more races.
> 

Does pxamci_dma_irq() depend on pxamci_irq() -> pxamci_data_done() NULLing host->data?

>> From my tests it seems at this point [2] the host->data is always NULL and rest
>> of the callback is never called. It is called once with a nonempty host->data
>> only just before the failure.
>>
>> During the testing I put udelay(100) at the start of pxamci_dma_irq() and fail
>> occurred after like 2 hours (when I for the first time tapped the touchscreen -
>> higher CPU usage and interrupts).
> Mmm I would need more data here.
> 
> The biggest help I could get would be the pxa dma traces here :
> echo -n 'file pxa_dma.c +p' > /sys/kernel/debug/dynamic_debug/control
> echo -n 'file virt-dma.c +p' > /sys/kernel/debug/dynamic_debug/control
> 
> And then capture the last traces and send them to me.

Last traces before the failure are in the attachment. It was copied (by a continual dmesg dump) from a ssh terminal over infraport (/var/log/messages gets corrupted after MMC DMA error).

> 
> Cheers.
> 


[-- Attachment #2: dmesg_mmc.log --]
[-- Type: text/x-log, Size: 28818 bytes --]

[ 1744.486438] dma dma0chan1: phy_enable(); phy=c393d0cc(13) misaligned=0
[ 1744.488362] dma dma0chan1: pxad_chan_handler(): checking txd c25d9ae0[221]: completed=1 dcsr=0x2000000c
[ 1744.488422] dma dma0chan1: pxad_chan_handler(): channel stopped, submitted_empty=1 issued_empty=1
[ 1744.490980] dma dma0chan1: pxad_get_config(): dev_addr=0x41100044 maxburst=32 width=1  dir=1
[ 1744.491072] dma dma0chan1: pxad_prep_slave_sg(): dir=1 flags=1
[ 1744.491175] dma dma0chan1: pxad_tx_prep(): vc=c39bfb30 txd=c25d9da0[0] flags=0x1
[ 1744.491231] dma dma0chan1: pxad_tx_submit(): txd c25d9da0[222]: submitted (not linked)
[ 1744.491286] dma dma0chan1: pxad_issue_pending(): txd c25d9da0[222]
[ 1744.491311] dma dma0chan1: pxad_launch_chan(): desc=c25d9da0
[ 1744.491339] dma dma0chan1: phy_enable(); phy=c393d0cc(13) misaligned=0
[ 1744.493261] dma dma0chan1: pxad_chan_handler(): checking txd c25d9da0[222]: completed=1 dcsr=0x2000000c
[ 1744.493322] dma dma0chan1: pxad_chan_handler(): channel stopped, submitted_empty=1 issued_empty=1
[ 1744.515259] dma dma0chan1: pxad_get_config(): dev_addr=0x41100044 maxburst=32 width=1  dir=1
[ 1744.515364] dma dma0chan1: pxad_prep_slave_sg(): dir=1 flags=1
[ 1744.515460] dma dma0chan1: pxad_tx_prep(): vc=c39bfb30 txd=c25d98c0[0] flags=0x1
[ 1744.515689] dma dma0chan1: pxad_tx_submit(): txd c25d98c0[223]: submitted (not linked)
[ 1744.515753] dma dma0chan1: pxad_issue_pending(): txd c25d98c0[223]
[ 1744.515780] dma dma0chan1: pxad_launch_chan(): desc=c25d98c0
[ 1744.515810] dma dma0chan1: phy_enable(); phy=c393d0cc(13) misaligned=0
[ 1744.517984] dma dma0chan1: pxad_chan_handler(): checking txd c25d98c0[223]: completed=1 dcsr=0x2000000c
[ 1744.518049] dma dma0chan1: pxad_chan_handler(): channel stopped, submitted_empty=1 issued_empty=1
[ 1744.523061] dma dma0chan1: pxad_get_config(): dev_addr=0x41100044 maxburst=32 width=1  dir=1
[ 1744.523136] dma dma0chan1: pxad_prep_slave_sg(): dir=1 flags=1
[ 1744.523229] dma dma0chan1: pxad_tx_prep(): vc=c39bfb30 txd=c25d9b00[0] flags=0x1
[ 1744.523277] dma dma0chan1: pxad_tx_submit(): txd c25d9b00[224]: submitted (not linked)
[ 1744.523332] dma dma0chan1: pxad_issue_pending(): txd c25d9b00[224]
[ 1744.523357] dma dma0chan1: pxad_launch_chan(): desc=c25d9b00
[ 1744.523385] dma dma0chan1: phy_enable(); phy=c393d0cc(13) misaligned=0
[ 1744.525304] dma dma0chan1: pxad_chan_handler(): checking txd c25d9b00[224]: completed=1 dcsr=0x2000000c
[ 1744.525362] dma dma0chan1: pxad_chan_handler(): channel stopped, submitted_empty=1 issued_empty=1
[ 1744.529985] dma dma0chan1: pxad_get_config(): dev_addr=0x41100044 maxburst=32 width=1  dir=1
[ 1744.530102] dma dma0chan1: pxad_prep_slave_sg(): dir=1 flags=1
[ 1744.530195] dma dma0chan1: pxad_tx_prep(): vc=c39bfb30 txd=c25d9600[0] flags=0x1
[ 1744.530232] dma dma0chan1: pxad_tx_submit(): txd c25d9600[225]: submitted (not linked)
[ 1744.530302] dma dma0chan1: pxad_issue_pending(): txd c25d9600[225]
[ 1744.530328] dma dma0chan1: pxad_launch_chan(): desc=c25d9600
[ 1744.530356] dma dma0chan1: phy_enable(); phy=c393d0cc(13) misaligned=0
[ 1744.532278] dma dma0chan1: pxad_chan_handler(): checking txd c25d9600[225]: completed=1 dcsr=0x2000000c
[ 1744.532339] dma dma0chan1: pxad_chan_handler(): channel stopped, submitted_empty=1 issued_empty=1
[ 1744.539374] dma dma0chan1: pxad_get_config(): dev_addr=0x41100044 maxburst=32 width=1  dir=1
[ 1744.539459] dma dma0chan1: pxad_prep_slave_sg(): dir=1 flags=1
[ 1744.543232] dma dma0chan1: pxad_tx_prep(): vc=c39bfb30 txd=c25d9c60[0] flags=0x1
[ 1744.543329] dma dma0chan1: pxad_tx_submit(): txd c25d9c60[226]: submitted (not linked)
[ 1744.543418] dma dma0chan1: pxad_issue_pending(): txd c25d9c60[226]
[ 1744.543443] dma dma0chan1: pxad_launch_chan(): desc=c25d9c60
[ 1744.543475] dma dma0chan1: phy_enable(); phy=c393d0cc(13) misaligned=0
[ 1744.545408] dma dma0chan1: pxad_chan_handler(): checking txd c25d9c60[226]: completed=1 dcsr=0x2000000c
[ 1744.545471] dma dma0chan1: pxad_chan_handler(): channel stopped, submitted_empty=1 issued_empty=1
[ 1744.552053] dma dma0chan1: pxad_get_config(): dev_addr=0x41100044 maxburst=32 width=1  dir=1
[ 1744.552132] dma dma0chan1: pxad_prep_slave_sg(): dir=1 flags=1
[ 1744.552223] dma dma0chan1: pxad_tx_prep(): vc=c39bfb30 txd=c25d9a40[0] flags=0x1
[ 1744.552260] dma dma0chan1: pxad_tx_submit(): txd c25d9a40[227]: submitted (not linked)
[ 1744.552329] dma dma0chan1: pxad_issue_pending(): txd c25d9a40[227]
[ 1744.552355] dma dma0chan1: pxad_launch_chan(): desc=c25d9a40
[ 1744.552383] dma dma0chan1: phy_enable(); phy=c393d0cc(13) misaligned=0
[ 1744.554327] dma dma0chan1: pxad_chan_handler(): checking txd c25d9a40[227]: completed=1 dcsr=0x2000000c
[ 1744.554393] dma dma0chan1: pxad_chan_handler(): channel stopped, submitted_empty=1 issued_empty=1
[ 1744.558435] dma dma0chan1: pxad_get_config(): dev_addr=0x41100044 maxburst=32 width=1  dir=1
[ 1744.564320] dma dma0chan1: pxad_prep_slave_sg(): dir=1 flags=1
[ 1744.564431] dma dma0chan1: pxad_tx_prep(): vc=c39bfb30 txd=c25d9ce0[0] flags=0x1
[ 1744.564485] dma dma0chan1: pxad_tx_submit(): txd c25d9ce0[228]: submitted (not linked)
[ 1744.564782] dma dma0chan1: pxad_issue_pending(): txd c25d9ce0[228]
[ 1744.564813] dma dma0chan1: pxad_launch_chan(): desc=c25d9ce0
[ 1744.564844] dma dma0chan1: phy_enable(); phy=c393d0cc(13) misaligned=0
[ 1744.566941] dma dma0chan1: pxad_chan_handler(): checking txd c25d9ce0[228]: completed=1 dcsr=0x2000000c
[ 1744.566999] dma dma0chan1: pxad_chan_handler(): channel stopped, submitted_empty=1 issued_empty=1
[ 1744.570471] dma dma0chan1: pxad_get_config(): dev_addr=0x41100044 maxburst=32 width=1  dir=1
[ 1744.570715] dma dma0chan1: pxad_prep_slave_sg(): dir=1 flags=1
[ 1744.570822] dma dma0chan1: pxad_tx_prep(): vc=c39bfb30 txd=c25d9800[0] flags=0x1
[ 1744.570858] dma dma0chan1: pxad_tx_submit(): txd c25d9800[229]: submitted (not linked)
[ 1744.570925] dma dma0chan1: pxad_issue_pending(): txd c25d9800[229]
[ 1744.570951] dma dma0chan1: pxad_launch_chan(): desc=c25d9800
[ 1744.570979] dma dma0chan1: phy_enable(); phy=c393d0cc(13) misaligned=0
[ 1744.572909] dma dma0chan1: pxad_chan_handler(): checking txd c25d9800[229]: completed=1 dcsr=0x2000000c
[ 1744.572967] dma dma0chan1: pxad_chan_handler(): channel stopped, submitted_empty=1 issued_empty=1
[ 1744.614160] dma dma0chan1: pxad_get_config(): dev_addr=0x41100044 maxburst=32 width=1  dir=1
[ 1744.614218] dma dma0chan1: pxad_prep_slave_sg(): dir=1 flags=1
[ 1744.614296] dma dma0chan1: pxad_tx_prep(): vc=c39bfb30 txd=c25d98c0[0] flags=0x1
[ 1744.614333] dma dma0chan1: pxad_tx_submit(): txd c25d98c0[22a]: submitted (not linked)
[ 1744.614396] dma dma0chan1: pxad_issue_pending(): txd c25d98c0[22a]
[ 1744.614421] dma dma0chan1: pxad_launch_chan(): desc=c25d98c0
[ 1744.614449] dma dma0chan1: phy_enable(); phy=c393d0cc(13) misaligned=0
[ 1744.616398] dma dma0chan1: pxad_chan_handler(): checking txd c25d98c0[22a]: completed=1 dcsr=0x2000000c
[ 1744.616462] dma dma0chan1: pxad_chan_handler(): channel stopped, submitted_empty=1 issued_empty=1
[ 1744.618257] dma dma0chan0: pxad_get_config(): dev_addr=0x41100040 maxburst=32 width=1  dir=2
[ 1744.618316] dma dma0chan0: pxad_prep_slave_sg(): dir=2 flags=1
[ 1744.618379] dma dma0chan0: pxad_tx_prep(): vc=c39bfa30 txd=c25d9b00[0] flags=0x1
[ 1744.618415] dma dma0chan0: pxad_tx_submit(): txd c25d9b00[418f]: submitted (not linked)
[ 1744.618446] dma dma0chan0: pxad_issue_pending(): txd c25d9b00[418f]
[ 1744.618471] dma dma0chan0: pxad_launch_chan(): desc=c25d9b00
[ 1744.618499] dma dma0chan0: phy_enable(); phy=c393d0c0(12) misaligned=0
[ 1744.621330] dma dma0chan0: pxad_chan_handler(): checking txd c25d9b00[418f]: completed=1 dcsr=0x2000000c
[ 1744.621394] dma dma0chan0: pxad_chan_handler(): channel stopped, submitted_empty=1 issued_empty=1
[ 1744.622913] dma dma0chan0: pxad_get_config(): dev_addr=0x41100040 maxburst=32 width=1  dir=2
[ 1744.622969] dma dma0chan0: pxad_prep_slave_sg(): dir=2 flags=1
[ 1744.623052] dma dma0chan0: pxad_tx_prep(): vc=c39bfa30 txd=c25d9c60[0] flags=0x1
[ 1744.623090] dma dma0chan0: pxad_tx_submit(): txd c25d9c60[4190]: submitted (not linked)
[ 1744.623121] dma dma0chan0: pxad_issue_pending(): txd c25d9c60[4190]
[ 1744.623146] dma dma0chan0: pxad_launch_chan(): desc=c25d9c60
[ 1744.623175] dma dma0chan0: phy_enable(); phy=c393d0c0(12) misaligned=0
[ 1744.625671] dma dma0chan0: pxad_chan_handler(): checking txd c25d9c60[4190]: completed=1 dcsr=0x2000000c
[ 1744.625729] dma dma0chan0: pxad_chan_handler(): channel stopped, submitted_empty=1 issued_empty=1
[ 1744.628134] dma dma0chan0: pxad_get_config(): dev_addr=0x41100040 maxburst=32 width=1  dir=2
[ 1744.628196] dma dma0chan0: pxad_prep_slave_sg(): dir=2 flags=1
[ 1744.628278] dma dma0chan0: pxad_tx_prep(): vc=c39bfa30 txd=c25d9ce0[0] flags=0x1
[ 1744.628316] dma dma0chan0: pxad_tx_submit(): txd c25d9ce0[4191]: submitted (not linked)
[ 1744.628347] dma dma0chan0: pxad_issue_pending(): txd c25d9ce0[4191]
[ 1744.628371] dma dma0chan0: pxad_launch_chan(): desc=c25d9ce0
[ 1744.628399] dma dma0chan0: phy_enable(); phy=c393d0c0(12) misaligned=0
[ 1744.631024] dma dma0chan0: pxad_chan_handler(): checking txd c25d9ce0[4191]: completed=1 dcsr=0x2000000c
[ 1744.631083] dma dma0chan0: pxad_chan_handler(): channel stopped, submitted_empty=1 issued_empty=1
[ 1744.634950] dma dma0chan0: pxad_get_config(): dev_addr=0x41100040 maxburst=32 width=1  dir=2
[ 1744.635016] dma dma0chan0: pxad_prep_slave_sg(): dir=2 flags=1
[ 1744.635097] dma dma0chan0: pxad_tx_prep(): vc=c39bfa30 txd=c25d9d60[0] flags=0x1
[ 1744.635136] dma dma0chan0: pxad_tx_submit(): txd c25d9d60[4192]: submitted (not linked)
[ 1744.635167] dma dma0chan0: pxad_issue_pending(): txd c25d9d60[4192]
[ 1744.635192] dma dma0chan0: pxad_launch_chan(): desc=c25d9d60
[ 1744.635220] dma dma0chan0: phy_enable(); phy=c393d0c0(12) misaligned=0
[ 1744.637612] dma dma0chan0: pxad_chan_handler(): checking txd c25d9d60[4192]: completed=1 dcsr=0x2000000c
[ 1744.637674] dma dma0chan0: pxad_chan_handler(): channel stopped, submitted_empty=1 issued_empty=1
[ 1744.649254] dma dma0chan0: pxad_get_config(): dev_addr=0x41100040 maxburst=32 width=1  dir=2
[ 1744.649317] dma dma0chan0: pxad_prep_slave_sg(): dir=2 flags=1
[ 1744.649399] dma dma0chan0: pxad_tx_prep(): vc=c39bfa30 txd=c24fb640[0] flags=0x1
[ 1744.649437] dma dma0chan0: pxad_tx_submit(): txd c24fb640[4193]: submitted (not linked)
[ 1744.649469] dma dma0chan0: pxad_issue_pending(): txd c24fb640[4193]
[ 1744.649493] dma dma0chan0: pxad_launch_chan(): desc=c24fb640
[ 1744.649522] dma dma0chan0: phy_enable(); phy=c393d0c0(12) misaligned=0
[ 1744.652246] dma dma0chan0: pxad_chan_handler(): checking txd c24fb640[4193]: completed=1 dcsr=0x2000000c
[ 1744.652307] dma dma0chan0: pxad_chan_handler(): channel stopped, submitted_empty=1 issued_empty=1
[ 1744.660324] dma dma0chan0: pxad_get_config(): dev_addr=0x41100040 maxburst=32 width=1  dir=2
[ 1744.660383] dma dma0chan0: pxad_prep_slave_sg(): dir=2 flags=1
[ 1744.660469] dma dma0chan0: pxad_tx_prep(): vc=c39bfa30 txd=c24fbd20[0] flags=0x1
[ 1744.660742] dma dma0chan0: pxad_tx_submit(): txd c24fbd20[4194]: submitted (not linked)
[ 1744.660774] dma dma0chan0: pxad_issue_pending(): txd c24fbd20[4194]
[ 1744.660799] dma dma0chan0: pxad_launch_chan(): desc=c24fbd20
[ 1744.660828] dma dma0chan0: phy_enable(); phy=c393d0c0(12) misaligned=0
[ 1744.663174] dma dma0chan0: pxad_chan_handler(): checking txd c24fbd20[4194]: completed=1 dcsr=0x2000000c
[ 1744.663239] dma dma0chan0: pxad_chan_handler(): channel stopped, submitted_empty=1 issued_empty=1
[ 1744.667122] dma dma0chan0: pxad_get_config(): dev_addr=0x41100040 maxburst=32 width=1  dir=2
[ 1744.667185] dma dma0chan0: pxad_prep_slave_sg(): dir=2 flags=1
[ 1744.667268] dma dma0chan0: pxad_tx_prep(): vc=c39bfa30 txd=c24fb540[0] flags=0x1
[ 1744.667307] dma dma0chan0: pxad_tx_submit(): txd c24fb540[4195]: submitted (not linked)
[ 1744.667338] dma dma0chan0: pxad_issue_pending(): txd c24fb540[4195]
[ 1744.667363] dma dma0chan0: pxad_launch_chan(): desc=c24fb540
[ 1744.667391] dma dma0chan0: phy_enable(); phy=c393d0c0(12) misaligned=0
[ 1744.669743] dma dma0chan0: pxad_chan_handler(): checking txd c24fb540[4195]: completed=1 dcsr=0x2000000c
[ 1744.669803] dma dma0chan0: pxad_chan_handler(): channel stopped, submitted_empty=1 issued_empty=1
[ 1744.674144] dma dma0chan0: pxad_get_config(): dev_addr=0x41100040 maxburst=32 width=1  dir=2
[ 1744.674208] dma dma0chan0: pxad_prep_slave_sg(): dir=2 flags=1
[ 1744.674294] dma dma0chan0: pxad_tx_prep(): vc=c39bfa30 txd=c24fbf60[0] flags=0x1
[ 1744.674332] dma dma0chan0: pxad_tx_submit(): txd c24fbf60[4196]: submitted (not linked)
[ 1744.674363] dma dma0chan0: pxad_issue_pending(): txd c24fbf60[4196]
[ 1744.674387] dma dma0chan0: pxad_launch_chan(): desc=c24fbf60
[ 1744.674415] dma dma0chan0: phy_enable(); phy=c393d0c0(12) misaligned=0
[ 1744.676927] dma dma0chan0: pxad_chan_handler(): checking txd c24fbf60[4196]: completed=1 dcsr=0x2000000c
[ 1744.676987] dma dma0chan0: pxad_chan_handler(): channel stopped, submitted_empty=1 issued_empty=1
[ 1744.680962] dma dma0chan0: pxad_get_config(): dev_addr=0x41100040 maxburst=32 width=1  dir=2
[ 1744.681022] dma dma0chan0: pxad_prep_slave_sg(): dir=2 flags=1
[ 1744.681109] dma dma0chan0: pxad_tx_prep(): vc=c39bfa30 txd=c2593920[0] flags=0x1
[ 1744.681146] dma dma0chan0: pxad_tx_submit(): txd c2593920[4197]: submitted (not linked)
[ 1744.681179] dma dma0chan0: pxad_issue_pending(): txd c2593920[4197]
[ 1744.681204] dma dma0chan0: pxad_launch_chan(): desc=c2593920
[ 1744.681233] dma dma0chan0: phy_enable(); phy=c393d0c0(12) misaligned=0
[ 1744.683544] dma dma0chan0: pxad_chan_handler(): checking txd c2593920[4197]: completed=1 dcsr=0x2000000c
[ 1744.683604] dma dma0chan0: pxad_chan_handler(): channel stopped, submitted_empty=1 issued_empty=1
[ 1744.685019] dma dma0chan0: pxad_get_config(): dev_addr=0x41100040 maxburst=32 width=1  dir=2
[ 1744.685081] dma dma0chan0: pxad_prep_slave_sg(): dir=2 flags=1
[ 1744.685247] dma dma0chan0: pxad_tx_prep(): vc=c39bfa30 txd=c32c77c0[0] flags=0x1
[ 1744.685284] dma dma0chan0: pxad_tx_submit(): txd c32c77c0[4198]: submitted (not linked)
[ 1744.685316] dma dma0chan0: pxad_issue_pending(): txd c32c77c0[4198]
[ 1744.685340] dma dma0chan0: pxad_launch_chan(): desc=c32c77c0
[ 1744.685369] dma dma0chan0: phy_enable(); phy=c393d0c0(12) misaligned=0
[ 1744.687807] dma dma0chan0: pxad_chan_handler(): checking txd c32c77c0[4198]: completed=1 dcsr=0x2000000c
[ 1744.687864] dma dma0chan0: pxad_chan_handler(): channel stopped, submitted_empty=1 issued_empty=1
[ 1744.690083] dma dma0chan0: pxad_get_config(): dev_addr=0x41100040 maxburst=32 width=1  dir=2
[ 1744.690143] dma dma0chan0: pxad_prep_slave_sg(): dir=2 flags=1
[ 1744.690239] dma dma0chan0: pxad_tx_prep(): vc=c39bfa30 txd=c32c7e20[0] flags=0x1
[ 1744.690278] dma dma0chan0: pxad_tx_submit(): txd c32c7e20[4199]: submitted (not linked)
[ 1744.690309] dma dma0chan0: pxad_issue_pending(): txd c32c7e20[4199]
[ 1744.690335] dma dma0chan0: pxad_launch_chan(): desc=c32c7e20
[ 1744.690363] dma dma0chan0: phy_enable(); phy=c393d0c0(12) misaligned=0
[ 1744.692742] dma dma0chan0: pxad_chan_handler(): checking txd c32c7e20[4199]: completed=1 dcsr=0x2000000c
[ 1744.692804] dma dma0chan0: pxad_chan_handler(): channel stopped, submitted_empty=1 issued_empty=1
[ 1744.697989] dma dma0chan0: pxad_get_config(): dev_addr=0x41100040 maxburst=32 width=1  dir=2
[ 1744.698048] dma dma0chan0: pxad_prep_slave_sg(): dir=2 flags=1
[ 1744.698147] dma dma0chan0: pxad_tx_prep(): vc=c39bfa30 txd=c32c7ea0[0] flags=0x1
[ 1744.698188] dma dma0chan0: pxad_tx_submit(): txd c32c7ea0[419a]: submitted (not linked)
[ 1744.698219] dma dma0chan0: pxad_issue_pending(): txd c32c7ea0[419a]
[ 1744.698244] dma dma0chan0: pxad_launch_chan(): desc=c32c7ea0
[ 1744.698271] dma dma0chan0: phy_enable(); phy=c393d0c0(12) misaligned=0
[ 1744.700709] dma dma0chan0: pxad_chan_handler(): checking txd c32c7ea0[419a]: completed=1 dcsr=0x2000000c
[ 1744.700769] dma dma0chan0: pxad_chan_handler(): channel stopped, submitted_empty=1 issued_empty=1
[ 1744.703772] dma dma0chan1: pxad_get_config(): dev_addr=0x41100044 maxburst=32 width=1  dir=1
[ 1744.703832] dma dma0chan1: pxad_prep_slave_sg(): dir=1 flags=1
[ 1744.703906] dma dma0chan1: pxad_tx_prep(): vc=c39bfb30 txd=c27c0020[0] flags=0x1
[ 1744.703944] dma dma0chan1: pxad_tx_submit(): txd c27c0020[22b]: submitted (not linked)
[ 1744.704016] dma dma0chan1: pxad_issue_pending(): txd c27c0020[22b]
[ 1744.704046] dma dma0chan1: pxad_launch_chan(): desc=c27c0020
[ 1744.704075] dma dma0chan1: phy_enable(); phy=c393d0cc(13) misaligned=0
[ 1744.706172] dma dma0chan1: pxad_chan_handler(): checking txd c27c0020[22b]: completed=1 dcsr=0x2000000c
[ 1744.706229] dma dma0chan1: pxad_chan_handler(): channel stopped, submitted_empty=1 issued_empty=1
[ 1744.715827] dma dma0chan1: pxad_get_config(): dev_addr=0x41100044 maxburst=32 width=1  dir=1
[ 1744.715885] dma dma0chan1: pxad_prep_slave_sg(): dir=1 flags=1
[ 1744.715962] dma dma0chan1: pxad_tx_prep(): vc=c39bfb30 txd=c27c0480[0] flags=0x1
[ 1744.715999] dma dma0chan1: pxad_tx_submit(): txd c27c0480[22c]: submitted (not linked)
[ 1744.716066] dma dma0chan1: pxad_issue_pending(): txd c27c0480[22c]
[ 1744.716091] dma dma0chan1: pxad_launch_chan(): desc=c27c0480
[ 1744.716120] dma dma0chan1: phy_enable(); phy=c393d0cc(13) misaligned=0
[ 1744.718052] dma dma0chan1: pxad_chan_handler(): checking txd c27c0480[22c]: completed=1 dcsr=0x2000000c
[ 1744.718110] dma dma0chan1: pxad_chan_handler(): channel stopped, submitted_empty=1 issued_empty=1
[ 1744.724194] dma dma0chan1: pxad_get_config(): dev_addr=0x41100044 maxburst=32 width=1  dir=1
[ 1744.724255] dma dma0chan1: pxad_prep_slave_sg(): dir=1 flags=1
[ 1744.724335] dma dma0chan1: pxad_tx_prep(): vc=c39bfb30 txd=c24fa440[0] flags=0x1
[ 1744.724370] dma dma0chan1: pxad_tx_submit(): txd c24fa440[22d]: submitted (not linked)
[ 1744.724447] dma dma0chan1: pxad_issue_pending(): txd c24fa440[22d]
[ 1744.724474] dma dma0chan1: pxad_launch_chan(): desc=c24fa440
[ 1744.724502] dma dma0chan1: phy_enable(); phy=c393d0cc(13) misaligned=0
[ 1744.726476] dma dma0chan1: pxad_chan_handler(): checking txd c24fa440[22d]: completed=1 dcsr=0x2000000c
[ 1744.726535] dma dma0chan1: pxad_chan_handler(): channel stopped, submitted_empty=1 issued_empty=1
[ 1744.730882] dma dma0chan1: pxad_get_config(): dev_addr=0x41100044 maxburst=32 width=1  dir=1
[ 1744.730942] dma dma0chan1: pxad_prep_slave_sg(): dir=1 flags=1
[ 1744.731032] dma dma0chan1: pxad_tx_prep(): vc=c39bfb30 txd=c24fa800[0] flags=0x1
[ 1744.731067] dma dma0chan1: pxad_tx_submit(): txd c24fa800[22e]: submitted (not linked)
[ 1744.731131] dma dma0chan1: pxad_issue_pending(): txd c24fa800[22e]
[ 1744.731156] dma dma0chan1: pxad_launch_chan(): desc=c24fa800
[ 1744.731184] dma dma0chan1: phy_enable(); phy=c393d0cc(13) misaligned=0
[ 1744.733124] dma dma0chan1: pxad_chan_handler(): checking txd c24fa800[22e]: completed=1 dcsr=0x2000000c
[ 1744.733185] dma dma0chan1: pxad_chan_handler(): channel stopped, submitted_empty=1 issued_empty=1
[ 1744.738034] dma dma0chan1: pxad_get_config(): dev_addr=0x41100044 maxburst=32 width=1  dir=1
[ 1744.738094] dma dma0chan1: pxad_prep_slave_sg(): dir=1 flags=1
[ 1744.738186] dma dma0chan1: pxad_tx_prep(): vc=c39bfb30 txd=c24fa880[0] flags=0x1
[ 1744.738221] dma dma0chan1: pxad_tx_submit(): txd c24fa880[22f]: submitted (not linked)
[ 1744.738287] dma dma0chan1: pxad_issue_pending(): txd c24fa880[22f]
[ 1744.738312] dma dma0chan1: pxad_launch_chan(): desc=c24fa880
[ 1744.738340] dma dma0chan1: phy_enable(); phy=c393d0cc(13) misaligned=0
[ 1744.740314] dma dma0chan1: pxad_chan_handler(): checking txd c24fa880[22f]: completed=1 dcsr=0x2000000c
[ 1744.740375] dma dma0chan1: pxad_chan_handler(): channel stopped, submitted_empty=1 issued_empty=1
[ 1744.745047] dma dma0chan1: pxad_get_config(): dev_addr=0x41100044 maxburst=32 width=1  dir=1
[ 1744.745105] dma dma0chan1: pxad_prep_slave_sg(): dir=1 flags=1
[ 1744.745198] dma dma0chan1: pxad_tx_prep(): vc=c39bfb30 txd=c24fa900[0] flags=0x1
[ 1744.745233] dma dma0chan1: pxad_tx_submit(): txd c24fa900[230]: submitted (not linked)
[ 1744.745303] dma dma0chan1: pxad_issue_pending(): txd c24fa900[230]
[ 1744.745329] dma dma0chan1: pxad_launch_chan(): desc=c24fa900
[ 1744.745358] dma dma0chan1: phy_enable(); phy=c393d0cc(13) misaligned=0
[ 1744.747331] dma dma0chan1: pxad_chan_handler(): checking txd c24fa900[230]: completed=1 dcsr=0x2000000c
[ 1744.747391] dma dma0chan1: pxad_chan_handler(): channel stopped, submitted_empty=1 issued_empty=1
[ 1744.750498] dma dma0chan1: pxad_get_config(): dev_addr=0x41100044 maxburst=32 width=1  dir=1
[ 1744.750755] dma dma0chan1: pxad_prep_slave_sg(): dir=1 flags=1
[ 1744.750840] dma dma0chan1: pxad_tx_prep(): vc=c39bfb30 txd=c24fa980[0] flags=0x1
[ 1744.750876] dma dma0chan1: pxad_tx_submit(): txd c24fa980[231]: submitted (not linked)
[ 1744.750941] dma dma0chan1: pxad_issue_pending(): txd c24fa980[231]
[ 1744.750967] dma dma0chan1: pxad_launch_chan(): desc=c24fa980
[ 1744.750996] dma dma0chan1: phy_enable(); phy=c393d0cc(13) misaligned=0
[ 1744.752917] dma dma0chan1: pxad_chan_handler(): checking txd c24fa980[231]: completed=1 dcsr=0x2000000c
[ 1744.752975] dma dma0chan1: pxad_chan_handler(): channel stopped, submitted_empty=1 issued_empty=1
[ 1744.757762] dma dma0chan1: pxad_get_config(): dev_addr=0x41100044 maxburst=32 width=1  dir=1
[ 1744.757820] dma dma0chan1: pxad_prep_slave_sg(): dir=1 flags=1
[ 1744.757907] dma dma0chan1: pxad_tx_prep(): vc=c39bfb30 txd=c24faa00[0] flags=0x1
[ 1744.757944] dma dma0chan1: pxad_tx_submit(): txd c24faa00[232]: submitted (not linked)
[ 1744.758002] dma dma0chan1: pxad_issue_pending(): txd c24faa00[232]
[ 1744.758027] dma dma0chan1: pxad_launch_chan(): desc=c24faa00
[ 1744.758054] dma dma0chan1: phy_enable(); phy=c393d0cc(13) misaligned=0
[ 1744.759976] dma dma0chan1: pxad_chan_handler(): checking txd c24faa00[232]: completed=1 dcsr=0x2000000c
[ 1744.760034] dma dma0chan1: pxad_chan_handler(): channel stopped, submitted_empty=1 issued_empty=1
[ 1744.763064] dma dma0chan1: pxad_get_config(): dev_addr=0x41100044 maxburst=32 width=1  dir=1
[ 1744.763122] dma dma0chan1: pxad_prep_slave_sg(): dir=1 flags=1
[ 1744.763216] dma dma0chan1: pxad_tx_prep(): vc=c39bfb30 txd=c24faa80[0] flags=0x1
[ 1744.763251] dma dma0chan1: pxad_tx_submit(): txd c24faa80[233]: submitted (not linked)
[ 1744.763322] dma dma0chan1: pxad_issue_pending(): txd c24faa80[233]
[ 1744.763347] dma dma0chan1: pxad_launch_chan(): desc=c24faa80
[ 1744.763376] dma dma0chan1: phy_enable(); phy=c393d0cc(13) misaligned=0
[ 1744.765349] dma dma0chan1: pxad_chan_handler(): checking txd c24faa80[233]: completed=1 dcsr=0x2000000c
[ 1744.765412] dma dma0chan1: pxad_chan_handler(): channel stopped, submitted_empty=1 issued_empty=1
[ 1744.772298] dma dma0chan1: pxad_get_config(): dev_addr=0x41100044 maxburst=32 width=1  dir=1
[ 1744.772355] dma dma0chan1: pxad_prep_slave_sg(): dir=1 flags=1
[ 1744.772449] dma dma0chan1: pxad_tx_prep(): vc=c39bfb30 txd=c24faba0[0] flags=0x1
[ 1744.772485] dma dma0chan1: pxad_tx_submit(): txd c24faba0[234]: submitted (not linked)
[ 1744.772834] dma dma0chan1: pxad_issue_pending(): txd c24faba0[234]
[ 1744.772861] dma dma0chan1: pxad_launch_chan(): desc=c24faba0
[ 1744.772891] dma dma0chan1: phy_enable(); phy=c393d0cc(13) misaligned=0
[ 1744.775009] dma dma0chan1: pxad_chan_handler(): checking txd c24faba0[234]: completed=1 dcsr=0x2000000c
[ 1744.775066] dma dma0chan1: pxad_chan_handler(): channel stopped, submitted_empty=1 issued_empty=1
[ 1744.778048] dma dma0chan1: pxad_get_config(): dev_addr=0x41100044 maxburst=32 width=1  dir=1
[ 1744.778110] dma dma0chan1: pxad_prep_slave_sg(): dir=1 flags=1
[ 1744.778203] dma dma0chan1: pxad_tx_prep(): vc=c39bfb30 txd=c24fac20[0] flags=0x1
[ 1744.778239] dma dma0chan1: pxad_tx_submit(): txd c24fac20[235]: submitted (not linked)
[ 1744.778308] dma dma0chan1: pxad_issue_pending(): txd c24fac20[235]
[ 1744.778333] dma dma0chan1: pxad_launch_chan(): desc=c24fac20
[ 1744.778361] dma dma0chan1: phy_enable(); phy=c393d0cc(13) misaligned=0
[ 1744.780298] dma dma0chan1: pxad_chan_handler(): checking txd c24fac20[235]: completed=1 dcsr=0x2000000c
[ 1744.780356] dma dma0chan1: pxad_chan_handler(): channel stopped, submitted_empty=1 issued_empty=1
[ 1744.782944] dma dma0chan1: pxad_get_config(): dev_addr=0x41100044 maxburst=32 width=1  dir=1
[ 1744.783004] dma dma0chan1: pxad_prep_slave_sg(): dir=1 flags=1
[ 1744.783081] dma dma0chan1: pxad_tx_prep(): vc=c39bfb30 txd=c24faca0[0] flags=0x1
[ 1744.783117] dma dma0chan1: pxad_tx_submit(): txd c24faca0[236]: submitted (not linked)
[ 1744.783178] dma dma0chan1: pxad_issue_pending(): txd c24faca0[236]
[ 1744.783205] dma dma0chan1: pxad_launch_chan(): desc=c24faca0
[ 1744.783233] dma dma0chan1: phy_enable(); phy=c393d0cc(13) misaligned=0
[ 1744.785163] dma dma0chan1: pxad_chan_handler(): checking txd c24faca0[236]: completed=1 dcsr=0x2000000c
[ 1744.785222] dma dma0chan1: pxad_chan_handler(): channel stopped, submitted_empty=1 issued_empty=1
[ 1744.790232] dma dma0chan1: pxad_get_config(): dev_addr=0x41100044 maxburst=32 width=1  dir=1
[ 1744.790292] dma dma0chan1: pxad_prep_slave_sg(): dir=1 flags=1
[ 1744.790385] dma dma0chan1: pxad_tx_prep(): vc=c39bfb30 txd=c24fad20[0] flags=0x1
[ 1744.790421] dma dma0chan1: pxad_tx_submit(): txd c24fad20[237]: submitted (not linked)
[ 1744.790483] dma dma0chan1: pxad_issue_pending(): txd c24fad20[237]
[ 1744.790508] dma dma0chan1: pxad_launch_chan(): desc=c24fad20
[ 1744.790536] dma dma0chan1: phy_enable(); phy=c393d0cc(13) misaligned=0
[ 1744.792486] dma dma0chan1: pxad_chan_handler(): checking txd c24fad20[237]: completed=1 dcsr=0x2000000c
[ 1744.792543] dma dma0chan1: pxad_chan_handler(): channel stopped, submitted_empty=1 issued_empty=1
[ 1744.796450] dma dma0chan1: pxad_get_config(): dev_addr=0x41100044 maxburst=32 width=1  dir=1
[ 1744.796711] dma dma0chan1: pxad_prep_slave_sg(): dir=1 flags=1
[ 1744.796803] dma dma0chan1: pxad_tx_prep(): vc=c39bfb30 txd=c24fada0[0] flags=0x1
[ 1744.796839] dma dma0chan1: pxad_tx_submit(): txd c24fada0[238]: submitted (not linked)
[ 1744.796901] dma dma0chan1: pxad_issue_pending(): txd c24fada0[238]
[ 1744.796926] dma dma0chan1: pxad_launch_chan(): desc=c24fada0
[ 1744.796956] dma dma0chan1: phy_enable(); phy=c393d0cc(13) misaligned=0
[ 1744.798894] dma dma0chan1: pxad_chan_handler(): checking txd c24fada0[238]: completed=1 dcsr=0x2000000c
[ 1744.798950] dma dma0chan1: pxad_chan_handler(): channel stopped, submitted_empty=1 issued_empty=1
[ 1744.805444] dma dma0chan1: pxad_get_config(): dev_addr=0x41100044 maxburst=32 width=1  dir=1
[ 1744.805707] dma dma0chan1: pxad_prep_slave_sg(): dir=1 flags=1
[ 1744.805799] dma dma0chan1: pxad_tx_prep(): vc=c39bfb30 txd=c24fae20[0] flags=0x1
[ 1744.805835] dma dma0chan1: pxad_tx_submit(): txd c24fae20[239]: submitted (not linked)
[ 1744.805900] dma dma0chan1: pxad_issue_pending(): txd c24fae20[239]
[ 1744.805925] dma dma0chan1: pxad_launch_chan(): desc=c24fae20
[ 1744.805954] dma dma0chan1: phy_enable(); phy=c393d0cc(13) misaligned=0
[ 1744.807888] dma dma0chan1: pxad_chan_handler(): checking txd c24fae20[239]: completed=1 dcsr=0x2000000c
[ 1744.807947] dma dma0chan1: pxad_chan_handler(): channel stopped, submitted_empty=1 issued_empty=1
[ 1744.814156] dma dma0chan1: pxad_get_config(): dev_addr=0x41100044 maxburst=32 width=1  dir=1
[ 1744.814233] dma dma0chan1: pxad_prep_slave_sg(): dir=1 flags=1
[ 1744.814313] dma dma0chan1: pxad_tx_prep(): vc=c39bfb30 txd=c24fa800[0] flags=0x1
[ 1744.814364] dma dma0chan1: pxad_tx_submit(): txd c24fa800[23a]: submitted (not linked)
[ 1744.814420] dma dma0chan1: pxad_issue_pending(): txd c24fa800[23a]
[ 1744.814446] dma dma0chan1: pxad_launch_chan(): desc=c24fa800
[ 1744.814474] dma dma0chan1: phy_enable(); phy=c393d0cc(13) misaligned=0
[ 1744.816416] dma dma0chan1: pxad_chan_handler(): checking txd c24fa800[23a]: completed=1 dcsr=0x2000000c
[ 1744.816479] dma dma0chan1: pxad_chan_handler(): channel stopped, submitted_empty=1 issued_empty=1
[ 1744.822095] dma dma0chan1: pxad_get_config(): dev_addr=0x41100044 maxburst=32 width=1  dir=1
[ 1744.822188] dma dma0chan1: pxad_prep_slave_sg(): dir=1 flags=1
[ 1744.822301] dma dma0chan1: pxad_tx_prep(): vc=c39bfb30 txd=c24fa880[0] flags=0x1
[ 1744.822337] dma dma0chan1: pxad_tx_submit(): txd c24fa880[23b]: submitted (not linked)
[ 1744.822406] dma dma0chan1: pxad_issue_pending(): txd c24fa880[23b]
[ 1744.822431] dma dma0chan1: pxad_launch_chan(): desc=c24fa880
[ 1744.822460] dma dma0chan1: phy_enable(); phy=c393d0cc(13) misaligned=0
[ 1744.823948] dma dma0chan1: pxad_residue(): txd c24fa880[23b] sw_desc=c24fa880: 1024
[ 1744.823992] mmc0: DMA error on tx channel

[-- Attachment #3: Type: text/plain, Size: 176 bytes --]

_______________________________________________
linux-arm-kernel mailing list
linux-arm-kernel@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-arm-kernel

^ permalink raw reply	[flat|nested] 12+ messages in thread

* [BUG] dmaengine: pxa_dma: + mmc: pxamci: race condition with DMA error on tx channel
@ 2017-03-10  0:49     ` Petr Cvek
  0 siblings, 0 replies; 12+ messages in thread
From: Petr Cvek @ 2017-03-10  0:49 UTC (permalink / raw)
  To: linux-arm-kernel

Dne 8.3.2017 v 17:43 Robert Jarzmik napsal(a):
> Petr Cvek <petr.cvek@tul.cz> writes:
> 
> Hi Petr,
>> I wasn't able to track the problem to a single patch as the problem occurs at
>> random time (from the boot to like a half an hour) and it's maybe dependent on a
>> level of a battery charge (maybe because of kernel log writes of charging
>> messages).
> Mmmh, long reproduction time, that will be bad.

Sent log is for a machine which finally died when I tried to start an X server. These debug printks slow it down.

>> It seems that most occurrency is during writes on an SD card. Using an SDHC
>> card decreases the time to fail. After failure the OS is unavailable (rootfs
>> in on the card).
> Okay, let me try to make write loop on my SD card to see if I manage to
> reproduce this.
> 

I tried to enable and disable soundcard (other part which is using DMA), but it does not have any effect. Concurrent interrupts may have.

>> From my poking in the kernel source code it seems there is a probability that pxamci_irq() takes longer to call and its subsequent call pxamci_data_done() isn't fast enough to set [1]
>> 	host->data = NULL;
> 
>> From the DMA side, the DMA done interrupt is generated:
>> 	pxad_chan_handler() -> vchan_cookie_complete()
>> ...where a tasklet for vchan_complete() is scheduled
> At least that seems to hint the DMA part is sound so for.
> The bothering part is the log error "mmc0: DMA error on tx channel". I would
> need a bit of guidance here, with the same log with [1] applied.
> 

Probably some cooperation of the DMA engine and the PXA MMC (like that other mail I've sent to you with UDC and g_webcam). I made another version of debug kernel with my own asserts:

In pxamci_dma_irq() before dmaengine_tx_status() call I've put:

pr_info("!!!cookie=%x complete=%x used=%x\n", 
	host->dma_cookie,chan->completed_cookie,chan->cookie);

It gets called only ONCE, just before failure, which values like this:
	cookie=372 complete=371 used=372

vchan_cyclic_callback() is called only with the soundcard in my machine IMO. I first thought there is regression with vd_completed in pxad_chan_handler() being changed during vchan_cyclic_callback() but it seems not.

pxad_tx_status() returns DMA_IN_PROGRESS before the failure.

>> , where finally with interrupts enabled (can pxamci_irq() be called here?) the
>> callback pxamci_dma_irq() is called.
> When DMA completes, there is a tiny window, before pxamci_dma_irq() is called,
> when pxamci_irq() can be called, yes. As soon as the spinlock is taken in
> pxamci_dma_irq() is taken, no more races.
> 

Does pxamci_dma_irq() depend on pxamci_irq() -> pxamci_data_done() NULLing host->data?

>> From my tests it seems at this point [2] the host->data is always NULL and rest
>> of the callback is never called. It is called once with a nonempty host->data
>> only just before the failure.
>>
>> During the testing I put udelay(100) at the start of pxamci_dma_irq() and fail
>> occurred after like 2 hours (when I for the first time tapped the touchscreen -
>> higher CPU usage and interrupts).
> Mmm I would need more data here.
> 
> The biggest help I could get would be the pxa dma traces here :
> echo -n 'file pxa_dma.c +p' > /sys/kernel/debug/dynamic_debug/control
> echo -n 'file virt-dma.c +p' > /sys/kernel/debug/dynamic_debug/control
> 
> And then capture the last traces and send them to me.

Last traces before the failure are in the attachment. It was copied (by a continual dmesg dump) from a ssh terminal over infraport (/var/log/messages gets corrupted after MMC DMA error).

> 
> Cheers.
> 

-------------- next part --------------
A non-text attachment was scrubbed...
Name: dmesg_mmc.log
Type: text/x-log
Size: 28818 bytes
Desc: not available
URL: <http://lists.infradead.org/pipermail/linux-arm-kernel/attachments/20170310/9ee74ab3/attachment-0001.bin>

^ permalink raw reply	[flat|nested] 12+ messages in thread

* Re: [BUG] dmaengine: pxa_dma: + mmc: pxamci: race condition with DMA error on tx channel
  2017-03-10  0:49     ` Petr Cvek
@ 2017-03-14 21:11       ` Robert Jarzmik
  -1 siblings, 0 replies; 12+ messages in thread
From: Robert Jarzmik @ 2017-03-14 21:11 UTC (permalink / raw)
  To: Petr Cvek
  Cc: vinod.koul, Ulf Hansson, Daniel Mack, Haojian Zhuang, linux-mmc,
	linux-arm-kernel, dmaengine

Petr Cvek <petr.cvek@tul.cz> writes:

Ok Petr, I've been trying for days to reproduce without any luck.

I had a look at your traces, and I'd like something else when it happens :
 1) The patch I provided earlier applied
 2) This done (the 'cat' after the bug) :
	mount -t debugfs none /sys/kernel/debug/
	cat /sys/kernel/debug/pxa-dma.0/channels/4/[sd]*

Cheers.

--
Robert

^ permalink raw reply	[flat|nested] 12+ messages in thread

* [BUG] dmaengine: pxa_dma: + mmc: pxamci: race condition with DMA error on tx channel
@ 2017-03-14 21:11       ` Robert Jarzmik
  0 siblings, 0 replies; 12+ messages in thread
From: Robert Jarzmik @ 2017-03-14 21:11 UTC (permalink / raw)
  To: linux-arm-kernel

Petr Cvek <petr.cvek@tul.cz> writes:

Ok Petr, I've been trying for days to reproduce without any luck.

I had a look at your traces, and I'd like something else when it happens :
 1) The patch I provided earlier applied
 2) This done (the 'cat' after the bug) :
	mount -t debugfs none /sys/kernel/debug/
	cat /sys/kernel/debug/pxa-dma.0/channels/4/[sd]*

Cheers.

--
Robert

^ permalink raw reply	[flat|nested] 12+ messages in thread

* Re: [BUG] dmaengine: pxa_dma: + mmc: pxamci: race condition with DMA error on tx channel
  2017-03-14 21:11       ` Robert Jarzmik
@ 2017-03-26  2:43         ` Petr Cvek
  -1 siblings, 0 replies; 12+ messages in thread
From: Petr Cvek @ 2017-03-26  2:43 UTC (permalink / raw)
  To: Robert Jarzmik
  Cc: vinod.koul, Ulf Hansson, Daniel Mack, Haojian Zhuang, linux-mmc,
	linux-arm-kernel, dmaengine

[-- Attachment #1: Type: text/plain, Size: 3856 bytes --]

Dne 14.3.2017 v 22:11 Robert Jarzmik napsal(a):
> Petr Cvek <petr.cvek@tul.cz> writes:
> 
> Ok Petr, I've been trying for days to reproduce without any luck.

Hi,

I think I was able to finally find the problem with the PXA MCI and DMA. It seems to be a problem with a race condition with vchan_complete() tasklet.

The pxa_dma driver handles IRQ with pxad_chan_handler(), which calls vchan_cookie_complete(), which schedules the vchan_complete() tasklet. 

Starting the tasklet may take a long time. The race condition appeared during the heavy IRQ load. During that time, the pxamci driver can start another data write transmit. This another transmit with again schedule the tasklet. But as tasklet schedules are not cumulative, it will (probably) add item to a list. 

After some time the tasklet is finally scheduled and for every item in the list the callback pxamci_dma_irq() is called. And there is the main problem, the pxamci_dma_irq() is using __actual__ transmit variables (e.g. host->data). My debug printk shows the code tests a cookie of the actual transmit, which may be in a DMA_IN_PROGRESS state (every failure is during this state).

Solution:

I commented the error handling parts of the callback function and the driver works, but it is only for the testing purposes, there can be a partially filled FIFO (BUF_PART_FULL) which will not be handled. Problem is the driver won't wait on the completion before starting a new transmission. But this waiting on completion will probably slow down the MMC communication :-/.

The best thing would be to handle the partial buffer somewhere else and get rid of the callback completely. If it is possible, probably not as I assume the partially filled buffer will not create pxamci interrupt? In the other case then maybe in pxamci_data_done()?

Log:

	[ 2669.917946] dma dma0chan1: pxad_chan_handler(): checking txd c18c2f20[135f]: completed=1 dcsr=0x2000000c
		^^^ schedules the tasklet
	[ 2669.924255] dma dma0chan1: pxad_chan_handler(): checking txd c1a6b740[1360]: completed=1 dcsr=0x2000000c
		^^^ reschedule the tasklet
	[ 2669.934441] dma dma0chan1: pxad_chan_handler(): checking txd c1a6b880[1361]: completed=1 dcsr=0x2000000c
		^^^ reschedule the tasklet
	[ 2669.944893] dma dma0chan1: pxad_chan_handler(): checking txd c1a78ba0[1362]: completed=1 dcsr=0x2000000c
		^^^ reschedule the tasklet
	[ 2670.081114] ###pre
		^^^ tasklet has finally started
	[ 2670.081187] ###post
		^^^ first item of the list, callback
	[ 2670.081369] !!!cookie=1364 complete=1363 used=1364 ... status=1
		^^^ There it would fail with "DMA error on tx channel"
	[ 2670.081608] ###post
		^^^ The second item of the list
	[ 2670.081678] !!!cookie=1364 complete=1363 used=1364 ... status=1
		^^^ Again called with the same host->data, notice same cookie, status=1 == DMA_IN_PROGRESS (always)

The full log and used debug patch are attached. The machine is PXA272 @ 416MHz, during logging (over irda or usb ssh console) I created multiple interrupt sources by touching a touchscreen and pressing GPIO buttons. A higher bug occurrence was observed with sync-written files of unusual lengths:

	while : ; do
	dd if=/dev/urandom bs=7777 count=11 of=/tmp/file conv=fsync
	done

> 
> I had a look at your traces, and I'd like something else when it happens :
>  1) The patch I provided earlier applied

Yeah it is DMA_IN_PROGRESS in the "bug" case and a few DMA_COMPLETE in the "normal" case, but I don't know if it is a valid value due to the race condition "aliasing". Anyway the status value is written in the "!!!cookie=" printk.

>  2) This done (the 'cat' after the bug) :
> 	mount -t debugfs none /sys/kernel/debug/
> 	cat /sys/kernel/debug/pxa-dma.0/channels/4/[sd]*
> 

This wasn't possible as everything freezes on the vanilla kernel and with my debug patch the DMA transactions just continue.

Cheers,
Petr


[-- Attachment #2: 0001-DMA-MMC-debugs.patch --]
[-- Type: text/x-patch, Size: 3144 bytes --]

>From 070a9c01d94e5efbdf0afae9ad2ddab380a2513e Mon Sep 17 00:00:00 2001
From: Petr Cvek <petr.cvek@tul.cz>
Date: Thu, 23 Feb 2017 01:07:51 +0100
Subject: [PATCH] DMA/MMC debugs

---
 drivers/dma/virt-dma.c    |  6 +++++-
 drivers/mmc/host/pxamci.c | 18 ++++++++++++++++--
 2 files changed, 21 insertions(+), 3 deletions(-)

diff --git a/drivers/dma/virt-dma.c b/drivers/dma/virt-dma.c
index e47fc9b0944f..c7ea39ea97fb 100644
--- a/drivers/dma/virt-dma.c
+++ b/drivers/dma/virt-dma.c
@@ -101,15 +101,19 @@ static void vchan_complete(unsigned long arg)
 	}
 	spin_unlock_irq(&vc->lock);
 
+pr_info("###pre\n");
 	dmaengine_desc_callback_invoke(&cb, NULL);
 
 	while (!list_empty(&head)) {
 		vd = list_first_entry(&head, struct virt_dma_desc, node);
 		dmaengine_desc_get_callback(&vd->tx, &cb);
+pr_info("###post\n");
 
 		list_del(&vd->node);
-		if (dmaengine_desc_test_reuse(&vd->tx))
+		if (dmaengine_desc_test_reuse(&vd->tx)) {
+			pr_info("###reuse\n");
 			list_add(&vd->node, &vc->desc_allocated);
+		}
 		else
 			vc->desc_free(vd);
 
diff --git a/drivers/mmc/host/pxamci.c b/drivers/mmc/host/pxamci.c
index c763b404510f..d7f04b11e9e6 100644
--- a/drivers/mmc/host/pxamci.c
+++ b/drivers/mmc/host/pxamci.c
@@ -191,6 +191,8 @@ static void pxamci_setup_data(struct pxamci_host *host, struct mmc_data *data)
 
 	host->data = data;
 
+pr_info("##pxamci_setup_data\n");
+
 	writel(nob, host->base + MMC_NOB);
 	writel(data->blksz, host->base + MMC_BLKLEN);
 
@@ -300,8 +302,10 @@ static int pxamci_cmd_done(struct pxamci_host *host, unsigned int stat)
 	int i;
 	u32 v;
 
-	if (!cmd)
+	if (!cmd) {
+pr_info("###pxamci_cmd_done NONE\n");
 		return 0;
+	}
 
 	host->cmd = NULL;
 
@@ -354,8 +358,10 @@ static int pxamci_data_done(struct pxamci_host *host, unsigned int stat)
 	struct mmc_data *data = host->data;
 	struct dma_chan *chan;
 
-	if (!data)
+	if (!data) {
+pr_info("###pxamci_data_done NONE\n");
 		return 0;
+	}
 
 	if (data->flags & MMC_DATA_READ)
 		chan = host->dma_chan_rx;
@@ -385,6 +391,7 @@ static int pxamci_data_done(struct pxamci_host *host, unsigned int stat)
 	host->data = NULL;
 	if (host->mrq->stop) {
 		pxamci_stop_clock(host);
+pr_info("##pxamci_start_cmd DD\n");
 		pxamci_start_cmd(host, host->mrq->stop, host->cmdat);
 	} else {
 		pxamci_finish_request(host, host->mrq);
@@ -441,6 +448,7 @@ static void pxamci_request(struct mmc_host *mmc, struct mmc_request *mrq)
 		if (mrq->data->flags & MMC_DATA_WRITE)
 			cmdat |= CMDAT_WRITE;
 	}
+pr_info("##pxamci_start_cmd RQ\n");
 
 	pxamci_start_cmd(host, mrq->cmd, cmdat);
 }
@@ -568,13 +576,19 @@ static void pxamci_dma_irq(void *param)
 
 	status = dmaengine_tx_status(chan, host->dma_cookie, &state);
 
+pr_info("!!!cookie=%x complete=%x used=%x ... status=%i\n",
+    host->dma_cookie,chan->completed_cookie,chan->cookie,
+    status);
+
 	if (likely(status == DMA_COMPLETE)) {
 		writel(BUF_PART_FULL, host->base + MMC_PRTBUF);
+/*
 	} else {
 		pr_err("%s: DMA error on %s channel\n", mmc_hostname(host->mmc),
 			host->data->flags & MMC_DATA_READ ? "rx" : "tx");
 		host->data->error = -EIO;
 		pxamci_data_done(host, 0);
+*/
 	}
 
 out_unlock:
-- 
2.11.0


[-- Attachment #3: dmesg_mmc4_final.log --]
[-- Type: text/x-log, Size: 25014 bytes --]

[ 2669.855800] PXAMCI: irq 00000001 stat 00003940
[ 2669.855835] ##pxamci_start_cmd DD
[ 2669.855869] PXAMCI: irq 00000004 stat 00002140
[ 2669.861016] ##pxamci_start_cmd RQ
[ 2669.861150] PXAMCI: irq 00000004 stat 00002140
[ 2669.861230] ##pxamci_setup_data
[ 2669.861473] dma dma0chan1: pxad_get_config(): dev_addr=0x41100044 maxburst=32 width=1  dir=1
[ 2669.861504] dma dma0chan1: pxad_prep_slave_sg(): dir=1 flags=1
[ 2669.861598] dma dma0chan1: pxad_tx_prep(): vc=c39bfcb0 txd=c14c7b80[0] flags=0x1
[ 2669.861644] dma dma0chan1: pxad_tx_submit(): txd c14c7b80[135e]: submitted (not linked)
[ 2669.861663] ##pxamci_start_cmd RQ
[ 2669.861726] PXAMCI: irq 00000004 stat 00002040
[ 2669.861765] dma dma0chan1: pxad_issue_pending(): txd c14c7b80[135e]
[ 2669.861791] dma dma0chan1: pxad_launch_chan(): desc=c14c7b80
[ 2669.861821] dma dma0chan1: phy_enable(); phy=c393d0cc(13) misaligned=0
[ 2669.864501] PXAMCI: irq 00000001 stat 00003940
[ 2669.864566] ##pxamci_start_cmd DD
[ 2669.864618] PXAMCI: irq 00000004 stat 00002140
[ 2669.864776] dma dma0chan1: pxad_chan_handler(): checking txd c14c7b80[135e]: completed=1 dcsr=0x2000000c
[ 2669.864812] dma dma0chan1: pxad_chan_handler(): channel stopped, submitted_empty=1 issued_empty=1
[ 2669.902634] ###pre
[ 2669.902707] ###post
[ 2669.902771] ###post
[ 2669.902789] ###post
[ 2669.902839] ###post
[ 2669.902862] ###post
[ 2669.902878] ###post
[ 2669.902919] ###post
[ 2669.902935] ###post
[ 2669.902956] ###post
[ 2669.904113] ##pxamci_start_cmd RQ
[ 2669.904231] PXAMCI: irq 00000004 stat 00002140
[ 2669.905030] ##pxamci_setup_data
[ 2669.905275] dma dma0chan1: pxad_get_config(): dev_addr=0x41100044 maxburst=32 width=1  dir=1
[ 2669.914749] dma dma0chan1: pxad_prep_slave_sg(): dir=1 flags=1
[ 2669.914851] dma dma0chan1: pxad_tx_prep(): vc=c39bfcb0 txd=c18c2f20[0] flags=0x1
[ 2669.914893] dma dma0chan1: pxad_tx_submit(): txd c18c2f20[135f]: submitted (not linked)
[ 2669.914912] ##pxamci_start_cmd RQ
[ 2669.914966] PXAMCI: irq 00000004 stat 00002040
[ 2669.915010] dma dma0chan1: pxad_issue_pending(): txd c18c2f20[135f]
[ 2669.915036] dma dma0chan1: pxad_launch_chan(): desc=c18c2f20
[ 2669.915067] dma dma0chan1: phy_enable(); phy=c393d0cc(13) misaligned=0
[ 2669.917946] dma dma0chan1: pxad_chan_handler(): checking txd c18c2f20[135f]: completed=1 dcsr=0x2000000c
[ 2669.918015] dma dma0chan1: pxad_chan_handler(): channel stopped, submitted_empty=1 issued_empty=1
[ 2669.918092] PXAMCI: irq 00000001 stat 00003940
[ 2669.918129] ##pxamci_start_cmd DD
[ 2669.918162] PXAMCI: irq 00000004 stat 00002140
[ 2669.921740] ##pxamci_start_cmd RQ
[ 2669.921857] PXAMCI: irq 00000004 stat 00002140
[ 2669.921930] ##pxamci_setup_data
[ 2669.922014] dma dma0chan1: pxad_get_config(): dev_addr=0x41100044 maxburst=32 width=1  dir=1
[ 2669.922044] dma dma0chan1: pxad_prep_slave_sg(): dir=1 flags=1
[ 2669.922117] dma dma0chan1: pxad_tx_prep(): vc=c39bfcb0 txd=c1a6b740[0] flags=0x1
[ 2669.922156] dma dma0chan1: pxad_tx_submit(): txd c1a6b740[1360]: submitted (not linked)
[ 2669.922168] ##pxamci_start_cmd RQ
[ 2669.922212] PXAMCI: irq 00000004 stat 00002040
[ 2669.922250] dma dma0chan1: pxad_issue_pending(): txd c1a6b740[1360]
[ 2669.922275] dma dma0chan1: pxad_launch_chan(): desc=c1a6b740
[ 2669.922303] dma dma0chan1: phy_enable(); phy=c393d0cc(13) misaligned=0
[ 2669.924255] dma dma0chan1: pxad_chan_handler(): checking txd c1a6b740[1360]: completed=1 dcsr=0x2000000c
[ 2669.924318] dma dma0chan1: pxad_chan_handler(): channel stopped, submitted_empty=1 issued_empty=1
[ 2669.924386] PXAMCI: irq 00000001 stat 00003940
[ 2669.924417] ##pxamci_start_cmd DD
[ 2669.924451] PXAMCI: irq 00000004 stat 00002140
[ 2669.931088] ##pxamci_start_cmd RQ
[ 2669.931235] PXAMCI: irq 00000004 stat 00002140
[ 2669.931488] ##pxamci_setup_data
[ 2669.931572] dma dma0chan1: pxad_get_config(): dev_addr=0x41100044 maxburst=32 width=1  dir=1
[ 2669.931603] dma dma0chan1: pxad_prep_slave_sg(): dir=1 flags=1
[ 2669.931693] dma dma0chan1: pxad_tx_prep(): vc=c39bfcb0 txd=c1a6b880[0] flags=0x1
[ 2669.931735] dma dma0chan1: pxad_tx_submit(): txd c1a6b880[1361]: submitted (not linked)
[ 2669.931753] ##pxamci_start_cmd RQ
[ 2669.931812] PXAMCI: irq 00000004 stat 00002040
[ 2669.931852] dma dma0chan1: pxad_issue_pending(): txd c1a6b880[1361]
[ 2669.931879] dma dma0chan1: pxad_launch_chan(): desc=c1a6b880
[ 2669.931908] dma dma0chan1: phy_enable(); phy=c393d0cc(13) misaligned=0
[ 2669.934441] dma dma0chan1: pxad_chan_handler(): checking txd c1a6b880[1361]: completed=1 dcsr=0x2000000c
[ 2669.934506] dma dma0chan1: pxad_chan_handler(): channel stopped, submitted_empty=1 issued_empty=1
[ 2669.934587] PXAMCI: irq 00000001 stat 00003940
[ 2669.934621] ##pxamci_start_cmd DD
[ 2669.934656] PXAMCI: irq 00000004 stat 00002140
[ 2669.935046] ##pxamci_start_cmd RQ
[ 2669.935128] PXAMCI: irq 00000004 stat 00002140
[ 2669.939669] ##pxamci_start_cmd RQ
[ 2669.939786] PXAMCI: irq 00000004 stat 00002140
[ 2669.941248] ##pxamci_setup_data
[ 2669.941657] dma dma0chan1: pxad_get_config(): dev_addr=0x41100044 maxburst=32 width=1  dir=1
[ 2669.941691] dma dma0chan1: pxad_prep_slave_sg(): dir=1 flags=1
[ 2669.941771] dma dma0chan1: pxad_tx_prep(): vc=c39bfcb0 txd=c1a78ba0[0] flags=0x1
[ 2669.941813] dma dma0chan1: pxad_tx_submit(): txd c1a78ba0[1362]: submitted (not linked)
[ 2669.941827] ##pxamci_start_cmd RQ
[ 2669.941874] PXAMCI: irq 00000004 stat 00002040
[ 2669.941918] dma dma0chan1: pxad_issue_pending(): txd c1a78ba0[1362]
[ 2669.941948] dma dma0chan1: pxad_launch_chan(): desc=c1a78ba0
[ 2669.941976] dma dma0chan1: phy_enable(); phy=c393d0cc(13) misaligned=0
[ 2669.944645] PXAMCI: irq 00000001 stat 00003940
[ 2669.944711] ##pxamci_start_cmd DD
[ 2669.944746] PXAMCI: irq 00000004 stat 00002140
[ 2669.944893] dma dma0chan1: pxad_chan_handler(): checking txd c1a78ba0[1362]: completed=1 dcsr=0x2000000c
[ 2669.944930] dma dma0chan1: pxad_chan_handler(): channel stopped, submitted_empty=1 issued_empty=1
[ 2669.950787] ##pxamci_start_cmd RQ
[ 2669.950906] PXAMCI: irq 00000004 stat 00002140
[ 2669.989148] ##pxamci_setup_data
[ 2669.989314] dma dma0chan1: pxad_get_config(): dev_addr=0x41100044 maxburst=32 width=1  dir=1
[ 2669.989557] dma dma0chan1: pxad_prep_slave_sg(): dir=1 flags=1
[ 2669.989636] dma dma0chan1: pxad_tx_prep(): vc=c39bfcb0 txd=c15b98c0[0] flags=0x1
[ 2669.989675] dma dma0chan1: pxad_tx_submit(): txd c15b98c0[1363]: submitted (not linked)
[ 2669.989691] ##pxamci_start_cmd RQ
[ 2669.989730] PXAMCI: irq 00000004 stat 00002040
[ 2669.989774] dma dma0chan1: pxad_issue_pending(): txd c15b98c0[1363]
[ 2669.989805] dma dma0chan1: pxad_launch_chan(): desc=c15b98c0
[ 2669.989836] dma dma0chan1: phy_enable(); phy=c393d0cc(13) misaligned=0
[ 2669.992247] dma dma0chan1: pxad_chan_handler(): checking txd c15b98c0[1363]: completed=1 dcsr=0x2000000c
[ 2669.992312] dma dma0chan1: pxad_chan_handler(): channel stopped, submitted_empty=1 issued_empty=1
[ 2669.992391] PXAMCI: irq 00000001 stat 00002940
[ 2669.992427] ##pxamci_start_cmd DD
[ 2669.992462] PXAMCI: irq 00000004 stat 00002140
[ 2669.992855] ##pxamci_start_cmd RQ
[ 2669.992944] PXAMCI: irq 00000004 stat 00002140
[ 2669.993033] ##pxamci_start_cmd RQ
[ 2669.993132] PXAMCI: irq 00000004 stat 00002140
[ 2669.993704] ##pxamci_start_cmd RQ
[ 2669.993820] PXAMCI: irq 00000004 stat 00002140
[ 2669.993894] ##pxamci_start_cmd RQ
[ 2669.993967] PXAMCI: irq 00000004 stat 00002140
[ 2669.994266] ##pxamci_start_cmd RQ
[ 2669.994655] PXAMCI: irq 00000004 stat 00002140
[ 2669.994778] ##pxamci_setup_data
[ 2669.994870] dma dma0chan1: pxad_get_config(): dev_addr=0x41100044 maxburst=32 width=1  dir=1
[ 2669.994899] dma dma0chan1: pxad_prep_slave_sg(): dir=1 flags=1
[ 2669.994990] dma dma0chan1: pxad_tx_prep(): vc=c39bfcb0 txd=c15b9ac0[0] flags=0x1
[ 2669.995030] dma dma0chan1: pxad_tx_submit(): txd c15b9ac0[1364]: submitted (not linked)
[ 2669.995046] ##pxamci_start_cmd RQ
[ 2669.995090] PXAMCI: irq 00000004 stat 00002040
[ 2669.995129] dma dma0chan1: pxad_issue_pending(): txd c15b9ac0[1364]
[ 2669.995156] dma dma0chan1: pxad_launch_chan(): desc=c15b9ac0
[ 2669.995184] dma dma0chan1: phy_enable(); phy=c393d0cc(13) misaligned=0
[ 2670.081114] ###pre
[ 2670.081187] ###post
[ 2670.081345] dma dma0chan1: pxad_residue(): txd c15b9ac0[1364] sw_desc=c15b9ac0: 3008
[ 2670.081369] !!!cookie=1364 complete=1363 used=1364 ... status=1
[ 2670.081608] ###post
[ 2670.081661] dma dma0chan1: pxad_residue(): txd c15b9ac0[1364] sw_desc=c15b9ac0: 3008
[ 2670.081678] !!!cookie=1364 complete=1363 used=1364 ... status=1
[ 2670.081715] ###post
[ 2670.081752] dma dma0chan1: pxad_residue(): txd c15b9ac0[1364] sw_desc=c15b9ac0: 3008
[ 2670.081768] !!!cookie=1364 complete=1363 used=1364 ... status=1
[ 2670.081801] ###post
[ 2670.081847] dma dma0chan1: pxad_residue(): txd c15b9ac0[1364] sw_desc=c15b9ac0: 3008
[ 2670.081863] !!!cookie=1364 complete=1363 used=1364 ... status=1
[ 2670.081896] ###post
[ 2670.081945] dma dma0chan1: pxad_residue(): txd c15b9ac0[1364] sw_desc=c15b9ac0: 3008
[ 2670.081961] !!!cookie=1364 complete=1363 used=1364 ... status=1
[ 2670.491058] dma dma0chan1: pxad_chan_handler(): checking txd c15b9da0[1367]: completed=1 dcsr=0x2000000c
[ 2670.491124] dma dma0chan1: pxad_chan_handler(): channel stopped, submitted_empty=1 issued_empty=1
[ 2670.491221] PXAMCI: irq 00000001 stat 00003940
[ 2670.491257] ##pxamci_start_cmd DD
[ 2670.491317] PXAMCI: irq 00000004 stat 00002140
[ 2670.491648] ###pre
[ 2670.491658] ###post
[ 2670.492224] ##pxamci_start_cmd RQ
[ 2670.492571] PXAMCI: irq 00000004 stat 00002140
[ 2670.492666] ##pxamci_start_cmd RQ
[ 2670.492701] PXAMCI: irq 00000004 stat 00002140
[ 2670.494661] ##pxamci_start_cmd RQ
[ 2670.494784] PXAMCI: irq 00000004 stat 00002140
[ 2670.494907] ##pxamci_setup_data
[ 2670.494994] dma dma0chan1: pxad_get_config(): dev_addr=0x41100044 maxburst=32 width=1  dir=1
[ 2670.495024] dma dma0chan1: pxad_prep_slave_sg(): dir=1 flags=1
[ 2670.495097] dma dma0chan1: pxad_tx_prep(): vc=c39bfcb0 txd=c1547020[0] flags=0x1
[ 2670.495135] dma dma0chan1: pxad_tx_submit(): txd c1547020[1368]: submitted (not linked)
[ 2670.495147] ##pxamci_start_cmd RQ
[ 2670.495190] PXAMCI: irq 00000004 stat 00002040
[ 2670.495226] dma dma0chan1: pxad_issue_pending(): txd c1547020[1368]
[ 2670.495251] dma dma0chan1: pxad_launch_chan(): desc=c1547020
[ 2670.495281] dma dma0chan1: phy_enable(); phy=c393d0cc(13) misaligned=0
[ 2670.497774] dma dma0chan1: pxad_chan_handler(): checking txd c1547020[1368]: completed=1 dcsr=0x2000000c
[ 2670.497841] dma dma0chan1: pxad_chan_handler(): channel stopped, submitted_empty=1 issued_empty=1
[ 2670.497904] PXAMCI: irq 00000001 stat 00003940
[ 2670.497939] ##pxamci_start_cmd DD
[ 2670.497981] PXAMCI: irq 00000004 stat 00002140
[ 2670.498027] ###pre
[ 2670.498037] ###post
[ 2670.501941] ##pxamci_start_cmd RQ
[ 2670.502077] PXAMCI: irq 00000004 stat 00002140
[ 2670.502161] ##pxamci_setup_data
[ 2670.502247] dma dma0chan1: pxad_get_config(): dev_addr=0x41100044 maxburst=32 width=1  dir=1
[ 2670.502475] dma dma0chan1: pxad_prep_slave_sg(): dir=1 flags=1
[ 2670.502560] dma dma0chan1: pxad_tx_prep(): vc=c39bfcb0 txd=c1547020[0] flags=0x1
[ 2670.502612] dma dma0chan1: pxad_tx_submit(): txd c1547020[1369]: submitted (not linked)
[ 2670.502635] ##pxamci_start_cmd RQ
[ 2670.502701] PXAMCI: irq 00000004 stat 00002040
[ 2670.502743] dma dma0chan1: pxad_issue_pending(): txd c1547020[1369]
[ 2670.502769] dma dma0chan1: pxad_launch_chan(): desc=c1547020
[ 2670.502800] dma dma0chan1: phy_enable(); phy=c393d0cc(13) misaligned=0
[ 2670.505457] dma dma0chan1: pxad_chan_handler(): checking txd c1547020[1369]: completed=1 dcsr=0x2000000c
[ 2670.505527] dma dma0chan1: pxad_chan_handler(): channel stopped, submitted_empty=1 issued_empty=1
[ 2670.505603] PXAMCI: irq 00000001 stat 00003940
[ 2670.505639] ##pxamci_start_cmd DD
[ 2670.505678] PXAMCI: irq 00000004 stat 00002140
[ 2670.505956] ###pre
[ 2670.505965] ###post
[ 2670.506539] ##pxamci_start_cmd RQ
[ 2670.506647] PXAMCI: irq 00000004 stat 00002140
[ 2670.506724] ##pxamci_setup_data
[ 2670.506802] dma dma0chan1: pxad_get_config(): dev_addr=0x41100044 maxburst=32 width=1  dir=1
[ 2670.506830] dma dma0chan1: pxad_prep_slave_sg(): dir=1 flags=1
[ 2670.506899] dma dma0chan1: pxad_tx_prep(): vc=c39bfcb0 txd=c1547020[0] flags=0x1
[ 2670.506938] dma dma0chan1: pxad_tx_submit(): txd c1547020[136a]: submitted (not linked)
[ 2670.506951] ##pxamci_start_cmd RQ
[ 2670.506988] PXAMCI: irq 00000004 stat 00002040
[ 2670.507023] dma dma0chan1: pxad_issue_pending(): txd c1547020[136a]
[ 2670.507049] dma dma0chan1: pxad_launch_chan(): desc=c1547020
[ 2670.507079] dma dma0chan1: phy_enable(); phy=c393d0cc(13) misaligned=0
[ 2670.509895] dma dma0chan1: pxad_chan_handler(): checking txd c1547020[136a]: completed=1 dcsr=0x2000000c
[ 2670.509960] dma dma0chan1: pxad_chan_handler(): channel stopped, submitted_empty=1 issued_empty=1
[ 2670.510032] PXAMCI: irq 00000001 stat 00003940
[ 2670.510070] ##pxamci_start_cmd DD
[ 2670.510114] PXAMCI: irq 00000004 stat 00002140
[ 2670.510218] ###pre
[ 2670.510229] ###post
[ 2670.513533] ##pxamci_start_cmd RQ
[ 2670.513643] PXAMCI: irq 00000004 stat 00002140
[ 2670.513714] ##pxamci_setup_data
[ 2670.513802] dma dma0chan1: pxad_get_config(): dev_addr=0x41100044 maxburst=32 width=1  dir=1
[ 2670.513831] dma dma0chan1: pxad_prep_slave_sg(): dir=1 flags=1
[ 2670.513904] dma dma0chan1: pxad_tx_prep(): vc=c39bfcb0 txd=c1547020[0] flags=0x1
[ 2670.513942] dma dma0chan1: pxad_tx_submit(): txd c1547020[136b]: submitted (not linked)
[ 2670.513955] ##pxamci_start_cmd RQ
[ 2670.513995] PXAMCI: irq 00000004 stat 00002040
[ 2670.514031] dma dma0chan1: pxad_issue_pending(): txd c1547020[136b]
[ 2670.514057] dma dma0chan1: pxad_launch_chan(): desc=c1547020
[ 2670.514085] dma dma0chan1: phy_enable(); phy=c393d0cc(13) misaligned=0
[ 2670.516018] dma dma0chan1: pxad_chan_handler(): checking txd c1547020[136b]: completed=1 dcsr=0x2000000c
[ 2670.516083] dma dma0chan1: pxad_chan_handler(): channel stopped, submitted_empty=1 issued_empty=1
[ 2670.516169] PXAMCI: irq 00000001 stat 00003940
[ 2670.516204] ##pxamci_start_cmd DD
[ 2670.516246] PXAMCI: irq 00000004 stat 00002140
[ 2670.516427] ###pre
[ 2670.516437] ###post
[ 2670.523779] ##pxamci_start_cmd RQ
[ 2670.523909] PXAMCI: irq 00000004 stat 00002140
[ 2670.523981] ##pxamci_setup_data
[ 2670.524066] dma dma0chan1: pxad_get_config(): dev_addr=0x41100044 maxburst=32 width=1  dir=1
[ 2670.524096] dma dma0chan1: pxad_prep_slave_sg(): dir=1 flags=1
[ 2670.524169] dma dma0chan1: pxad_tx_prep(): vc=c39bfcb0 txd=c1547020[0] flags=0x1
[ 2670.524207] dma dma0chan1: pxad_tx_submit(): txd c1547020[136c]: submitted (not linked)
[ 2670.524220] ##pxamci_start_cmd RQ
[ 2670.524262] PXAMCI: irq 00000004 stat 00002040
[ 2670.524300] dma dma0chan1: pxad_issue_pending(): txd c1547020[136c]
[ 2670.524325] dma dma0chan1: pxad_launch_chan(): desc=c1547020
[ 2670.524354] dma dma0chan1: phy_enable(); phy=c393d0cc(13) misaligned=0
[ 2670.526806] PXAMCI: irq 00000001 stat 00003940
[ 2670.526871] ##pxamci_start_cmd DD
[ 2670.526912] PXAMCI: irq 00000004 stat 00002140
[ 2670.527039] dma dma0chan1: pxad_chan_handler(): checking txd c1547020[136c]: completed=1 dcsr=0x2000000c
[ 2670.527077] dma dma0chan1: pxad_chan_handler(): channel stopped, submitted_empty=1 issued_empty=1
[ 2670.527105] ###pre
[ 2670.527115] ###post
[ 2670.532609] ##pxamci_start_cmd RQ
[ 2670.532728] PXAMCI: irq 00000004 stat 00002140
[ 2670.532799] ##pxamci_setup_data
[ 2670.532884] dma dma0chan1: pxad_get_config(): dev_addr=0x41100044 maxburst=32 width=1  dir=1
[ 2670.532914] dma dma0chan1: pxad_prep_slave_sg(): dir=1 flags=1
[ 2670.546064] dma dma0chan1: pxad_tx_prep(): vc=c39bfcb0 txd=c29fb280[0] flags=0x1
[ 2670.546130] dma dma0chan1: pxad_tx_submit(): txd c29fb280[136d]: submitted (not linked)
[ 2670.546153] ##pxamci_start_cmd RQ
[ 2670.546234] PXAMCI: irq 00000004 stat 00002040
[ 2670.546277] dma dma0chan1: pxad_issue_pending(): txd c29fb280[136d]
[ 2670.546304] dma dma0chan1: pxad_launch_chan(): desc=c29fb280
[ 2670.546333] dma dma0chan1: phy_enable(); phy=c393d0cc(13) misaligned=0
[ 2670.548955] dma dma0chan1: pxad_chan_handler(): checking txd c29fb280[136d]: completed=1 dcsr=0x2000000c
[ 2670.549021] dma dma0chan1: pxad_chan_handler(): channel stopped, submitted_empty=1 issued_empty=1
[ 2670.549085] PXAMCI: irq 00000001 stat 00003940
[ 2670.549121] ##pxamci_start_cmd DD
[ 2670.549166] PXAMCI: irq 00000004 stat 00002140
[ 2670.549232] ###pre
[ 2670.549241] ###post
[ 2670.553563] ##pxamci_start_cmd RQ
[ 2670.553681] PXAMCI: irq 00000004 stat 00002140
[ 2670.553752] ##pxamci_setup_data
[ 2670.553838] dma dma0chan1: pxad_get_config(): dev_addr=0x41100044 maxburst=32 width=1  dir=1
[ 2670.553868] dma dma0chan1: pxad_prep_slave_sg(): dir=1 flags=1
[ 2670.553938] dma dma0chan1: pxad_tx_prep(): vc=c39bfcb0 txd=c222cac0[0] flags=0x1
[ 2670.553978] dma dma0chan1: pxad_tx_submit(): txd c222cac0[136e]: submitted (not linked)
[ 2670.553991] ##pxamci_start_cmd RQ
[ 2670.554033] PXAMCI: irq 00000004 stat 00002040
[ 2670.554070] dma dma0chan1: pxad_issue_pending(): txd c222cac0[136e]
[ 2670.554096] dma dma0chan1: pxad_launch_chan(): desc=c222cac0
[ 2670.554125] dma dma0chan1: phy_enable(); phy=c393d0cc(13) misaligned=0
[ 2670.556962] PXAMCI: irq 00000001 stat 00003940
[ 2670.557025] ##pxamci_start_cmd DD
[ 2670.557085] PXAMCI: irq 00000004 stat 00002140
[ 2670.557192] dma dma0chan1: pxad_chan_handler(): checking txd c222cac0[136e]: completed=1 dcsr=0x2000000c
[ 2670.557232] dma dma0chan1: pxad_chan_handler(): channel stopped, submitted_empty=1 issued_empty=1
[ 2670.557450] ###pre
[ 2670.557458] ###post
[ 2670.559813] ##pxamci_start_cmd RQ
[ 2670.559939] PXAMCI: irq 00000004 stat 00002140
[ 2670.560007] ##pxamci_setup_data
[ 2670.560091] dma dma0chan1: pxad_get_config(): dev_addr=0x41100044 maxburst=32 width=1  dir=1
[ 2670.560120] dma dma0chan1: pxad_prep_slave_sg(): dir=1 flags=1
[ 2670.560207] dma dma0chan1: pxad_tx_prep(): vc=c39bfcb0 txd=c222cac0[0] flags=0x1
[ 2670.560248] dma dma0chan1: pxad_tx_submit(): txd c222cac0[136f]: submitted (not linked)
[ 2670.560260] ##pxamci_start_cmd RQ
[ 2670.560545] PXAMCI: irq 00000004 stat 00002040
[ 2670.560607] dma dma0chan1: pxad_issue_pending(): txd c222cac0[136f]
[ 2670.560639] dma dma0chan1: pxad_launch_chan(): desc=c222cac0
[ 2670.560673] dma dma0chan1: phy_enable(); phy=c393d0cc(13) misaligned=0
[ 2670.562653] PXAMCI: irq 00000001 stat 00003940
[ 2670.562717] ##pxamci_start_cmd DD
[ 2670.562755] PXAMCI: irq 00000004 stat 00002140
[ 2670.562903] dma dma0chan1: pxad_chan_handler(): checking txd c222cac0[136f]: completed=1 dcsr=0x2000000c
[ 2670.562939] dma dma0chan1: pxad_chan_handler(): channel stopped, submitted_empty=1 issued_empty=1
[ 2670.562981] ###pre
[ 2670.562991] ###post
[ 2670.569784] ##pxamci_start_cmd RQ
[ 2670.569920] PXAMCI: irq 00000004 stat 00002140
[ 2670.569997] ##pxamci_setup_data
[ 2670.570082] dma dma0chan1: pxad_get_config(): dev_addr=0x41100044 maxburst=32 width=1  dir=1
[ 2670.570113] dma dma0chan1: pxad_prep_slave_sg(): dir=1 flags=1
[ 2670.570189] dma dma0chan1: pxad_tx_prep(): vc=c39bfcb0 txd=c222cac0[0] flags=0x1
[ 2670.570229] dma dma0chan1: pxad_tx_submit(): txd c222cac0[1370]: submitted (not linked)
[ 2670.570241] ##pxamci_start_cmd RQ
[ 2670.570279] PXAMCI: irq 00000004 stat 00002040
[ 2670.570316] dma dma0chan1: pxad_issue_pending(): txd c222cac0[1370]
[ 2670.570341] dma dma0chan1: pxad_launch_chan(): desc=c222cac0
[ 2670.570370] dma dma0chan1: phy_enable(); phy=c393d0cc(13) misaligned=0
[ 2670.572835] dma dma0chan1: pxad_chan_handler(): checking txd c222cac0[1370]: completed=1 dcsr=0x2000000c
[ 2670.572900] dma dma0chan1: pxad_chan_handler(): channel stopped, submitted_empty=1 issued_empty=1
[ 2670.572963] PXAMCI: irq 00000001 stat 00003940
[ 2670.572999] ##pxamci_start_cmd DD
[ 2670.573034] PXAMCI: irq 00000004 stat 00002140
[ 2670.573078] ###pre
[ 2670.573089] ###post
[ 2670.581915] ##pxamci_start_cmd RQ
[ 2670.582057] PXAMCI: irq 00000004 stat 00002140
[ 2670.582163] ##pxamci_setup_data
[ 2670.582250] dma dma0chan1: pxad_get_config(): dev_addr=0x41100044 maxburst=32 width=1  dir=1
[ 2670.582487] dma dma0chan1: pxad_prep_slave_sg(): dir=1 flags=1
[ 2670.582580] dma dma0chan1: pxad_tx_prep(): vc=c39bfcb0 txd=c222cac0[0] flags=0x1
[ 2670.582633] dma dma0chan1: pxad_tx_submit(): txd c222cac0[1371]: submitted (not linked)
[ 2670.582650] ##pxamci_start_cmd RQ
[ 2670.582720] PXAMCI: irq 00000004 stat 00002040
[ 2670.582767] dma dma0chan1: pxad_issue_pending(): txd c222cac0[1371]
[ 2670.582795] dma dma0chan1: pxad_launch_chan(): desc=c222cac0
[ 2670.582824] dma dma0chan1: phy_enable(); phy=c393d0cc(13) misaligned=0
[ 2670.585516] PXAMCI: irq 00000001 stat 00003940
[ 2670.585579] ##pxamci_start_cmd DD
[ 2670.585622] PXAMCI: irq 00000004 stat 00002140
[ 2670.585770] dma dma0chan1: pxad_chan_handler(): checking txd c222cac0[1371]: completed=1 dcsr=0x2000000c
[ 2670.585808] dma dma0chan1: pxad_chan_handler(): channel stopped, submitted_empty=1 issued_empty=1
[ 2670.585938] ###pre
[ 2670.585948] ###post
[ 2670.592212] ##pxamci_start_cmd RQ
[ 2670.592359] PXAMCI: irq 00000004 stat 00002140
[ 2670.598989] ##pxamci_setup_data
[ 2670.599155] dma dma0chan1: pxad_get_config(): dev_addr=0x41100044 maxburst=32 width=1  dir=1
[ 2670.599189] dma dma0chan1: pxad_prep_slave_sg(): dir=1 flags=1
[ 2670.599271] dma dma0chan1: pxad_tx_prep(): vc=c39bfcb0 txd=c2a72700[0] flags=0x1
[ 2670.609732] dma dma0chan1: pxad_tx_submit(): txd c2a72700[1372]: submitted (not linked)
[ 2670.609758] ##pxamci_start_cmd RQ
[ 2670.609814] PXAMCI: irq 00000004 stat 00002040
[ 2670.609859] dma dma0chan1: pxad_issue_pending(): txd c2a72700[1372]
[ 2670.609885] dma dma0chan1: pxad_launch_chan(): desc=c2a72700
[ 2670.609916] dma dma0chan1: phy_enable(); phy=c393d0cc(13) misaligned=0
[ 2670.612797] dma dma0chan1: pxad_chan_handler(): checking txd c2a72700[1372]: completed=1 dcsr=0x2000000c
[ 2670.612867] dma dma0chan1: pxad_chan_handler(): channel stopped, submitted_empty=1 issued_empty=1
[ 2670.612945] PXAMCI: irq 00000001 stat 00003940
[ 2670.612979] ##pxamci_start_cmd DD
[ 2670.613017] PXAMCI: irq 00000004 stat 00002140
[ 2670.613116] ###pre
[ 2670.613126] ###post
[ 2670.613508] ##pxamci_start_cmd RQ
[ 2670.613606] PXAMCI: irq 00000004 stat 00002140
[ 2670.618698] ##pxamci_start_cmd RQ
[ 2670.618897] PXAMCI: irq 00000004 stat 00002140
[ 2670.646290] ##pxamci_setup_data
[ 2670.646683] dma dma0chan1: pxad_get_config(): dev_addr=0x41100044 maxburst=32 width=1  dir=1
[ 2670.646716] dma dma0chan1: pxad_prep_slave_sg(): dir=1 flags=1
[ 2670.646796] dma dma0chan1: pxad_tx_prep(): vc=c39bfcb0 txd=c14c76c0[0] flags=0x1
[ 2670.646840] dma dma0chan1: pxad_tx_submit(): txd c14c76c0[1373]: submitted (not linked)
[ 2670.646854] ##pxamci_start_cmd RQ
[ 2670.646899] PXAMCI: irq 00000004 stat 00002040
[ 2670.646941] dma dma0chan1: pxad_issue_pending(): txd c14c76c0[1373]
[ 2670.646970] dma dma0chan1: pxad_launch_chan(): desc=c14c76c0
[ 2670.646999] dma dma0chan1: phy_enable(); phy=c393d0cc(13) misaligned=0
[ 2670.649372] dma dma0chan1: pxad_chan_handler(): checking txd c14c76c0[1373]: completed=1 dcsr=0x2000000c
[ 2670.649439] dma dma0chan1: pxad_chan_handler(): channel stopped, submitted_empty=1 issued_empty=1
[ 2670.649505] PXAMCI: irq 00000001 stat 00002940
[ 2670.649542] ##pxamci_start_cmd DD
[ 2670.649590] PXAMCI: irq 00000004 stat 00002140
[ 2670.649852] ###pre
[ 2670.649861] ###post
[ 2670.650111] ##pxamci_start_cmd RQ
[ 2670.650228] PXAMCI: irq 00000004 stat 00002140
[ 2670.650436] ##pxamci_start_cmd RQ
[ 2670.650540] PXAMCI: irq 00000004 stat 00002140
[ 2670.650875] ##pxamci_start_cmd RQ
[ 2670.651028] PXAMCI: irq 00000004 stat 00002140
[ 2670.651101] ##pxamci_start_cmd RQ
[ 2670.651133] PXAMCI: irq 00000004 stat 00002140
[ 2670.651187] ##pxamci_start_cmd RQ
[ 2670.651244] PXAMCI: irq 00000004 stat 00002140
[ 2670.652688] ##pxamci_start_cmd RQ
[ 2670.652834] PXAMCI: irq 00000004 stat 00002140
[ 2670.652943] ##pxamci_setup_data
[ 2670.653055] dma dma0chan1: pxad_get_config(): dev_addr=0x41100044 maxburst=32 width=1  dir=1
[ 2670.653122] dma dma0chan1: pxad_prep_slave_sg(): dir=1 flags=1
[ 2670.653226] dma dma0chan1: pxad_tx_prep(): vc=c39bfcb0 txd=c14c7780[0] flags=0x1
[ 2670.653538] dma dma0chan1: pxad_tx_submit(): txd c14c7780[1374]: submitted (not linked)
[ 2670.653570] ##pxamci_start_cmd RQ
[ 2670.653633] PXAMCI: irq 00000004 stat 00002040
[ 2670.653683] dma dma0chan1: pxad_issue_pending(): txd c14c7780[1374]
[ 2670.653713] dma dma0chan1: pxad_launch_chan(): desc=c14c7780
[ 2670.653744] dma dma0chan1: phy_enable(); phy=c393d0cc(13) misaligned=0
[ 2670.889030] dma dma0chan1: pxad_chan_handler(): checking txd c14c7780[1374]: completed=1 dcsr=0x2000000c
[ 2670.889098] dma dma0chan1: pxad_chan_handler(): channel stopped, submitted_empty=1 issued_empty=1
[ 2670.889165] PXAMCI: irq 00000001 stat 00003940
[ 2670.889201] ##pxamci_start_cmd DD
[ 2670.889241] PXAMCI: irq 00000004 stat 00002140

^ permalink raw reply related	[flat|nested] 12+ messages in thread

* [BUG] dmaengine: pxa_dma: + mmc: pxamci: race condition with DMA error on tx channel
@ 2017-03-26  2:43         ` Petr Cvek
  0 siblings, 0 replies; 12+ messages in thread
From: Petr Cvek @ 2017-03-26  2:43 UTC (permalink / raw)
  To: linux-arm-kernel

Dne 14.3.2017 v 22:11 Robert Jarzmik napsal(a):
> Petr Cvek <petr.cvek@tul.cz> writes:
> 
> Ok Petr, I've been trying for days to reproduce without any luck.

Hi,

I think I was able to finally find the problem with the PXA MCI and DMA. It seems to be a problem with a race condition with vchan_complete() tasklet.

The pxa_dma driver handles IRQ with pxad_chan_handler(), which calls vchan_cookie_complete(), which schedules the vchan_complete() tasklet. 

Starting the tasklet may take a long time. The race condition appeared during the heavy IRQ load. During that time, the pxamci driver can start another data write transmit. This another transmit with again schedule the tasklet. But as tasklet schedules are not cumulative, it will (probably) add item to a list. 

After some time the tasklet is finally scheduled and for every item in the list the callback pxamci_dma_irq() is called. And there is the main problem, the pxamci_dma_irq() is using __actual__ transmit variables (e.g. host->data). My debug printk shows the code tests a cookie of the actual transmit, which may be in a DMA_IN_PROGRESS state (every failure is during this state).

Solution:

I commented the error handling parts of the callback function and the driver works, but it is only for the testing purposes, there can be a partially filled FIFO (BUF_PART_FULL) which will not be handled. Problem is the driver won't wait on the completion before starting a new transmission. But this waiting on completion will probably slow down the MMC communication :-/.

The best thing would be to handle the partial buffer somewhere else and get rid of the callback completely. If it is possible, probably not as I assume the partially filled buffer will not create pxamci interrupt? In the other case then maybe in pxamci_data_done()?

Log:

	[ 2669.917946] dma dma0chan1: pxad_chan_handler(): checking txd c18c2f20[135f]: completed=1 dcsr=0x2000000c
		^^^ schedules the tasklet
	[ 2669.924255] dma dma0chan1: pxad_chan_handler(): checking txd c1a6b740[1360]: completed=1 dcsr=0x2000000c
		^^^ reschedule the tasklet
	[ 2669.934441] dma dma0chan1: pxad_chan_handler(): checking txd c1a6b880[1361]: completed=1 dcsr=0x2000000c
		^^^ reschedule the tasklet
	[ 2669.944893] dma dma0chan1: pxad_chan_handler(): checking txd c1a78ba0[1362]: completed=1 dcsr=0x2000000c
		^^^ reschedule the tasklet
	[ 2670.081114] ###pre
		^^^ tasklet has finally started
	[ 2670.081187] ###post
		^^^ first item of the list, callback
	[ 2670.081369] !!!cookie=1364 complete=1363 used=1364 ... status=1
		^^^ There it would fail with "DMA error on tx channel"
	[ 2670.081608] ###post
		^^^ The second item of the list
	[ 2670.081678] !!!cookie=1364 complete=1363 used=1364 ... status=1
		^^^ Again called with the same host->data, notice same cookie, status=1 == DMA_IN_PROGRESS (always)

The full log and used debug patch are attached. The machine is PXA272 @ 416MHz, during logging (over irda or usb ssh console) I created multiple interrupt sources by touching a touchscreen and pressing GPIO buttons. A higher bug occurrence was observed with sync-written files of unusual lengths:

	while : ; do
	dd if=/dev/urandom bs=7777 count=11 of=/tmp/file conv=fsync
	done

> 
> I had a look at your traces, and I'd like something else when it happens :
>  1) The patch I provided earlier applied

Yeah it is DMA_IN_PROGRESS in the "bug" case and a few DMA_COMPLETE in the "normal" case, but I don't know if it is a valid value due to the race condition "aliasing". Anyway the status value is written in the "!!!cookie=" printk.

>  2) This done (the 'cat' after the bug) :
> 	mount -t debugfs none /sys/kernel/debug/
> 	cat /sys/kernel/debug/pxa-dma.0/channels/4/[sd]*
> 

This wasn't possible as everything freezes on the vanilla kernel and with my debug patch the DMA transactions just continue.

Cheers,
Petr

-------------- next part --------------
A non-text attachment was scrubbed...
Name: 0001-DMA-MMC-debugs.patch
Type: text/x-patch
Size: 3144 bytes
Desc: not available
URL: <http://lists.infradead.org/pipermail/linux-arm-kernel/attachments/20170326/e1a9b1c9/attachment-0002.bin>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: dmesg_mmc4_final.log
Type: text/x-log
Size: 25014 bytes
Desc: not available
URL: <http://lists.infradead.org/pipermail/linux-arm-kernel/attachments/20170326/e1a9b1c9/attachment-0003.bin>

^ permalink raw reply	[flat|nested] 12+ messages in thread

* Re: [BUG] dmaengine: pxa_dma: + mmc: pxamci: race condition with DMA error on tx channel
  2017-03-26  2:43         ` Petr Cvek
@ 2017-04-06  6:42           ` Robert Jarzmik
  -1 siblings, 0 replies; 12+ messages in thread
From: Robert Jarzmik @ 2017-04-06  6:42 UTC (permalink / raw)
  To: Petr Cvek
  Cc: vinod.koul, Ulf Hansson, Daniel Mack, Haojian Zhuang, linux-mmc,
	linux-arm-kernel, dmaengine

Petr Cvek <petr.cvek@tul.cz> writes:

Hi Petr,

Sorry I was on holidays away from computers.

> I think I was able to finally find the problem with the PXA MCI and DMA. It
> seems to be a problem with a race condition with vchan_complete() tasklet.
I completely agree with this analysis.

... zip the analysis, good catch ...

> Solution:
>
> I commented the error handling parts of the callback function and the driver
> works, but it is only for the testing purposes, there can be a partially
> filled FIFO (BUF_PART_FULL) which will not be handled. Problem is the driver
> won't wait on the completion before starting a new transmission. But this
> waiting on completion will probably slow down the MMC communication :-/.
I has to, the PXA can handle only one request at a time.

> The best thing would be to handle the partial buffer somewhere else and get
> rid of the callback completely. If it is possible, probably not as I assume
> the partially filled buffer will not create pxamci interrupt? In the other
> case then maybe in pxamci_data_done()?
That looks a bit over complicated, but you can try to send a patch for this.
I would try a simpler road if I were you :
 - in pxamci_irq()
 - call pxamci_data_done() _only_ in the error case or if host->data = NULL,
 ie. if "stat" states that the transfer was in error or the transfer is without
 data.

Either way you choose, pxamci_data_done() should only be called once per
transfer, and this is the fix you're aiming at.

Actually the title might be amended, as the bug is not as much in the dmaengine
driver as in the pxamci driver. I was thinking that 6464b7140951 ("mmc: pxamci:
switch over to dmaengine use") had broken it, but it looks to me the same
pattern was there, but without a tasklet, and the bug didn't occurr because of
the fast dma interrupt handling.

Cheers.

-- 
Robert

^ permalink raw reply	[flat|nested] 12+ messages in thread

* [BUG] dmaengine: pxa_dma: + mmc: pxamci: race condition with DMA error on tx channel
@ 2017-04-06  6:42           ` Robert Jarzmik
  0 siblings, 0 replies; 12+ messages in thread
From: Robert Jarzmik @ 2017-04-06  6:42 UTC (permalink / raw)
  To: linux-arm-kernel

Petr Cvek <petr.cvek@tul.cz> writes:

Hi Petr,

Sorry I was on holidays away from computers.

> I think I was able to finally find the problem with the PXA MCI and DMA. It
> seems to be a problem with a race condition with vchan_complete() tasklet.
I completely agree with this analysis.

... zip the analysis, good catch ...

> Solution:
>
> I commented the error handling parts of the callback function and the driver
> works, but it is only for the testing purposes, there can be a partially
> filled FIFO (BUF_PART_FULL) which will not be handled. Problem is the driver
> won't wait on the completion before starting a new transmission. But this
> waiting on completion will probably slow down the MMC communication :-/.
I has to, the PXA can handle only one request at a time.

> The best thing would be to handle the partial buffer somewhere else and get
> rid of the callback completely. If it is possible, probably not as I assume
> the partially filled buffer will not create pxamci interrupt? In the other
> case then maybe in pxamci_data_done()?
That looks a bit over complicated, but you can try to send a patch for this.
I would try a simpler road if I were you :
 - in pxamci_irq()
 - call pxamci_data_done() _only_ in the error case or if host->data = NULL,
 ie. if "stat" states that the transfer was in error or the transfer is without
 data.

Either way you choose, pxamci_data_done() should only be called once per
transfer, and this is the fix you're aiming at.

Actually the title might be amended, as the bug is not as much in the dmaengine
driver as in the pxamci driver. I was thinking that 6464b7140951 ("mmc: pxamci:
switch over to dmaengine use") had broken it, but it looks to me the same
pattern was there, but without a tasklet, and the bug didn't occurr because of
the fast dma interrupt handling.

Cheers.

-- 
Robert

^ permalink raw reply	[flat|nested] 12+ messages in thread

end of thread, other threads:[~2017-04-06  6:42 UTC | newest]

Thread overview: 12+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2017-03-08  6:57 [BUG] dmaengine: pxa_dma: + mmc: pxamci: race condition with DMA error on tx channel Petr Cvek
2017-03-08  6:57 ` Petr Cvek
2017-03-08 16:43 ` Robert Jarzmik
2017-03-08 16:43   ` Robert Jarzmik
2017-03-10  0:49   ` Petr Cvek
2017-03-10  0:49     ` Petr Cvek
2017-03-14 21:11     ` Robert Jarzmik
2017-03-14 21:11       ` Robert Jarzmik
2017-03-26  2:43       ` Petr Cvek
2017-03-26  2:43         ` Petr Cvek
2017-04-06  6:42         ` Robert Jarzmik
2017-04-06  6:42           ` Robert Jarzmik

This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.