Regression: USB/xhci issues on some systems with newer kernel versions

From: Bernhard Gebetsberger <bernhard.gebetsberger@gmx.at>
To: linux-usb@vger.kernel.org
Subject: Regression: USB/xhci issues on some systems with newer kernel versions
Date: Wed, 2 Oct 2019 14:28:59 +0200	[thread overview]
Message-ID: <3edaf835-7cde-37d9-5a0a-5a9b21a02968@gmx.at> (raw)

Hi,

There has been a regression in the xhci driver since kernel version 4.20, on some systems some usb devices won't work until the system gets rebooted.
The error message in dmesg is "WARN Set TR Deq Ptr cmd failed due to incorrect slot or ep state", although for some reason there are some usb devices that are affected by this issue but don't throw the error message(including the device I'm using, I got the error in previous kernel versions though).
It seems like this bug can also lead to system instability, one user reported in the bug tracker(https://bugzilla.kernel.org/show_bug.cgi?id=202541#c58) that he got a system freeze because of this when using kernel 5.3.1.

When looking at the responses in the bug tracker, it looks like it mostly affects Ryzen based systems with 300 series motherboards, although there are some other affected systems as well. It doesn't only affect wifi/bluetooth sticks, some users even got this issue when connecting their smartphone or their external hard drive to their PC.

After enabling kernel debugging/tracing for xhci_hcd I got the following messages in dmesg(short version, link to the whole file below):
[  231.185635] xhci_hcd 0000:38:00.4: xhci_get_isoc_frame_id: index 0, reg 0x1b29 start_frame_id 0x366, end_frame_id 0x6e4, start_frame 0x372
[  231.185642] xhci_hcd 0000:38:00.4: xhci_get_isoc_frame_id: index 1, reg 0x1b29 start_frame_id 0x366, end_frame_id 0x6e4, start_frame 0x373
[  231.185646] xhci_hcd 0000:38:00.4: xhci_get_isoc_frame_id: index 2, reg 0x1b29 start_frame_id 0x366, end_frame_id 0x6e4, start_frame 0x374
......
[  231.887681] xhci_hcd 0000:38:00.4: xhci_get_isoc_frame_id: index 4, reg 0x3119 start_frame_id 0x624, end_frame_id 0x1a2, start_frame 0x633
[  231.887687] xhci_hcd 0000:38:00.4: xhci_get_isoc_frame_id: index 5, reg 0x3119 start_frame_id 0x624, end_frame_id 0x1a2, start_frame 0x634
[  231.892346] xhci_hcd 0000:38:00.4: Cancel URB 000000008599ca58, dev 1, ep 0x1, starting at offset 0xff388ea0
[  231.892355] xhci_hcd 0000:38:00.4: // Ding dong!
[  231.892363] xhci_hcd 0000:38:00.4: Cancel URB 000000000d35fd5d, dev 1, ep 0x1, starting at offset 0xff388ef0
[  231.892368] xhci_hcd 0000:38:00.4: Cancel URB 0000000074e3ee88, dev 1, ep 0x1, starting at offset 0xff388e40
[  231.892640] xhci_hcd 0000:38:00.4: Stopped on Transfer TRB for slot 1 ep 1
[  231.892647] xhci_hcd 0000:38:00.4: Removing canceled TD starting at 0xff388ea0 (dma).
[  231.892651] xhci_hcd 0000:38:00.4: Removing canceled TD starting at 0xff388eb0 (dma).
[  231.892653] xhci_hcd 0000:38:00.4: Removing canceled TD starting at 0xff388ec0 (dma).
[  231.892656] xhci_hcd 0000:38:00.4: Removing canceled TD starting at 0xff388ed0 (dma).
[  231.892658] xhci_hcd 0000:38:00.4: Removing canceled TD starting at 0xff388ee0 (dma).
[  231.892661] xhci_hcd 0000:38:00.4: Removing canceled TD starting at 0xff388ef0 (dma).
[  231.892663] xhci_hcd 0000:38:00.4: Removing canceled TD starting at 0xff388f00 (dma).
[  231.892666] xhci_hcd 0000:38:00.4: Removing canceled TD starting at 0xff388f10 (dma).
[  231.892668] xhci_hcd 0000:38:00.4: Removing canceled TD starting at 0xff388f20 (dma).
[  231.892670] xhci_hcd 0000:38:00.4: Removing canceled TD starting at 0xff388f30 (dma).
[  231.892672] xhci_hcd 0000:38:00.4: Removing canceled TD starting at 0xff388f40 (dma).
[  231.892675] xhci_hcd 0000:38:00.4: Removing canceled TD starting at 0xff388e90 (dma).
[  231.892677] xhci_hcd 0000:38:00.4: Finding endpoint context
[  231.892679] xhci_hcd 0000:38:00.4: Cycle state = 0x1
[  231.892682] xhci_hcd 0000:38:00.4: New dequeue segment = 000000005d174923 (virtual)
[  231.892685] xhci_hcd 0000:38:00.4: New dequeue pointer = 0xff388ea0 (DMA)
[  231.892688] xhci_hcd 0000:38:00.4: Set TR Deq Ptr cmd, new deq seg = 000000005d174923 (0xff388000 dma), new deq ptr = 00000000d5c5ed2a (0xff388ea0 dma), new cycle = 1
[  231.892693] xhci_hcd 0000:38:00.4: // Ding dong!
[  231.892728] xhci_hcd 0000:38:00.4: Successful Set TR Deq Ptr cmd, deq = @ff388ea0
[  231.897107] xhci_hcd 0000:38:00.4: xhci_drop_endpoint called for udev 0000000043fc1c1f
[  231.897126] xhci_hcd 0000:38:00.4: drop ep 0x1, slot id 1, new drop flags = 0x4, new add flags = 0x0
[  231.897129] xhci_hcd 0000:38:00.4: xhci_check_bandwidth called for udev 0000000043fc1c1f
[  231.897137] xhci_hcd 0000:38:00.4: // Ding dong!
[  231.898523] xhci_hcd 0000:38:00.4: Successful Endpoint Configure command

I have uploaded the whole dmesg file and the tracing file to transfer.sh: https://transfer.sh/zYohl/dmesg and https://transfer.sh/KNbFL/xhci-trace

The issues occur since commit f8f80be501aa2f10669585c3e328fad079d8cb3a "xhci: Use soft retry to recover faster from transaction errors". I think this commit should be reverted at least until a workaround has been found, especially since the next two kernel versions will be used by a lot of distributions(5.4 because it's a LTS kernel and 5.5 will probably be used in Ubuntu 20.04) so more users would be affected by this.

- Bernhard