xHCI bug

[Felipe Balbi]

Hi Mathias,

I seem to be able to rather easily kill xHCI by just running
test.sh/testusb with a USB2 device attached to it (I used my AM437x
Starter Kit for the test).

I noticed that after not too long, all tests started failing (see below)
but using ehci, it works just fine (afaicr).

Here's a snippet of the hang, but it has been running for a while and
before testusb I ran over 24 hours of MSC testing, also passed full
USB20CV and USB30CV with g_mass_storage and g_zero (and most other
gadget drivers too):

[874685.176903] usbtest 1-7:3.0: Linux gadget zero
[874685.176906] usbtest 1-7:3.0: high-speed {control in/out bulk-in bulk-out} tests (+alt)
[874703.140258] usbtest 1-7:3.0: TEST 9: ch9 (subset) control tests, 5000 times
[874723.716857] usbtest 1-7:3.0: TEST 10: queue 32 control calls, 5000 times
[874743.773236] usbtest 1-7:3.0: TEST 14: 15000 ep0out, 1..256 vary 1
[874748.774291] usbtest 1-7:3.0: ctrl_out write failed, code -110, count 0
[874754.297205] usbtest 1-7:3.0: set altsetting to 0 failed, -110
[874759.819703] usbtest 1-7:3.0: set altsetting to 0 failed, -110
[874765.341962] usbtest 1-7:3.0: set altsetting to 0 failed, -110
[874765.863127] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874766.383337] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874766.903526] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874767.423750] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874767.943965] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874768.464174] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874768.988078] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874769.376451] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874769.896675] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874770.416920] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874770.937170] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874771.306870] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874771.829525] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874772.349723] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874772.870041] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874773.363080] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874773.866381] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874774.386594] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874774.910836] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874775.431062] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874775.951018] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874776.347478] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874776.867690] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874777.387859] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874777.911980] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874778.432250] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874778.952692] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874779.472784] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874780.008646] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874780.528880] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874780.925468] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874781.297533] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874781.817776] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874782.341828] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874782.862237] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874783.382444] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874783.902684] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874784.430835] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874784.954964] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874785.475225] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874785.999464] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874786.519801] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874787.039882] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874787.560232] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874788.080327] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874788.600517] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874789.120687] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874789.641042] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874790.161156] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874790.680681] xhci_hcd 0000:00:14.0: URB transfer length is wrong, xHC issue? req. len = 0, act. len = 4294967288
[874790.680707] usbtest 1-7:3.0: TEST 1: write 2048 bytes 5000 times
[874800.683902] usb 1-7: test1 failed, iterations left 4999, status -110 (not 0)
[874801.205807] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874801.726028] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874802.246264] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874802.770493] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874803.290302] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874803.810881] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874804.331116] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874804.851432] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874805.371576] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874805.891800] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874806.412040] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874806.936311] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874807.460458] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874807.980610] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874808.500802] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874809.020982] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874809.541290] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874810.065583] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874810.585678] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874811.106000] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874811.630164] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874812.150468] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874812.670556] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874813.194790] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874813.715062] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874814.239361] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874814.763513] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874815.283835] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874815.807702] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874816.328202] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874816.848348] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874817.372674] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874817.892779] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874818.413039] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874818.933147] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874819.453549] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874819.973687] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874820.497913] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874821.018020] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874821.538384] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874822.058512] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874822.582741] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874823.102946] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874823.623217] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874824.147402] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874824.667670] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874825.187794] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874825.712031] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874826.236288] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874826.760597] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874827.284690] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874827.804832] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874828.293948] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874828.813345] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874829.333534] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874829.857820] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874830.378004] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874830.898252] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874831.314448] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874831.834668] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874832.358846] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874832.883075] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874833.402489] xhci_hcd 0000:00:14.0: URB transfer length is wrong, xHC issue? req. len = 0, act. len = 4294967288
[874833.402511] usbtest 1-7:3.0: TEST 10: queue 32 control calls, 5000 times
[874833.402558] usbtest 1-7:3.0: subtest 0 error, status -71
[874833.402562] usbtest 1-7:3.0: control queue 80.06, err -71, 159999 left, subcase 0, len 0/18
[874833.922827] xhci_hcd 0000:00:14.0: URB transfer length is wrong, xHC issue? req. len = 0, act. len = 4294967288
[874833.922854] usbtest 1-7:3.0: TEST 14: 15000 ep0out, 1..256 vary 1
[874833.922902] usbtest 1-7:3.0: ctrl_out write failed, code -71, count 0
[874834.443593] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874834.963891] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874835.484114] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874836.004316] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874836.524502] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874837.048783] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874837.569073] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874838.089142] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874838.609439] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874839.133696] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874839.653645] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874840.046062] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874840.565995] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874840.990235] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874841.382566] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874841.742792] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874842.263019] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874842.787199] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874843.315454] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874843.819569] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874844.239656] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874844.748105] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874845.256333] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874845.776425] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874846.300376] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874846.768932] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874847.289037] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874847.809379] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874848.298296] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874848.817698] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874849.337940] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874849.858118] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874850.378397] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874850.886529] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874851.406778] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874851.931068] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874852.455183] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874852.979525] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874853.499764] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874854.019849] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874854.540184] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874855.060345] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874855.584596] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874856.108739] usbtest 1-7:3.0: set altsetting to 0 failed, -71
[874856.628230] xhci_hcd 0000:00:14.0: URB transfer length is wrong, xHC issue? req. len = 0, act. len = 4294967288
[874856.628255] usbtest 1-7:3.0: TEST 7: write/63 2000 sglists 32 entries 0..64 bytes
[875045.590161] INFO: task testusb:18493 blocked for more than 120 seconds.
[875045.590164] Not tainted 3.16-2-amd64 #1
[875045.590164] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[875045.590165] testusb D ffff88031c208f38 0 18493 18217 0x00000000
[875045.590168] ffff88031c208ae0 0000000000000082 0000000000014240 ffff8802a7127fd8
[875045.590169] 0000000000014240 ffff88031c208ae0 ffff8802a7127de0 ffff8802a7127be0
[875045.590171] ffff8802a7127dd8 ffff88031c208ae0 0000000000000001 0000000000000001
[875045.590172] Call Trace:
[875045.590177] [<ffffffff81507ec9>] ? schedule_timeout+0x229/0x2a0
[875045.590200] [<ffffffffa0026736>] ? usb_hcd_submit_urb+0xa6/0xa60 [usbcore]
[875045.590202] [<ffffffff815093d8>] ? wait_for_completion+0xa8/0x120
[875045.590205] [<ffffffff81094a80>] ? wake_up_state+0x10/0x10
[875045.590210] [<ffffffffa0029eb0>] ? usb_sg_wait+0x120/0x180 [usbcore]
[875045.590212] [<ffffffffa09c92e4>] ? perform_sglist+0xf4/0x170 [usbtest]
[875045.590214] [<ffffffffa09c91e0>] ? free_sglist+0xb0/0xb0 [usbtest]
[875045.590216] [<ffffffffa09cbd13>] ? usbtest_ioctl+0x1d3/0x14b6 [usbtest]
[875045.590221] [<ffffffffa0031cf5>] ? proc_ioctl+0x135/0x210 [usbcore]
[875045.590225] [<ffffffffa00340d7>] ? usbdev_do_ioctl+0x267/0x1170 [usbcore]
[875045.590230] [<ffffffffa0034ffa>] ? usbdev_ioctl+0xa/0x10 [usbcore]
[875045.590233] [<ffffffff811b750f>] ? do_vfs_ioctl+0x2cf/0x4b0
[875045.590234] [<ffffffff811b7771>] ? SyS_ioctl+0x81/0xa0
[875045.590236] [<ffffffff8150c26d>] ? system_call_fast_compare_end+0x10/0x15
[875165.640330] INFO: task testusb:18493 blocked for more than 120 seconds.
[875165.640334] Not tainted 3.16-2-amd64 #1
[875165.640335] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[875165.640336] testusb D ffff88031c208f38 0 18493 18217 0x00000000
[875165.640339] ffff88031c208ae0 0000000000000082 0000000000014240 ffff8802a7127fd8
[875165.640341] 0000000000014240 ffff88031c208ae0 ffff8802a7127de0 ffff8802a7127be0
[875165.640343] ffff8802a7127dd8 ffff88031c208ae0 0000000000000001 0000000000000001
[875165.640345] Call Trace:
[875165.640352] [<ffffffff81507ec9>] ? schedule_timeout+0x229/0x2a0
[875165.640376] [<ffffffffa0026736>] ? usb_hcd_submit_urb+0xa6/0xa60 [usbcore]
[875165.640380] [<ffffffff815093d8>] ? wait_for_completion+0xa8/0x120
[875165.640383] [<ffffffff81094a80>] ? wake_up_state+0x10/0x10
[875165.640389] [<ffffffffa0029eb0>] ? usb_sg_wait+0x120/0x180 [usbcore]
[875165.640392] [<ffffffffa09c92e4>] ? perform_sglist+0xf4/0x170 [usbtest]
[875165.640394] [<ffffffffa09c91e0>] ? free_sglist+0xb0/0xb0 [usbtest]
[875165.640397] [<ffffffffa09cbd13>] ? usbtest_ioctl+0x1d3/0x14b6 [usbtest]
[875165.640403] [<ffffffffa0031cf5>] ? proc_ioctl+0x135/0x210 [usbcore]
[875165.640409] [<ffffffffa00340d7>] ? usbdev_do_ioctl+0x267/0x1170 [usbcore]
[875165.640415] [<ffffffffa0034ffa>] ? usbdev_ioctl+0xa/0x10 [usbcore]
[875165.640418] [<ffffffff811b750f>] ? do_vfs_ioctl+0x2cf/0x4b0
[875165.640420] [<ffffffff811b7771>] ? SyS_ioctl+0x81/0xa0
[875165.640422] [<ffffffff8150c26d>] ? system_call_fast_compare_end+0x10/0x15
[875285.690460] INFO: task testusb:18493 blocked for more than 120 seconds.
[875285.690464] Not tainted 3.16-2-amd64 #1
[875285.690466] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[875285.690467] testusb D ffff88031c208f38 0 18493 18217 0x00000000
[875285.690471] ffff88031c208ae0 0000000000000082 0000000000014240 ffff8802a7127fd8
[875285.690474] 0000000000014240 ffff88031c208ae0 ffff8802a7127de0 ffff8802a7127be0
[875285.690476] ffff8802a7127dd8 ffff88031c208ae0 0000000000000001 0000000000000001
[875285.690479] Call Trace:
[875285.690486] [<ffffffff81507ec9>] ? schedule_timeout+0x229/0x2a0
[875285.690515] [<ffffffffa0026736>] ? usb_hcd_submit_urb+0xa6/0xa60 [usbcore]
[875285.690520] [<ffffffff815093d8>] ? wait_for_completion+0xa8/0x120
[875285.690523] [<ffffffff81094a80>] ? wake_up_state+0x10/0x10
[875285.690532] [<ffffffffa0029eb0>] ? usb_sg_wait+0x120/0x180 [usbcore]
[875285.690536] [<ffffffffa09c92e4>] ? perform_sglist+0xf4/0x170 [usbtest]
[875285.690538] [<ffffffffa09c91e0>] ? free_sglist+0xb0/0xb0 [usbtest]
[875285.690541] [<ffffffffa09cbd13>] ? usbtest_ioctl+0x1d3/0x14b6 [usbtest]
[875285.690550] [<ffffffffa0031cf5>] ? proc_ioctl+0x135/0x210 [usbcore]
[875285.690559] [<ffffffffa00340d7>] ? usbdev_do_ioctl+0x267/0x1170 [usbcore]
[875285.690567] [<ffffffffa0034ffa>] ? usbdev_ioctl+0xa/0x10 [usbcore]
[875285.690570] [<ffffffff811b750f>] ? do_vfs_ioctl+0x2cf/0x4b0
[875285.690572] [<ffffffff811b7771>] ? SyS_ioctl+0x81/0xa0
[875285.690575] [<ffffffff8150c26d>] ? system_call_fast_compare_end+0x10/0x15
[875405.740543] INFO: task testusb:18493 blocked for more than 120 seconds.
[875405.740546] Not tainted 3.16-2-amd64 #1
[875405.740547] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[875405.740548] testusb D ffff88031c208f38 0 18493 18217 0x00000004
[875405.740550] ffff88031c208ae0 0000000000000082 0000000000014240 ffff8802a7127fd8
[875405.740552] 0000000000014240 ffff88031c208ae0 ffff8802a7127de0 ffff8802a7127be0
[875405.740553] ffff8802a7127dd8 ffff88031c208ae0 0000000000000001 0000000000000001
[875405.740555] Call Trace:
[875405.740561] [<ffffffff81507ec9>] ? schedule_timeout+0x229/0x2a0
[875405.740582] [<ffffffffa0026736>] ? usb_hcd_submit_urb+0xa6/0xa60 [usbcore]
[875405.740584] [<ffffffff815093d8>] ? wait_for_completion+0xa8/0x120
[875405.740587] [<ffffffff81094a80>] ? wake_up_state+0x10/0x10
[875405.740592] [<ffffffffa0029eb0>] ? usb_sg_wait+0x120/0x180 [usbcore]
[875405.740594] [<ffffffffa09c92e4>] ? perform_sglist+0xf4/0x170 [usbtest]
[875405.740596] [<ffffffffa09c91e0>] ? free_sglist+0xb0/0xb0 [usbtest]
[875405.740598] [<ffffffffa09cbd13>] ? usbtest_ioctl+0x1d3/0x14b6 [usbtest]
[875405.740603] [<ffffffffa0031cf5>] ? proc_ioctl+0x135/0x210 [usbcore]
[875405.740607] [<ffffffffa00340d7>] ? usbdev_do_ioctl+0x267/0x1170 [usbcore]
[875405.740612] [<ffffffffa0034ffa>] ? usbdev_ioctl+0xa/0x10 [usbcore]
[875405.740614] [<ffffffff811b750f>] ? do_vfs_ioctl+0x2cf/0x4b0
[875405.740616] [<ffffffff811b7771>] ? SyS_ioctl+0x81/0xa0
[875405.740617] [<ffffffff8150c26d>] ? system_call_fast_compare_end+0x10/0x15
[875525.790697] INFO: task testusb:18493 blocked for more than 120 seconds.
[875525.790700] Not tainted 3.16-2-amd64 #1
[875525.790701] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[875525.790702] testusb D ffff88031c208f38 0 18493 1 0x00000004
[875525.790705] ffff88031c208ae0 0000000000000082 0000000000014240 ffff8802a7127fd8
[875525.790706] 0000000000014240 ffff88031c208ae0 ffff8802a7127de0 ffff8802a7127be0
[875525.790707] ffff8802a7127dd8 ffff88031c208ae0 0000000000000001 0000000000000001
[875525.790709] Call Trace:
[875525.790714] [<ffffffff81507ec9>] ? schedule_timeout+0x229/0x2a0
[875525.790737] [<ffffffffa0026736>] ? usb_hcd_submit_urb+0xa6/0xa60 [usbcore]
[875525.790739] [<ffffffff815093d8>] ? wait_for_completion+0xa8/0x120
[875525.790742] [<ffffffff81094a80>] ? wake_up_state+0x10/0x10
[875525.790747] [<ffffffffa0029eb0>] ? usb_sg_wait+0x120/0x180 [usbcore]
[875525.790749] [<ffffffffa09c92e4>] ? perform_sglist+0xf4/0x170 [usbtest]
[875525.790751] [<ffffffffa09c91e0>] ? free_sglist+0xb0/0xb0 [usbtest]
[875525.790752] [<ffffffffa09cbd13>] ? usbtest_ioctl+0x1d3/0x14b6 [usbtest]
[875525.790758] [<ffffffffa0031cf5>] ? proc_ioctl+0x135/0x210 [usbcore]
[875525.790762] [<ffffffffa00340d7>] ? usbdev_do_ioctl+0x267/0x1170 [usbcore]
[875525.790767] [<ffffffffa0034ffa>] ? usbdev_ioctl+0xa/0x10 [usbcore]
[875525.790769] [<ffffffff811b750f>] ? do_vfs_ioctl+0x2cf/0x4b0
[875525.790770] [<ffffffff811b7771>] ? SyS_ioctl+0x81/0xa0
[875525.790772] [<ffffffff8150c26d>] ? system_call_fast_compare_end+0x10/0x15
[875645.840821] INFO: task testusb:18493 blocked for more than 120 seconds.
[875645.840825] Not tainted 3.16-2-amd64 #1
[875645.840826] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[875645.840826] testusb D ffff88031c208f38 0 18493 1 0x00000004
[875645.840829] ffff88031c208ae0 0000000000000082 0000000000014240 ffff8802a7127fd8
[875645.840831] 0000000000014240 ffff88031c208ae0 ffff8802a7127de0 ffff8802a7127be0
[875645.840832] ffff8802a7127dd8 ffff88031c208ae0 0000000000000001 0000000000000001
[875645.840834] Call Trace:
[875645.840839] [<ffffffff81507ec9>] ? schedule_timeout+0x229/0x2a0
[875645.840861] [<ffffffffa0026736>] ? usb_hcd_submit_urb+0xa6/0xa60 [usbcore]
[875645.840863] [<ffffffff815093d8>] ? wait_for_completion+0xa8/0x120
[875645.840866] [<ffffffff81094a80>] ? wake_up_state+0x10/0x10
[875645.840871] [<ffffffffa0029eb0>] ? usb_sg_wait+0x120/0x180 [usbcore]
[875645.840873] [<ffffffffa09c92e4>] ? perform_sglist+0xf4/0x170 [usbtest]
[875645.840875] [<ffffffffa09c91e0>] ? free_sglist+0xb0/0xb0 [usbtest]
[875645.840877] [<ffffffffa09cbd13>] ? usbtest_ioctl+0x1d3/0x14b6 [usbtest]
[875645.840882] [<ffffffffa0031cf5>] ? proc_ioctl+0x135/0x210 [usbcore]
[875645.840886] [<ffffffffa00340d7>] ? usbdev_do_ioctl+0x267/0x1170 [usbcore]
[875645.840891] [<ffffffffa0034ffa>] ? usbdev_ioctl+0xa/0x10 [usbcore]
[875645.840893] [<ffffffff811b750f>] ? do_vfs_ioctl+0x2cf/0x4b0
[875645.840894] [<ffffffff811b7771>] ? SyS_ioctl+0x81/0xa0
[875645.840896] [<ffffffff8150c26d>] ? system_call_fast_compare_end+0x10/0x15

[Felipe Balbi]

Hi again,

Post by Felipe Balbi
I seem to be able to rather easily kill xHCI by just running
test.sh/testusb with a USB2 device attached to it (I used my AM437x
Starter Kit for the test).

I think Tony mentioned taht it's also pretty easy to break xHCI by
trying to cold flash an old N900

[Tony Lindgren]

Post by Felipe Balbi
Hi again,

Post by Felipe Balbi
I seem to be able to rather easily kill xHCI by just running
test.sh/testusb with a USB2 device attached to it (I used my AM437x
Starter Kit for the test).

I think Tony mentioned taht it's also pretty easy to break xHCI by
trying to cold flash an old N900

Heh yeah. After upgrading my build box, I noticed few things.
The new mobo came with xchi, and the following broke:

1. My old printer MFC-7820N no longer worked for scanning

2. Trying to cold flash any omap3 boards over USB stopped working
for most of the time

3. Back-ups to a USB drive occasionally started failing

4. After disabling xhci in the BIOS, things were still flakey
with ehci

5. I ended up installing a usb2.0 ehci pcie card to fix things

Regards,

Tony
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majordomo-***@public.gmane.org
More majordomo info at http://vger.kernel.org/majordomo-info.html

[Mathias Nyman]

Post by Tony Lindgren

Post by Felipe Balbi
Hi again,

Post by Felipe Balbi
I seem to be able to rather easily kill xHCI by just running
test.sh/testusb with a USB2 device attached to it (I used my AM437x
Starter Kit for the test).

I think Tony mentioned taht it's also pretty easy to break xHCI by
trying to cold flash an old N900

Heh yeah. After upgrading my build box, I noticed few things.
1. My old printer MFC-7820N no longer worked for scanning
2. Trying to cold flash any omap3 boards over USB stopped working
for most of the time
3. Back-ups to a USB drive occasionally started failing
4. After disabling xhci in the BIOS, things were still flakey
with ehci
5. I ended up installing a usb2.0 ehci pcie card to fix things

Hmm, sounds like it might not only be a xhci issue then.

If you for some reason want to enable xhci and try coldflashing n900/use scanner
could you enable xhci debugging and send me the output of a failing case?

echo -n 'module xhci_hcd =p' > /sys/kernel/debug/dynamic_debug/control

-Mathias

--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majordomo-***@public.gmane.org
More majordomo info at http://vger.kernel.org/majordomo-info.html

[Mathias Nyman]

Hi

Post by Felipe Balbi
Hi Mathias,
I seem to be able to rather easily kill xHCI by just running
test.sh/testusb with a USB2 device attached to it (I used my AM437x
Starter Kit for the test).
I noticed that after not too long, all tests started failing (see below)
but using ehci, it works just fine (afaicr).
Here's a snippet of the hang, but it has been running for a while and
before testusb I ran over 24 hours of MSC testing, also passed full
USB20CV and USB30CV with g_mass_storage and g_zero (and most other

Ouch, I don't have a proper device in my office to run testusb with, I probably should set up one here.
(If I understood correctly any device able to use g_zero should work?)

Could you try with xhci debugging enabled? (will probably produce a lot of output)

echo -n 'module xhci_hcd =p' > /sys/kernel/debug/dynamic_debug/control

Post by Felipe Balbi
[874685.176903] usbtest 1-7:3.0: Linux gadget zero
[874685.176906] usbtest 1-7:3.0: high-speed {control in/out bulk-in bulk-out} tests (+alt)
[874703.140258] usbtest 1-7:3.0: TEST 9: ch9 (subset) control tests, 5000 times
[874723.716857] usbtest 1-7:3.0: TEST 10: queue 32 control calls, 5000 times
[874743.773236] usbtest 1-7:3.0: TEST 14: 15000 ep0out, 1..256 vary 1
[874748.774291] usbtest 1-7:3.0: ctrl_out write failed, code -110, count 0
[874754.297205] usbtest 1-7:3.0: set altsetting to 0 failed, -110

Timeout?
...

Post by Felipe Balbi
[874790.680681] xhci_hcd 0000:00:14.0: URB transfer length is wrong, xHC issue? req. len = 0, act. len = 4294967288

Hmm, "act. len" value looks awfully close to full 32 bit, driver might be wrapping around something here.

-Mathias

--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majordomo-***@public.gmane.org
More majordomo info at http://vger.kernel.org/majordomo-info.html

[Felipe Balbi]

Post by Mathias Nyman
Hi

Post by Felipe Balbi
Hi Mathias,
I seem to be able to rather easily kill xHCI by just running
test.sh/testusb with a USB2 device attached to it (I used my AM437x
Starter Kit for the test).
I noticed that after not too long, all tests started failing (see below)
but using ehci, it works just fine (afaicr).
Here's a snippet of the hang, but it has been running for a while and
before testusb I ran over 24 hours of MSC testing, also passed full
USB20CV and USB30CV with g_mass_storage and g_zero (and most other

Ouch, I don't have a proper device in my office to run testusb with, I
probably should set up one here.
(If I understood correctly any device able to use g_zero should work?)

correct, anything that can run g_zero.

Post by Mathias Nyman
Could you try with xhci debugging enabled? (will probably produce a lot of output)
echo -n 'module xhci_hcd =p' > /sys/kernel/debug/dynamic_debug/control

I'll try, sure.

Post by Mathias Nyman

Post by Felipe Balbi
[874685.176903] usbtest 1-7:3.0: Linux gadget zero
[874685.176906] usbtest 1-7:3.0: high-speed {control in/out bulk-in bulk-out} tests (+alt)
[874703.140258] usbtest 1-7:3.0: TEST 9: ch9 (subset) control tests, 5000 times
[874723.716857] usbtest 1-7:3.0: TEST 10: queue 32 control calls, 5000 times
[874743.773236] usbtest 1-7:3.0: TEST 14: 15000 ep0out, 1..256 vary 1
[874748.774291] usbtest 1-7:3.0: ctrl_out write failed, code -110, count 0
[874754.297205] usbtest 1-7:3.0: set altsetting to 0 failed, -110

Timeout?

yeah, testusb won't wait forever :-)

Post by Mathias Nyman

Post by Felipe Balbi
[874790.680681] xhci_hcd 0000:00:14.0: URB transfer length is wrong, xHC issue? req. len = 0, act. len = 4294967288

Hmm, "act. len" value looks awfully close to full 32 bit, driver might be wrapping around something here.

true.

[Felipe Balbi]

Hi,

Post by Felipe Balbi

Post by Mathias Nyman
Could you try with xhci debugging enabled? (will probably produce a lot of output)
echo -n 'module xhci_hcd =p' > /sys/kernel/debug/dynamic_debug/control

I'll try, sure.

I used tracing otherwise the problem wouldn't show up. Attached you can
find output:

0b7e070de7b65de9f70805f4639b3e58 xhci-timeout-testusb.txt.gz

[Mathias Nyman]

Post by Felipe Balbi
Hi,

Post by Felipe Balbi

Post by Mathias Nyman
Could you try with xhci debugging enabled? (will probably produce a lot of output)
echo -n 'module xhci_hcd =p' > /sys/kernel/debug/dynamic_debug/control

I'll try, sure.

I used tracing otherwise the problem wouldn't show up. Attached you can
0b7e070de7b65de9f70805f4639b3e58 xhci-timeout-testusb.txt.gz

Thanks, looks like we end up calling cleanup_halted_endpoint() a lot.
This will (try to) reset the endpoint and move to handle the next TD (URB).

This is called when we're processing contorl transfers and something out of the ordinary happends (returned STALL, BABBLE, and some other reasons)

I need to dig a bit deeper to know what actually is going on.

-Mathias


--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majordomo-***@public.gmane.org
More majordomo info at http://vger.kernel.org/majordomo-info.html