On 2018-04-17 18:04, Mathias Nyman wrote:
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.
yea, but stream 1 will finish once you receive DATA-IN, SENSE_IU. I mean
it will
success (as per UASP Rev 1.0). As from the logs we could not see such
completion.
So we need to check what is causing this not to complete ? how?
Want to add one more thing...
UASP spec, UASP Rev 1.0 5.4.3 says
"In response to the ERDY (Data-in) the xHCI controller sends an IN ACK
(Data-in)
to the device with the SID set to the ERDY Tag value."
As per UAS spec. device will send DATA-IN once he has data for
COMMAND_IU and later it
will send SENSE_IU with same uas-tag as COMMAND_IU. In this case device
is sending
the ERDY(Data-in) on ep1 after device receiving COMMAND_IU, post to that
there should be IN-ACK saying NUMp > 0...
Which I could not see. And timeout happened.
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."
no idea on this :(
Stream protocol states and current stream (cstream) are not visible to
xhci driver.
Details of URBs in xhci:
Thanks a lot for this, Mathias :)
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
Oliver/Greg,
Weather you are able to reproduce the issue?
Did you tested it on dwc3 previously?
--
Best Regards,
Tushar R Nimkar
QUALCOMM INDIA, on behalf of Qualcomm Innovation Center, Inc. is a
member of Code Aurora Forum, hosted by The Linux Foundation
--
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
