On 17.04.2018 09:23, Tushar Nimkar wrote:
On 2018-04-16 18:46, Mathias Nyman wrote:
On 16.04.2018 13:20, Tushar Nimkar wrote:
On 2018-04-05 11:31, Felipe Balbi wrote:
Hi,
it would help if you would Cc XHCI's maintainer :-)
tnimkar@xxxxxxxxxxxxxx writes:
On 2018-04-04 19:28, Greg KH wrote:
On Wed, Apr 04, 2018 at 06:41:41PM +0530, tnimkar@xxxxxxxxxxxxxx wrote:
On 2018-04-04 18:07, Greg KH wrote:
> On Wed, Apr 04, 2018 at 05:14:50PM +0530, tnimkar@xxxxxxxxxxxxxx wrote:
> > Hi Oliver/Greg,
> >
> > I am able to duplicated the UAS issue on 4.16 as well.
> > The behavior is same new usb device detects and reset after aprox 30
> > sec(SD_TIMEOUT)
> > Logs are already shared below.
> >
> > We are using Synopsys dwc3 as host controller, May I know have
> > tested it
> > with dwc3?
> > I have tried it on Linux PC (x86 Ubuntu machine) I could not see the
> > issue.
> > It enumerates well.
>
> Great, stick with an x86 platform! :)
>
> Looks like a dwc3 host controller issue, try enabling tracing and
> debugging in that driver when this happens to see what is going on.
Oh if so let me enable the trace for that. I will respond you on this.
I did not get much clue, Greg. sometime this device enumerates well,
attached both working and non working case logs.
following is not working case
root@OpenWrt:/# dmesg
...
[57214.172683] xhci-hcd xhci-hcd.0.auto: ep 0x83 - asked for 112 bytes,
96 bytes untransferred
[57214.172809] xhci-hcd xhci-hcd.0.auto: ep 0x83 - asked for 112 bytes,
96 bytes untransferred
[57214.172840] sd 1:0:0:0: [sdb] 976773168 512-byte logical blocks: (500
GB/466 GiB)
[57214.172843] xhci-hcd xhci-hcd.0.auto: ep 0x81 - asked for 4096 bytes,
4080 bytes untransferred
[57214.172851] xhci-hcd xhci-hcd.0.auto: ep 0x83 - asked for 112 bytes,
96 bytes untransferred
[57214.253085] xhci-hcd xhci-hcd.0.auto: xhci_hub_status_data: stopping
port polling.
Huge gap before uas_eh_abort_eh_handler is called.
SD_TIMEOUT of 30 sec ...
[57246.701096] sd 1:0:0:0: tag#0 uas_eh_abort_handler 0 uas-tag 1
inflight: CMD IN
[57246.701130] sd 1:0:0:0: tag#0 CDB: opcode=0x1a 1a 00 3f 00 04 00
URB is canceled, maybe that URB never finished?
[57246.707583] xhci-hcd xhci-hcd.0.auto: Cancel URB 0000000007b523f0,
dev 1, ep 0x81, starting at offset 0
[57246.707594] xhci-hcd xhci-hcd.0.auto: // Ding dong!
[57246.707616] xhci-hcd xhci-hcd.0.auto: Stopped on No-op or Link TRB
for slot 1 ep 2
[57246.707625] xhci-hcd xhci-hcd.0.auto: Removing canceled TD starting
at 0x7f0cd0a0 (dma).
[57246.707630] xhci-hcd xhci-hcd.0.auto: Finding endpoint context
[57246.707634] xhci-hcd xhci-hcd.0.auto: Cycle state = 0x1
[57246.707637] xhci-hcd xhci-hcd.0.auto: New dequeue segment =
00000000890c7dc4 (virtual)
[57246.707641] xhci-hcd xhci-hcd.0.auto: New dequeue pointer =
0x7f0cd0b0 (DMA)
[57246.707646] xhci-hcd xhci-hcd.0.auto: Set TR Deq Ptr cmd, new deq seg
= 00000000890c7dc4 (0x7f0cd000 dmeq ptr = 000000000ce7faa0 (0x7f0cd0b0
dma), new cycle = 1
[57246.707651] xhci-hcd xhci-hcd.0.auto: // Ding dong!
[57246.707671] xhci-hcd xhci-hcd.0.auto: Successful Set TR Deq Ptr cmd,
deq = @7f0cd0b0
[57246.721090] scsi host1: uas_eh_device_reset_handler start
[57246.721114] xhci-hcd xhci-hcd.0.auto: Cancel URB 00000000279f06a2,
dev 1, ep 0x83, starting at offset 0
[57246.721120] xhci-hcd xhci-hcd.0.auto: // Ding dong!
[57246.721135] xhci-hcd xhci-hcd.0.auto: ERROR Transfer event for
unknown stream ring slot 1 ep 6
[57246.725463] xhci-hcd xhci-hcd.0.auto: @000000007f044780 00000000
00000000 1b000000 01078001
Stop -Length invalid transfer event. That is normal when canceling a URB,
but it should point to the TRB xhc was working on when stopped.
Here it just points to 0. That part looks like some issue with this specific
controller.
Some other errors may return 0 as their TRB pointer, but not this event.
But this is not the cause, just a detail while handling the real cause.
Nothing in this log shows why the URB was canceled in the first place.
usbmon and xhci traces could help, xhci traces:
mount -t debugfs none /sys/kernel/debug
echo 81920 > /sys/kernel/debug/tracing/buffer_size_kb
echo 1 > /sys/kernel/debug/tracing/events/xhci-hcd/enable
then send /sys/kernel/debug/tracing/trace after issue triggered.
-Mathias
Mathias, here is usbmon and trace ..let us know on your observation which will help to learn more on xhci level :-)
(same is attached)
The xhci traces show that a ep1in bulk URB is queued on Stream 1, but never completes.
Similar URBs queued on the same stream ring before this one work and complete fine.
xhci driver never gets a short or success completion transfer event for the URB.
No error messages, nothing special going on either.
To me it looks like the URB was queued correctly, but after the stream protocol chose
to transfer and finish stream 2 it never went back to transfer what was queued for stream 1.
xhci specs section 4.12.1 say that
"Stream selection is driven by a USB device. The Stream Protocol allows a device to switch Streams on
packet boundaries."
Stream protocol states and current stream (cstream) are not visible to xhci driver.
Details of URBs in xhci:
Queue URB 11a1a8 on STREAM 1 at 8050 ( )
kworker/u8:2-34 [003] d..2 99.076009: xhci_urb_enqueue: ep1in-bulk: urb 000000004011a1a8 pipe 3221258880 slot 1 length 0/32 sgs 1/1 stream 1 flags 00040200
kworker/u8:2-34 [003] d..3 99.076011: xhci_queue_trb: STREAM: Buffer 00000000663a8000 length 32 TD size 0 intr 0 type 'Normal' flags b:i:I:c:s:I:e:c
kworker/u8:2-34 [003] d..3 99.076013: xhci_inc_enq: STREAM 00000000800bffa2: enq 0x000000007f098060 deq 0x000000007f098050 segs 2 stream 1 free_trbs 508 bounce 1024 cycle 1
Finish URB 11a1a8 STREAM 1 (success)
kworker/0:0-3 [000] d.h1 99.076077: xhci_handle_event: EVENT: TRB 000000007f098050 status 'Success' len 0 slot 1 ep 3 type 'Transfer Event' flags e:C
kworker/0:0-3 [000] d.h1 99.076080: xhci_handle_transfer: STREAM: Buffer 00000000663a8000 length 32 TD size 0 intr 0 type 'Normal' flags b:i:I:c:s:I:e:C
kworker/0:0-3 [000] d.h1 99.076082: xhci_inc_deq: STREAM 00000000800bffa2: enq 0x000000007f098060 deq 0x000000007f098060 segs 2 stream 1 free_trbs 509 bounce 1024 cycle 1
kworker/0:0-3 [000] d.h. 99.076083: xhci_urb_giveback: ep1in-bulk: urb 000000004011a1a8 pipe 3221258880 slot 1 length 32/32 sgs 1/1
Queue URB 11a1a8 on STREAM 1 at 8060
kworker/u8:2-34 [003] d..2 99.076157: xhci_urb_enqueue: ep1in-bulk: urb 000000004011a1a8 pipe 3221258880 slot 1 length 0/64 sgs 1/1 stream 1 flags 00040200
kworker/u8:2-34 [003] d..3 99.076158: xhci_queue_trb: STREAM: Buffer 00000000663bb000 length 64 TD size 0 intr 0 type 'Normal' flags b:i:I:c:s:I:e:c
kworker/u8:2-34 [003] d..3 99.076160: xhci_inc_enq: STREAM 00000000800bffa2: enq 0x000000007f098070 deq 0x000000007f098060 segs 2 stream 1 free_trbs 508 bounce 1024 cycle 1
Queue URB 7021d on STREAM 2 at a000
kworker/0:0-3 [000] d..2 99.076204: xhci_urb_enqueue: ep1in-bulk: urb 00000000e4d7021d pipe 3221258880 slot 1 length 0/4096 sgs 1/1 stream 2 flags 00040200
kworker/0:0-3 [000] d..3 99.076207: xhci_queue_trb: STREAM: Buffer 000000007cc11000 length 4096 TD size 0 intr 0 type 'Normal' flags b:i:I:c:s:I:e:c
kworker/0:0-3 [000] d..3 99.076208: xhci_inc_enq: STREAM 000000000f29181e: enq 0x000000007f09a010 deq 0x000000007f09a000 segs 2 stream 2 free_trbs 508 bounce 1024 cycle 1
Finish URB 11a1a8 STREAM 1 (short packet, we got 54 bytes instead of asked 64)
<idle>-0 [000] d.h2 99.076223: xhci_handle_event: EVENT: TRB 000000007f098060 status 'Short Packet' len 54 slot 1 ep 3 type 'Transfer Event' flags e:C
<idle>-0 [000] d.h2 99.076227: xhci_handle_transfer: STREAM: Buffer 00000000663bb000 length 64 TD size 0 intr 0 type 'Normal' flags b:i:I:c:s:I:e:C
<idle>-0 [000] d.h2 99.076230: xhci_inc_deq: STREAM 00000000800bffa2: enq 0x000000007f098070 deq 0x000000007f098070 segs 2 stream 1 free_trbs 509 bounce 1024 cycle 1
<idle>-0 [000] d.h1 99.076231: xhci_urb_giveback: ep1in-bulk: urb 000000004011a1a8 pipe 3221258880 slot 1 length 10/64 sgs 1/1 stream 1 flags 00040200
Finish URB 7021d STREAM 2 (short packet, we got 4080 bytes instead of 4096 asked for)
<idle>-0 [000] dnH3 99.076267: xhci_handle_event: EVENT: TRB 000000007f09a000 status 'Short Packet' len 4080 slot 1 ep 3 type 'Transfer Event' flags e:C
<idle>-0 [000] dnH3 99.076269: xhci_handle_transfer: STREAM: Buffer 000000007cc11000 length 4096 TD size 0 intr 0 type 'Normal' flags b:i:I:c:s:I:e:C
<idle>-0 [000] dnH3 99.076272: xhci_inc_deq: STREAM 000000000f29181e: enq 0x000000007f09a010 deq 0x000000007f09a010 segs 2 stream 2 free_trbs 509 bounce 1024 cycle 1
<idle>-0 [000] dnH2 99.076273: xhci_urb_giveback: ep1in-bulk: urb 00000000e4d7021d pipe 3221258880 slot 1 length 16/4096 sgs 1/1 stream 2 flags 00040200
Queue URB 7021d STREAM 1 (this one never finishes)
kworker/u8:2-34 [000] d..2 99.076334: xhci_urb_enqueue: ep1in-bulk: urb 00000000e4d7021d pipe 3221258880 slot 1 length 0/64 sgs 1/1 stream 1 flags 00040200
kworker/u8:2-34 [000] d..3 99.076336: xhci_queue_trb: STREAM: Buffer 00000000663bb000 length 64 TD size 0 intr 0 type 'Normal' flags b:i:I:c:s:I:e:c
kworker/u8:2-34 [000] d..3 99.076337: xhci_inc_enq: STREAM 00000000800bffa2: enq 0x000000007f098080 deq 0x000000007f098070 segs 2 stream 1 free_trbs 508 bounce 1024 cycle 1
Finally URB 7021d is cancelled ( a lot later)
kworker/u8:0-5 [002] d..1 130.036368: xhci_urb_dequeue: ep1in-bulk: urb 00000000e4d7021d pipe 3221258880 slot 1 length 0/64 sgs 1/1 stream 1 flags 00040200
kworker/u8:0-5 [002] d..1 130.036379: xhci_dbg_cancel_urb: Cancel URB 00000000e4d7021d, dev 1, ep 0x81, starting at offset 0x7f098070
scsi_eh_0-2529 [001] d..1 130.049902: xhci_dbg_cancel_urb: Cancel URB 0000000040befd80, dev 1, ep 0x83, starting at offset 0x7f04f080
<idle>-0 [000] d.h2 130.229531: xhci_dbg_cancel_urb: Cancel URB 000000001fd28c2d, dev 1, ep 0x81, starting at offset 0x7f0cf060
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
