[Bug 220936] New: ASMedia ASM4242 USB 3.2 xHCI Controller gives command timeout

[Bug 220936] New: ASMedia ASM4242 USB 3.2 xHCI Controller gives command timeout

[bugzilla-daemon]

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: drivers_usb@kernel-bugs.kernel.org
          Reporter: stuart.a.hayhurst@gmail.com
        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.

[Bug 220936] ASMedia ASM4242 USB 3.2 xHCI Controller gives command timeout

[bugzilla-daemon]

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

--- Comment #1 from Stuart Hayhurst (stuart.a.hayhurst@gmail.com) ---
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.

[Bug 220936] ASMedia ASM4242 USB 3.2 xHCI Controller gives command timeout

[bugzilla-daemon]

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

--- Comment #2 from Stuart Hayhurst (stuart.a.hayhurst@gmail.com) ---
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.

[Bug 220936] ASMedia ASM4242 USB 3.2 xHCI Controller gives command timeout

[bugzilla-daemon]

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

Michał Pecio (michal.pecio@gmail.com) changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
                 CC|                            |michal.pecio@gmail.com

--- Comment #3 from Michał Pecio (michal.pecio@gmail.com) ---
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.

[Bug 220936] ASMedia ASM4242 USB 3.2 xHCI Controller gives command timeout

[bugzilla-daemon]

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

--- Comment #4 from Stuart Hayhurst (stuart.a.hayhurst@gmail.com) ---
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.

[Bug 220936] ASMedia ASM4242 USB 3.2 xHCI Controller gives command timeout

[bugzilla-daemon]

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

--- Comment #5 from Stuart Hayhurst (stuart.a.hayhurst@gmail.com) ---
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.

[Bug 220936] ASMedia ASM4242 USB 3.2 xHCI Controller gives command timeout

[bugzilla-daemon]

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

--- Comment #6 from Stuart Hayhurst (stuart.a.hayhurst@gmail.com) ---
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.

[Bug 220936] ASMedia ASM4242 USB 3.2 xHCI Controller gives command timeout

[bugzilla-daemon]

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

--- Comment #7 from Stuart Hayhurst (stuart.a.hayhurst@gmail.com) ---
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.

[Bug 220936] ASMedia ASM4242 USB 3.2 xHCI Controller gives command timeout

[bugzilla-daemon]

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

--- Comment #8 from Michał Pecio (michal.pecio@gmail.com) ---
"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.

[Bug 220936] ASMedia ASM4242 USB 3.2 xHCI Controller gives command timeout

[bugzilla-daemon]

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

--- Comment #9 from Stuart Hayhurst (stuart.a.hayhurst@gmail.com) ---
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?

> Passing quirks=0x20000 parameter to xhci_hcd increases the timeout

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

> Does it also show up when suspending the system?

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.

> Are you able to compile and test patches?

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.