Re: xhci_hcd: unstable communication with Opella-XD JTAG probe
On 16.09.2015 00:06, Alexey Brodkin wrote: Hi Mathias, On Tue, 2015-09-15 at 16:18 +0300, Mathias Nyman wrote: On 10.09.2015 14:54, Alexey Brodkin wrote: I'm not sure what happens here, have you tried the 4.2 kernel? I've just tried vanilla 4.3-rc1 and see exactly the same picture. If I send additional xhci debugging patches can you apply and test them? Sure! An additional usbmon trace showing which URBs are actually sent could help. Below are simple "usbmon" outputs. If there's a need for additional options for usbmon let me know which ones I need to pass. Thanks, Looks like a we have at least one bug in how we handle short packet transfers for bulk transfer we expect to be large. The driver ask for 65664 bytes from the device, but the device only sends 73 bytes (see log below) 09c4b540 0.374261 C Bo:1:002:1 0 5 > 09c4b540 0.374312 S Bi:1:002:2 - 65664 < 09c4b540 0.374368 C Bi:1:002:2 0 73 = 0001 08200716 00100400 . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . If xhci gets less data than requested it will issue a short transfer event. But as the difference is bigger than 64k we will get this event before the last TRB of that TD, and then we will get an additional event for the actual last TRB. This doesn't yet explain the 5 seconds timeout, but it should solve the "WARN Event TRB for slot 8 ep 4 with no TDs queued?" warning. I'll scribble down a patch for this shortly -Mathias -- To unsubscribe from this list: send the line "unsubscribe linux-usb" in the body of a message to majord...@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
Re: xhci_hcd: unstable communication with Opella-XD JTAG probe
Hi Mathias,
On Tue, 2015-09-15 at 16:18 +0300, Mathias Nyman wrote:
> On 10.09.2015 14:54, Alexey Brodkin wrote:
> I'm not sure what happens here, have you tried the 4.2 kernel?
I've just tried vanilla 4.3-rc1 and see exactly the same picture.
> If I send additional xhci debugging patches can you apply and test them?
Sure!
> An additional usbmon trace showing which URBs are actually sent could help.
Below are simple "usbmon" outputs. If there's a need for additional
options for usbmon let me know which ones I need to pass.
Successful run:
--->8-
09c4b540 0.363288 S Ci:1:002:0 s 80 06 0300 00ff 255 <
09c4b540 0.363389 C Ci:1:002:0 0 4 =
04030904
09c4b540 0.363438 S Ci:1:002:0 s 80 06 0305 0409 00ff 255 <
09c4b540 0.363537 C Ci:1:002:0 0 14 =
0e033800 38003000 34003700 3500
. . 8 . 8 . 0 . 4 . 7 . 5 .
09c4b540 0.363587 S Co:1:002:0 s 00 09 0001 0
09c4b540 0.363621 C Co:1:002:0 0 0
09c4b540 0.363748 S Ci:1:002:0 s 80 06 0300 00ff 255 <
09c4b540 0.363849 C Ci:1:002:0 0 4 =
04030904
09c4b540 0.363893 S Ci:1:002:0 s 80 06 0305 0409 00ff 255 <
09c4b540 0.363993 C Ci:1:002:0 0 14 =
0e033800 38003000 34003700 3500
. . 8 . 8 . 0 . 4 . 7 . 5 .
09c4b540 0.364046 S Co:1:002:0 s 00 09 0001 0
09c4b540 0.364058 C Co:1:002:0 0 0
09c4b540 0.364124 S Bi:1:002:2 - 65664 <
09c4b540 0.374150 C Bi:1:002:2 -2 0
09c4b540 0.374248 S Bo:1:002:1 - 5 =
0b00 38
. . . . 8
09c4b540 0.374261 C Bo:1:002:1 0 5 >
09c4b540 0.374312 S Bi:1:002:2 - 65664 <
09c4b540 0.374368 C Bi:1:002:2 0 73 =
0001 08200716 00100400
. . . . . . . . . . . . . . . . . . . . . . . . . . . . . . .
09c4b540 0.374434 S Bo:1:002:1 - 5 =
0c00 00
09c4b540 0.374449 C Bo:1:002:1 0 5 >
09c4b540 0.374488 S Bi:1:002:2 - 65664 <
09c4b540 0.374498 C Bi:1:002:2 0 21 =
00010101 12201220 18420100 00
. . . . . . . . . .. B . . . . . . .
09c4b540 0.374552 S Bo:1:002:1 - 5 =
0d00 00
09c4b540 0.374561 C Bo:1:002:1 0 5 >
09c4b540 0.374597 S Bi:1:002:2 - 65664 <
09c4b540 0.374605 C Bi:1:002:2 0 37 =
--->8-
Failed run:
--->8-
081ade40 5.512105 S Ci:1:002:0 s 80 06 0300 00ff 255 <
081ade40 5.514388 C Ci:1:002:0 0 4 =
04030904
c92cda80 5.514417 S Ci:1:002:0 s 80 06 0305 0409 00ff 255 <
c92cda80 5.514492 C Ci:1:002:0 0 14 =
0e033800 38003000 34003700 3500
. . 8 . 8 . 0 . 4 . 7 . 5 .
0a6aef00 5.516150 S Co:1:002:0 s 00 09 0001 0
0a6aef00 5.516167 C Co:1:002:0 0 0
0a6ae780 5.516289 S Ci:1:002:0 s 80 06 0300 00ff 255 <
0a6ae780 5.516366 C Ci:1:002:0 0 4 =
04030904
0a6ae780 5.516380 S Ci:1:002:0 s 80 06 0305 0409 00ff 255 <
0a6ae780 5.516454 C Ci:1:002:0 0 14 =
0e033800 38003000 34003700 3500
. . 8 . 8 . 0 . 4 . 7 . 5 .
0a6ae780 5.516466 S Co:1:002:0 s 00 09 0001 0
0a6ae780 5.516494 C Co:1:002:0 0 0
0a6ae780 5.516525 S Bi:1:002:2 - 65664 <
0a6ae780 5.526555 C Bi:1:002:2 -2 0
0a6ae780 5.526590 S Bo:1:002:1 - 5 =
0b00 38
. . . . 8
0a6ae780 5.526604 C Bo:1:002:1 0 5 >
0a6ae780 5.526637 S Bi:1:002:2 - 65664 <
< 5 seconds delay>
0a6ae780 10.526672 C Bi:1:002:2 -2 0
c92cd3c0 10.526789 S Bo:1:002:1 - 5 =
0c00 38
. . . . 8
c92cd3c0 10.526802 C Bo:1:002:1 0 5 >
c92cd3c0 10.526833 S Bi:1:002:2 - 65664 <
< 5 seconds delay>
c92cd3c0 15.526862 C Bi:1:002:2 -2 0
08fa46c0 15.526975 S Bo:1:002:1 - 5 =
0d00 38
. . . . 8
08fa46c0 15.526989 C Bo:1:002:1 0 5 >
08fa46c0 15.527034 S Bi:1:002:2 - 65664 <
08fa46c0 15.527045 C Bi:1:002:2 0 37 =
--->8-\
-Alexey--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Re: xhci_hcd: unstable communication with Opella-XD JTAG probe
On 10.09.2015 14:54, Alexey Brodkin wrote: Hello, I'm seeing a problem when attaching USB device (in my case Ashling Opella-XD JTAG probe) in Dell e7440 laptop if USB 3.0 is enable in BIOS. If I disable USB 3.0 in BIOS the same device works perfectly fine. What's also interesting on my previous laptop (it was HP Elitebook something) I saw the same device working fine even if plugged in USB 3.0 port (essentially USB 3.0 was enabled in BIOS as well). And essentially that same device works on the same Laptop in Windows 7. I run very simple utility that just reads some basic information from my JTAG probe like serial number, firmware version etc. And I see it succeeds every second run. I'm not sure what happens here, have you tried the 4.2 kernel? If I send additional xhci debugging patches can you apply and test them? An additional usbmon trace showing which URBs are actually sent could help. Below is a description on what the log says, mostly just notes for myself to keep track of this. Both the succeeding and failing case have the errors: WARN Event TRB for slot 8 ep 4 with no TDs queued which Starting point in both cases is probably that there are a few URBs queued, (seems to be 5 TRB long URBs) In the successful case, the first URB at xx500 is canceled, we correctly jumps to the next one five TRBs later, at 550: (Successful Set TR Deq Ptr cmd, deq = @3cd8fd550) Then xhci triggers an event saying a transfer was short, (ID 32) not all data was tranferred, the event is for TRB at 590 ( this would be the last TRB of the five long URB starting at 550, makes sense) xhci driver can't find a TD (URB) queued on the endpoint ring that would contain the TRB at 550, this should not happend. Ring keeps running anyway, and we get these short packet events and life goes on. In the failing case, it seems that ring stops running after canceling the first URB (or is never restarted after ring is stopped to remove TRBs in the canceled URB). Driver probably times out 5 seconds later as a queued URB never retuens to the driver, and the diver cancels the URB, This is repeated. 1. the URBs are probably queued to ring as the short packet Event TRB makes sense. Is the TD missing from our list, or is there some bug in the comparison, or is this some additional event and URB is already handled, make a patch that dumps both event and transfer rings when the event with out TD case is hit. 2. Why does the ring not start in some cases? do we think it's empty, race? -Mathias -- To unsubscribe from this list: send the line "unsubscribe linux-usb" in the body of a message to majord...@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
