am335x usb_bulk_read timeout error in DMA mode with kernel 4.6.0.11

Andrea Cattani

Hi all,

on my am335x board, moving from kernel 4.6.0.8 to 4.6.0.11, an issue rose up:
in host mode, with DMA enabled and Soc v. 2.1 the usb_bulk_read operation of
512 bytes of data fails with timeout error.

The issue is related to the patches:
usb: musb: cppi41: enable the generic rndis mode based on soc revision (2d87d46221d2772fe6305c7b908077925fe4cdd8)
and
usb: musb: cppi41: rxdma generic configuration for both host and device (dcfe81a8e7fd0dacacdfe2f59b08cde18c9a15cd)

Taking a look into the code, in host+dma mode, with packets multiple of 64 bytes,
the USB_GENERIC_RNDIS_MODE is set.

If I force USB_TRANSPARENT_MODE the issue is sorted out.

My questions are:
- why forcing USB_GENERIC_RNDIS_MODE on host/DMA rx operations?
- should I expect some side-effects by removing the patches?

Regards,
Andrea

over 12 years ago

0 Bin Liu over 12 years ago

TI__Guru**** 169561 points

Andrea,

The TRM has details about Generic RNDIS mode and Transparent mode. Basically G-RNDIS mode is more efficient and should be used over Transparent mode if applicable. If use Transparent mode, I think the USB throughput would lower.

What USB device do you read from?

0 Andrea Cattani over 12 years ago in reply to Bin Liu

Intellectual 380 points

Hi Bin,

I think you already know the devices involved. You previously talk with Max.
The USB device I read from is a custom HW, with a custom CDC interface.

Andrea

0 Bin Liu over 12 years ago in reply to Andrea Cattani

TI__Guru**** 169561 points

Do you mean Max in the thread below?

http://e2e.ti.com/support/arm/sitara_arm/f/791/p/231794/818635.aspx#818635

0 Andrea Cattani over 12 years ago in reply to Bin Liu

Intellectual 380 points

yes

0 Bin Liu over 12 years ago in reply to Andrea Cattani

TI__Guru**** 169561 points

Andrea,

It has been so long since the last time talked to your guys. Hope you are all doing well.

Is this still the same project as the one which had g_multi DMA issue?

Does the application only read 512 bytes in echo bulk read request as the workaround Max mentioned in the link above? or the request is greater than 512 bytes and relies on the kernel/hw to split it into 512-byte USB packets?

I forgot if I have asked you before, but do you have access to a USB protocol analyzer to capture a trace when the issue happens?

0 Andrea Cattani over 12 years ago in reply to Bin Liu

Intellectual 380 points

Hi Bin,

Yes, the project is the same.

We're still using the 512-byte split patch, so our application splits the read operation, not kernel.
Currently, I cannot access to an USB protocol analyzer.

Andrea

0 Bin Liu over 12 years ago in reply to Andrea Cattani

TI__Guru**** 169561 points

Andrea,

Since your application only reads 512 bytes in each bulk read request, G-RNDIS mode does not help at all. So is it possible to switch to Transparent mode in your project to workaround this timeout issue?

0 Andrea Cattani over 12 years ago in reply to Bin Liu

Intellectual 380 points

Bin,

I think so, I already verified that the issue is sorted out by commenting ti81xx.c:1377
(//usb_cppi41_info[musb->id].rx_dma_mode = USB_GENERIC_RNDIS_MODE;)

On the same USB port we use also mass storage devices and USB headset: what happens
to the USB performances by removing the patch in these cases?

Regards,
Andrea

0 Bin Liu over 12 years ago in reply to Andrea Cattani

TI__Guru**** 169561 points

Andrea,

I would think the RX performance will decrease about 20-30% for MSC device when using Transparent mode instead of G-RNDIS mode. But you probably want to run a performance test to figure out what the exact impact is,

0 Andrea Cattani over 12 years ago in reply to Bin Liu

Intellectual 380 points

Bin,

I confirm you the expected RX performance decrease. I cannot remove the patch to avoid my issue.
Is it possible to force the trasparent mode from userspace application only for a particular transaction?

Andrea

0 Bin Liu over 12 years ago in reply to Andrea Cattani

TI__Guru**** 169561 points

Andrea,

I cannot think of a simple way to tune the dma mode individually. And I don't have a full picture of your host mode use case yet. I will ask you for more details later.

But can you please run the following test first? I want to check if your application runs into rx buffer starvation problem.

- Please apply the following patch on .11 kernel, which enables RX buffer starvation interrupt.

diff --git a/drivers/usb/musb/ti81xx.c b/drivers/usb/musb/ti81xx.c
index 532a031..9c61130 100644
--- a/drivers/usb/musb/ti81xx.c
+++ b/drivers/usb/musb/ti81xx.c
@@ -859,6 +859,12 @@ static irqreturn_t cppi41dma_Interrupt(int irq, void *hci)
                        ((q_cmpl_status_2 & 0xFFF) << 3);
        usb1_rx_intr = ((q_cmpl_status_2 & 0x0fffe000) >> 13);
 
+       if (intr_status & USBSS_INTR_RX_STARV) {
+               printk("*** cppi intr %x\n", intr_status);
+               usbss_write(USBSS_IRQ_ENABLE_CLEAR, USBSS_INTR_RX_STARV | USBSS_INTR_RX_MOP_STARV);
+               ret = IRQ_HANDLED;
+       }
+
        /* get proper musb handle based usb0/usb1 ctrl-id */
 
        if (gmusb[0] && (usb0_tx_intr || usb0_rx_intr)) {
diff --git a/drivers/usb/musb/ti81xx.h b/drivers/usb/musb/ti81xx.h
index d173b55..cacf418 100644
--- a/drivers/usb/musb/ti81xx.h
+++ b/drivers/usb/musb/ti81xx.h
@@ -160,10 +160,12 @@
 #define A_WAIT_BCON_TIMEOUT    1100            /* in ms */
 
 #define USBSS_INTR_RX_STARV    0x00000001
+#define USBSS_INTR_RX_MOP_STARV        0x00000002
 #define USBSS_INTR_PD_CMPL     0x00000004
 #define USBSS_INTR_TX_CMPL     0x00000500
 #define USBSS_INTR_RX_CMPL     0x00000A00
 #define USBSS_INTR_FLAGS       (USBSS_INTR_PD_CMPL | USBSS_INTR_TX_CMPL \
+                                       | USBSS_INTR_RX_STARV | USBSS_INTR_RX_MOP_STARV \
                                        | USBSS_INTR_RX_CMPL)

- Build the kernel with dynamic debug enabled (if that is not in default).

- Boot the host board, and run the following commands.

    # echo 'file cppi41_dma.c +p' > /sys/kernel/debug/dynamic_debug/control
    # echo 'file ti81xx.c +p' > /sys/kernel/debug/dynamic_debug/control

- Finally run your libusb app and when bulk read hangs capture the dmesg log, and send it to me please.

0 Andrea Cattani over 12 years ago in reply to Bin Liu

Intellectual 380 points

Hi Bin,

attached the log during the faulted read operation. I don't see the starvation irq.
Andrea

Fullscreen 6445.usb-bulk-read.txt Download

Jan  1 00:12:04 kernel: [  724.817805] musb-hdrc musb-hdrc.1: Allocated DMA Tx channel 1 for EP2
Jan  1 00:12:04 kernel: [  724.817842] musb-hdrc musb-hdrc.1: TX DMA1, accelerated, maxpkt 16, 1 PDs, addr 0x87455200, len 16
Jan  1 00:12:04 kernel: [  724.817861] musb-hdrc musb-hdrc.1: TX PD ffdbffc0: buf 87455200, len 00000010, pkt info 1400007e
Jan  1 00:12:04 kernel: [  724.817887] musb-hdrc musb-hdrc.1: CPPI 4.1 IRQ: Tx 2, Rx 0
Jan  1 00:12:04 kernel: [  724.818103] musb-hdrc musb-hdrc.1: usbintr (0) epintr(4)
Jan  1 00:12:04 kernel: [  724.818314] musb-hdrc musb-hdrc.1: Allocated DMA Tx channel 1 for EP2
Jan  1 00:12:04 kernel: [  724.818335] musb-hdrc musb-hdrc.1: TX DMA1, accelerated, maxpkt 16, 1 PDs, addr 0x87455200, len 16
Jan  1 00:12:04 kernel: [  724.818352] musb-hdrc musb-hdrc.1: TX PD ffdbffc0: buf 87455200, len 00000010, pkt info 1400007e
Jan  1 00:12:04 kernel: [  724.818374] musb-hdrc musb-hdrc.1: CPPI 4.1 IRQ: Tx 2, Rx 0
Jan  1 00:12:04 kernel: [  724.818482] musb-hdrc musb-hdrc.1: usbintr (0) epintr(4)
Jan  1 00:12:04 kernel: [  724.818567] musb-hdrc musb-hdrc.1: Allocated free descriptor/buffer queue 2 in queue manager 0
Jan  1 00:12:04 kernel: [  724.818585] musb-hdrc musb-hdrc.1: Allocated DMA Rx channel 1 for EP2
Jan  1 00:12:04 kernel: [  724.818607] musb-hdrc musb-hdrc.1: RX DMA1, transparent, maxpkt 512, addr 0x87455200, rec'd 0/16
Jan  1 00:12:04 kernel: [  724.818628] musb-hdrc musb-hdrc.1: CPPI 4.1 IRQ: Tx 0, Rx 2
Jan  1 00:12:04 kernel: [  724.818644] musb-hdrc musb-hdrc.1: Rx complete: dma channel(1) ep2 len 0
Jan  1 00:12:04 kernel: [  724.818658] musb-hdrc musb-hdrc.1: curr_pd=ffdbffc0, len=0, origlen=16,rxch(alen/len)=0/16
Jan  1 00:12:04 kernel: [  724.818744] musb-hdrc musb-hdrc.1: Allocated free descriptor/buffer queue 2 in queue manager 0
Jan  1 00:12:04 kernel: [  724.818760] musb-hdrc musb-hdrc.1: Allocated DMA Rx channel 1 for EP2
Jan  1 00:12:04 kernel: [  724.818777] musb-hdrc musb-hdrc.1: RX DMA1, transparent, maxpkt 512, addr 0x87455200, rec'd 0/16
Jan  1 00:12:04 kernel: [  724.818811] musb-hdrc musb-hdrc.1: CPPI 4.1 IRQ: Tx 0, Rx 2
Jan  1 00:12:04 kernel: [  724.818826] musb-hdrc musb-hdrc.1: Rx complete: dma channel(1) ep2 len 0
Jan  1 00:12:04 kernel: [  724.818840] musb-hdrc musb-hdrc.1: curr_pd=ffdbffc0, len=0, origlen=16,rxch(alen/len)=0/16
Jan  1 00:12:04 kernel: [  724.818916] musb-hdrc musb-hdrc.1: Allocated free descriptor/buffer queue 2 in queue manager 0
Jan  1 00:12:04 kernel: [  724.818932] musb-hdrc musb-hdrc.1: Allocated DMA Rx channel 1 for EP2
Jan  1 00:12:04 kernel: [  724.818949] musb-hdrc musb-hdrc.1: RX DMA1, transparent, maxpkt 512, addr 0x87455200, rec'd 0/16
Jan  1 00:12:04 kernel: [  724.818969] musb-hdrc musb-hdrc.1: CPPI 4.1 IRQ: Tx 0, Rx 2
Jan  1 00:12:04 kernel: [  724.818982] musb-hdrc musb-hdrc.1: Rx complete: dma channel(1) ep2 len 0
Jan  1 00:12:04 kernel: [  724.818997] musb-hdrc musb-hdrc.1: curr_pd=ffdbffc0, len=0, origlen=16,rxch(alen/len)=0/16
Jan  1 00:12:04 kernel: [  724.819072] musb-hdrc musb-hdrc.1: Allocated free descriptor/buffer queue 2 in queue manager 0
Jan  1 00:12:04 kernel: [  724.819088] musb-hdrc musb-hdrc.1: Allocated DMA Rx channel 1 for EP2
Jan  1 00:12:04 kernel: [  724.819105] musb-hdrc musb-hdrc.1: RX DMA1, transparent, maxpkt 512, addr 0x87455200, rec'd 0/16
Jan  1 00:12:04 kernel: [  724.819131] musb-hdrc musb-hdrc.1: CPPI 4.1 IRQ: Tx 0, Rx 2
Jan  1 00:12:04 kernel: [  724.819145] musb-hdrc musb-hdrc.1: Rx complete: dma channel(1) ep2 len 0
Jan  1 00:12:04 kernel: [  724.819159] musb-hdrc musb-hdrc.1: curr_pd=ffdbffc0, len=0, origlen=16,rxch(alen/len)=0/16
Jan  1 00:12:04 kernel: [  724.819235] musb-hdrc musb-hdrc.1: Allocated free descriptor/buffer queue 2 in queue manager 0
Jan  1 00:12:04 kernel: [  724.819251] musb-hdrc musb-hdrc.1: Allocated DMA Rx channel 1 for EP2
Jan  1 00:12:04 kernel: [  724.819268] musb-hdrc musb-hdrc.1: RX DMA1, transparent, maxpkt 512, addr 0x87455200, rec'd 0/16
Jan  1 00:12:04 kernel: [  724.819291] musb-hdrc musb-hdrc.1: CPPI 4.1 IRQ: Tx 0, Rx 2
Jan  1 00:12:04 kernel: [  724.819305] musb-hdrc musb-hdrc.1: Rx complete: dma channel(1) ep2 len 16
Jan  1 00:12:04 kernel: [  724.819319] musb-hdrc musb-hdrc.1: curr_pd=ffdbffc0, len=16, origlen=16,rxch(alen/len)=16/16
Jan  1 00:12:04 kernel: [  724.819828] musb-hdrc musb-hdrc.1: Allocated free descriptor/buffer queue 2 in queue manager 0
Jan  1 00:12:04 kernel: [  724.819847] musb-hdrc musb-hdrc.1: Allocated DMA Rx channel 1 for EP2
Jan  1 00:12:04 kernel: [  724.819868] musb-hdrc musb-hdrc.1: RX DMA1, transparent, maxpkt 512, addr 0x87455200, rec'd 0/16
Jan  1 00:12:04 kernel: [  724.819893] musb-hdrc musb-hdrc.1: CPPI 4.1 IRQ: Tx 0, Rx 2
Jan  1 00:12:04 kernel: [  724.819906] musb-hdrc musb-hdrc.1: Rx complete: dma channel(1) ep2 len 16
Jan  1 00:12:04 kernel: [  724.819921] musb-hdrc musb-hdrc.1: curr_pd=ffdbffc0, len=16, origlen=16,rxch(alen/len)=16/16
Jan  1 00:12:04 kernel: [  724.826280] musb-hdrc musb-hdrc.1: Allocated DMA Tx channel 1 for EP2
Jan  1 00:12:04 kernel: [  724.826314] musb-hdrc musb-hdrc.1: TX DMA1, accelerated, maxpkt 16, 1 PDs, addr 0x87455200, len 16
Jan  1 00:12:04 kernel: [  724.826333] musb-hdrc musb-hdrc.1: TX PD ffdbffc0: buf 87455200, len 00000010, pkt info 1400007e
Jan  1 00:12:04 kernel: [  724.826358] musb-hdrc musb-hdrc.1: CPPI 4.1 IRQ: Tx 2, Rx 0
Jan  1 00:12:04 kernel: [  724.826545] musb-hdrc musb-hdrc.1: usbintr (0) epintr(4)
Jan  1 00:12:04 kernel: [  724.829516] musb-hdrc musb-hdrc.1: Allocated DMA Tx channel 1 for EP2
Jan  1 00:12:04 kernel: [  724.829543] musb-hdrc musb-hdrc.1: TX DMA1, accelerated, maxpkt 16, 1 PDs, addr 0x87455200, len 16
Jan  1 00:12:04 kernel: [  724.829562] musb-hdrc musb-hdrc.1: TX PD ffdbffc0: buf 87455200, len 00000010, pkt info 1400007e
Jan  1 00:12:04 kernel: [  724.829584] musb-hdrc musb-hdrc.1: CPPI 4.1 IRQ: Tx 2, Rx 0
Jan  1 00:12:04 kernel: [  724.829723] musb-hdrc musb-hdrc.1: usbintr (0) epintr(4)
Jan  1 00:12:04 kernel: [  724.829815] musb-hdrc musb-hdrc.1: Allocated free descriptor/buffer queue 2 in queue manager 0
Jan  1 00:12:04 kernel: [  724.829833] musb-hdrc musb-hdrc.1: Allocated DMA Rx channel 1 for EP2
Jan  1 00:12:04 kernel: [  724.829855] musb-hdrc musb-hdrc.1: RX DMA1, transparent, maxpkt 512, addr 0x87455200, rec'd 0/16
Jan  1 00:12:04 kernel: [  724.829877] musb-hdrc musb-hdrc.1: CPPI 4.1 IRQ: Tx 0, Rx 2
Jan  1 00:12:04 kernel: [  724.829892] musb-hdrc musb-hdrc.1: Rx complete: dma channel(1) ep2 len 0
Jan  1 00:12:04 kernel: [  724.829906] musb-hdrc musb-hdrc.1: curr_pd=ffdbffc0, len=0, origlen=16,rxch(alen/len)=0/16
Jan  1 00:12:04 kernel: [  724.829993] musb-hdrc musb-hdrc.1: Allocated free descriptor/buffer queue 2 in queue manager 0
Jan  1 00:12:04 kernel: [  724.830008] musb-hdrc musb-hdrc.1: Allocated DMA Rx channel 1 for EP2
Jan  1 00:12:04 kernel: [  724.830026] musb-hdrc musb-hdrc.1: RX DMA1, transparent, maxpkt 512, addr 0x87455200, rec'd 0/16
Jan  1 00:12:04 kernel: [  724.830061] musb-hdrc musb-hdrc.1: CPPI 4.1 IRQ: Tx 0, Rx 2
Jan  1 00:12:04 kernel: [  724.830077] musb-hdrc musb-hdrc.1: Rx complete: dma channel(1) ep2 len 0
Jan  1 00:12:04 kernel: [  724.830091] musb-hdrc musb-hdrc.1: curr_pd=ffdbffc0, len=0, origlen=16,rxch(alen/len)=0/16
Jan  1 00:12:04 kernel: [  724.830163] musb-hdrc musb-hdrc.1: Allocated free descriptor/buffer queue 2 in queue manager 0
Jan  1 00:12:04 kernel: [  724.830179] musb-hdrc musb-hdrc.1: Allocated DMA Rx channel 1 for EP2
Jan  1 00:12:04 kernel: [  724.830196] musb-hdrc musb-hdrc.1: RX DMA1, transparent, maxpkt 512, addr 0x87455200, rec'd 0/16
Jan  1 00:12:04 kernel: [  724.830216] musb-hdrc musb-hdrc.1: CPPI 4.1 IRQ: Tx 0, Rx 2
Jan  1 00:12:04 kernel: [  724.830230] musb-hdrc musb-hdrc.1: Rx complete: dma channel(1) ep2 len 0
Jan  1 00:12:04 kernel: [  724.830244] musb-hdrc musb-hdrc.1: curr_pd=ffdbffc0, len=0, origlen=16,rxch(alen/len)=0/16
Jan  1 00:12:04 kernel: [  724.830318] musb-hdrc musb-hdrc.1: Allocated free descriptor/buffer queue 2 in queue manager 0
Jan  1 00:12:04 kernel: [  724.830333] musb-hdrc musb-hdrc.1: Allocated DMA Rx channel 1 for EP2
Jan  1 00:12:04 kernel: [  724.830350] musb-hdrc musb-hdrc.1: RX DMA1, transparent, maxpkt 512, addr 0x87455200, rec'd 0/16
Jan  1 00:12:04 kernel: [  724.830376] musb-hdrc musb-hdrc.1: CPPI 4.1 IRQ: Tx 0, Rx 2
Jan  1 00:12:04 kernel: [  724.830389] musb-hdrc musb-hdrc.1: Rx complete: dma channel(1) ep2 len 0
Jan  1 00:12:04 kernel: [  724.830403] musb-hdrc musb-hdrc.1: curr_pd=ffdbffc0, len=0, origlen=16,rxch(alen/len)=0/16
Jan  1 00:12:04 kernel: [  724.830479] musb-hdrc musb-hdrc.1: Allocated free descriptor/buffer queue 2 in queue manager 0
Jan  1 00:12:04 kernel: [  724.830495] musb-hdrc musb-hdrc.1: Allocated DMA Rx channel 1 for EP2
Jan  1 00:12:04 kernel: [  724.830511] musb-hdrc musb-hdrc.1: RX DMA1, transparent, maxpkt 512, addr 0x87455200, rec'd 0/16
Jan  1 00:12:04 kernel: [  724.830532] musb-hdrc musb-hdrc.1: CPPI 4.1 IRQ: Tx 0, Rx 2
Jan  1 00:12:04 kernel: [  724.830546] musb-hdrc musb-hdrc.1: Rx complete: dma channel(1) ep2 len 0
Jan  1 00:12:04 kernel: [  724.830560] musb-hdrc musb-hdrc.1: curr_pd=ffdbffc0, len=0, origlen=16,rxch(alen/len)=0/16
Jan  1 00:12:04 kernel: [  724.830633] musb-hdrc musb-hdrc.1: Allocated free descriptor/buffer queue 2 in queue manager 0
Jan  1 00:12:04 kernel: [  724.830648] musb-hdrc musb-hdrc.1: Allocated DMA Rx channel 1 for EP2
Jan  1 00:12:04 kernel: [  724.830665] musb-hdrc musb-hdrc.1: RX DMA1, transparent, maxpkt 512, addr 0x87455200, rec'd 0/16
Jan  1 00:12:04 kernel: [  724.830686] musb-hdrc musb-hdrc.1: CPPI 4.1 IRQ: Tx 0, Rx 2
Jan  1 00:12:04 kernel: [  724.830699] musb-hdrc musb-hdrc.1: Rx complete: dma channel(1) ep2 len 0
Jan  1 00:12:04 kernel: [  724.830713] musb-hdrc musb-hdrc.1: curr_pd=ffdbffc0, len=0, origlen=16,rxch(alen/len)=0/16
Jan  1 00:12:04 kernel: [  724.830785] musb-hdrc musb-hdrc.1: Allocated free descriptor/buffer queue 2 in queue manager 0
Jan  1 00:12:04 kernel: [  724.830801] musb-hdrc musb-hdrc.1: Allocated DMA Rx channel 1 for EP2
Jan  1 00:12:04 kernel: [  724.830818] musb-hdrc musb-hdrc.1: RX DMA1, transparent, maxpkt 512, addr 0x87455200, rec'd 0/16
Jan  1 00:12:04 kernel: [  724.830837] musb-hdrc musb-hdrc.1: CPPI 4.1 IRQ: Tx 0, Rx 2
Jan  1 00:12:04 kernel: [  724.830851] musb-hdrc musb-hdrc.1: Rx complete: dma channel(1) ep2 len 0
Jan  1 00:12:04 kernel: [  724.830865] musb-hdrc musb-hdrc.1: curr_pd=ffdbffc0, len=0, origlen=16,rxch(alen/len)=0/16
Jan  1 00:12:04 kernel: [  724.830936] musb-hdrc musb-hdrc.1: Allocated free descriptor/buffer queue 2 in queue manager 0
Jan  1 00:12:04 kernel: [  724.830951] musb-hdrc musb-hdrc.1: Allocated DMA Rx channel 1 for EP2
Jan  1 00:12:04 kernel: [  724.830969] musb-hdrc musb-hdrc.1: RX DMA1, transparent, maxpkt 512, addr 0x87455200, rec'd 0/16
Jan  1 00:12:04 kernel: [  724.830992] musb-hdrc musb-hdrc.1: CPPI 4.1 IRQ: Tx 0, Rx 2
Jan  1 00:12:04 kernel: [  724.831006] musb-hdrc musb-hdrc.1: Rx complete: dma channel(1) ep2 len 0
Jan  1 00:12:04 kernel: [  724.831020] musb-hdrc musb-hdrc.1: curr_pd=ffdbffc0, len=0, origlen=16,rxch(alen/len)=0/16
Jan  1 00:12:04 kernel: [  724.831090] musb-hdrc musb-hdrc.1: Allocated free descriptor/buffer queue 2 in queue manager 0
Jan  1 00:12:04 kernel: [  724.831105] musb-hdrc musb-hdrc.1: Allocated DMA Rx channel 1 for EP2
Jan  1 00:12:04 kernel: [  724.831122] musb-hdrc musb-hdrc.1: RX DMA1, transparent, maxpkt 512, addr 0x87455200, rec'd 0/16
Jan  1 00:12:04 kernel: [  724.831143] musb-hdrc musb-hdrc.1: CPPI 4.1 IRQ: Tx 0, Rx 2
Jan  1 00:12:04 kernel: [  724.831156] musb-hdrc musb-hdrc.1: Rx complete: dma channel(1) ep2 len 0
Jan  1 00:12:04 kernel: [  724.831170] musb-hdrc musb-hdrc.1: curr_pd=ffdbffc0, len=0, origlen=16,rxch(alen/len)=0/16
Jan  1 00:12:04 kernel: [  724.831243] musb-hdrc musb-hdrc.1: Allocated free descriptor/buffer queue 2 in queue manager 0
Jan  1 00:12:04 kernel: [  724.831259] musb-hdrc musb-hdrc.1: Allocated DMA Rx channel 1 for EP2
Jan  1 00:12:04 kernel: [  724.831276] musb-hdrc musb-hdrc.1: RX DMA1, transparent, maxpkt 512, addr 0x87455200, rec'd 0/16
Jan  1 00:12:04 kernel: [  724.831317] musb-hdrc musb-hdrc.1: CPPI 4.1 IRQ: Tx 0, Rx 2
Jan  1 00:12:04 kernel: [  724.831332] musb-hdrc musb-hdrc.1: Rx complete: dma channel(1) ep2 len 16
Jan  1 00:12:04 kernel: [  724.831347] musb-hdrc musb-hdrc.1: curr_pd=ffdbffc0, len=16, origlen=16,rxch(alen/len)=16/16
Jan  1 00:12:04 kernel: [  724.831854] musb-hdrc musb-hdrc.1: Allocated free descriptor/buffer queue 2 in queue manager 0
Jan  1 00:12:04 kernel: [  724.831873] musb-hdrc musb-hdrc.1: Allocated DMA Rx channel 1 for EP2
Jan  1 00:12:04 kernel: [  724.831892] musb-hdrc musb-hdrc.1: RX DMA1, transparent, maxpkt 512, addr 0x87455200, rec'd 0/16
Jan  1 00:12:04 kernel: [  724.831913] musb-hdrc musb-hdrc.1: CPPI 4.1 IRQ: Tx 0, Rx 2
Jan  1 00:12:04 kernel: [  724.831927] musb-hdrc musb-hdrc.1: Rx complete: dma channel(1) ep2 len 0
Jan  1 00:12:04 kernel: [  724.831941] musb-hdrc musb-hdrc.1: curr_pd=ffdbffc0, len=0, origlen=16,rxch(alen/len)=0/16
Jan  1 00:12:04 kernel: [  724.832046] musb-hdrc musb-hdrc.1: Allocated free descriptor/buffer queue 2 in queue manager 0
Jan  1 00:12:04 kernel: [  724.832062] musb-hdrc musb-hdrc.1: Allocated DMA Rx channel 1 for EP2
Jan  1 00:12:04 kernel: [  724.832080] musb-hdrc musb-hdrc.1: RX DMA1, transparent, maxpkt 512, addr 0x87455200, rec'd 0/16
Jan  1 00:12:04 kernel: [  724.832101] musb-hdrc musb-hdrc.1: CPPI 4.1 IRQ: Tx 0, Rx 2
Jan  1 00:12:04 kernel: [  724.832115] musb-hdrc musb-hdrc.1: Rx complete: dma channel(1) ep2 len 0
Jan  1 00:12:04 kernel: [  724.832129] musb-hdrc musb-hdrc.1: curr_pd=ffdbffc0, len=0, origlen=16,rxch(alen/len)=0/16
Jan  1 00:12:04 kernel: [  724.832208] musb-hdrc musb-hdrc.1: Allocated free descriptor/buffer queue 2 in queue manager 0
Jan  1 00:12:04 kernel: [  724.832224] musb-hdrc musb-hdrc.1: Allocated DMA Rx channel 1 for EP2
Jan  1 00:12:04 kernel: [  724.832241] musb-hdrc musb-hdrc.1: RX DMA1, transparent, maxpkt 512, addr 0x87455200, rec'd 0/16
Jan  1 00:12:04 kernel: [  724.832261] musb-hdrc musb-hdrc.1: CPPI 4.1 IRQ: Tx 0, Rx 2
Jan  1 00:12:04 kernel: [  724.832274] musb-hdrc musb-hdrc.1: Rx complete: dma channel(1) ep2 len 0
Jan  1 00:12:04 kernel: [  724.832289] musb-hdrc musb-hdrc.1: curr_pd=ffdbffc0, len=0, origlen=16,rxch(alen/len)=0/16
Jan  1 00:12:04 kernel: [  724.832360] musb-hdrc musb-hdrc.1: Allocated free descriptor/buffer queue 2 in queue manager 0
Jan  1 00:12:04 kernel: [  724.832376] musb-hdrc musb-hdrc.1: Allocated DMA Rx channel 1 for EP2
Jan  1 00:12:04 kernel: [  724.832393] musb-hdrc musb-hdrc.1: RX DMA1, transparent, maxpkt 512, addr 0x87455200, rec'd 0/16
Jan  1 00:12:04 kernel: [  724.832416] musb-hdrc musb-hdrc.1: CPPI 4.1 IRQ: Tx 0, Rx 2
Jan  1 00:12:04 kernel: [  724.832430] musb-hdrc musb-hdrc.1: Rx complete: dma channel(1) ep2 len 16
Jan  1 00:12:04 kernel: [  724.832445] musb-hdrc musb-hdrc.1: curr_pd=ffdbffc0, len=16, origlen=16,rxch(alen/len)=16/16
Jan  1 00:12:04 kernel: [  724.833228] musb-hdrc musb-hdrc.1: Allocated DMA Tx channel 1 for EP2
Jan  1 00:12:04 kernel: [  724.833254] musb-hdrc musb-hdrc.1: TX DMA1, accelerated, maxpkt 16, 1 PDs, addr 0x87455200, len 16
Jan  1 00:12:04 kernel: [  724.833271] musb-hdrc musb-hdrc.1: TX PD ffdbffc0: buf 87455200, len 00000010, pkt info 1400007e
Jan  1 00:12:04 kernel: [  724.833292] musb-hdrc musb-hdrc.1: CPPI 4.1 IRQ: Tx 2, Rx 0
Jan  1 00:12:04 kernel: [  724.833440] musb-hdrc musb-hdrc.1: usbintr (0) epintr(4)
Jan  1 00:12:04 kernel: [  724.833661] musb-hdrc musb-hdrc.1: Allocated DMA Tx channel 1 for EP2
Jan  1 00:12:04 kernel: [  724.833680] musb-hdrc musb-hdrc.1: TX DMA1, accelerated, maxpkt 32, 1 PDs, addr 0x87455200, len 32
Jan  1 00:12:04 kernel: [  724.833697] musb-hdrc musb-hdrc.1: TX PD ffdbffc0: buf 87455200, len 00000020, pkt info 1400007e
Jan  1 00:12:04 kernel: [  724.833717] musb-hdrc musb-hdrc.1: CPPI 4.1 IRQ: Tx 2, Rx 0
Jan  1 00:12:04 kernel: [  724.833814] musb-hdrc musb-hdrc.1: usbintr (0) epintr(4)
Jan  1 00:12:04 kernel: [  724.833887] musb-hdrc musb-hdrc.1: Allocated free descriptor/buffer queue 2 in queue manager 0
Jan  1 00:12:04 kernel: [  724.833904] musb-hdrc musb-hdrc.1: Allocated DMA Rx channel 1 for EP2
Jan  1 00:12:04 kernel: [  724.833922] musb-hdrc musb-hdrc.1: RX DMA1, transparent, maxpkt 512, addr 0x87455200, rec'd 0/16
Jan  1 00:12:04 kernel: [  724.833945] musb-hdrc musb-hdrc.1: CPPI 4.1 IRQ: Tx 0, Rx 2
Jan  1 00:12:04 kernel: [  724.833959] musb-hdrc musb-hdrc.1: Rx complete: dma channel(1) ep2 len 0
Jan  1 00:12:04 kernel: [  724.833973] musb-hdrc musb-hdrc.1: curr_pd=ffdbffc0, len=0, origlen=16,rxch(alen/len)=0/16
Jan  1 00:12:04 kernel: [  724.834053] musb-hdrc musb-hdrc.1: Allocated free descriptor/buffer queue 2 in queue manager 0
Jan  1 00:12:04 kernel: [  724.834069] musb-hdrc musb-hdrc.1: Allocated DMA Rx channel 1 for EP2
Jan  1 00:12:04 kernel: [  724.834086] musb-hdrc musb-hdrc.1: RX DMA1, transparent, maxpkt 512, addr 0x87455200, rec'd 0/16
Jan  1 00:12:04 kernel: [  724.834106] musb-hdrc musb-hdrc.1: CPPI 4.1 IRQ: Tx 0, Rx 2
Jan  1 00:12:04 kernel: [  724.834120] musb-hdrc musb-hdrc.1: Rx complete: dma channel(1) ep2 len 0
Jan  1 00:12:04 kernel: [  724.834134] musb-hdrc musb-hdrc.1: curr_pd=ffdbffc0, len=0, origlen=16,rxch(alen/len)=0/16
Jan  1 00:12:04 kernel: [  724.834207] musb-hdrc musb-hdrc.1: Allocated free descriptor/buffer queue 2 in queue manager 0
Jan  1 00:12:04 kernel: [  724.834222] musb-hdrc musb-hdrc.1: Allocated DMA Rx channel 1 for EP2
Jan  1 00:12:04 kernel: [  724.834239] musb-hdrc musb-hdrc.1: RX DMA1, transparent, maxpkt 512, addr 0x87455200, rec'd 0/16
Jan  1 00:12:04 kernel: [  724.834260] musb-hdrc musb-hdrc.1: CPPI 4.1 IRQ: Tx 0, Rx 2
Jan  1 00:12:04 kernel: [  724.834273] musb-hdrc musb-hdrc.1: Rx complete: dma channel(1) ep2 len 0
Jan  1 00:12:04 kernel: [  724.834287] musb-hdrc musb-hdrc.1: curr_pd=ffdbffc0, len=0, origlen=16,rxch(alen/len)=0/16
Jan  1 00:12:04 kernel: [  724.834360] musb-hdrc musb-hdrc.1: Allocated free descriptor/buffer queue 2 in queue manager 0
Jan  1 00:12:04 kernel: [  724.834375] musb-hdrc musb-hdrc.1: Allocated DMA Rx channel 1 for EP2
Jan  1 00:12:04 kernel: [  724.834392] musb-hdrc musb-hdrc.1: RX DMA1, transparent, maxpkt 512, addr 0x87455200, rec'd 0/16
Jan  1 00:12:04 kernel: [  724.834413] musb-hdrc musb-hdrc.1: CPPI 4.1 IRQ: Tx 0, Rx 2
Jan  1 00:12:04 kernel: [  724.834426] musb-hdrc musb-hdrc.1: Rx complete: dma channel(1) ep2 len 0
Jan  1 00:12:04 kernel: [  724.834440] musb-hdrc musb-hdrc.1: curr_pd=ffdbffc0, len=0, origlen=16,rxch(alen/len)=0/16
Jan  1 00:12:04 kernel: [  724.834513] musb-hdrc musb-hdrc.1: Allocated free descriptor/buffer queue 2 in queue manager 0
Jan  1 00:12:04 kernel: [  724.834529] musb-hdrc musb-hdrc.1: Allocated DMA Rx channel 1 for EP2
Jan  1 00:12:04 kernel: [  724.834546] musb-hdrc musb-hdrc.1: RX DMA1, transparent, maxpkt 512, addr 0x87455200, rec'd 0/16
Jan  1 00:12:04 kernel: [  724.834566] musb-hdrc musb-hdrc.1: CPPI 4.1 IRQ: Tx 0, Rx 2
Jan  1 00:12:04 kernel: [  724.834579] musb-hdrc musb-hdrc.1: Rx complete: dma channel(1) ep2 len 0
Jan  1 00:12:04 kernel: [  724.834593] musb-hdrc musb-hdrc.1: curr_pd=ffdbffc0, len=0, origlen=16,rxch(alen/len)=0/16
Jan  1 00:12:04 kernel: [  724.834674] musb-hdrc musb-hdrc.1: Allocated free descriptor/buffer queue 2 in queue manager 0
Jan  1 00:12:04 kernel: [  724.834689] musb-hdrc musb-hdrc.1: Allocated DMA Rx channel 1 for EP2
Jan  1 00:12:04 kernel: [  724.834706] musb-hdrc musb-hdrc.1: RX DMA1, transparent, maxpkt 512, addr 0x87455200, rec'd 0/16
Jan  1 00:12:04 kernel: [  724.834729] musb-hdrc musb-hdrc.1: CPPI 4.1 IRQ: Tx 0, Rx 2
Jan  1 00:12:04 kernel: [  724.834742] musb-hdrc musb-hdrc.1: Rx complete: dma channel(1) ep2 len 0
Jan  1 00:12:04 kernel: [  724.834757] musb-hdrc musb-hdrc.1: curr_pd=ffdbffc0, len=0, origlen=16,rxch(alen/len)=0/16
Jan  1 00:12:04 kernel: [  724.834826] musb-hdrc musb-hdrc.1: Allocated free descriptor/buffer queue 2 in queue manager 0
Jan  1 00:12:04 kernel: [  724.834842] musb-hdrc musb-hdrc.1: Allocated DMA Rx channel 1 for EP2
Jan  1 00:12:04 kernel: [  724.834859] musb-hdrc musb-hdrc.1: RX DMA1, transparent, maxpkt 512, addr 0x87455200, rec'd 0/16
Jan  1 00:12:04 kernel: [  724.834879] musb-hdrc musb-hdrc.1: CPPI 4.1 IRQ: Tx 0, Rx 2
Jan  1 00:12:04 kernel: [  724.834893] musb-hdrc musb-hdrc.1: Rx complete: dma channel(1) ep2 len 0
Jan  1 00:12:04 kernel: [  724.834907] musb-hdrc musb-hdrc.1: curr_pd=ffdbffc0, len=0, origlen=16,rxch(alen/len)=0/16
Jan  1 00:12:04 kernel: [  724.834977] musb-hdrc musb-hdrc.1: Allocated free descriptor/buffer queue 2 in queue manager 0
Jan  1 00:12:04 kernel: [  724.834993] musb-hdrc musb-hdrc.1: Allocated DMA Rx channel 1 for EP2
Jan  1 00:12:04 kernel: [  724.835010] musb-hdrc musb-hdrc.1: RX DMA1, transparent, maxpkt 512, addr 0x87455200, rec'd 0/16
Jan  1 00:12:04 kernel: [  724.835031] musb-hdrc musb-hdrc.1: CPPI 4.1 IRQ: Tx 0, Rx 2
Jan  1 00:12:04 kernel: [  724.835044] musb-hdrc musb-hdrc.1: Rx complete: dma channel(1) ep2 len 0
Jan  1 00:12:04 kernel: [  724.835058] musb-hdrc musb-hdrc.1: curr_pd=ffdbffc0, len=0, origlen=16,rxch(alen/len)=0/16
Jan  1 00:12:04 kernel: [  724.835129] musb-hdrc musb-hdrc.1: Allocated free descriptor/buffer queue 2 in queue manager 0
Jan  1 00:12:04 kernel: [  724.835144] musb-hdrc musb-hdrc.1: Allocated DMA Rx channel 1 for EP2
Jan  1 00:12:04 kernel: [  724.835162] musb-hdrc musb-hdrc.1: RX DMA1, transparent, maxpkt 512, addr 0x87455200, rec'd 0/16
Jan  1 00:12:04 kernel: [  724.835184] musb-hdrc musb-hdrc.1: CPPI 4.1 IRQ: Tx 0, Rx 2
Jan  1 00:12:04 kernel: [  724.835198] musb-hdrc musb-hdrc.1: Rx complete: dma channel(1) ep2 len 0
Jan  1 00:12:04 kernel: [  724.835212] musb-hdrc musb-hdrc.1: curr_pd=ffdbffc0, len=0, origlen=16,rxch(alen/len)=0/16
Jan  1 00:12:04 kernel: [  724.835281] musb-hdrc musb-hdrc.1: Allocated free descriptor/buffer queue 2 in queue manager 0
Jan  1 00:12:04 kernel: [  724.835297] musb-hdrc musb-hdrc.1: Allocated DMA Rx channel 1 for EP2
Jan  1 00:12:04 kernel: [  724.835314] musb-hdrc musb-hdrc.1: RX DMA1, transparent, maxpkt 512, addr 0x87455200, rec'd 0/16
Jan  1 00:12:04 kernel: [  724.835334] musb-hdrc musb-hdrc.1: CPPI 4.1 IRQ: Tx 0, Rx 2
Jan  1 00:12:04 kernel: [  724.835347] musb-hdrc musb-hdrc.1: Rx complete: dma channel(1) ep2 len 0
Jan  1 00:12:04 kernel: [  724.835361] musb-hdrc musb-hdrc.1: curr_pd=ffdbffc0, len=0, origlen=16,rxch(alen/len)=0/16
Jan  1 00:12:04 kernel: [  724.835431] musb-hdrc musb-hdrc.1: Allocated free descriptor/buffer queue 2 in queue manager 0
Jan  1 00:12:04 kernel: [  724.835447] musb-hdrc musb-hdrc.1: Allocated DMA Rx channel 1 for EP2
Jan  1 00:12:04 kernel: [  724.835464] musb-hdrc musb-hdrc.1: RX DMA1, transparent, maxpkt 512, addr 0x87455200, rec'd 0/16
Jan  1 00:12:04 kernel: [  724.835485] musb-hdrc musb-hdrc.1: CPPI 4.1 IRQ: Tx 0, Rx 2
Jan  1 00:12:04 kernel: [  724.835498] musb-hdrc musb-hdrc.1: Rx complete: dma channel(1) ep2 len 0
Jan  1 00:12:04 kernel: [  724.835512] musb-hdrc musb-hdrc.1: curr_pd=ffdbffc0, len=0, origlen=16,rxch(alen/len)=0/16
Jan  1 00:12:04 kernel: [  724.835584] musb-hdrc musb-hdrc.1: Allocated free descriptor/buffer queue 2 in queue manager 0
Jan  1 00:12:04 kernel: [  724.835600] musb-hdrc musb-hdrc.1: Allocated DMA Rx channel 1 for EP2
Jan  1 00:12:04 kernel: [  724.835617] musb-hdrc musb-hdrc.1: RX DMA1, transparent, maxpkt 512, addr 0x87455200, rec'd 0/16
Jan  1 00:12:04 kernel: [  724.835637] musb-hdrc musb-hdrc.1: CPPI 4.1 IRQ: Tx 0, Rx 2
Jan  1 00:12:04 kernel: [  724.835650] musb-hdrc musb-hdrc.1: Rx complete: dma channel(1) ep2 len 0
Jan  1 00:12:04 kernel: [  724.835664] musb-hdrc musb-hdrc.1: curr_pd=ffdbffc0, len=0, origlen=16,rxch(alen/len)=0/16
Jan  1 00:12:04 kernel: [  724.835735] musb-hdrc musb-hdrc.1: Allocated free descriptor/buffer queue 2 in queue manager 0
Jan  1 00:12:04 kernel: [  724.835751] musb-hdrc musb-hdrc.1: Allocated DMA Rx channel 1 for EP2
Jan  1 00:12:04 kernel: [  724.835768] musb-hdrc musb-hdrc.1: RX DMA1, transparent, maxpkt 512, addr 0x87455200, rec'd 0/16
Jan  1 00:12:04 kernel: [  724.835787] musb-hdrc musb-hdrc.1: CPPI 4.1 IRQ: Tx 0, Rx 2
Jan  1 00:12:04 kernel: [  724.835801] musb-hdrc musb-hdrc.1: Rx complete: dma channel(1) ep2 len 0
Jan  1 00:12:04 kernel: [  724.835815] musb-hdrc musb-hdrc.1: curr_pd=ffdbffc0, len=0, origlen=16,rxch(alen/len)=0/16
Jan  1 00:12:04 kernel: [  724.835886] musb-hdrc musb-hdrc.1: Allocated free descriptor/buffer queue 2 in queue manager 0
Jan  1 00:12:04 kernel: [  724.835901] musb-hdrc musb-hdrc.1: Allocated DMA Rx channel 1 for EP2
Jan  1 00:12:04 kernel: [  724.835918] musb-hdrc musb-hdrc.1: RX DMA1, transparent, maxpkt 512, addr 0x87455200, rec'd 0/16
Jan  1 00:12:04 kernel: [  724.835939] musb-hdrc musb-hdrc.1: CPPI 4.1 IRQ: Tx 0, Rx 2
Jan  1 00:12:04 kernel: [  724.835952] musb-hdrc musb-hdrc.1: Rx complete: dma channel(1) ep2 len 0
Jan  1 00:12:04 kernel: [  724.835966] musb-hdrc musb-hdrc.1: curr_pd=ffdbffc0, len=0, origlen=16,rxch(alen/len)=0/16
Jan  1 00:12:04 kernel: [  724.836044] musb-hdrc musb-hdrc.1: Allocated free descriptor/buffer queue 2 in queue manager 0
Jan  1 00:12:04 kernel: [  724.836060] musb-hdrc musb-hdrc.1: Allocated DMA Rx channel 1 for EP2
Jan  1 00:12:04 kernel: [  724.836077] musb-hdrc musb-hdrc.1: RX DMA1, transparent, maxpkt 512, addr 0x87455200, rec'd 0/16
Jan  1 00:12:04 kernel: [  724.836098] musb-hdrc musb-hdrc.1: CPPI 4.1 IRQ: Tx 0, Rx 2
Jan  1 00:12:04 kernel: [  724.836111] musb-hdrc musb-hdrc.1: Rx complete: dma channel(1) ep2 len 0
Jan  1 00:12:04 kernel: [  724.836125] musb-hdrc musb-hdrc.1: curr_pd=ffdbffc0, len=0, origlen=16,rxch(alen/len)=0/16
Jan  1 00:12:04 kernel: [  724.836197] musb-hdrc musb-hdrc.1: Allocated free descriptor/buffer queue 2 in queue manager 0
Jan  1 00:12:04 kernel: [  724.836213] musb-hdrc musb-hdrc.1: Allocated DMA Rx channel 1 for EP2
Jan  1 00:12:04 kernel: [  724.836230] musb-hdrc musb-hdrc.1: RX DMA1, transparent, maxpkt 512, addr 0x87455200, rec'd 0/16
Jan  1 00:12:04 kernel: [  724.836251] musb-hdrc musb-hdrc.1: CPPI 4.1 IRQ: Tx 0, Rx 2
Jan  1 00:12:04 kernel: [  724.836264] musb-hdrc musb-hdrc.1: Rx complete: dma channel(1) ep2 len 0
Jan  1 00:12:04 kernel: [  724.836278] musb-hdrc musb-hdrc.1: curr_pd=ffdbffc0, len=0, origlen=16,rxch(alen/len)=0/16
Jan  1 00:12:04 kernel: [  724.836351] musb-hdrc musb-hdrc.1: Allocated free descriptor/buffer queue 2 in queue manager 0
Jan  1 00:12:04 kernel: [  724.836366] musb-hdrc musb-hdrc.1: Allocated DMA Rx channel 1 for EP2
Jan  1 00:12:04 kernel: [  724.836383] musb-hdrc musb-hdrc.1: RX DMA1, transparent, maxpkt 512, addr 0x87455200, rec'd 0/16
Jan  1 00:12:04 kernel: [  724.836404] musb-hdrc musb-hdrc.1: CPPI 4.1 IRQ: Tx 0, Rx 2
Jan  1 00:12:04 kernel: [  724.836417] musb-hdrc musb-hdrc.1: Rx complete: dma channel(1) ep2 len 0
Jan  1 00:12:04 kernel: [  724.836431] musb-hdrc musb-hdrc.1: curr_pd=ffdbffc0, len=0, origlen=16,rxch(alen/len)=0/16
Jan  1 00:12:04 kernel: [  724.836503] musb-hdrc musb-hdrc.1: Allocated free descriptor/buffer queue 2 in queue manager 0
Jan  1 00:12:04 kernel: [  724.836518] musb-hdrc musb-hdrc.1: Allocated DMA Rx channel 1 for EP2
Jan  1 00:12:04 kernel: [  724.836535] musb-hdrc musb-hdrc.1: RX DMA1, transparent, maxpkt 512, addr 0x87455200, rec'd 0/16
Jan  1 00:12:04 kernel: [  724.836559] musb-hdrc musb-hdrc.1: CPPI 4.1 IRQ: Tx 0, Rx 2
Jan  1 00:12:04 kernel: [  724.836572] musb-hdrc musb-hdrc.1: Rx complete: dma channel(1) ep2 len 0
Jan  1 00:12:04 kernel: [  724.836587] musb-hdrc musb-hdrc.1: curr_pd=ffdbffc0, len=0, origlen=16,rxch(alen/len)=0/16
Jan  1 00:12:04 kernel: [  724.841376] musb-hdrc musb-hdrc.1: Allocated free descriptor/buffer queue 2 in queue manager 0
Jan  1 00:12:04 kernel: [  724.841396] musb-hdrc musb-hdrc.1: Allocated DMA Rx channel 1 for EP2
Jan  1 00:12:04 kernel: [  724.841417] musb-hdrc musb-hdrc.1: RX DMA1, transparent, maxpkt 512, addr 0x87455200, rec'd 0/16
Jan  1 00:12:04 kernel: [  724.841442] musb-hdrc musb-hdrc.1: CPPI 4.1 IRQ: Tx 0, Rx 2
Jan  1 00:12:04 kernel: [  724.841455] musb-hdrc musb-hdrc.1: Rx complete: dma channel(1) ep2 len 0
Jan  1 00:12:04 kernel: [  724.841470] musb-hdrc musb-hdrc.1: curr_pd=ffdbffc0, len=0, origlen=16,rxch(alen/len)=0/16
Jan  1 00:12:04 kernel: [  724.841933] musb-hdrc musb-hdrc.1: Allocated free descriptor/buffer queue 2 in queue manager 0
Jan  1 00:12:04 kernel: [  724.841949] musb-hdrc musb-hdrc.1: Allocated DMA Rx channel 1 for EP2
Jan  1 00:12:04 kernel: [  724.841967] musb-hdrc musb-hdrc.1: RX DMA1, transparent, maxpkt 512, addr 0x87455200, rec'd 0/16
Jan  1 00:12:04 kernel: [  724.841990] musb-hdrc musb-hdrc.1: CPPI 4.1 IRQ: Tx 0, Rx 2
Jan  1 00:12:04 kernel: [  724.842003] musb-hdrc musb-hdrc.1: Rx complete: dma channel(1) ep2 len 0
Jan  1 00:12:04 kernel: [  724.842017] musb-hdrc musb-hdrc.1: curr_pd=ffdbffc0, len=0, origlen=16,rxch(alen/len)=0/16
Jan  1 00:12:04 kernel: [  724.842380] musb-hdrc musb-hdrc.1: Allocated free descriptor/buffer queue 2 in queue manager 0
Jan  1 00:12:04 kernel: [  724.842397] musb-hdrc musb-hdrc.1: Allocated DMA Rx channel 1 for EP2
Jan  1 00:12:04 kernel: [  724.842414] musb-hdrc musb-hdrc.1: RX DMA1, transparent, maxpkt 512, addr 0x87455200, rec'd 0/16
Jan  1 00:12:04 kernel: [  724.842437] musb-hdrc musb-hdrc.1: CPPI 4.1 IRQ: Tx 0, Rx 2
Jan  1 00:12:04 kernel: [  724.842450] musb-hdrc musb-hdrc.1: Rx complete: dma channel(1) ep2 len 0
Jan  1 00:12:04 kernel: [  724.842464] musb-hdrc musb-hdrc.1: curr_pd=ffdbffc0, len=0, origlen=16,rxch(alen/len)=0/16
Jan  1 00:12:04 kernel: [  724.842872] musb-hdrc musb-hdrc.1: Allocated free descriptor/buffer queue 2 in queue manager 0
Jan  1 00:12:04 kernel: [  724.842888] musb-hdrc musb-hdrc.1: Allocated DMA Rx channel 1 for EP2
Jan  1 00:12:04 kernel: [  724.842905] musb-hdrc musb-hdrc.1: RX DMA1, transparent, maxpkt 512, addr 0x87455200, rec'd 0/16
Jan  1 00:12:04 kernel: [  724.842935] musb-hdrc musb-hdrc.1: CPPI 4.1 IRQ: Tx 0, Rx 2
Jan  1 00:12:04 kernel: [  724.842949] musb-hdrc musb-hdrc.1: Rx complete: dma channel(1) ep2 len 0
Jan  1 00:12:04 kernel: [  724.842963] musb-hdrc musb-hdrc.1: curr_pd=ffdbffc0, len=0, origlen=16,rxch(alen/len)=0/16
Jan  1 00:12:04 kernel: [  724.843842] musb-hdrc musb-hdrc.1: Allocated free descriptor/buffer queue 2 in queue manager 0
Jan  1 00:12:04 kernel: [  724.843858] musb-hdrc musb-hdrc.1: Allocated DMA Rx channel 1 for EP2
Jan  1 00:12:04 kernel: [  724.843876] musb-hdrc musb-hdrc.1: RX DMA1, transparent, maxpkt 512, addr 0x87455200, rec'd 0/16
Jan  1 00:12:04 kernel: [  724.843898] musb-hdrc musb-hdrc.1: CPPI 4.1 IRQ: Tx 0, Rx 2
Jan  1 00:12:04 kernel: [  724.843912] musb-hdrc musb-hdrc.1: Rx complete: dma channel(1) ep2 len 0
Jan  1 00:12:04 kernel: [  724.843926] musb-hdrc musb-hdrc.1: curr_pd=ffdbffc0, len=0, origlen=16,rxch(alen/len)=0/16
Jan  1 00:12:04 kernel: [  724.844011] musb-hdrc musb-hdrc.1: Allocated free descriptor/buffer queue 2 in queue manager 0
Jan  1 00:12:04 kernel: [  724.844027] musb-hdrc musb-hdrc.1: Allocated DMA Rx channel 1 for EP2
Jan  1 00:12:04 kernel: [  724.844044] musb-hdrc musb-hdrc.1: RX DMA1, transparent, maxpkt 512, addr 0x87455200, rec'd 0/16
Jan  1 00:12:04 kernel: [  724.844064] musb-hdrc musb-hdrc.1: CPPI 4.1 IRQ: Tx 0, Rx 2
Jan  1 00:12:04 kernel: [  724.844077] musb-hdrc musb-hdrc.1: Rx complete: dma channel(1) ep2 len 0
Jan  1 00:12:04 kernel: [  724.844092] musb-hdrc musb-hdrc.1: curr_pd=ffdbffc0, len=0, origlen=16,rxch(alen/len)=0/16
Jan  1 00:12:04 kernel: [  724.844167] musb-hdrc musb-hdrc.1: Allocated free descriptor/buffer queue 2 in queue manager 0
Jan  1 00:12:04 kernel: [  724.844183] musb-hdrc musb-hdrc.1: Allocated DMA Rx channel 1 for EP2
Jan  1 00:12:04 kernel: [  724.844200] musb-hdrc musb-hdrc.1: RX DMA1, transparent, maxpkt 512, addr 0x87455200, rec'd 0/16
Jan  1 00:12:04 kernel: [  724.844220] musb-hdrc musb-hdrc.1: CPPI 4.1 IRQ: Tx 0, Rx 2
Jan  1 00:12:04 kernel: [  724.844234] musb-hdrc musb-hdrc.1: Rx complete: dma channel(1) ep2 len 0
Jan  1 00:12:04 kernel: [  724.844249] musb-hdrc musb-hdrc.1: curr_pd=ffdbffc0, len=0, origlen=16,rxch(alen/len)=0/16
Jan  1 00:12:04 kernel: [  724.844322] musb-hdrc musb-hdrc.1: Allocated free descriptor/buffer queue 2 in queue manager 0
Jan  1 00:12:04 kernel: [  724.844338] musb-hdrc musb-hdrc.1: Allocated DMA Rx channel 1 for EP2
Jan  1 00:12:04 kernel: [  724.844355] musb-hdrc musb-hdrc.1: RX DMA1, transparent, maxpkt 512, addr 0x87455200, rec'd 0/16
Jan  1 00:12:04 kernel: [  724.844375] musb-hdrc musb-hdrc.1: CPPI 4.1 IRQ: Tx 0, Rx 2
Jan  1 00:12:04 kernel: [  724.844388] musb-hdrc musb-hdrc.1: Rx complete: dma channel(1) ep2 len 0
Jan  1 00:12:04 kernel: [  724.844402] musb-hdrc musb-hdrc.1: curr_pd=ffdbffc0, len=0, origlen=16,rxch(alen/len)=0/16
Jan  1 00:12:04 kernel: [  724.844646] musb-hdrc musb-hdrc.1: Allocated free descriptor/buffer queue 2 in queue manager 0
Jan  1 00:12:04 kernel: [  724.844662] musb-hdrc musb-hdrc.1: Allocated DMA Rx channel 1 for EP2
Jan  1 00:12:04 kernel: [  724.844680] musb-hdrc musb-hdrc.1: RX DMA1, transparent, maxpkt 512, addr 0x87455200, rec'd 0/16
Jan  1 00:12:04 kernel: [  724.844701] musb-hdrc musb-hdrc.1: CPPI 4.1 IRQ: Tx 0, Rx 2
Jan  1 00:12:04 kernel: [  724.844715] musb-hdrc musb-hdrc.1: Rx complete: dma channel(1) ep2 len 0
Jan  1 00:12:04 kernel: [  724.844729] musb-hdrc musb-hdrc.1: curr_pd=ffdbffc0, len=0, origlen=16,rxch(alen/len)=0/16
Jan  1 00:12:04 kernel: [  724.845068] musb-hdrc musb-hdrc.1: Allocated free descriptor/buffer queue 2 in queue manager 0
Jan  1 00:12:04 kernel: [  724.845085] musb-hdrc musb-hdrc.1: Allocated DMA Rx channel 1 for EP2
Jan  1 00:12:04 kernel: [  724.845102] musb-hdrc musb-hdrc.1: RX DMA1, transparent, maxpkt 512, addr 0x87455200, rec'd 0/16
Jan  1 00:12:04 kernel: [  724.845123] musb-hdrc musb-hdrc.1: CPPI 4.1 IRQ: Tx 0, Rx 2
Jan  1 00:12:04 kernel: [  724.845136] musb-hdrc musb-hdrc.1: Rx complete: dma channel(1) ep2 len 0
Jan  1 00:12:04 kernel: [  724.845150] musb-hdrc musb-hdrc.1: curr_pd=ffdbffc0, len=0, origlen=16,rxch(alen/len)=0/16
Jan  1 00:12:04 kernel: [  724.845489] musb-hdrc musb-hdrc.1: Allocated free descriptor/buffer queue 2 in queue manager 0
Jan  1 00:12:04 kernel: [  724.845505] musb-hdrc musb-hdrc.1: Allocated DMA Rx channel 1 for EP2
Jan  1 00:12:04 kernel: [  724.845522] musb-hdrc musb-hdrc.1: RX DMA1, transparent, maxpkt 512, addr 0x87455200, rec'd 0/16
Jan  1 00:12:04 kernel: [  724.845563] musb-hdrc musb-hdrc.1: CPPI 4.1 IRQ: Tx 0, Rx 2
Jan  1 00:12:04 kernel: [  724.845579] musb-hdrc musb-hdrc.1: Rx complete: dma channel(1) ep2 len 0
Jan  1 00:12:04 kernel: [  724.845593] musb-hdrc musb-hdrc.1: curr_pd=ffdbffc0, len=0, origlen=16,rxch(alen/len)=0/16
Jan  1 00:12:04 kernel: [  724.845926] musb-hdrc musb-hdrc.1: Allocated free descriptor/buffer queue 2 in queue manager 0
Jan  1 00:12:04 kernel: [  724.845942] musb-hdrc musb-hdrc.1: Allocated DMA Rx channel 1 for EP2
Jan  1 00:12:04 kernel: [  724.845960] musb-hdrc musb-hdrc.1: RX DMA1, transparent, maxpkt 512, addr 0x87455200, rec'd 0/16
Jan  1 00:12:04 kernel: [  724.845981] musb-hdrc musb-hdrc.1: CPPI 4.1 IRQ: Tx 0, Rx 2
Jan  1 00:12:04 kernel: [  724.845995] musb-hdrc musb-hdrc.1: Rx complete: dma channel(1) ep2 len 0
Jan  1 00:12:04 kernel: [  724.846009] musb-hdrc musb-hdrc.1: curr_pd=ffdbffc0, len=0, origlen=16,rxch(alen/len)=0/16
Jan  1 00:12:04 kernel: [  724.846411] musb-hdrc musb-hdrc.1: Allocated free descriptor/buffer queue 2 in queue manager 0
Jan  1 00:12:04 kernel: [  724.846428] musb-hdrc musb-hdrc.1: Allocated DMA Rx channel 1 for EP2
Jan  1 00:12:04 kernel: [  724.846445] musb-hdrc musb-hdrc.1: RX DMA1, transparent, maxpkt 512, addr 0x87455200, rec'd 0/16
Jan  1 00:12:04 kernel: [  724.846467] musb-hdrc musb-hdrc.1: CPPI 4.1 IRQ: Tx 0, Rx 2
Jan  1 00:12:04 kernel: [  724.846481] musb-hdrc musb-hdrc.1: Rx complete: dma channel(1) ep2 len 16
Jan  1 00:12:04 kernel: [  724.846495] musb-hdrc musb-hdrc.1: curr_pd=ffdbffc0, len=16, origlen=16,rxch(alen/len)=16/16
Jan  1 00:12:04 kernel: [  724.847675] musb-hdrc musb-hdrc.1: Allocated free descriptor/buffer queue 2 in queue manager 0
Jan  1 00:12:04 kernel: [  724.847696] musb-hdrc musb-hdrc.1: Allocated DMA Rx channel 1 for EP2
Jan  1 00:12:04 kernel: [  724.847717] musb-hdrc musb-hdrc.1: RX DMA1, accelerated, maxpkt 512, addr 0x873fdc00, rec'd 0/512
Jan  1 00:12:04 kernel: [  724.847739] musb-hdrc musb-hdrc.1: CPPI 4.1 IRQ: Tx 0, Rx 2
Jan  1 00:12:04 kernel: [  724.847753] musb-hdrc musb-hdrc.1: Rx complete: dma channel(1) ep2 len 0
Jan  1 00:12:04 kernel: [  724.847768] musb-hdrc musb-hdrc.1: curr_pd=ffdbffc0, len=0, origlen=512,rxch(alen/len)=0/512
Jan  1 00:12:04 kernel: [  724.847785] musb-hdrc musb-hdrc.1: RX DMA1, accelerated, maxpkt 512, addr 0x873fdc00, rec'd 0/512

0 Bin Liu over 12 years ago in reply to Andrea Cattani

TI__Guru**** 169561 points

Andrea,

Thanks for running the test for me.

Can you please try the following patch and let me know if it fixes the timeout issue? Please revert all changes you have done on .11 kernel - forcing Transparent mode in ti81xx.c and my starvation test.

diff --git a/drivers/usb/musb/cppi41_dma.c b/drivers/usb/musb/cppi41_dma.c
index 815cfb0..0c2fab4 100644
--- a/drivers/usb/musb/cppi41_dma.c
+++ b/drivers/usb/musb/cppi41_dma.c
@@ -856,7 +856,7 @@ static unsigned cppi41_next_rx_segment(struct cppi41_channel *rx_ch)
                }
        }
 
-       if (length < rx_ch->pkt_size)
+       if (length <= rx_ch->pkt_size)
                dma_mode = USB_TRANSPARENT_MODE;
 
        if (dma_mode == USB_INFINITE_DMAMODE) {

0 Andrea Cattani over 12 years ago in reply to Bin Liu

Intellectual 380 points

Bin,

your latest patch sorted out the issue and mass storage performances are not affected.
Now I'll do a complete set of tests and I'll let you know.

Many thanks for your support.
Andrea

0 Bin Liu over 12 years ago in reply to Andrea Cattani

TI__Guru**** 169561 points

Andrea, great, thanks for the update.

0 Bin Liu over 12 years ago in reply to Bin Liu

TI__Guru**** 169561 points

Hi Andrea,

When I worked with Max for all your USB issue previously, it had always been that AM335x USB works in device mode loaded with g_multi, and this device port suppose to connect to a PC. But in this timeout issue, we are talking about AM335x host port with a CDC/MSC device connected. Is the device to the host port the same as we worked on before - AM335x with g_multi?

If you will confirm that is so, I think I 'know' why switching to G-RNDIS from Transparent mode breaks your app.

0 Andrea Cattani over 12 years ago in reply to Bin Liu

Intellectual 380 points

Bin,

yes, the AM335x device is the same. So a USB device port with g_multi connected on a PC and a USB host port with differents devices connected. The timeout issue is related to a particular custon USB device.

Actually, on previous thread (http://e2e.ti.com/support/arm/sitara_arm/f/791/t/231794.aspx), the issue was related to the AM335x host port.

Please, let me know about your idea.

Regards,
Andrea

0 Bin Liu over 12 years ago in reply to Andrea Cattani

TI__Guru**** 169561 points

Andrea,

Andrea Cattani said:
The timeout issue is related to a particular custon USB device.

Is this custom device uses AM335x? If so, I think my suspicion is correct; othwise, only the protocol analyzer trace will confirm if that is a buggy device.

Andrea Cattani said:
Actually, on previous thread (http://e2e.ti.com/support/arm/sitara_arm/f/791/t/231794.aspx), the issue was related to the AM335x host port.

I meant another DMA issue before this one. That was on the USB device port and solved around July last year. ;)

0 Andrea Cattani over 12 years ago in reply to Bin Liu

Intellectual 380 points

Bin,

no, the custom device involved is not AM335x device.
Andrea

0 Bin Liu over 12 years ago in reply to Andrea Cattani

TI__Guru**** 169561 points

Andrea,

Ok, that is fine. Here is my theory:

In this bulk transfer case, the transfer size is 512 bytes, which is exact the same as a single usb packet. By USB specs, the device should send *two* usb packets for the transfer, the first one has 512 bytes data, and the second one has 0 bytes data. The second packet is used to terminate the transfer. I suspect the usb device firmware has a bug which does not send the second packet. I guess only the protocol analyzer trace could tell.

Then on the host side, when AM335x USB uses G-RNDIS mode, the DMA only generates the interrupt when it received the whole transfer which includes the second packet. If the device does not send it, the DMA will wait there forever. Then libusb function times out.

But if AM335x uses Transparent mode, the DMA will generate the interrupt when received every packet. So after received the first 512 bytes, DMA interrupts and gives back the data to driver upper layer. Then libusb function returns normally.

Anyway, no matter what the root cause it, the last patch should work around the issue on the host side without any side affects.

Processors

Processors forum

am335x usb_bulk_read timeout error in DMA mode with kernel 4.6.0.11