Hi,
I am using “3.1.0-7.fc16.x86_64” kernel and testing eight USB
Bluetooth dongles using btusb.ko module.
Once I power-on the system and loading the btusb.ko driver immediately
results the below mentioned errors:
[ 1389.410907] hci3 urb ffff88012954dd80 status -32 count 0
[ 1389.411367] hci4 urb ffff88012954d3c0 status -32 count 0
[ 1389.411845] hci1 urb ffff88012b4b6b40 status -32 count 0
[ 1389.412238] hci2 urb ffff8801347ee0c0 status -32 count 0
[ 1518.647255] hci3 urb ffff88012954dd80 status -32 count 0
[ 1518.647722] hci4 urb ffff88012954d3c0 status -32 count 0
[ 1518.648120] hci1 urb ffff88012b4b6b40 status -32 count 0
[ 1518.648514] hci2 urb ffff8801347ee0c0 status -32 count 0
[ 1518.722033] hci2 urb ffff8801347ee0c0 status -32 count 0
[ 2191.964545] hci4 urb ffff88012954d3c0 status -32 count 0
[ 2191.965001] hci1 urb ffff88012b4b6b40 status -32 count 0
[ 2191.965396] hci2 urb ffff8801347ee0c0 status -32 count 0
[ 2191.966530] hci2 urb ffff8801347ee0c0 status -32 count 0
[ 2191.975514] hci4 urb ffff88012954d3c0 status -32 count 0
[ 2191.975936] hci1 urb ffff88012b4b6b40 status -32 count 0
[ 2191.976330] hci2 urb ffff8801347ee0c0 status -32 count 0
[ 2191.977503] hci4 urb ffff88012954d3c0 status -32 count 0
[ 2191.977929] hci1 urb ffff88012b4b6b40 status -32 count 0
[ 2191.978325] hci2 urb ffff8801347ee0c0 status -32 count 0
[ 2560.132682] hci2 urb ffff8801347ee0c0 status -32 count 0
[ 2569.160895] hci4 urb ffff88012954d3c0 status -32 count 0
[ 2569.161367] hci1 urb ffff88012b4b6b40 status -32 count 0
[ 2569.161827] hci2 urb ffff8801347ee0c0 status -32 count 0
[ 3022.252541] hci2 urb ffff8801347ee0c0 status -32 count 0
[ 3022.254504] hci2 urb ffff8801347ee0c0 status -32 count 0
These errors will repeat until sending a proper HCI command on the USB
bus. Again after some time duration same error will repeats.
The error -32(-EPIPE) says , Endpoint stalled. For non-control
endpoints, reset this status with usb_clear_halt().
But I don’t see the error(-EPIPE) handling code in btusb module. Does
anyone has the patch for this scenario?
Thanks,
Naveen
On Tue, 11 Nov 2014, Naveen Kumar Parna wrote:
> I am really glad we reached to a conclusion on this.
> Thanks for all your help, without which I could not have seen this through.
You're welcome.
> Now I am confronted with many of these controllers in my lab, with
> this hardware issue.
> I am not sure I can find a better way than just to tell people to replace them.
You could try contacting the manufacturer to see if they are aware of
this problem and have any suggestions.
Alan Stern
On Mon, Nov 10, 2014 at 10:26 PM, Alan Stern <[email protected]> wrote:
> On Mon, 10 Nov 2014, Naveen Kumar Parna wrote:
>
>> I am sorry for the late response.
>>
>> I applied the patch and here is the dmesg log:
>>
>> [ 713.125709] ehci-pci 0000:00:1a.0: split intr info2 42821c01 token
>> 80108d46 overlay token 80108d46
>> [ 713.125796] ehci-pci 0000:00:1a.0: split intr info2 42821c01 token
>> 80108d46 overlay token 80108d46
>> [ 713.125853] hci4 urb ffff8800b89a7c00 status -32 count 0
>> [ 713.125857] hci3 urb ffff8800b7399c00 status -32 count 0
>
>> Does it gives the reason for -32 status code?
>
> More or less. The last (status) byte in the "token" values is 0x46,
> and the 0x04 status bit is documented in the EHCI spec as follows:
>
> Missed Micro-Frame. This bit is ignored unless the QH.EPS field
> indicates a full- or low-speed endpoint and the queue head is
> in the periodic list. This bit is set when the host controller
> detected that a host-induced hold-off caused the host
> controller to miss a required complete-split transaction. If the
> host controller sets this bit to a one, then it remains a one
> for the duration of thetransfer.
>
> This means the host controller is telling you it was unable to carry
> out the CSPLIT part of the transaction, which means it really is a
> hardware problem (and not a bad memory chip). Either the controller
> isn't working right or else your system is somehow overloaded.
>
> The 0x42 bits indicate that the Queue Head was halted and a CSPLIT is
> pending (which we already knew). The "halted" status bit is the reason
> why you got a -32 status code.
>
> Alan Stern
>
I am really glad we reached to a conclusion on this.
Thanks for all your help, without which I could not have seen this through.
Now I am confronted with many of these controllers in my lab, with
this hardware issue.
I am not sure I can find a better way than just to tell people to replace them.
Thanks,
Naveen
On Mon, 10 Nov 2014, Naveen Kumar Parna wrote:
> I am sorry for the late response.
>
> I applied the patch and here is the dmesg log:
>
> [ 713.125709] ehci-pci 0000:00:1a.0: split intr info2 42821c01 token
> 80108d46 overlay token 80108d46
> [ 713.125796] ehci-pci 0000:00:1a.0: split intr info2 42821c01 token
> 80108d46 overlay token 80108d46
> [ 713.125853] hci4 urb ffff8800b89a7c00 status -32 count 0
> [ 713.125857] hci3 urb ffff8800b7399c00 status -32 count 0
> Does it gives the reason for -32 status code?
More or less. The last (status) byte in the "token" values is 0x46,
and the 0x04 status bit is documented in the EHCI spec as follows:
Missed Micro-Frame. This bit is ignored unless the QH.EPS field
indicates a full- or low-speed endpoint and the queue head is
in the periodic list. This bit is set when the host controller
detected that a host-induced hold-off caused the host
controller to miss a required complete-split transaction. If the
host controller sets this bit to a one, then it remains a one
for the duration of thetransfer.
This means the host controller is telling you it was unable to carry
out the CSPLIT part of the transaction, which means it really is a
hardware problem (and not a bad memory chip). Either the controller
isn't working right or else your system is somehow overloaded.
The 0x42 bits indicate that the Queue Head was halted and a CSPLIT is
pending (which we already knew). The "halted" status bit is the reason
why you got a -32 status code.
Alan Stern
On Thu, Nov 6, 2014 at 10:14 PM, Alan Stern <[email protected]> wrote:
> On Thu, 6 Nov 2014, Naveen Kumar Parna wrote:
>
>> > Any idea why you see the CSPLITs now but didn't see them before?
>>
>> It looks like , I failed to locate the exact portion of the analyzer
>> log that corresponds to one of those -32 events in the usbmon log.
>
> Well, I still don't understand that, but never mind...
>
>> USB Analyzer records several megabytes of data very quickly, so it’s
>> very hard to find the portion of the analyzer log that corresponds to
>> one of those -32 events in the usbmon log. To avoid this difficulty I
>> applied the attached patch
>> (0002-btusb-clear-halt-if-intr-in-stalls.patch – got it from Oliver
>> Neukum) to btusb driver and reloaded this driver.
>>
>> The applied patch calls usb_clear_halt() on receiving the stall
>> response, so now I can easily search for ClearFeature(ENDPOINT_HALT)
>> request in the analyzer log. It can be found at "2.304 252 217" &
>> "2.316 264 600" time instance in the attached log.
>>
>> Re ran the Analyzer again and attached it’s exported text
>> log([2014-11-06 session 125138] Trace0000_only_ep0_ep1.txt). Here
>> filtered out the BulkIN transactions.
>>
>> usbmon log:
>> ffff8800b7670a80 506095728 C Ii:1:108:1 -32:1 0
>> ffff8800affdccc0 506107757 C Ii:1:108:1 -32:1 0
>
>> Here is the portion of the log that corresponds to “ffff8800b7670a80
>> 506095728 C Ii:1:108:1 -32:1 0”:
>>
>> Start of Frame (6) HS 553.2 -> 553.7 2.302 964 717
>> SSPLIT IN transaction 105 1 HS No data 2.303 590 367
>> SSPLIT IN transaction 106 1 HS No data 2.303 591 283
>> SSPLIT IN transaction 107 1 HS No data 2.303 600 283
>> SSPLIT IN transaction 108 1 HS No data 2.303 601 350
>> Start of Frame (2) HS 554.0 -> 554.1 2.303 714 817
>> CSPLIT IN transaction 105 1 NAK HS No data 2.303 840 400
>> CSPLIT IN transaction 106 1 NAK HS No data 2.303 842 033
>> CSPLIT IN transaction 107 1 NAK HS No data 2.303 855 317
>> Start of Frame (3) HS 554.2 -> 554.4 2.303 964 850
>
> Obviously, there aren't any CSPLITs for device 108 ep 1.
>
>> Here is the portion of the log that corresponds to “ffff8800affdccc0
>> 506107757 C Ii:1:108:1 -32:1 0":
>>
>> Start of Frame (6) HS 565.2 -> 565.7 2.314 966 383
>> SSPLIT IN transaction 105 1 HS No data 2.315 592 033
>> SSPLIT IN transaction 106 1 HS No data 2.315 592 967
>> SSPLIT IN transaction 107 1 HS No data 2.315 612 800
>> SSPLIT IN transaction 108 1 HS No data 2.315 613 850
>> Start of Frame (2) HS 566.0 -> 566.1 2.315 716 483
>> CSPLIT IN transaction 105 1 NAK HS No data 2.315 842 067
>> CSPLIT IN transaction 106 1 NAK HS No data 2.315 843 683
>> CSPLIT IN transaction 107 1 NAK HS No data 2.315 928 750
>> Start of Frame (3) HS 566.2 -> 566.4 2.315 966 517
>
>> In both the cases, CSPLIT of Dev-108 is missing in this portion of the log.
>>
>> So, Does this test log gives some conclusion?
>
> It indicates that the EHCI host controller hardware isn't working
> right. Every now and then it skips sending CSPLIT packets when it
> should send them.
>
> I suppose it's possible that the host controller is okay and the
> problem is a bad memory chip. That could also cause this sort of
> error. Regardless, it has to be a hardware problem.
Is there any test I can run to prove that memory chip is bad?
>
> Now, this doesn't explain why you get the -32 status code. Maybe the
> patch below will provide more information. Try running your test with
> this patch installed and see what shows up in the dmesg log.
>
> Alan Stern
>
>
>
> Index: usb-3.18/drivers/usb/host/ehci-q.c
> ===================================================================
> --- usb-3.18.orig/drivers/usb/host/ehci-q.c
> +++ usb-3.18/drivers/usb/host/ehci-q.c
> @@ -346,6 +346,12 @@ qh_completions (struct ehci_hcd *ehci, s
> /* always clean up qtds the hc de-activated */
> retry_xacterr:
> if ((token & QTD_STS_ACTIVE) == 0) {
> + u32 info2 = hc32_to_cpu(ehci, hw->hw_info2);
> +
> + if ((info2 & QH_SMASK) && (token & 0x7e))
> + ehci_info(ehci, "split intr info2 %x token %x overlay token %x\n",
> + info2, token, hc32_to_cpu(ehci,
> + hw->hw_token));
>
> /* Report Data Buffer Error: non-fatal but useful */
> if (token & QTD_STS_DBE)
>
Here is the dmesg log:
[ 713.125709] ehci-pci 0000:00:1a.0: split intr info2 42821c01 token
80108d46 overlay token 80108d46
[ 713.125796] ehci-pci 0000:00:1a.0: split intr info2 42821c01 token
80108d46 overlay token 80108d46
[ 713.125853] hci4 urb ffff8800b89a7c00 status -32 count 0
[ 713.125857] hci3 urb ffff8800b7399c00 status -32 count 0
[ 713.126801] hci4
[ 713.127003] hci3
[ 3046.032153] ehci-pci 0000:00:1a.0: split intr info2 42821c01 token
108d46 overlay token 108d46
[ 3046.032227] ehci-pci 0000:00:1a.0: split intr info2 42821c01 token
108d46 overlay token 108d46
[ 3046.032272] hci3 urb ffff8800b30f5a80 status -32 count 0
[ 3046.032278] hci4 urb ffff8800b30f53c0 status -32 count 0
[ 3046.033326] hci4
[ 3046.033344] hci3
[ 3586.175590] ehci-pci 0000:00:1a.0: split intr info2 42821c01 token
108d46 overlay token 108d46
[ 3586.175698] ehci-pci 0000:00:1a.0: split intr info2 42821c01 token
108d46 overlay token 108d46
[ 3586.175759] hci4 urb ffff8800b8a64a80 status -32 count 0
[ 3586.175766] hci3 urb ffff8800b8a64cc0 status -32 count 0
[ 3586.176625] hci4
[ 3586.177000] hci3
[ 4310.473875] ehci-pci 0000:00:1a.0: split intr info2 42821c01 token
108d46 overlay token 108d46
[ 4310.473972] ehci-pci 0000:00:1a.0: split intr info2 42821c01 token
108d46 overlay token 108d46
[ 4310.474019] hci3 urb ffff8800b3099c00 status -32 count 0
[ 4310.474023] hci4 urb ffff8800b3099480 status -32 count 0
[ 4310.474912] hci3
[ 4310.475027] hci4
[ 4313.710199] ehci-pci 0000:00:1a.0: split intr info2 42821c01 token
108d46 overlay token 108d46
[ 4313.710325] hci4 urb ffff8800b8012a80 status -32 count 0
[ 4313.711207] hci4
[ 4314.722302] ehci-pci 0000:00:1a.0: split intr info2 42821c01 token
108d46 overlay token 108d46
[ 4314.722359] hci4 urb ffff8800b8012a80 status -32 count 0
[ 4314.723472] hci4
[ 5210.940319] ehci-pci 0000:00:1a.0: split intr info2 42821c01 token
108d46 overlay token 108d46
[ 5210.940423] ehci-pci 0000:00:1a.0: split intr info2 42821c01 token
108d46 overlay token 108d46
[ 5210.940471] hci4 urb ffff8800b8012a80 status -32 count 0
[ 5210.940475] hci3 urb ffff8800b8012180 status -32 count 0
[ 5210.941309] hci4
[ 5210.941703] hci3
[ 5211.464329] ehci-pci 0000:00:1a.0: split intr info2 42821c01 token
108d46 overlay token 108d46
[ 5211.464437] ehci-pci 0000:00:1a.0: split intr info2 42821c01 token
108d46 overlay token 108d46
[ 5211.464490] hci3 urb ffff8800b8bb9000 status -32 count 0
[ 5211.464493] hci4 urb ffff8800b8bb90c0 status -32 count 0
[ 5211.465367] hci4
[ 5211.465383] hci3
[ 5211.508336] ehci-pci 0000:00:1a.0: split intr info2 42821c01 token
108d46 overlay token 108d46
[ 5211.508426] ehci-pci 0000:00:1a.0: split intr info2 42821c01 token
108d46 overlay token 108d46
[ 5211.508469] hci4 urb ffff8800b8bb9000 status -32 count 0
[ 5211.508472] hci3 urb ffff8800b8bb90c0 status -32 count 0
[ 5211.509375] hci3
[ 5211.509390] hci4
[ 5212.144419] ehci-pci 0000:00:1a.0: split intr info2 42821c01 token
108d46 overlay token 108d46
[ 5212.144500] ehci-pci 0000:00:1a.0: split intr info2 42821c01 token
108d46 overlay token 108d46
[ 5212.144539] ehci-pci 0000:00:1a.0: split intr info2 42821c01 token
80108d46 overlay token 80108d46
[ 5212.144598] hci3 urb ffff8800b8bb9000 status -32 count 0
[ 5212.144603] hci4 urb ffff8800b8bb90c0 status -32 count 0
[ 5212.144605] hci2 urb ffff8800b7399600 status -32 count 0
[ 5212.145406] hci3
[ 5212.145685] hci4
[ 5212.145697] hci2
[ 5212.284485] ehci-pci 0000:00:1a.0: split intr info2 42821c01 token
108d46 overlay token 108d46
[ 5212.284603] hci2 urb ffff8800b8bb9180 status -32 count 0
[ 5212.285452] hci2
[ 5213.084540] ehci-pci 0000:00:1a.0: split intr info2 42821c01 token
108d46 overlay token 108d46
[ 5213.084660] hci2 urb ffff8800b8bb9180 status -32 count 0
[ 5213.085778] hci2
[ 5213.996615] ehci-pci 0000:00:1a.0: split intr info2 42821c01 token
108d46 overlay token 108d46
[ 5213.996763] hci2 urb ffff8800b8bb9180 status -32 count 0
[ 5214.000391] hci2
[ 5216.156816] ehci-pci 0000:00:1a.0: split intr info2 42821c01 token
108d46 overlay token 108d46
[ 5216.156939] hci2 urb ffff8800b8bb9180 status -32 count 0
[ 5216.157807] hci2
[ 5741.146808] ehci-pci 0000:00:1a.0: split intr info2 42821c01 token
108d46 overlay token 108d46
[ 5741.146906] ehci-pci 0000:00:1a.0: split intr info2 42821c01 token
108d46 overlay token 108d46
[ 5741.146946] ehci-pci 0000:00:1a.0: split intr info2 42821c01 token
108d46 overlay token 108d46
[ 5741.146994] hci2 urb ffff8800b8bb9180 status -32 count 0
[ 5741.146998] hci4 urb ffff8800b8bb9000 status -32 count 0
[ 5741.147001] hci3 urb ffff8800b8bb90c0 status -32 count 0
[ 5741.147807] hci2
[ 5741.148068] hci3
[ 5741.148204] hci4
[ 8327.577511] ehci-pci 0000:00:1a.0: split intr info2 42821c01 token
108d46 overlay token 108d46
[ 8327.577600] ehci-pci 0000:00:1a.0: split intr info2 42821c01 token
108d46 overlay token 108d46
[ 8327.577639] ehci-pci 0000:00:1a.0: split intr info2 42821c01 token
108d46 overlay token 108d46
[ 8327.577690] hci3 urb ffff8800b8bb9d80 status -32 count 0
[ 8327.577695] hci4 urb ffff8800b8bb9180 status -32 count 0
[ 8327.577697] hci2 urb ffff8800b8bb90c0 status -32 count 0
[ 8327.578683] hci4
[ 8327.578698] hci2
[ 8327.581162] hci3
[ 9347.950892] ehci-pci 0000:00:1a.0: split intr info2 42821c01 token
108d46 overlay token 108d46
[ 9347.951007] ehci-pci 0000:00:1a.0: split intr info2 42821c01 token
108d46 overlay token 108d46
[ 9347.951046] ehci-pci 0000:00:1a.0: split intr info2 42821c01 token
108d46 overlay token 108d46
[ 9347.951108] hci2 urb ffff8801399bf600 status -32 count 0
[ 9347.951113] hci4 urb ffff8801399bff00 status -32 count 0
[ 9347.951115] hci3 urb ffff8801399bf6c0 status -32 count 0
[ 9347.952070] hci2
[ 9347.952307] hci4
[ 9347.952422] hci3
[10016.619096] ehci-pci 0000:00:1a.0: split intr info2 42821c01 token
108d46 overlay token 108d46
[10016.619188] ehci-pci 0000:00:1a.0: split intr info2 42821c01 token
108d46 overlay token 108d46
[10016.619227] ehci-pci 0000:00:1a.0: split intr info2 42821c01 token
108d46 overlay token 108d46
[10016.619288] hci3 urb ffff8800b4097000 status -32 count 0
[10016.619293] hci4 urb ffff8800b4097240 status -32 count 0
[10016.619295] hci2 urb ffff8800b4097480 status -32 count 0
[10016.620257] hci4
[10016.620273] hci2
[10016.625393] hci3
[10016.663094] ehci-pci 0000:00:1a.0: split intr info2 42821c01 token
108d46 overlay token 108d46
[10016.663178] ehci-pci 0000:00:1a.0: split intr info2 42821c01 token
108d46 overlay token 108d46
[10016.663228] hci3 urb ffff8800371c1900 status -32 count 0
[10016.663233] hci2 urb ffff8800371c1cc0 status -32 count 0
[10016.664152] hci3
[10016.664162] hci2
[10016.683124] ehci-pci 0000:00:1a.0: split intr info2 42821c01 token
108d46 overlay token 108d46
[10016.683200] ehci-pci 0000:00:1a.0: split intr info2 42821c01 token
108d46 overlay token 108d46
[10016.683239] ehci-pci 0000:00:1a.0: split intr info2 42821c01 token
108d46 overlay token 108d46
[10016.683289] hci2 urb ffff8800371c1900 status -32 count 0
[10016.683293] hci3 urb ffff8800371c1cc0 status -32 count 0
[10016.683295] hci4 urb ffff8800371c1000 status -32 count 0
[10016.684132] hci4
[10016.684139] hci3
[10016.684144] hci2
[10366.025162] ehci-pci 0000:00:1a.0: split intr info2 42821c01 token
108d46 overlay token 108d46
[10366.025240] ehci-pci 0000:00:1a.0: split intr info2 42821c01 token
108d46 overlay token 108d46
[10366.025280] ehci-pci 0000:00:1a.0: split intr info2 42821c01 token
108d46 overlay token 108d46
[10366.025332] hci4 urb ffff8800371c1900 status -32 count 0
[10366.025336] hci3 urb ffff8800371c1cc0 status -32 count 0
[10366.025339] hci2 urb ffff8800371c1000 status -32 count 0
[10366.026485] hci3
[10366.026502] hci4
[10366.026565] hci2
[11095.765903] ehci-pci 0000:00:1a.0: split intr info2 42821c01 token
108d46 overlay token 108d46
[11095.765981] ehci-pci 0000:00:1a.0: split intr info2 42821c01 token
108d46 overlay token 108d46
[11095.766021] ehci-pci 0000:00:1a.0: split intr info2 42821c01 token
108d46 overlay token 108d46
[11095.766085] hci2 urb ffff8800372ad9c0 status -32 count 0
[11095.766090] hci3 urb ffff8800372ad6c0 status -32 count 0
[11095.766092] hci4 urb ffff8800372ad240 status -32 count 0
[11095.767016] hci2
[11095.767032] hci3
[11095.767043] hci4
[11527.042340] ehci-pci 0000:00:1a.0: split intr info2 42821c01 token
108d46 overlay token 108d46
[11527.042425] ehci-pci 0000:00:1a.0: split intr info2 42821c01 token
108d46 overlay token 108d46
[11527.042464] ehci-pci 0000:00:1a.0: split intr info2 42821c01 token
108d46 overlay token 108d46
[11527.042516] hci4 urb ffff8800aed34780 status -32 count 0
[11527.042520] hci3 urb ffff8800aed34c00 status -32 count 0
[11527.042522] hci2 urb ffff8800aed343c0 status -32 count 0
[11527.043377] hci4
[11527.043479] hci3
[11527.043983] hci2
[11716.767697] ehci-pci 0000:00:1a.0: split intr info2 42821c01 token
108d46 overlay token 108d46
[11716.767769] ehci-pci 0000:00:1a.0: split intr info2 42821c01 token
108d46 overlay token 108d46
[11716.767816] hci2 urb ffff8800b88be840 status -32 count 0
[11716.767820] hci3 urb ffff8800b88bed80 status -32 count 0
[11716.768712] hci3
[11716.768721] hci2
[11816.865884] ehci-pci 0000:00:1a.0: split intr info2 42821c01 token
108d46 overlay token 108d46
[11816.865964] ehci-pci 0000:00:1a.0: split intr info2 42821c01 token
108d46 overlay token 108d46
[11816.866003] ehci-pci 0000:00:1a.0: split intr info2 42821c01 token
108d46 overlay token 108d46
[11816.866058] hci3 urb ffff8800b88be840 status -32 count 0
[11816.866063] hci2 urb ffff8800b88bed80 status -32 count 0
[11816.866065] hci4 urb ffff8800b88bea80 status -32 count 0
[11816.867026] hci2
[11816.867112] hci3
[11816.869653] hci4
[11816.877845] ehci-pci 0000:00:1a.0: split intr info2 42821c01 token
108d46 overlay token 108d46
[11816.877950] ehci-pci 0000:00:1a.0: split intr info2 42821c01 token
108d46 overlay token 108d46
[11816.877994] ehci-pci 0000:00:1a.0: split intr info2 42821c01 token
108d46 overlay token 108d46
[11816.878058] hci4 urb ffff8800b88be840 status -32 count 0
[11816.878062] hci2 urb ffff8800b88bed80 status -32 count 0
[11816.878064] hci3 urb ffff8800b88bea80 status -32 count 0
[11816.878885] hci2
[11816.878901] hci4
[11816.878910] hci3
Thanks,
Naveen
I am sorry for the late response.
I applied the patch and here is the dmesg log:
[ 713.125709] ehci-pci 0000:00:1a.0: split intr info2 42821c01 token
80108d46 overlay token 80108d46
[ 713.125796] ehci-pci 0000:00:1a.0: split intr info2 42821c01 token
80108d46 overlay token 80108d46
[ 713.125853] hci4 urb ffff8800b89a7c00 status -32 count 0
[ 713.125857] hci3 urb ffff8800b7399c00 status -32 count 0
[ 713.126801] hci4
[ 713.127003] hci3
[ 3046.032153] ehci-pci 0000:00:1a.0: split intr info2 42821c01 token
108d46 overlay token 108d46
[ 3046.032227] ehci-pci 0000:00:1a.0: split intr info2 42821c01 token
108d46 overlay token 108d46
[ 3046.032272] hci3 urb ffff8800b30f5a80 status -32 count 0
[ 3046.032278] hci4 urb ffff8800b30f53c0 status -32 count 0
[ 3046.033326] hci4
[ 3046.033344] hci3
Does it gives the reason for -32 status code?
Thanks,
Naveen
On Thu, Nov 6, 2014 at 10:14 PM, Alan Stern <[email protected]> wrote:
> On Thu, 6 Nov 2014, Naveen Kumar Parna wrote:
>
>> > Any idea why you see the CSPLITs now but didn't see them before?
>>
>> It looks like , I failed to locate the exact portion of the analyzer
>> log that corresponds to one of those -32 events in the usbmon log.
>
> Well, I still don't understand that, but never mind...
>
>> USB Analyzer records several megabytes of data very quickly, so it’s
>> very hard to find the portion of the analyzer log that corresponds to
>> one of those -32 events in the usbmon log. To avoid this difficulty I
>> applied the attached patch
>> (0002-btusb-clear-halt-if-intr-in-stalls.patch – got it from Oliver
>> Neukum) to btusb driver and reloaded this driver.
>>
>> The applied patch calls usb_clear_halt() on receiving the stall
>> response, so now I can easily search for ClearFeature(ENDPOINT_HALT)
>> request in the analyzer log. It can be found at "2.304 252 217" &
>> "2.316 264 600" time instance in the attached log.
>>
>> Re ran the Analyzer again and attached it’s exported text
>> log([2014-11-06 session 125138] Trace0000_only_ep0_ep1.txt). Here
>> filtered out the BulkIN transactions.
>>
>> usbmon log:
>> ffff8800b7670a80 506095728 C Ii:1:108:1 -32:1 0
>> ffff8800affdccc0 506107757 C Ii:1:108:1 -32:1 0
>
>> Here is the portion of the log that corresponds to “ffff8800b7670a80
>> 506095728 C Ii:1:108:1 -32:1 0”:
>>
>> Start of Frame (6) HS 553.2 -> 553.7 2.302 964 717
>> SSPLIT IN transaction 105 1 HS No data 2.303 590 367
>> SSPLIT IN transaction 106 1 HS No data 2.303 591 283
>> SSPLIT IN transaction 107 1 HS No data 2.303 600 283
>> SSPLIT IN transaction 108 1 HS No data 2.303 601 350
>> Start of Frame (2) HS 554.0 -> 554.1 2.303 714 817
>> CSPLIT IN transaction 105 1 NAK HS No data 2.303 840 400
>> CSPLIT IN transaction 106 1 NAK HS No data 2.303 842 033
>> CSPLIT IN transaction 107 1 NAK HS No data 2.303 855 317
>> Start of Frame (3) HS 554.2 -> 554.4 2.303 964 850
>
> Obviously, there aren't any CSPLITs for device 108 ep 1.
>
>> Here is the portion of the log that corresponds to “ffff8800affdccc0
>> 506107757 C Ii:1:108:1 -32:1 0":
>>
>> Start of Frame (6) HS 565.2 -> 565.7 2.314 966 383
>> SSPLIT IN transaction 105 1 HS No data 2.315 592 033
>> SSPLIT IN transaction 106 1 HS No data 2.315 592 967
>> SSPLIT IN transaction 107 1 HS No data 2.315 612 800
>> SSPLIT IN transaction 108 1 HS No data 2.315 613 850
>> Start of Frame (2) HS 566.0 -> 566.1 2.315 716 483
>> CSPLIT IN transaction 105 1 NAK HS No data 2.315 842 067
>> CSPLIT IN transaction 106 1 NAK HS No data 2.315 843 683
>> CSPLIT IN transaction 107 1 NAK HS No data 2.315 928 750
>> Start of Frame (3) HS 566.2 -> 566.4 2.315 966 517
>
>> In both the cases, CSPLIT of Dev-108 is missing in this portion of the log.
>>
>> So, Does this test log gives some conclusion?
>
> It indicates that the EHCI host controller hardware isn't working
> right. Every now and then it skips sending CSPLIT packets when it
> should send them.
>
> I suppose it's possible that the host controller is okay and the
> problem is a bad memory chip. That could also cause this sort of
> error. Regardless, it has to be a hardware problem.
>
> Now, this doesn't explain why you get the -32 status code. Maybe the
> patch below will provide more information. Try running your test with
> this patch installed and see what shows up in the dmesg log.
>
> Alan Stern
>
>
>
> Index: usb-3.18/drivers/usb/host/ehci-q.c
> ===================================================================
> --- usb-3.18.orig/drivers/usb/host/ehci-q.c
> +++ usb-3.18/drivers/usb/host/ehci-q.c
> @@ -346,6 +346,12 @@ qh_completions (struct ehci_hcd *ehci, s
> /* always clean up qtds the hc de-activated */
> retry_xacterr:
> if ((token & QTD_STS_ACTIVE) == 0) {
> + u32 info2 = hc32_to_cpu(ehci, hw->hw_info2);
> +
> + if ((info2 & QH_SMASK) && (token & 0x7e))
> + ehci_info(ehci, "split intr info2 %x token %x overlay token %x\n",
> + info2, token, hc32_to_cpu(ehci,
> + hw->hw_token));
>
> /* Report Data Buffer Error: non-fatal but useful */
> if (token & QTD_STS_DBE)
>
On Thu, 6 Nov 2014, Naveen Kumar Parna wrote:
> > Any idea why you see the CSPLITs now but didn't see them before?
>
> It looks like , I failed to locate the exact portion of the analyzer
> log that corresponds to one of those -32 events in the usbmon log.
Well, I still don't understand that, but never mind...
> USB Analyzer records several megabytes of data very quickly, so it’s
> very hard to find the portion of the analyzer log that corresponds to
> one of those -32 events in the usbmon log. To avoid this difficulty I
> applied the attached patch
> (0002-btusb-clear-halt-if-intr-in-stalls.patch – got it from Oliver
> Neukum) to btusb driver and reloaded this driver.
>
> The applied patch calls usb_clear_halt() on receiving the stall
> response, so now I can easily search for ClearFeature(ENDPOINT_HALT)
> request in the analyzer log. It can be found at "2.304 252 217" &
> "2.316 264 600" time instance in the attached log.
>
> Re ran the Analyzer again and attached it’s exported text
> log([2014-11-06 session 125138] Trace0000_only_ep0_ep1.txt). Here
> filtered out the BulkIN transactions.
>
> usbmon log:
> ffff8800b7670a80 506095728 C Ii:1:108:1 -32:1 0
> ffff8800affdccc0 506107757 C Ii:1:108:1 -32:1 0
> Here is the portion of the log that corresponds to “ffff8800b7670a80
> 506095728 C Ii:1:108:1 -32:1 0”:
>
> Start of Frame (6) HS 553.2 -> 553.7 2.302 964 717
> SSPLIT IN transaction 105 1 HS No data 2.303 590 367
> SSPLIT IN transaction 106 1 HS No data 2.303 591 283
> SSPLIT IN transaction 107 1 HS No data 2.303 600 283
> SSPLIT IN transaction 108 1 HS No data 2.303 601 350
> Start of Frame (2) HS 554.0 -> 554.1 2.303 714 817
> CSPLIT IN transaction 105 1 NAK HS No data 2.303 840 400
> CSPLIT IN transaction 106 1 NAK HS No data 2.303 842 033
> CSPLIT IN transaction 107 1 NAK HS No data 2.303 855 317
> Start of Frame (3) HS 554.2 -> 554.4 2.303 964 850
Obviously, there aren't any CSPLITs for device 108 ep 1.
> Here is the portion of the log that corresponds to “ffff8800affdccc0
> 506107757 C Ii:1:108:1 -32:1 0":
>
> Start of Frame (6) HS 565.2 -> 565.7 2.314 966 383
> SSPLIT IN transaction 105 1 HS No data 2.315 592 033
> SSPLIT IN transaction 106 1 HS No data 2.315 592 967
> SSPLIT IN transaction 107 1 HS No data 2.315 612 800
> SSPLIT IN transaction 108 1 HS No data 2.315 613 850
> Start of Frame (2) HS 566.0 -> 566.1 2.315 716 483
> CSPLIT IN transaction 105 1 NAK HS No data 2.315 842 067
> CSPLIT IN transaction 106 1 NAK HS No data 2.315 843 683
> CSPLIT IN transaction 107 1 NAK HS No data 2.315 928 750
> Start of Frame (3) HS 566.2 -> 566.4 2.315 966 517
> In both the cases, CSPLIT of Dev-108 is missing in this portion of the log.
>
> So, Does this test log gives some conclusion?
It indicates that the EHCI host controller hardware isn't working
right. Every now and then it skips sending CSPLIT packets when it
should send them.
I suppose it's possible that the host controller is okay and the
problem is a bad memory chip. That could also cause this sort of
error. Regardless, it has to be a hardware problem.
Now, this doesn't explain why you get the -32 status code. Maybe the
patch below will provide more information. Try running your test with
this patch installed and see what shows up in the dmesg log.
Alan Stern
Index: usb-3.18/drivers/usb/host/ehci-q.c
===================================================================
--- usb-3.18.orig/drivers/usb/host/ehci-q.c
+++ usb-3.18/drivers/usb/host/ehci-q.c
@@ -346,6 +346,12 @@ qh_completions (struct ehci_hcd *ehci, s
/* always clean up qtds the hc de-activated */
retry_xacterr:
if ((token & QTD_STS_ACTIVE) == 0) {
+ u32 info2 = hc32_to_cpu(ehci, hw->hw_info2);
+
+ if ((info2 & QH_SMASK) && (token & 0x7e))
+ ehci_info(ehci, "split intr info2 %x token %x overlay token %x\n",
+ info2, token, hc32_to_cpu(ehci,
+ hw->hw_token));
/* Report Data Buffer Error: non-fatal but useful */
if (token & QTD_STS_DBE)
On Wed, 5 Nov 2014, Naveen Kumar Parna wrote:
> > Can you do it again, but this time keep the SOF packets?
> >
> > You don't have to post the entire analyzer log. Just extract 3 or 4 ms
> > from the middle, where it shows the SSPLITS but no CSPLITS for the
> > interrupt endpoints, and post only that portion.
> >
>
> I tried again, I keep getting STALL's but this time I see CSPLITS for
> the interrupt end points.
Any idea why you see the CSPLITs now but didn't see them before?
> usbmon log:
> ffff8800b2cce6c0 1558099725 C Ii:1:055:1 -32:1 0
> ffff8800b2cce6c0 1558099740 S Ii:1:055:1 -115:1 16 <
> ffff8800b2cce6c0 1558435684 C Ii:1:055:1 -32:1 0
> ffff8800b2cce6c0 1558435700 S Ii:1:055:1 -115:1 16 <
> ffff8800b2cce6c0 1558447773 C Ii:1:055:1 -32:1 0
> ffff8800b2cce6c0 1558447790 S Ii:1:055:1 -115:1 16 <
> ffff8800b2cce6c0 1562003759 C Ii:1:055:1 -32:1 0
> ffff8800b2cce6c0 1562003777 S Ii:1:055:1 -115:1 16 <
> ffff8800b2cce6c0 1835091798 C Ii:1:055:1 -32:1 0
> ffff8800b2cce6c0 1835091818 S Ii:1:055:1 -115:1 16 <
> ffff8800b2cce6c0 2360295770 C Ii:1:055:1 -32:1 0
> ffff8800b2cce6c0 2360295785 S Ii:1:055:1 -115:1 16 <
> ffff8800b2cce6c0 2360307814 C Ii:1:055:1 -32:1 0
> ffff8800b2cce6c0 2360307827 S Ii:1:055:1 -115:1 16 <
> ffff8800b2cce6c0 2746327776 C Ii:1:055:1 -32:1 0
> ffff8800b2cce6c0 2746327796 S Ii:1:055:1 -115:1 16 <
> ffff8800b2cce6c0 2750455832 C Ii:1:055:1 -32:1 0
> ffff8800b2cce6c0 2750455844 S Ii:1:055:1 -115:1 16 <
> ffff8800b2cce6c0 2751751777 C Ii:1:055:1 -32:1 0
> ffff8800b2cce6c0 2751751788 S Ii:1:055:1 -115:1 16 <
> ffff8800b2cce6c0 2752707689 C Ii:1:055:1 -32:1 0
> ffff8800b2cce6c0 2752707707 S Ii:1:055:1 -115:1 16 <
> ffff8800b2cce6c0 2762271761 C Ii:1:055:1 -32:1 0
> ffff8800b2cce6c0 2762271776 S Ii:1:055:1 -115:1 16 <
> ffff8800b2cce6c0 2977131824 C Ii:1:055:1 -32:1 0
> ffff8800b2cce6c0 2977131835 S Ii:1:055:1 -115:1 16 <
> ffff8800b2cce6c0 3602679779 C Ii:1:055:1 -32:1 0
> ffff8800b2cce6c0 3602679798 S Ii:1:055:1 -115:1 16 <
> ffff8800b2cce6c0 456023739 C Ii:1:055:1 -32:1 0
> ffff8800b2cce6c0 456023758 S Ii:1:055:1 -115:1 16 <
> ffff8800b2cce6c0 456231695 C Ii:1:055:1 -32:1 0
> ffff8800b2cce6c0 456231712 S Ii:1:055:1 -115:1 16 <
Notice that the problem seems to occur very rarely. There are often
many seconds between the -32 status values, whereas the interrupt
endpoint gets polled 1000 times per second.
Inconsistent behavior like that tends to indicate a hardware problem.
Software would behave the same way every time, unless there was some
sort of race.
> Dev 55 usb log:
>
> SSPLIT IN transaction 55 1 HS No data 0.000 238 117
> Start of Frame (2) HS 228.0 -> 228.1 0.000 340 583
> CSPLIT IN transaction 55 1 NAK HS No data 0.000 489 817
> Start of Frame (6) HS 228.2 -> 228.7 0.000 590 617
> SSPLIT IN transaction 55 1 HS No data 0.001 238 117
> Start of Frame (2) HS 229.0 -> 229.1 0.001 340 733
> CSPLIT IN transaction 55 1 NAK HS No data 0.001 489 850
> Start of Frame (6) HS 229.2 -> 229.7 0.001 590 767
> SSPLIT IN transaction 55 1 HS No data 0.002 238 933
> Start of Frame (2) HS 230.0 -> 230.1 0.002 340 867
> CSPLIT IN transaction 55 1 NAK HS No data 0.002 489 933
> Start of Frame (6) HS 230.2 -> 230.7 0.002 590 900
> SSPLIT IN transaction 55 1 HS No data 0.003 238 967
> Start of Frame (2) HS 231.0 -> 231.1 0.003 341 017
> CSPLIT IN transaction 55 1 NAK HS No data 0.003 489 900
> Start of Frame (6) HS 231.2 -> 231.7 0.003 591 050
> SSPLIT IN transaction 55 1 HS No data 0.004 238 950
> Start of Frame (2) HS 232.0 -> 232.1 0.004 341 150
> CSPLIT IN transaction 55 1 NAK HS No data 0.004 489 950
> Start of Frame (6) HS 232.2 -> 232.7 0.004 591 183
> SSPLIT IN transaction 55 1 HS No data 0.005 239 000
> Start of Frame (2) HS 233.0 -> 233.1 0.005 341 283
> CSPLIT IN transaction 55 1 NAK HS No data 0.005 490 000
This looks right. The SSPLIT packets get sent in microframe 7 of each
frame and the CSPLIT packets get sent in microframe 1. (The full-speed
bus transaction occurs during microframe 0, in between.)
Also, a NAK response to a CSPLIT is correct when the device has no data
to send. It wouldn't cause you to get a STALL indication.
I need to see the portion of the analyzer log that corresponds to one
of those -32 events in the usbmon log. It ought to show something
different, something that would cause the -32 status.
> External USB-2 hub (Dev 51) log:
> Start of Frame (570) HS 258.7 -> 330.0 0.000 090 550
> IN transaction 51 1 NAK HS No data 0.071 226 050
> Start of Frame (2,048) HS 299.0 -> 554.7 0.071 350 517
> IN transaction 51 1 NAK HS No data 0.327 261 817
> Start of Frame (2,048) HS 555.0 -> 810.7 0.327 386 250
> IN transaction 51 1 NAK HS No data 0.583 297 550
> Start of Frame (2,048) HS 811.0 -> 1,066.7 0.583 422 000
> IN transaction 51 1 NAK HS No data 0.839 333 283
> Start of Frame (2,048) HS 1,067.0 -> 1,322.7 0.839 457 733
> IN transaction 51 1 NAK HS No data 1.095 369 050
> Start of Frame (2,048) HS 1,323.0 -> 1,578.7 1.095 493 483
> IN transaction 51 1 NAK HS No data 1.351 404 767
> Start of Frame (2,048) HS 1,579.0 -> 1,834.7 1.351 529 233
> IN transaction 51 1 NAK HS No data 1.607 440 517
This also looks right. The hub won't have any data to send until you
plug in or unplug a device from one of its ports.
> Internal USB-2 hub (Dev 2) log:
> Start of Frame (266) HS 258.7 -> 292.0 0.000 090 550
> Incomplete IN transaction 2 1 INCOMPLETE HS No data 0.033 220 750
> Start of Frame (2,048) HS 261.0 -> 516.7 0.033 345 200
> Incomplete IN transaction 2 1 INCOMPLETE HS No data 0.289 256 517
> Start of Frame (2,048) HS 517.0 -> 772.7 0.289 380 950
> Incomplete IN transaction 2 1 INCOMPLETE HS No data 0.545 292 233
> Start of Frame (2,048) HS 773.0 -> 1,028.7 0.545 416 683
> Incomplete IN transaction 2 1 INCOMPLETE HS No data 0.801 328 000
And this looks right too. The analyzer was unable to record the
responses to the IN transactions because the response packets were sent
directly back to the host controller -- they don't get sent to the
external port where the analyzer is attached.
Alan Stern
>> >> Split packet transactions are hidden. I could see them by clicking on
>> >> the (Show/Hide Split transactions) button. For INT IN, I could see
>> >> only Start Split packet.
>> >>
>> >> I attached([2014-10-28 session 144012] Trace0003.rar) complete log for
>> >> this scenario.
>> >
>> > How come the log doesn't contain any SOF packets?
>>
>>
>> To avoid recording a huge quantity of data , I enabled the "Drop Start
>> of Frames" filter in the recording options.
>
> Can you do it again, but this time keep the SOF packets?
>
> You don't have to post the entire analyzer log. Just extract 3 or 4 ms
> from the middle, where it shows the SSPLITS but no CSPLITS for the
> interrupt endpoints, and post only that portion.
>
I tried again, I keep getting STALL's but this time I see CSPLITS for
the interrupt end points.
[root@banunxcas29 ns06]# lsusb -t
1-1.5.1:1.2: No such file or directory
1-1.5.2:1.2: No such file or directory
1-1.5.3:1.2: No such file or directory
1-1.5.4:1.2: No such file or directory
/: Bus 02.Port 1: Dev 1, Class=root_hub, Driver=ehci-pci/2p, 480M
/: Bus 01.Port 1: Dev 1, Class=root_hub, Driver=ehci-pci/2p, 480M
|__ Port 1: Dev 2, If 0, Class=hub, Driver=hub/6p, 480M
|__ Port 5: Dev 51, If 0, Class=hub, Driver=hub/4p, 480M
|__ Port 1: Dev 52, If 0, Class='bInterfaceClass 0xe0 not
yet handled', Driver=btusb, 12M
|__ Port 1: Dev 52, If 1, Class='bInterfaceClass 0xe0 not
yet handled', Driver=btusb, 12M
|__ Port 1: Dev 52, If 2, Class=app., Driver=, 12M
|__ Port 2: Dev 53, If 0, Class='bInterfaceClass 0xe0 not
yet handled', Driver=btusb, 12M
|__ Port 2: Dev 53, If 1, Class='bInterfaceClass 0xe0 not
yet handled', Driver=btusb, 12M
|__ Port 2: Dev 53, If 2, Class=app., Driver=, 12M
|__ Port 3: Dev 56, If 0, Class='bInterfaceClass 0xe0 not
yet handled', Driver=btusb, 12M
|__ Port 3: Dev 56, If 1, Class='bInterfaceClass 0xe0 not
yet handled', Driver=btusb, 12M
|__ Port 3: Dev 56, If 2, Class=app., Driver=, 12M
|__ Port 4: Dev 55, If 0, Class='bInterfaceClass 0xe0 not
yet handled', Driver=btusb, 12M
|__ Port 4: Dev 55, If 1, Class='bInterfaceClass 0xe0 not
yet handled', Driver=btusb, 12M
|__ Port 4: Dev 55, If 2, Class=app., Driver=, 12M
Here Dev 51 is external USB-2 hub.
usbmon log:
ffff8800b2cce6c0 1558099725 C Ii:1:055:1 -32:1 0
ffff8800b2cce6c0 1558099740 S Ii:1:055:1 -115:1 16 <
ffff8800b2cce6c0 1558435684 C Ii:1:055:1 -32:1 0
ffff8800b2cce6c0 1558435700 S Ii:1:055:1 -115:1 16 <
ffff8800b2cce6c0 1558447773 C Ii:1:055:1 -32:1 0
ffff8800b2cce6c0 1558447790 S Ii:1:055:1 -115:1 16 <
ffff8800b2cce6c0 1562003759 C Ii:1:055:1 -32:1 0
ffff8800b2cce6c0 1562003777 S Ii:1:055:1 -115:1 16 <
ffff8800b2cce6c0 1835091798 C Ii:1:055:1 -32:1 0
ffff8800b2cce6c0 1835091818 S Ii:1:055:1 -115:1 16 <
ffff8800b2cce6c0 2360295770 C Ii:1:055:1 -32:1 0
ffff8800b2cce6c0 2360295785 S Ii:1:055:1 -115:1 16 <
ffff8800b2cce6c0 2360307814 C Ii:1:055:1 -32:1 0
ffff8800b2cce6c0 2360307827 S Ii:1:055:1 -115:1 16 <
ffff8800b2cce6c0 2746327776 C Ii:1:055:1 -32:1 0
ffff8800b2cce6c0 2746327796 S Ii:1:055:1 -115:1 16 <
ffff8800b2cce6c0 2750455832 C Ii:1:055:1 -32:1 0
ffff8800b2cce6c0 2750455844 S Ii:1:055:1 -115:1 16 <
ffff8800b2cce6c0 2751751777 C Ii:1:055:1 -32:1 0
ffff8800b2cce6c0 2751751788 S Ii:1:055:1 -115:1 16 <
ffff8800b2cce6c0 2752707689 C Ii:1:055:1 -32:1 0
ffff8800b2cce6c0 2752707707 S Ii:1:055:1 -115:1 16 <
ffff8800b2cce6c0 2762271761 C Ii:1:055:1 -32:1 0
ffff8800b2cce6c0 2762271776 S Ii:1:055:1 -115:1 16 <
ffff8800b2cce6c0 2977131824 C Ii:1:055:1 -32:1 0
ffff8800b2cce6c0 2977131835 S Ii:1:055:1 -115:1 16 <
ffff8800b2cce6c0 3602679779 C Ii:1:055:1 -32:1 0
ffff8800b2cce6c0 3602679798 S Ii:1:055:1 -115:1 16 <
ffff8800b2cce6c0 456023739 C Ii:1:055:1 -32:1 0
ffff8800b2cce6c0 456023758 S Ii:1:055:1 -115:1 16 <
ffff8800b2cce6c0 456231695 C Ii:1:055:1 -32:1 0
ffff8800b2cce6c0 456231712 S Ii:1:055:1 -115:1 16 <
Dev 55 usb log:
SSPLIT IN transaction 55 1 HS No data 0.000 238 117
Start of Frame (2) HS 228.0 -> 228.1 0.000 340 583
CSPLIT IN transaction 55 1 NAK HS No data 0.000 489 817
Start of Frame (6) HS 228.2 -> 228.7 0.000 590 617
SSPLIT IN transaction 55 1 HS No data 0.001 238 117
Start of Frame (2) HS 229.0 -> 229.1 0.001 340 733
CSPLIT IN transaction 55 1 NAK HS No data 0.001 489 850
Start of Frame (6) HS 229.2 -> 229.7 0.001 590 767
SSPLIT IN transaction 55 1 HS No data 0.002 238 933
Start of Frame (2) HS 230.0 -> 230.1 0.002 340 867
CSPLIT IN transaction 55 1 NAK HS No data 0.002 489 933
Start of Frame (6) HS 230.2 -> 230.7 0.002 590 900
SSPLIT IN transaction 55 1 HS No data 0.003 238 967
Start of Frame (2) HS 231.0 -> 231.1 0.003 341 017
CSPLIT IN transaction 55 1 NAK HS No data 0.003 489 900
Start of Frame (6) HS 231.2 -> 231.7 0.003 591 050
SSPLIT IN transaction 55 1 HS No data 0.004 238 950
Start of Frame (2) HS 232.0 -> 232.1 0.004 341 150
CSPLIT IN transaction 55 1 NAK HS No data 0.004 489 950
Start of Frame (6) HS 232.2 -> 232.7 0.004 591 183
SSPLIT IN transaction 55 1 HS No data 0.005 239 000
Start of Frame (2) HS 233.0 -> 233.1 0.005 341 283
CSPLIT IN transaction 55 1 NAK HS No data 0.005 490 000
External USB-2 hub (Dev 51) log:
Start of Frame (570) HS 258.7 -> 330.0 0.000 090 550
IN transaction 51 1 NAK HS No data 0.071 226 050
Start of Frame (2,048) HS 299.0 -> 554.7 0.071 350 517
IN transaction 51 1 NAK HS No data 0.327 261 817
Start of Frame (2,048) HS 555.0 -> 810.7 0.327 386 250
IN transaction 51 1 NAK HS No data 0.583 297 550
Start of Frame (2,048) HS 811.0 -> 1,066.7 0.583 422 000
IN transaction 51 1 NAK HS No data 0.839 333 283
Start of Frame (2,048) HS 1,067.0 -> 1,322.7 0.839 457 733
IN transaction 51 1 NAK HS No data 1.095 369 050
Start of Frame (2,048) HS 1,323.0 -> 1,578.7 1.095 493 483
IN transaction 51 1 NAK HS No data 1.351 404 767
Start of Frame (2,048) HS 1,579.0 -> 1,834.7 1.351 529 233
IN transaction 51 1 NAK HS No data 1.607 440 517
Internal USB-2 hub (Dev 2) log:
Start of Frame (266) HS 258.7 -> 292.0 0.000 090 550
Incomplete IN transaction 2 1 INCOMPLETE HS No data 0.033 220 750
Start of Frame (2,048) HS 261.0 -> 516.7 0.033 345 200
Incomplete IN transaction 2 1 INCOMPLETE HS No data 0.289 256 517
Start of Frame (2,048) HS 517.0 -> 772.7 0.289 380 950
Incomplete IN transaction 2 1 INCOMPLETE HS No data 0.545 292 233
Start of Frame (2,048) HS 773.0 -> 1,028.7 0.545 416 683
Incomplete IN transaction 2 1 INCOMPLETE HS No data 0.801 328 000
[root@banunxcas29 ns06]# lspci | grep -i usb
00:1a.0 USB Controller: Intel Corporation 5 Series/3400 Series Chipset
USB2 Enhanced Host Controller (rev 05)
00:1d.0 USB Controller: Intel Corporation 5 Series/3400 Series Chipset
USB2 Enhanced Host Controller (rev 05)
[root@banunxcas29 ns06]# lsusb -v -s 1:1 | grep iSerial
iSerial 1 0000:00:1a.0
Attached the files present under /sys/kernel/debug/usb/ehci/0000\:00\:1a.0/.
Thanks,
Naveen
On Mon, 3 Nov 2014, Naveen Kumar Parna wrote:
> On Sat, Nov 1, 2014 at 2:21 AM, Alan Stern <[email protected]> wrote:
> > On Wed, 29 Oct 2014, Naveen Kumar Parna wrote:
> >
> >> Split packet transactions are hidden. I could see them by clicking on
> >> the (Show/Hide Split transactions) button. For INT IN, I could see
> >> only Start Split packet.
> >>
> >> I attached([2014-10-28 session 144012] Trace0003.rar) complete log for
> >> this scenario.
> >
> > How come the log doesn't contain any SOF packets?
>
>
> To avoid recording a huge quantity of data , I enabled the "Drop Start
> of Frames" filter in the recording options.
Can you do it again, but this time keep the SOF packets?
You don't have to post the entire analyzer log. Just extract 3 or 4 ms
from the middle, where it shows the SSPLITS but no CSPLITS for the
interrupt endpoints, and post only that portion.
> > I see what you mean -- the log doesn't contain any CSPLIT transactions
> > for the interrupt endpoints. Only SSPLIT.
> >
> > I'll need to see the scheduling information for these endpoints.
> > You'll have to run a 3.13 or later kernel; then the important files
> > will be under /sys/kernel/debug/usb/ehci/X/, where X is the PCI address
> > of the EHCI controller you are using.
> >
> > Copy the files in that directory while the test is running.
> >
>
>
> I attached all the files. Please let me know if I miss anything?
All the information in the files looks correct, as far as I can see. I
have no idea why the CSPLIT packets are missing.
Alan Stern