Thomas16
New Contributor
New ContributorDebugging testusb problems
Hi all,
We are verifying the USB ports on a new design based on the Cyclone V SoC. The port seems to work functionally okay. However, we ran `testusb` (as included in tools/usb) which produced some unexpected results.
Our board has two USB ports, with two distinct USB controllers (USB3300). One is configured as USB gadget (gadget zero, for the purpose of this test). The other is a generic USB host. Hence, we can connect the gadget port, to the host port on the same board.
This produces the following logs. Please note that this log includes stdin/stdout and system messages (dmesg). Lines starting with a timestamp originate are system logs, mainly the usbtest module handling test execution (host side), and dwc2 as USB driver.
root@board06F886:~# modprobe g_zero [ 97.989731] zero gadget.0: Gadget Zero, version: Cinco de Mayo 2008 [ 97.996001] zero gadget.0: zero ready [ 97.999729] dwc2 ffb00000.usb: bound driver zero root@board06F886:~# modprobe usbtest alt=1 [ 103.431240] usbcore: registered new interface driver usbtest root@board06F886:~# [ 116.016867] dwc2 ffb00000.usb: new device is high-speed [ 116.166762] usb 2-1: new high-speed USB device number 2 using dwc2 [ 116.236861] dwc2 ffb00000.usb: new device is high-speed [ 116.386878] dwc2 ffb00000.usb: new address 2 [ 116.420468] usbtest 2-1:3.0: Linux gadget zero [ 116.424965] usbtest 2-1:3.0: high-speed {control in/out bulk-in bulk-out iso-in iso-out} tests (+alt) root@board06F886:~# root@board06F886:~# ./testusb -a -v512 high speed[ 119.929886] usbtest 2-1:3.0: TEST 0: NOP /dev/bus/usb/002/002 0 [ 119.934760] usbtest 2-1:3.0: TEST 1: write 1024 bytes 1000 times /dev/bus/usb/002/002 test 0, 0.004313 secs /dev/bus/usb/002/002 test 1, 0.211566 secs [ 120.146912] usbtest 2-1:3.0: TEST 2: read 1024 bytes 1000 times /dev/bus/usb/002/002 test 2, 0.276874 secs [ 120.424338] usbtest 2-1:3.0: TEST 3: write/512 0..1024 bytes 1000 times /dev/bus/usb/002/002 test 3, 0.173212 secs [ 120.598085] usbtest 2-1:3.0: TEST 4: read/512 0..1024 bytes 1000 times /dev/bus/usb/002/002 test 4, 0.174881 secs [ 120.773512] usbtest 2-1:3.0: TEST 5: write 1000 sglists 32 entries of 1024 bytes /dev/bus/usb/002/002 test 5, 3.504830 secs [ 124.278928] usbtest 2-1:3.0: TEST 6: read 1000 sglists 32 entries of 1024 bytes /dev/bus/usb/002/002 test 6, 2.654906 secs [ 126.934424] usbtest 2-1:3.0: TEST 7: write/512 1000 sglists 32 entries 0..1024 bytes /dev/bus/usb/002/002 test 7, 2.533509 secs [ 129.468518] usbtest 2-1:3.0: TEST 8: read/512 1000 sglists 32 entries 0..1024 bytes /dev/bus/usb/002/002 test 8, 1.890307 secs [ 131.359394] usbtest 2-1:3.0: TEST 9: ch9 (subset) control tests, 1000 times /dev/bus/usb/002/002 test 9, 3.304770 secs [ 134.664683] usbtest 2-1:3.0: TEST 10: queue 32 control calls, 1000 times [ 134.676143] dwc2 ffb00000.usb: dwc2_hsotg_ep_sethalt(ep f15390dd ep0, 0) [ 134.682842] dwc2 ffb00000.usb: dwc2_hsotg_ep_sethalt: can't clear halt on ep0 ... ... !!! repeated 1998 times !!! ... ... [ 165.754296] dwc2 ffb00000.usb: dwc2_hsotg_ep_sethalt(ep f15390dd ep0, 0) [ 165.760994] dwc2 ffb00000.usb: dwc2_hsotg_ep_sethalt: can't clear halt on ep0 /dev/bus/usb/002/002 test 10, 31.104456 secs [ 165.769796] usbtest 2-1:3.0: TEST 11: unlink 1000 reads of 1024 [ 165.796818] usbtest 2-1:3.0: unlink retry ... ... !!! repeated 193 times !!! ... ... [ 209.916767] usbtest 2-1:3.0: unlink retry /dev/bus/usb/002/002 test 11, 46.627111 secs [ 212.397493] usbtest 2-1:3.0: TEST 12: unlink 1000 writes of 1024 [ 214.997119] usbtest 2-1:3.0: unlink retry ... ... !!! repeated 55 times !!! ... ... [ 240.134799] usbtest 2-1:3.0: unlink retry /dev/bus/usb/002/002 test 12, 42.299444 secs [ 254.697545] usbtest 2-1:3.0: TEST 13: set/clear 1000 halts [ 254.711562] dwc2 ffb00000.usb: dwc2_hsotg_ep_sethalt(ep 91286f5d ep1in, 1) [ 254.719117] dwc2 ffb00000.usb: dwc2_hsotg_ep_sethalt(ep 91286f5d ep1in, 0) [ 254.727023] dwc2 ffb00000.usb: dwc2_hsotg_ep_sethalt(ep 4e774b5f ep1out, 1) [ 254.734462] dwc2 ffb00000.usb: dwc2_hsotg_ep_sethalt(ep 4e774b5f ep1out, 0) ... ... !!! repeated 1070+ (lost messages) times !!! ... ... [ 287.277841] dwc2 ffb00000.usb: dwc2_hsotg_ep_sethalt(ep 91286f5d ep1in, 1) [ 287.285096] dwc2 ffb00000.usb: dwc2_hsotg_ep_sethalt(ep 91286f5d ep1in, 0) [ 287.292856] dwc2 ffb00000.usb: dwc2_hsotg_ep_sethalt(ep 4e774b5f ep1out, 1) [ 287.300372] dwc2 ffb00000.usb: dwc2_hsotg_ep_sethalt(ep 4e774b5f ep1out, 0) /dev/bus/usb/002/002 test 13, 32.617536 secs [ 287.315668] usbtest 2-1:3.0: TEST 14: 1000 ep0out, 1..1024 vary 512 /dev/bus/usb/002/002 test 14, 0.434559 secs [ 287.750792] usbtest 2-1:3.0: TEST 15: write 1000 iso, 32 entries of 1024 bytes [ 287.762973] usbtest 2-1:3.0: iso period 8 microframes, wMaxPacket 1024, transactions: 1 [ 287.771034] usbtest 2-1:3.0: total 32000 msec (32000 packets) [ 319.776211] usbtest 2-1:3.0: during the test, 32000 errors out of 32000 /dev/bus/usb/002/002 test 15 --> 5 (Input/output error) [ 319.783673] usbtest 2-1:3.0: TEST 16: read 1000 iso, 32 entries of 1024 bytes [ 319.795312] usbtest 2-1:3.0: iso period 8 microframes, wMaxPacket 1024, transactions: 1 [ 319.803363] usbtest 2-1:3.0: total 32000 msec (32000 packets) [ 351.809253] usbtest 2-1:3.0: during the test, 32000 errors out of 32000 /dev/bus/usb/002/002 test 16 --> 5 (Input/output error) [ 351.816608] usbtest 2-1:3.0: TEST 17: write odd addr 1024 bytes 1000 times core map /dev/bus/usb/002/002 test 17, 0.222856 secs [ 352.040032] usbtest 2-1:3.0: TEST 18: read odd addr 1024 bytes 1000 times core map /dev/bus/usb/002/002 test 18, 0.161525 secs [ 352.202113] usbtest 2-1:3.0: TEST 19: write odd addr 1024 bytes 1000 times premapped [ 352.213592] ------------[ cut here ]------------ [ 352.218197] WARNING: CPU: 1 PID: 258 at drivers/usb/dwc2/hcd.c:2648 dwc2_assign_and_init_hc+0x7dc/0x958 [ 352.227578] Modules linked in: usbtest usb_f_ss_lb g_zero libcomposite altera_sysid [ 352.235245] CPU: 1 PID: 258 Comm: testusb Not tainted 6.1.20-altera #1 [ 352.241755] Hardware name: Altera SOCFPGA [ 352.245761] unwind_backtrace from show_stack+0x18/0x1c [ 352.251013] show_stack from dump_stack_lvl+0x40/0x4c [ 352.256079] dump_stack_lvl from __warn+0x80/0x12c [ 352.260896] __warn from warn_slowpath_fmt+0xc0/0x194 [ 352.265969] warn_slowpath_fmt from dwc2_assign_and_init_hc+0x7dc/0x958 [ 352.272591] dwc2_assign_and_init_hc from dwc2_hcd_select_transactions+0x110/0x1d4 [ 352.280150] dwc2_hcd_select_transactions from _dwc2_hcd_urb_enqueue+0x2c4/0x6a8 [ 352.287541] _dwc2_hcd_urb_enqueue from usb_hcd_submit_urb+0xc4/0x8b0 [ 352.293988] usb_hcd_submit_urb from simple_io+0xb0/0x200 [usbtest] [ 352.300287] simple_io [usbtest] from test_unaligned_bulk+0x74/0x90 [usbtest] [ 352.307449] test_unaligned_bulk [usbtest] from usbtest_do_ioctl+0x658/0x191c [usbtest] [ 352.315474] usbtest_do_ioctl [usbtest] from usbtest_ioctl+0x188/0x288 [usbtest] [ 352.322891] usbtest_ioctl [usbtest] from usbdev_ioctl+0x1e28/0x292c [ 352.329268] usbdev_ioctl from sys_ioctl+0x4ac/0xc40 [ 352.334243] sys_ioctl from ret_fast_syscall+0x0/0x54 [ 352.339294] Exception stack(0xe0971fa8 to 0xe0971ff0) [ 352.344336] 1fa0: 000253b8 00000003 00000003 c00c5512 be9e8b64 be9e8b48 [ 352.352482] 1fc0: 000253b8 00000003 00012f14 00000036 000112a8 b6f94d38 00000000 be9e8b74 [ 352.360621] 1fe0: 00013038 be9e8b38 00010f24 b6eed09c [ 352.365653] ---[ end trace 0000000000000000 ]--- [ 352.370407] zero gadget.0: bad OUT byte, buf[0] = 165 [ 352.375466] dwc2 ffb00000.usb: dwc2_hsotg_ep_sethalt(ep 4e774b5f ep1out, 1) [ 352.382829] usb 2-1: test19 failed, iterations left 998, status -32 (not 0) /dev/bus/usb/002/002 test 19 --> 32 (Broken pipe) [ 352.390217] dwc2 ffb00000.usb: dwc2_hsotg_start_req: ep1 is stalled [ 352.400828] usbtest 2-1:3.0: TEST 20: read odd addr 1024 bytes 1000 times premapped [ 352.408782] usbtest 2-1:3.0: guard byte[0] 0 (not 165) [ 352.413927] usb 2-1: test20 failed, iterations left 999, status -22 (not 0) /dev/bus/usb/002/002 test 20 --> 22 (Invalid argument) [ 352.421541] dwc2 ffb00000.usb: dwc2_hsotg_start_req: ep1 is stalled [ 352.432587] usbtest 2-1:3.0: TEST 21: 1000 ep0out odd addr, 1..1024 vary 512 /dev/bus/usb/002/002 test 21, 0.425480 secs [ 352.858398] dwc2 ffb00000.usb: dwc2_hsotg_start_req: ep1 is stalled [ 352.868890] usbtest 2-1:3.0: TEST 22: write 1000 iso odd, 32 entries of 1024 bytes [ 352.876700] usbtest 2-1:3.0: iso period 8 microframes, wMaxPacket 1024, transactions: 1 [ 352.884794] usbtest 2-1:3.0: total 32000 msec (32000 packets) [ 384.890213] usbtest 2-1:3.0: during the test, 32000 errors out of 32000 /dev/bus/usb/002/002 test 22 --> 5 (Input/output error) [ 384.897393] dwc2 ffb00000.usb: dwc2_hsotg_start_req: ep1 is stalled [ 384.908543] usbtest 2-1:3.0: TEST 23: read 1000 iso odd, 32 entries of 1024 bytes [ 384.916206] usbtest 2-1:3.0: iso period 8 microframes, wMaxPacket 1024, transactions: 1 [ 384.924270] usbtest 2-1:3.0: total 32000 msec (32000 packets) [ 416.930259] usbtest 2-1:3.0: during the test, 32000 errors out of 32000 /dev/bus/usb/002/002 test 23 --> 5 (Input/output error) [ 416.937449] dwc2 ffb00000.usb: dwc2_hsotg_start_req: ep1 is stalled [ 416.948589] usbtest 2-1:3.0: TEST 24: unlink from 1000 queues of 32 1024-byte writes [ 416.962234] usbtest 2-1:3.0: unlink queued writes failed -32, iterations left 1000 /dev/bus/usb/002/002 test 24 --> 32 (Broken pipe) [ 416.970293] dwc2 ffb00000.usb: dwc2_hsotg_start_req: ep1 is stalled [ 416.981511] dwc2 ffb00000.usb: dwc2_hsotg_start_req: ep1 is stalled [ 416.988579] dwc2 ffb00000.usb: dwc2_hsotg_start_req: ep1 is stalled [ 416.995085] usbtest 2-1:3.0: TEST 27: bulk write 31Mbytes [ 417.003318] usbtest 2-1:3.0: during the test, 32 errors out of 0 /dev/bus/usb/002/002 test 27 --> 5 (Input/output error) [ 417.010205] dwc2 ffb00000.usb: dwc2_hsotg_start_req: ep1 is stalled [ 417.021162] usbtest 2-1:3.0: TEST 28: bulk read 31Mbytes /dev/bus/usb/002/002 test 28, 2.342144 secs [ 419.363675] dwc2 ffb00000.usb: dwc2_hsotg_start_req: ep1 is stalled [ 419.373998] usbtest 2-1:3.0: TEST 29: Clear toggle between bulk writes 1000 times [ 419.381607] dwc2 ffb00000.usb: dwc2_hsotg_ep_sethalt(ep 4e774b5f ep1out, 0) [ 429.918856] usb 2-1: test_toggle_sync failed, iterations left 0, status -110 (not 0) [ 429.926602] usbtest 2-1:3.0: toggle sync failed, iterations left 999 /dev/bus/usb/002/002 test 29 --> 22 (Invalid argument) root@board06F886:~#
In short, test 1-14 and 17-18 seem to succeed. Test 15, 16, 19-29 fail with a variety of error codes. Most notable is the stack trace during test 19 (`dwc2_assign_and_init_hc`).
Executing the test from another machine is successful. However, it still produces a lot of log entries ("dwc2_hsotg_ep_sethalt" + "can't clear halt on ep0" (device side) & "unlink retry" (host)).
We do not know how to further analyze this issue. It is unclear whether this should be an issue in software (configuration) only, or could have a root cause in hardware as well.
Any suggestions for methods we could use to gain a better understanding of this issue would be much appreciated.
Thanks!
Thomas
PS:
Our device tree looks as follows:
hps_0_usb0: usb@0xffb00000 { compatible = "snps,dwc-otg-22.1", "snps,dwc-otg", "snps,dwc2"; reg = <0xffb00000 0x00040000>; interrupt-parent = <&hps_0_arm_gic_0>; interrupts = <0 125 4>; clocks = <&usb_mp_clk>; clock-names = "otg"; /* embeddedsw.dts.params.clock-names type STRING */ dev-nperio-tx-fifo-size = <4096>; /* embeddedsw.dts.params.dev-nperio-tx-fifo-size type NUMBER */ dev-perio-tx-fifo-size = "<512 512 512 512 512 512 512 512 512 512 512 512 512 512 512>"; /* embeddedsw.dts.params.dev-perio-tx-fifo-size type STRING */ dev-rx-fifo-size = <512>; /* embeddedsw.dts.params.dev-rx-fifo-size type NUMBER */ dev-tx-fifo-size = "<512 512 512 512 512 512 512 512 512 512 512 512 512 512 512>"; /* embeddedsw.dts.params.dev-tx-fifo-size type STRING */ dma-mask = <268435455>; /* embeddedsw.dts.params.dma-mask type NUMBER */ enable-dynamic-fifo = <1>; /* embeddedsw.dts.params.enable-dynamic-fifo type NUMBER */ host-nperio-tx-fifo-size = <2560>; /* embeddedsw.dts.params.host-nperio-tx-fifo-size type NUMBER */ host-perio-tx-fifo-size = <2560>; /* embeddedsw.dts.params.host-perio-tx-fifo-size type NUMBER */ host-rx-fifo-size = <2560>; /* embeddedsw.dts.params.host-rx-fifo-size type NUMBER */ phy-names = "usb2-phy"; /* embeddedsw.dts.params.phy-names type STRING */ status = "okay"; /* embeddedsw.dts.params.status type STRING */ ulpi-ddr = <0>; /* embeddedsw.dts.params.ulpi-ddr type NUMBER */ voltage-switch = <0>; /* embeddedsw.dts.params.voltage-switch type NUMBER */ phys = <&usbphy0>; /* appended from boardinfo */ }; //end usb@0xffb00000 (hps_0_usb0) hps_0_usb1: usb@0xffb40000 { compatible = "snps,dwc-otg-22.1", "snps,dwc-otg", "snps,dwc2"; reg = <0xffb40000 0x00040000>; interrupt-parent = <&hps_0_arm_gic_0>; interrupts = <0 128 4>; clocks = <&usb_mp_clk>; clock-names = "otg"; /* embeddedsw.dts.params.clock-names type STRING */ dev-nperio-tx-fifo-size = <4096>; /* embeddedsw.dts.params.dev-nperio-tx-fifo-size type NUMBER */ dev-perio-tx-fifo-size = "<512 512 512 512 512 512 512 512 512 512 512 512 512 512 512>"; /* embeddedsw.dts.params.dev-perio-tx-fifo-size type STRING */ dev-rx-fifo-size = <512>; /* embeddedsw.dts.params.dev-rx-fifo-size type NUMBER */ dev-tx-fifo-size = "<512 512 512 512 512 512 512 512 512 512 512 512 512 512 512>"; /* embeddedsw.dts.params.dev-tx-fifo-size type STRING */ dma-mask = <268435455>; /* embeddedsw.dts.params.dma-mask type NUMBER */ enable-dynamic-fifo = <1>; /* embeddedsw.dts.params.enable-dynamic-fifo type NUMBER */ host-nperio-tx-fifo-size = <2560>; /* embeddedsw.dts.params.host-nperio-tx-fifo-size type NUMBER */ host-perio-tx-fifo-size = <2560>; /* embeddedsw.dts.params.host-perio-tx-fifo-size type NUMBER */ host-rx-fifo-size = <2560>; /* embeddedsw.dts.params.host-rx-fifo-size type NUMBER */ phy-names = "usb2-phy"; /* embeddedsw.dts.params.phy-names type STRING */ status = "okay"; /* embeddedsw.dts.params.status type STRING */ ulpi-ddr = <0>; /* embeddedsw.dts.params.ulpi-ddr type NUMBER */ voltage-switch = <0>; /* embeddedsw.dts.params.voltage-switch type NUMBER */ phys = <&usbphy1>; /* appended from boardinfo */ }; //end usb@0xffb40000 (hps_0_usb1)
