Re:Debugging testusb problems

Thomas16 · ‎09-26-2023

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)

aikeu · ‎10-01-2023

Hi Thomas,

May I know what do you mean by "Executing the test from another machine is successful"

I would like to know more about your setup.

Thanks.

Regards,

Aik Eu

Thomas16 · ‎10-02-2023

Hi Aik,

We have a board with two USB ports. One of them is configured as "gadget", the other as host.

In the "other machine" (laptop) test scenario. We connect the board' gadget USB to the USB port of the laptop. The laptop recognizes the USB device. On the laptop, we can execute the `usbtest`. This means that the laptop is performing the test steps. This works fine.

/--------------\                     /-----------\
| Laptop       | host         gadget |     Board |
|              |======= USB =======> |           |
|   $ usbtest  |                     | g_zero    |
\--------------/                     \-----------/

In the "board-only" test scenario. We connect the board' gadget USB to the board' host USB. The logs indicate that the USB device is correctly recognized. But executing `usbtest` on the board, leads to some successful and some failed test steps.

/--------------\
| Board        | gadget
|       g_zero |=====\\
|              |      \\
|              |      || USB
| $ usbtest    |      //
|              |=====//
|              | host
\--------------/

I hope this makes it more clear.

Thomas

aikeu · ‎10-04-2023

Hi Thomas16,

I am still consulting the team regarding the matter. Will get back to you when there is new info.

Thanks.

Regards,

Aik Eu

aikeu · ‎10-06-2023

Hi Thomas16,

Do you have another soc board which can act as a host to perform the usb test on the cyclone V board to act as a gadget?

Thanks.

Regards,

Aik Eu

aikeu · ‎10-08-2023

Hi Thomas16,

May I know is there any follow up from the prevous comment?

Thanks.

Regards,

Aik Eu

Thomas16 · ‎10-09-2023

Hi Aik Eu,

Thanks for getting back to me. I've setup two board, running the same firmware. It produces the same results.

On the host side, the testusb output is

# ./testusb -a
high speed      /dev/bus/usb/002/004    0
/dev/bus/usb/002/004 test 0,    0.004049 secs
/dev/bus/usb/002/004 test 1,    0.146089 secs
/dev/bus/usb/002/004 test 2,    0.278257 secs
/dev/bus/usb/002/004 test 3,    0.150696 secs
/dev/bus/usb/002/004 test 4,    0.278766 secs
/dev/bus/usb/002/004 test 5,    3.139878 secs
/dev/bus/usb/002/004 test 6,    2.610817 secs
/dev/bus/usb/002/004 test 7,    3.137456 secs
/dev/bus/usb/002/004 test 8,    2.619083 secs
/dev/bus/usb/002/004 test 9,    2.862658 secs
/dev/bus/usb/002/004 test 10,   30.767096 secs
/dev/bus/usb/002/004 test 11,   47.345873 secs
/dev/bus/usb/002/004 test 12,   46.529739 secs
/dev/bus/usb/002/004 test 13,   31.737337 secs
/dev/bus/usb/002/004 test 14 --> 22 (Invalid argument)
/dev/bus/usb/002/004 test 17,    0.156749 secs
/dev/bus/usb/002/004 test 18,    0.147973 secs
/dev/bus/usb/002/004 test 19 --> 32 (Broken pipe)
/dev/bus/usb/002/004 test 20 --> 22 (Invalid argument)
/dev/bus/usb/002/004 test 21 --> 22 (Invalid argument)
/dev/bus/usb/002/004 test 24 --> 32 (Broken pipe)
/dev/bus/usb/002/004 test 27 --> 5 (Input/output error)
/dev/bus/usb/002/004 test 28,    2.313950 secs
/dev/bus/usb/002/004 test 29 --> 22 (Invalid argument)

Dmesg (host side) produces

[  344.870543] usbtest 2-1:3.0: Linux gadget zero
[  344.875000] usbtest 2-1:3.0: high-speed {control in/out bulk-in bulk-out} tests (+alt)
[  415.732606] usbtest 2-1:3.0: TEST 0:  NOP
[  415.737052] usbtest 2-1:3.0: TEST 1:  write 1024 bytes 1000 times
[  415.883544] usbtest 2-1:3.0: TEST 2:  read 1024 bytes 1000 times
[  416.162200] usbtest 2-1:3.0: TEST 3:  write/1024 0..1024 bytes 1000 times
[  416.313294] usbtest 2-1:3.0: TEST 4:  read/1024 0..1024 bytes 1000 times
[  416.592455] usbtest 2-1:3.0: TEST 5:  write 1000 sglists 32 entries of 1024 bytes
[  419.733174] usbtest 2-1:3.0: TEST 6:  read 1000 sglists 32 entries of 1024 bytes
[  422.345047] usbtest 2-1:3.0: TEST 7:  write/1024 1000 sglists 32 entries 0..1024 bytes
[  425.482910] usbtest 2-1:3.0: TEST 8:  read/1024 1000 sglists 32 entries 0..1024 bytes
[  428.102398] usbtest 2-1:3.0: TEST 9:  ch9 (subset) control tests, 1000 times
[  430.966457] usbtest 2-1:3.0: TEST 10:  queue 32 control calls, 1000 times
[  461.734217] usbtest 2-1:3.0: TEST 11:  unlink 1000 reads of 1024
[  463.150059] usbtest 2-1:3.0: unlink retry
[            ] ...REPEATED...
[  508.740029] usbtest 2-1:3.0: unlink retry
[  509.080496] usbtest 2-1:3.0: TEST 12:  unlink 1000 writes of 1024
[  509.840028] usbtest 2-1:3.0: unlink retry
[            ] ...REPEATED...
[  553.538165] usbtest 2-1:3.0: unlink retry
[  555.610635] usbtest 2-1:3.0: TEST 13:  set/clear 1000 halts
[  587.348359] usbtest 2-1:3.0: TEST 14:  1000 ep0out, 1..1024 vary 1024
[  587.357009] usbtest 2-1:3.0: TEST 17:  write odd addr 1024 bytes 1000 times core map
[  587.514579] usbtest 2-1:3.0: TEST 18:  read odd addr 1024 bytes 1000 times core map
[  587.663348] usbtest 2-1:3.0: TEST 19:  write odd addr 1024 bytes 1000 times premapped
[  587.671233] ------------[ cut here ]------------
[  587.675839] WARNING: CPU: 1 PID: 324 at drivers/usb/dwc2/hcd.c:2648 dwc2_assign_and_init_hc+0x7dc/0x9b4
[  587.685224] Modules linked in: usbtest
[  587.688982] CPU: 1 PID: 324 Comm: testusb Not tainted 6.1.20-altera #1
[  587.695491] Hardware name: Altera SOCFPGA
[  587.699498]  unwind_backtrace from show_stack+0x18/0x1c
[  587.704751]  show_stack from dump_stack_lvl+0x40/0x4c
[  587.709823]  dump_stack_lvl from __warn+0x80/0x12c
[  587.714647]  __warn from warn_slowpath_fmt+0xc0/0x194
[  587.719723]  warn_slowpath_fmt from dwc2_assign_and_init_hc+0x7dc/0x9b4
[  587.726348]  dwc2_assign_and_init_hc from dwc2_hcd_select_transactions+0x110/0x1d4
[  587.733914]  dwc2_hcd_select_transactions from _dwc2_hcd_urb_enqueue+0x2c4/0x6a8
[  587.741311]  _dwc2_hcd_urb_enqueue from usb_hcd_submit_urb+0xc4/0x9bc
[  587.747765]  usb_hcd_submit_urb from simple_io+0xb0/0x200 [usbtest]
[  587.754064]  simple_io [usbtest] from test_unaligned_bulk+0x74/0x90 [usbtest]
[  587.761225]  test_unaligned_bulk [usbtest] from usbtest_do_ioctl+0x658/0x191c [usbtest]
[  587.769249]  usbtest_do_ioctl [usbtest] from usbtest_ioctl+0x188/0x288 [usbtest]
[  587.776668]  usbtest_ioctl [usbtest] from usbdev_ioctl+0x1e24/0x2958
[  587.783050]  usbdev_ioctl from sys_ioctl+0x4ac/0xc40
[  587.788027]  sys_ioctl from ret_fast_syscall+0x0/0x54
[  587.793077] Exception stack(0xe1065fa8 to 0xe1065ff0)
[  587.798119] 5fa0:                   000253b8 00000002 00000003 c00c5512 bef96ab4 bef96a98
[  587.806266] 5fc0: 000253b8 00000002 00012f14 00000036 000112a8 b6fd0d38 00000000 bef96ac4
[  587.814406] 5fe0: 00013038 bef96a88 00010f24 b6f2909c
[  587.819437] ---[ end trace 0000000000000000 ]---
[  587.908919] usb 2-1: test19 failed, iterations left 992, status -32 (not 0)
[  587.923027] usbtest 2-1:3.0: TEST 20:  read odd addr 1024 bytes 1000 times premapped
[  587.931127] usbtest 2-1:3.0: guard byte[0] 0 (not 165)
[  587.936274] usb 2-1: test20 failed, iterations left 999, status -22 (not 0)
[  587.950642] usbtest 2-1:3.0: TEST 21:  1000 ep0out odd addr, 1..1024 vary 1024
[  587.977954] usbtest 2-1:3.0: TEST 24:  unlink from 1000 queues of 32 1024-byte writes
[  587.988256] usbtest 2-1:3.0: unlink queued writes failed -32, iterations left 1000
[  588.016186] usbtest 2-1:3.0: TEST 27: bulk write 31Mbytes
[  588.025442] usbtest 2-1:3.0: during the test, 32 errors out of 0
[  588.038788] usbtest 2-1:3.0: TEST 28: bulk read 31Mbytes
[  590.359391] usbtest 2-1:3.0: TEST 29: Clear toggle between bulk writes 1000 times
[  600.820105] usb 2-1: test_toggle_sync failed, iterations left 0, status -110 (not 0)
[  600.827852] usbtest 2-1:3.0: toggle sync failed, iterations left 999

and dmesg on the gadget side produces

[  428.402140] zero gadget.0: Gadget Zero, version: Cinco de Mayo 2008
[  428.408514] zero gadget.0: zero ready
[  428.412189] dwc2 ffb00000.usb: bound driver zero
[  455.676134] dwc2 ffb00000.usb: new device is high-speed
[  455.896122] dwc2 ffb00000.usb: new device is high-speed
[  456.046118] dwc2 ffb00000.usb: new address 4
[  542.190016] dwc2 ffb00000.usb: dwc2_hsotg_ep_sethalt(ep 06938844 ep0, 0)
[  542.196727] dwc2 ffb00000.usb: dwc2_hsotg_ep_sethalt: can't clear halt on ep0
[  542.205002] dwc2 ffb00000.usb: dwc2_hsotg_ep_sethalt(ep 06938844 ep0, 0)
[  542.211706] dwc2 ffb00000.usb: dwc2_hsotg_ep_sethalt: can't clear halt on ep0
...REPEATED...
[  572.912673] dwc2 ffb00000.usb: dwc2_hsotg_ep_sethalt(ep 06938844 ep0, 0)
[  572.919368] dwc2 ffb00000.usb: dwc2_hsotg_ep_sethalt: can't clear halt on ep0
[  572.926905] systemd-journald[69]: /dev/kmsg buffer overrun, some messages lost.
[  572.934774] dwc2 ffb00000.usb: dwc2_hsotg_ep_sethalt(ep 06938844 ep0, 0)
[  572.941464] dwc2 ffb00000.usb: dwc2_hsotg_ep_sethalt: can't clear halt on ep0
[  572.951634] systemd-journald[69]: /dev/kmsg buffer overrun, some messages lost.
[  666.832135] dwc2 ffb00000.usb: dwc2_hsotg_ep_sethalt(ep f1d60933 ep1in, 1)
[  666.839990] dwc2 ffb00000.usb: dwc2_hsotg_ep_sethalt(ep f1d60933 ep1in, 0)
[  666.847483] dwc2 ffb00000.usb: dwc2_hsotg_ep_sethalt(ep 2c511fcf ep1out, 1)
[  666.854821] dwc2 ffb00000.usb: dwc2_hsotg_ep_sethalt(ep 2c511fcf ep1out, 0)
...REPEATED...
[  698.533924] dwc2 ffb00000.usb: dwc2_hsotg_ep_sethalt(ep f1d60933 ep1in, 1)
[  698.541120] dwc2 ffb00000.usb: dwc2_hsotg_ep_sethalt(ep f1d60933 ep1in, 0)
[  698.548597] dwc2 ffb00000.usb: dwc2_hsotg_ep_sethalt(ep 2c511fcf ep1out, 1)
[  698.555937] dwc2 ffb00000.usb: dwc2_hsotg_ep_sethalt(ep 2c511fcf ep1out, 0)
[  698.564138] systemd-journald[69]: /dev/kmsg buffer overrun, some messages lost.
[  699.039391] zero gadget.0: bad OUT byte, buf[0] = 165
[  699.044456] dwc2 ffb00000.usb: dwc2_hsotg_ep_sethalt(ep 2c511fcf ep1out, 1)
[  699.051523] zero gadget.0: bad OUT byte, buf[0] = 165
[  699.056571] dwc2 ffb00000.usb: dwc2_hsotg_ep_sethalt(ep 2c511fcf ep1out, 1)
[  699.063632] zero gadget.0: bad OUT byte, buf[0] = 165
[  699.068679] dwc2 ffb00000.usb: dwc2_hsotg_ep_sethalt(ep 2c511fcf ep1out, 1)
[  699.075719] zero gadget.0: bad OUT byte, buf[0] = 165
[  699.080763] dwc2 ffb00000.usb: dwc2_hsotg_ep_sethalt(ep 2c511fcf ep1out, 1)
[  699.087800] zero gadget.0: bad OUT byte, buf[0] = 165
[  699.092845] dwc2 ffb00000.usb: dwc2_hsotg_ep_sethalt(ep 2c511fcf ep1out, 1)
[  699.099880] zero gadget.0: bad OUT byte, buf[0] = 165
[  699.104925] dwc2 ffb00000.usb: dwc2_hsotg_ep_sethalt(ep 2c511fcf ep1out, 1)
[  699.111961] zero gadget.0: bad OUT byte, buf[0] = 165
[  699.117007] dwc2 ffb00000.usb: dwc2_hsotg_ep_sethalt(ep 2c511fcf ep1out, 1)
[  699.131847] dwc2 ffb00000.usb: dwc2_hsotg_start_req: ep1 is stalled
[  699.159461] dwc2 ffb00000.usb: dwc2_hsotg_start_req: ep1 is stalled
[  699.173742] dwc2 ffb00000.usb: dwc2_hsotg_start_req: ep1 is stalled
[  699.180303] dwc2 ffb00000.usb: dwc2_hsotg_start_req: ep1 is stalled
[  699.186816] dwc2 ffb00000.usb: dwc2_hsotg_start_req: ep1 is stalled
[  699.212008] dwc2 ffb00000.usb: dwc2_hsotg_start_req: ep1 is stalled
[  699.218567] dwc2 ffb00000.usb: dwc2_hsotg_start_req: ep1 is stalled
[  699.225048] dwc2 ffb00000.usb: dwc2_hsotg_start_req: ep1 is stalled
[  699.247607] dwc2 ffb00000.usb: dwc2_hsotg_start_req: ep1 is stalled
[  701.568207] dwc2 ffb00000.usb: dwc2_hsotg_start_req: ep1 is stalled
[  701.582168] dwc2 ffb00000.usb: dwc2_hsotg_ep_sethalt(ep 2c511fcf ep1out, 0)

Good thing to try! Unfortunately, I'm not sure how to proceed.

aikeu · ‎10-10-2023

Hi Thomas16,

I think there is the limitation for soc board to perform all the available test under USBtest due to some configuration settings which relates to the USB operation.

I think will need to know which type of test which you required to run. Some of the common test which mentioned under the readme should be passing but eventually not all the test will be expected to pass.

http://www.linux-usb.org/usbtest/

Thanks.

Regards,

Aik Eu

Thomas16 · ‎10-13-2023

Hi Aik Eu,

Thank you pointing out that documentation. It was insightful indeed. We now estimate that the failing tests are indeed not a problem.

However, the documentation lists using an Ethernet gadget as a good method on verifying USB. Coincidentally, this is exactly the reason we started looking into usbtest. When performing benchmarks on our USB device port with Ethernet gadget we are dealing with packet loss. Most notably, packet loss specifically in the direction of device -> host. We are using `iperf3` to perform the benchmark.

[ ID][Role] Interval           Transfer     Bitrate         Retr
[  5][RX-S]   0.00-125.00 sec   735 MBytes  49.3 Mbits/sec                  receiver
[  8][TX-S]   0.00-125.00 sec  1.00 GBytes  68.9 Mbits/sec   88             sender

This is also visible in network statistics of `ip-tools`.

How would you suggest us to debug this?

Regards,

Thomas

aikeu · ‎10-17-2023

Hi Thomas16,

Sorry that I not able to find any information related to USB ethernet gadget test which may help. I think can check if the related USB drivers are present when running the test.

Thanks.

Regards,

Aik Eu

aikeu · ‎10-19-2023

Hi Thomas16,

I will close the thread if no further question.

Thanks.

Regards,

Aik Eu

aikeu · ‎10-22-2023

Hi Thomas16,

I am closing the thread for now. This thread will be transitioned to community support. If you have a new question, feel free to open a new thread to get the support from Intel experts. Otherwise, the community users will continue to help you on this thread. Thank you.

p/s: If any answer from the community or Intel Support are helpful, please feel free to give best answer or rate 4/5 survey.

Thanks.

Regards,

Aik Eu

Debugging testusb problems

Board|Test Design|Layout

I|O