Re: PROBLEM: Error 110 from ASMedia Host Controller

[Mathias Nyman <mathias.nyman@linux.intel.com>]

On 28.1.2023 0.47, Joe Bolling wrote:
> Thanks Mathias!
> 
> I received an updated firmware image from ASMedia. It seems to improve
> the 110 error problem a little bit - after the error occurs, I can
> still run lsusb without it hanging. However, the streaming performance
> of the camera has worsened with the new firmware; even with only one
> camera connected, I get "ERROR Transfer event TRB DMA ptr not part of
> current TD ep_index 8 comp_code 1" after just a few frames.
> 
> I guess the good news is these logs might be easier to analyze, since
> there's only one endpoint needed to reproduce the error. I'm not sure
> if this is the same behavior I was seeing before or not.
> Trace: https://bostondynamics1.box.com/s/3ovxdzu8g276os0pur5rmqbj2vzsgk79

Trace is missing most events, maybe the CPU handing the xHC interrupts
is not being traced. Getting all the events would help.

> dmesg: https://bostondynamics1.box.com/s/7420hi96o5o0f8rmsc2vaafwxf8fcv9y

Combining dmesg and trace it looks like ASMedia hosts fails to create a
transfer completion event for the last normal transfer block (TRB) on the
last segment before ringbuffer wraps back and continues handling events at
the beginning of the ring.

[  116.226252] xhci_hcd 0000:01:00.0: ERROR Transfer event TRB DMA ptr not part of current TD ep_index 8 comp_code 1
[  116.226254] xhci_hcd 0000:01:00.0: Looking for event-dma 000000003f82b000 trb-start 000000003f82cfe0 trb-end 000000003f82cfe0 seg-start 000000003f82c000

The xHC host hardware itself probably handled the transfer as it continues
handling later TRBs on this ring (cycling back to first segment).
So driver is waiting for an event for TRB at 0x3f82cfe0, while driver is
generating events for later TRBs at:
000000003f82b000
000000003f82b010
000000003f82b020
000000003f82b030

bulk endpoint 4 i(n) has a ring buffer with two segments. each fits 256TRBs
0x000000003f82b000
0x000000003f82c000

last TRB of each segment contains a link TRB (at 0x..bff0 and 0x..cff0) that
points to next segment, link TRB on last segment has a cycle bit set.

Looks like TRBs are queued normally,
queue TRB @ 0x3f82cfe0
116.257625: xhci_queue_trb: BULK: Buffer 000000003f930000 length 32768 TD size 0 intr 0 type 'Normal' flags b:i:I:c:s:I:e:c
116.257625: xhci_inc_enq: BULK 0000000084ebe58d: enq 0x000000003f82cff0(0x000000003f82c000) deq 0x000000003f82cfa0(0x000000
...
queue TRB @ 0x3f82b000
116.259186: xhci_queue_trb: BULK: Buffer 000000003f910000 length 32768 TD size 0 intr 0 type 'Normal' flags b:i:I:c:s:I:e:c
116.259186: xhci_inc_enq: BULK 0000000084ebe58d: enq 0x000000003f82b010(0x000000003f82b000) deq 0x000000003f82cfb0

A wild guess would be that this is somehow related to the cycle bit in of the
Link TRB. Maybe ASMedia HW processes the link TRB before creating the event for
the last normal TRB, and sets the cycle bit incorrectly for it?

Thanks
Mathias