On 3.10.2019 18.13, Bernhard Gebetsberger wrote:
I sent the instructions to one of the users in the bug tracker.
Here is the download link for his logs: https://www.sendspace.com/file/413hlj
Thanks.
Traces show driver handles the Transaction error normally by issuing a endpoint
reset,
which is successful, but after that there is no activity on that endpoint even
if there
are over 120 transfers requests (TRB) pending.
After over 40 seconds the class driver starts canceling the pending transfers.
after soft retry the xhci driver should ring the doorbell of the endpoint, and
hardware
should start processing pending TRBs, but ring is not handling pending TRBs
Looks like either driver or hardware fails to start the endpoint ring again
I'll add some more tracing to check driver correctly rings the endpoint
doorbell.
Details of trace:
-Several TRBs (over 120) queued for slot 4 ep 3 (ep1in-bulk), starting at
0xff2d1000, up to 0xff2d1800 (0x10 per TRB)
164.884097: xhci_urb_enqueue: ep1in-bulk: urb 000000005ebe7973 pipe
3221259648 slot 4 length 0/3860 sgs 0/0 stream 0 flags 00010200
164.884099: xhci_queue_trb: BULK: Buffer 00000000f9e2304c length 3860 TD size
0 intr 0 type 'Normal' flags b:i:I:c:s:I:e:c
164.884101: xhci_inc_enq: BULK 00000000be510b60: enq
0x00000000ff2d1010(0x00000000ff2d1000) deq
0x00000000ff2d1000(0x00000000ff2d1000)
...
164.884304: xhci_urb_enqueue: ep1in-bulk: urb 00000000fee4e260 pipe
3221259648 slot 4 length 0/3860 sgs 0/0 stream 0 flags 00010200
164.884304: xhci_queue_trb: BULK: Buffer 00000000ff3a304c length 3860 TD size
0 intr 0 type 'Normal' flags b:i:I:c:s:I:e:c
164.884304: xhci_inc_enq: BULK 00000000be510b60: enq
0x00000000ff2d1800(0x00000000ff2d1000) deq
0x00000000ff2d1000(0x00000000ff2d1000)
-Transaction error 3 seconds later for TRB at 0xff2d1000
167.578273: xhci_handle_event: EVENT: TRB 00000000ff2d1000 status 'USB
Transaction Error' len 3860 slot 4 ep 3 type 'Transfer Event' flags e:c
167.578288: xhci_handle_transfer: BULK: Buffer 00000000f9e2304c length 3860
TD size 0 intr 0 type 'Normal' flags b:i:I:c:s:I:e:C
-Soft retry by issuing a host side reset endpoint command,
167.578297: xhci_queue_trb: CMD: Reset Endpoint Command: ctx 0000000000000000
slot 4 ep 3 flags C
167.578416: xhci_handle_event: EVENT: TRB 00000000ffefe440 status 'Success'
len 0 slot 4 ep 0 type 'Command Completion Event' flags e:c
-Host side of endpoint reset successful, endpoint is in stopped state as it
should
167.578417: xhci_handle_command: CMD: Reset Endpoint Command: ctx
0000000000000000 slot 4 ep 3 flags C
167.578419: xhci_handle_cmd_reset_ep: State stopped mult 1 max P. Streams 0
interval 125 us max ESIT payload 0 CErr 3 Type Bulk IN burst
-Driver should ring endpoint doorbell, and hardware should continue procressing
TRBs
No activity at all on slot 4 ep 3, other endpoints continue running normally.
Check driver really rang ep doorbell
A lot later class driver asks to cancel pending tranfer:
214.132531: xhci_urb_dequeue: ep1in-bulk: urb 000000005ebe7973 pipe
3221259648 slot 4 length 0/3860 sgs 0/0 stream 0 flags 00010200
214.132548: xhci_dbg_cancel_urb: Cancel URB 000000005ebe7973, dev 2, ep 0x81,
starting at offset 0xff2d1000
-xhci driver tries to stop endpoint to cancel transfer:
214.132555: xhci_queue_trb: CMD: Stop Ring Command: slot 4 sp 0 ep 3 flags C
-but it fails as slot is not in a proper state to be stopped, ep is in halted
state after failed stop attempt.
214.132679: xhci_handle_event: EVENT: TRB 00000000ffefe450 status 'Context
State Error' len 0 slot 4 ep 0 type 'Command Completion Event' flags e:C
214.132680: xhci_handle_command: CMD: Stop Ring Command: slot 4 sp 0 ep 3
flags C
214.132682: xhci_handle_cmd_stop_ep: State halted mult 1 max P. Streams 0
interval 125 us max ESIT payload 0 CErr 3 Type Bulk IN burst 0 maxp 512
-After this endpoint stays in halted state, xhci driver fails to recover from
this while canceling the reset of the TRBs
-Mathias
