New: ASMedia ASM4242 USB 3.2 xHCI Controller gives command timeout

https://bugzilla.kernel.org/show_bug.cgi?id=220936

            Bug ID: 220936
           Summary: ASMedia ASM4242 USB 3.2 xHCI Controller gives command
                    timeout
           Product: Drivers
           Version: 2.5
          Hardware: All
                OS: Linux
            Status: NEW
          Severity: normal
          Priority: P3
         Component: USB
          Assignee: [email protected]
          Reporter: [email protected]
        Regression: No

Created attachment 309123
--> https://bugzilla.kernel.org/attachment.cgi?id=309123&action=edit
dmesg log with the warning

After enabling the USB 4 controller on my motherboard (previously disabled to use the lanes for an NVMe), I've started seeing a warning about a command / suspend timeout for that controller.

I'm running mainline 6.18.3 on top of Debian Sid, the motherboard is an MSI X870E Tomahawk WiFi. This also happens on 6.17 kernels, I didn't test any further back.

I've attached a full log, but the warning I get:

```
[  160.064098] xhci_hcd 0000:77:00.0: WARN: xHC CMD_RUN timeout
[  160.064117] xhci_hcd 0000:77:00.0: PM: suspend_common(): xhci_pci_suspend
[xhci_pci] returns -110
[  160.064124] xhci_hcd 0000:77:00.0: can't suspend (hcd_pci_runtime_suspend
[usbcore] returned -110)
```

Corresponding part of lspci:

```
77:00.0 USB controller: ASMedia Technology Inc. ASM4242 USB 3.2 xHCI Controller
(rev 01)
78:00.0 USB controller: ASMedia Technology Inc. ASM4242 USB 4 / Thunderbolt 3
Host Router (rev 01)
79:00.0 Non-Essential Instrumentation [1300]: Advanced Micro Devices, Inc.
[AMD] Raphael/Granite Ridge PCIe Dummy Function (rev c3)
79:00.2 Encryption controller: Advanced Micro Devices, Inc. [AMD] Family 19h
PSP/CCP
79:00.3 USB controller: Advanced Micro Devices, Inc. [AMD] Raphael/Granite
Ridge USB 3.1 xHCI
79:00.4 USB controller: Advanced Micro Devices, Inc. [AMD] Raphael/Granite
Ridge USB 3.1 xHCI
79:00.6 Audio device: Advanced Micro Devices, Inc. [AMD] Ryzen HD Audio
Controller
7a:00.0 USB controller: Advanced Micro Devices, Inc. [AMD] Raphael/Granite
Ridge USB 2.0 xHCI
```

Sorry if this is the wrong category, I wasn't sure exactly where to put it

You may reply to this email to add a comment.

You are receiving this mail because:
You are watching the assignee of the bug.

https://bugzilla.kernel.org/show_bug.cgi?id=220936

--- Comment #1 from Stuart Hayhurst ([email protected]) --- After the error is thrown the USB 4 ports attached completely stop working, and don't recognise anything plugged in.

Before the error is thrown, it still seems very unhappy.

Mice and keyboards are basically non-functional. Both devices tested were Logitech HID++ peripherals (G502 mouse, G915 TKL keyboard), and took ~10 seconds to be completely detected / initialised by hid-logitech-hidpp. Afterwards, the keyboard is totally unresponsive, and the mouse position updates every now and then. Normally, the HID++ part would be initialised immediately after being interacted with, and be completely smooth.

USB storage devices (and NVMes over Thunderbolt) take a long time to open for benchmarking, but afterwards their throughput is as expected.

The controller will also complain with errors in the format of [ 293.922068] xhci_hcd 0000:77:00.0: bad transfer trb length 13 in event trb when a device is plugged in, but the size seems to vary.

I tried looking for firmware updates, but MSI doesn't seem to have published any. fwupdmgr get-devices reports the current version as 200011.240802.

You may reply to this email to add a comment.

You are receiving this mail because:
You are watching the assignee of the bug.

https://bugzilla.kernel.org/show_bug.cgi?id=220936

--- Comment #2 from Stuart Hayhurst ([email protected]) --- I had another go at troubleshooting, disabling ASPM doesn't seem to help.

If I can get a device connected without the controller giving up, when I unplug it I get:

```
[  243.504068] xhci_hcd 0000:77:00.0: WARN Set TR Deq Ptr cmd failed due to
incorrect slot or ep state.
```

When I shut the computer down, if the controller hasn't already given up I see the previously mentioned warning about command timeouts. Sometimes it throws it when plugging a device in, but this isn't as reliable.

I tested it on Windows 11, and everything seems to work flawlessly.

You may reply to this email to add a comment.

You are receiving this mail because:
You are watching the assignee of the bug.

https://bugzilla.kernel.org/show_bug.cgi?id=220936

Michał Pecio ([email protected]) changed:

What |Removed |Added
----------------------------------------------------------------------------
CC| |[email protected]

--- Comment #3 from Michał Pecio ([email protected]) --- That's some bizarre behavior. The CMD_RUN timeout on suspend probably occurs due to runtime autosuspend, you can disable that with

echo on > /sys/bus/pci/devices/0000:77:00.0/power/control

I wonder if this would improve anything? If not, try also

echo 0000:77:00.0 > /sys/bus/pci/drivers/xhci_hcd/unbind echo 0000:77:00.0 > /sys/bus/pci/drivers/xhci_hcd/bind

and maybe check if power/control stays 'on' and doesn't flip back to 'auto'.

If any overclocking is involved, try without it.

You may reply to this email to add a comment.

You are receiving this mail because:
You are watching the assignee of the bug.

https://bugzilla.kernel.org/show_bug.cgi?id=220936

--- Comment #4 from Stuart Hayhurst ([email protected]) --- Thanks, disabling autosuspend seems to solve the CMD_RUN timeout, I can at least connect and disconnect devices now (I only tested, maybe 10 unplugs and replugs, but that far beats any previous attempt).

The device is still unbearably slow though, it still takes 10+ seconds to get my mouse to finish connecting:

```
[ 8344.769964] usb 5-1.1: new full-speed USB device number 4 using xhci_hcd
[ 8345.029328] usb 5-1.1: New USB device found, idVendor=046d, idProduct=c539,
bcdDevice=39.06
[ 8345.029333] usb 5-1.1: New USB device strings: Mfr=1, Product=2,
SerialNumber=0
[ 8345.029334] usb 5-1.1: Product: USB Receiver
[ 8345.029335] usb 5-1.1: Manufacturer: Logitech
[ 8345.049306] logitech-djreceiver 0003:046D:C539.000C: hidraw0: USB HID v1.11
Keyboard [Logitech USB Receiver] on usb-0000:77:00.0-1.1/input0
[ 8345.104692] logitech-djreceiver 0003:046D:C539.000D: hiddev0,hidraw1: USB
HID v1.11 Mouse [Logitech USB Receiver] on usb-0000:77:00.0-1.1/input1
[ 8345.160297] logitech-djreceiver 0003:046D:C539.000E: hiddev1,hidraw2: USB
HID v1.11 Device [Logitech USB Receiver] on usb-0000:77:00.0-1.1/input2
[ 8347.111395] logitech-djreceiver 0003:046D:C539.000E: device of type eQUAD
Lightspeed 1 (0x0c) connected on slot 1
[ 8347.127481] input: Logitech G502 as
/devices/pci0000:00/0000:00:02.2/0000:15:00.0/0000:16:02.0/0000:77:00.0/usb5/5-1/5-1.1/5-1.1:1.2/0003:046D:C539.000E/0003:046D:407F.000F/input/input31
[ 8347.205902] logitech-hidpp-device 0003:046D:407F.000F: input,hidraw4: USB
HID v1.11 Keyboard [Logitech G502] on usb-0000:77:00.0-1.1/input2:1
[ 8357.290785] logitech-hidpp-device 0003:046D:407F.000F: HID++ 4.2 device
connected.
```

Unbind and rebind didn't improve anything.

I believe I've had this problem with 2 different CPUs (both R7 7700Xs, but the first one had a useless memory controller). It's undervolted, so I'll give it a try without that.

You may reply to this email to add a comment.

You are receiving this mail because:
You are watching the assignee of the bug.

https://bugzilla.kernel.org/show_bug.cgi?id=220936

--- Comment #5 from Stuart Hayhurst ([email protected]) --- Dropping the undervolt didn't have any effect, but it might actually be the that it doesn't like Logitech wireless peripherals connected through USB hubs...

Connecting my mouse dongle to it via an adapter is fine.

Connecting an NVMe via an enclosure is fine.

Connecting a USB stick via an adapter is fine.

Connecting a USB stick via a USB hub is fine.

Connecting my mouse or keyboard dongle to it via a USB hub is extremely slow.

Connecting my headset dongle to it via a USB hub is fine.

Last time I tested this I tried 2 different USB hubs to make sure it wasn't the hub acting up, and the hubs both work fine on ports connected to a different controller. Unfortunately I only have 1 USB hub with me to test with at the moment, so I can't reconfirm that.

You may reply to this email to add a comment.

You are receiving this mail because:
You are watching the assignee of the bug.

https://bugzilla.kernel.org/show_bug.cgi?id=220936

--- Comment #6 from Stuart Hayhurst ([email protected]) --- Updating the firmware just released by my motherboard vendor has fixed the Logitech device issues, it seems like it's just the power management issue now.

You may reply to this email to add a comment.

You are receiving this mail because:
You are watching the assignee of the bug.

https://bugzilla.kernel.org/show_bug.cgi?id=220936

--- Comment #7 from Stuart Hayhurst ([email protected]) --- To be more specific, I still see:

```
[  160.064098] xhci_hcd 0000:77:00.0: WARN: xHC CMD_RUN timeout
[  160.064117] xhci_hcd 0000:77:00.0: PM: suspend_common(): xhci_pci_suspend
[xhci_pci] returns -110
[  160.064124] xhci_hcd 0000:77:00.0: can't suspend (hcd_pci_runtime_suspend
[usbcore] returned -110)
```

But the first line seems to vary. I've also seen:

```
[ 26.056278] xhci_hcd 0000:77:00.0: Clearing Run/Stop bit failed -110
```

and

```
[ 26.056278] xhci_hcd 0000:77:00.0: Host halt failed, -110
```

I also still see [ 105.189845] xhci_hcd 0000:77:00.0: bad transfer trb length 4 in event trb on systemctl suspend or the resume, or sometimes when a device is plugged in.

The new firmware has fixed incompatibilities with specific devices, and it's also a lot less likely to completely stop working now.

I also see the suspend error quite often when shutting down if the error didn't occur in the first few minutes after booting. I've seen it on a friend's machine with an ASM4242 (with a different motherboard). I've also reported it to my motherboard vendor (MSI), but they seem to be having a hard time reproducing it.

You may reply to this email to add a comment.

You are receiving this mail because:
You are watching the assignee of the bug.

https://bugzilla.kernel.org/show_bug.cgi?id=220936

--- Comment #8 from Michał Pecio ([email protected]) --- "Clearing Run/Stop failed" is same thing as "xHC CMD_RUN timeout", somebody reworded the error message, that's all. The chip should stop operation within 16ms of clearing the Run/Stop bit, but it still hasn't after 64ms.

Passing quirks=0x20000 parameter to xhci_hcd increases the timeout further to 640ms, so you could try that.

The issue occurs during PCI auto PM attempt (shutting down the whole controller when all USB devices are idle) if you are seeing the message in normal operation. Does it also show up when suspending the system?

Can we know if there are successful suspend/resume cycles, or does it fail on the first try every time? Enabling this will produce some debug info in dmesg:

echo 'func xhci_suspend +p' >/proc/dynamic_debug/control echo 'func xhci_resume +p' >/proc/dynamic_debug/control

The cause may be some remaining bug in the chip's FW or possibly out of spec behavior by the kernel. For one, USB subsystem is not particularly good at stopping drivers from trying to communicate with suspended devices and some particular drivers may have bugs like that. The issue would go away when the offending device is disconnected.

Are you able to compile and test patches?

You may reply to this email to add a comment.

You are receiving this mail because:
You are watching the assignee of the bug.

https://bugzilla.kernel.org/show_bug.cgi?id=220936

--- Comment #9 from Stuart Hayhurst ([email protected]) --- Hi,

Thanks for the suggestions. I had small amount of time so I enabled the debug info and it seems that it does have some successful suspend resume cycles. All the debug info also made me realise that the Steam flatpak wakes up (all?) the USB controllers and then they autosuspend again, which is what was usually triggering the bug on my system.

I did manage to open and close Steam without any issue maybe 10 or so times, then I unbound and rebound the controller and it immediately failed on the next Steam launch. So I suppose sometimes the controller just behaves (totally?) fine, and other times fails easily?

I'll give it a try and report back when I have some time, hopefully at the weekend

I hadn't noticed it, but I'd only been able to test it on boots where it didn't immediately get killed by Steam autolaunching. I'll give it a try again, and also try unbinding then binding the controller again since that seemed to get the controller to fail on the next suspend / resume cycle (Steam launch) when it was behaving.

Yep

Stuart

You may reply to this email to add a comment.

You are receiving this mail because:
You are watching the assignee of the bug.

https://bugzilla.kernel.org/show_bug.cgi?id=220936

--- Comment #10 from Stuart Hayhurst ([email protected]) ---

I still get the error with xhci_hcd.quirks=0x20000

Yes, but it doesn't seem to be consistent

I still don't have a 100% reliable reproducer, some boots it's completely fine with no errors until shutdown if at all. Other boots it fails within 30 seconds.

You may reply to this email to add a comment.

You are receiving this mail because:
You are watching the assignee of the bug.

https://bugzilla.kernel.org/show_bug.cgi?id=220936

Jiayi Li ([email protected]) changed:

What |Removed |Added
----------------------------------------------------------------------------
CC| |[email protected]

--- Comment #11 from Jiayi Li ([email protected]) --- Hi,

I encountered the same error on the same controller model, and enabling XHCI_SUSPEND_DELAY resolved it for me. You could try xhci_hcd.quirks=0x40000000 as well.

You may reply to this email to add a comment.

You are receiving this mail because:
You are watching the assignee of the bug.

https://bugzilla.kernel.org/show_bug.cgi?id=220936

--- Comment #12 from Stuart Hayhurst ([email protected]) --- Hi,

That doesn't seem to help. I also tried it with xhci_hcd.quirks=0x40020000 and that didn't help either.

Stuart

You may reply to this email to add a comment.

You are receiving this mail because:
You are watching the assignee of the bug.