HC died

HC died

[Seth Bollinger]

Hello All,

We're experiencing a problem with our devices in the field where our
customers attach problematic USB devices that are causing the xhci
host controller to shut down with the "HC died; cleaning up" message.

I've narrowed this down to a timeout of the address device TRB on the
command ring (currently 5 seconds).  It sometimes takes our hardware
9.6 to complete this TRB.  When the driver is trying to stop the cmd
ring, the controller is busy for an additional 4.6 seconds.  This
results in the "HC died" message and shutdown of the host controller.

If I bump the command ring timeout beyond the max TRB completion time,
the host controller continues to be responsive and doesn't need to be
shut down.

My knowledge of how the usb protocol should handle this problem isn't
strong enough to know if there is a better solution than simply
increasing the command ring default timeout.

Is there a better way to handle this problem?

I've reproduced this on kernel 6.0, and 6.1.

Here is a log of the issue, along with some extra tracing I added to
track the duration of the command ring TRB completions.  FYI, I
recreate this problem by connecting/disconnecting the 5V pin quickly.
The theory is that the device is no longer present on the bus when the
hardware is trying to address the device.  I understand this is
somewhat degenerate, but it's happening frequently to our customers in
the field and it would be nice if the HC didn't die requiring them to
reboot to recover.

[F00:P06]  Feb 16 16:40:14  kernel: usb 3-2.1: new high-speed USB
device number 13 using xhci_hcd
[F00:P07]  Feb 16 16:40:14  kernel: xhci_hcd 0002:01:00.0: Set root
hub portnum to 4
[F00:P07]  Feb 16 16:40:14  kernel: xhci_hcd 0002:01:00.0: Set fake
root hub portnum to 2
[F00:P07]  Feb 16 16:40:14  kernel: xhci_hcd 0002:01:00.0: udev->tt =
0000000000000000
[F00:P07]  Feb 16 16:40:14  kernel: xhci_hcd 0002:01:00.0: udev->ttport = 0x0
[F00:P06]  Feb 16 16:40:14  kernel: xhci_hcd 0002:01:00.0:
xhci_setup_device: xhci_queue_address_device
[F00:P07]  Feb 16 16:40:14  kernel: xhci_hcd 0002:01:00.0: // Ding dong!
[F00:P06]  Feb 16 16:40:23  kernel: xhci_hcd 0002:01:00.0: completion
cmd 11, time: 163776215, duration: 9596181 us
[F00:P04]  Feb 16 16:40:23  kernel: usb 3-2.1: Device not responding
to setup address.
[F00:P07]  Feb 16 16:40:23  kernel: xhci_hcd 0002:01:00.0: // Ding dong!
[F00:P06]  Feb 16 16:40:23  kernel: xhci_hcd 0002:01:00.0: completion
cmd 10, time: 163778807, duration: 2530 us
[F00:P06]  Feb 16 16:40:23  kernel: xhci_hcd 0002:01:00.0: completion
cmd 9, time: 163778906, duration: 90 us
[F00:P07]  Feb 16 16:40:23  kernel: xhci_hcd 0002:01:00.0: Slot 15
output ctx = 0x8422f000 (dma)
[F00:P07]  Feb 16 16:40:23  kernel: xhci_hcd 0002:01:00.0: Slot 15
input ctx = 0x87ea9000 (dma)
[F00:P07]  Feb 16 16:40:23  kernel: xhci_hcd 0002:01:00.0: Set slot id
15 dcbaa entry 000000001958e382 to 0x8422f000
[F00:P07]  Feb 16 16:40:24  kernel: xhci_hcd 0002:01:00.0: Set root
hub portnum to 4
[F00:P07]  Feb 16 16:40:24  kernel: xhci_hcd 0002:01:00.0: Set fake
root hub portnum to 2
[F00:P07]  Feb 16 16:40:24  kernel: xhci_hcd 0002:01:00.0: udev->tt =
0000000000000000
[F00:P07]  Feb 16 16:40:24  kernel: xhci_hcd 0002:01:00.0: udev->ttport = 0x0
[F00:P06]  Feb 16 16:40:24  kernel: xhci_hcd 0002:01:00.0:
xhci_setup_device: xhci_queue_address_device
[F00:P07]  Feb 16 16:40:24  kernel: xhci_hcd 0002:01:00.0: // Ding dong!
[F00:P06]  Feb 16 16:40:33  kernel: xhci_hcd 0002:01:00.0: completion
cmd 11, time: 173580444, duration: 9596416 us
[F00:P04]  Feb 16 16:40:33  kernel: usb 3-2.1: Device not responding
to setup address.
[F00:P07]  Feb 16 16:40:33  kernel: xhci_hcd 0002:01:00.0: // Ding dong!
[F00:P06]  Feb 16 16:40:33  kernel: xhci_hcd 0002:01:00.0: completion
cmd 10, time: 173583035, duration: 2529 us
[F00:P06]  Feb 16 16:40:33  kernel: xhci_hcd 0002:01:00.0: completion
cmd 9, time: 173583129, duration: 83 us
[F00:P07]  Feb 16 16:40:33  kernel: xhci_hcd 0002:01:00.0: Slot 16
output ctx = 0x8422f000 (dma)
[F00:P07]  Feb 16 16:40:33  kernel: xhci_hcd 0002:01:00.0: Slot 16
input ctx = 0x87ea9000 (dma)
[F00:P07]  Feb 16 16:40:33  kernel: xhci_hcd 0002:01:00.0: Set slot id
16 dcbaa entry 00000000ae4b7693 to 0x8422f000
[F00:P03]  Feb 16 16:40:33  kernel: usb 3-2.1: device not accepting
address 13, error -71
[F00:P07]  Feb 16 16:40:33  kernel: xhci_hcd 0002:01:00.0: // Ding dong!
[F00:P06]  Feb 16 16:40:33  kernel: xhci_hcd 0002:01:00.0: completion
cmd 10, time: 173790654, duration: 2529 us
[F00:P07]  Feb 16 16:40:33  kernel: xhci_hcd 0002:01:00.0: Bad real port.
[F00:P06]  Feb 16 16:40:33  kernel: xhci_hcd 0002:01:00.0: completion
cmd 9, time: 173790749, duration: 86 us
[F00:P07]  Feb 16 16:40:33  kernel: xhci_hcd 0002:01:00.0: Slot 17
output ctx = 0x8422f000 (dma)
[F00:P07]  Feb 16 16:40:33  kernel: xhci_hcd 0002:01:00.0: Slot 17
input ctx = 0x87ea9000 (dma)
[F00:P07]  Feb 16 16:40:33  kernel: xhci_hcd 0002:01:00.0: Set slot id
17 dcbaa entry 00000000e45e3c7b to 0x8422f000
[F00:P07]  Feb 16 16:40:34  kernel: xhci_hcd 0002:01:00.0: // Ding dong!
[F00:P06]  Feb 16 16:40:34  kernel: xhci_hcd 0002:01:00.0: completion
cmd 10, time: 174478971, duration: 2528 us
[F00:P07]  Feb 16 16:40:34  kernel: xhci_hcd 0002:01:00.0: Bad real port.

Thanks for your assistance,

Seth

Re: HC died

[Mathias Nyman]

On 17.2.2023 16.21, Seth Bollinger wrote:
> Hello All,
> 
> We're experiencing a problem with our devices in the field where our
> customers attach problematic USB devices that are causing the xhci
> host controller to shut down with the "HC died; cleaning up" message.

Is this seen only on some specific xHC host controller?

> 
> I've narrowed this down to a timeout of the address device TRB on the
> command ring (currently 5 seconds).  It sometimes takes our hardware
> 9.6 to complete this TRB.  When the driver is trying to stop the cmd
> ring, the controller is busy for an additional 4.6 seconds.  This
> results in the "HC died" message and shutdown of the host controller.
> 
> If I bump the command ring timeout beyond the max TRB completion time,
> the host controller continues to be responsive and doesn't need to be
> shut down.
> 
> My knowledge of how the usb protocol should handle this problem isn't
> strong enough to know if there is a better solution than simply
> increasing the command ring default timeout.

Are these problematic devices USB 2 or USB 3 devices?

You could try playing with the Address device command BSR (block set
address request) flag and see if helps.
Xhci has two ways to get a slot from the Enabled to the Addressed state.

option 1: move slot from Enabled state to Addressed in one go:
Enabled --(Addr dev cmd, BSR=0)--> Addressed

option 2: move from Enabled state via Default state to Addressed state:
Enabled --(Addr dev cmd, BSR=1)--> Default --(Addr dev cmd, BSR=0)--> Addressed

I think the usb core "old_scheme_first" module parameter will end up doing this.

-Mathias

Re: HC died

[Seth Bollinger]

> > We're experiencing a problem with our devices in the field where our
> > customers attach problematic USB devices that are causing the xhci
> > host controller to shut down with the "HC died; cleaning up" message.
>
> Is this seen only on some specific xHC host controller?

I don't think so.  We've seen this on pcie attached asmedia 3142 and
NXP ls1012a/ls1046a SOC controllers (which I think are dwc3 IP).
Strangely the timing seems to be much easier to reproduce on the pcie
attached asm3142.

> > I've narrowed this down to a timeout of the address device TRB on the
> > command ring (currently 5 seconds).  It sometimes takes our hardware
> > 9.6 to complete this TRB.  When the driver is trying to stop the cmd
> > ring, the controller is busy for an additional 4.6 seconds.  This
> > results in the "HC died" message and shutdown of the host controller.
> >
> > If I bump the command ring timeout beyond the max TRB completion time,
> > the host controller continues to be responsive and doesn't need to be
> > shut down.
> >
> > My knowledge of how the usb protocol should handle this problem isn't
> > strong enough to know if there is a better solution than simply
> > increasing the command ring default timeout.
>
> Are these problematic devices USB 2 or USB 3 devices?

Both.

> You could try playing with the Address device command BSR (block set
> address request) flag and see if helps.
> Xhci has two ways to get a slot from the Enabled to the Addressed state.
>
> option 1: move slot from Enabled state to Addressed in one go:
> Enabled --(Addr dev cmd, BSR=0)--> Addressed
>
> option 2: move from Enabled state via Default state to Addressed state:
> Enabled --(Addr dev cmd, BSR=1)--> Default --(Addr dev cmd, BSR=0)--> Addressed
>
> I think the usb core "old_scheme_first" module parameter will end up doing this.

Apologies for taking so long to respond to this as I've been a little
busy this week.

I tried setting old_scheme_first and this didn't have any effect.
Here's the kernel log without my patch to track command ring TRB
completion times (as well as extra debug disabled).

kernel: usb 3-2.1: new high-speed USB device number 4 using xhci_hcd
kernel: usb 3-2.1: New USB device found, idVendor=058f,
idProduct=6387, bcdDevice= 1.03
kernel: usb 3-2.1: New USB device strings: Mfr=1, Product=2, SerialNumber=3
kernel: usb 3-2.1: Product: Mass Storage
kernel: usb 3-2.1: Manufacturer: Generic
kernel: usb 3-2.1: SerialNumber: B1EC2EB2
kernel: usb 3-2.1: USB disconnect, device number 4
kernel: usb 3-2.1: new high-speed USB device number 5 using xhci_hcd
kernel: xhci_hcd 0002:01:00.0: Abort failed to stop command ring: -110
kernel: xhci_hcd 0002:01:00.0: xHCI host controller not responding, assume dead
kernel: xhci_hcd 0002:01:00.0: HC died; cleaning up
kernel: xhci_hcd 0002:01:00.0: Timeout while waiting for setup device command
kernel: usb 3-1: USB disconnect, device number 2
kernel: usb 3-2: USB disconnect, device number 3
kernel: usb 4-1: USB disconnect, device number 2
kernel: usb 4-2: USB disconnect, device number 3
kernel: usb 3-2.1: device not accepting address 5, error -108
kernel: usb 3-2-port1: couldn't allocate usb_device

If I push XHCI_CMD_DEFAULT_TIMEOUT beyond 9.6 seconds, the HC will
continue to function normally.

From a quick web search, I can see that other people are experiencing
the same issue.  None of those threads offer any solutions.  Many seem
to revolve around disabling usb power management, and this did not
help in our case.

I wish I could gain some insight on how the hardware is handling this edge case.

> -Mathias
>

Re: HC died

[Alan Stern]

On Thu, Feb 23, 2023 at 09:31:05AM -0600, Seth Bollinger wrote:
> > > We're experiencing a problem with our devices in the field where our
> > > customers attach problematic USB devices that are causing the xhci
> > > host controller to shut down with the "HC died; cleaning up" message.
> >
> > Is this seen only on some specific xHC host controller?
> 
> I don't think so.  We've seen this on pcie attached asmedia 3142 and
> NXP ls1012a/ls1046a SOC controllers (which I think are dwc3 IP).
> Strangely the timing seems to be much easier to reproduce on the pcie
> attached asm3142.
> 
> > > I've narrowed this down to a timeout of the address device TRB on the
> > > command ring (currently 5 seconds).  It sometimes takes our hardware
> > > 9.6 to complete this TRB.  When the driver is trying to stop the cmd

Note that the USB-2.0 spec says (section 9.2.6.3, Set Address 
Processing):

	After the reset/resume recovery interval, if a device receives a 
	SetAddress() request, the device must be able to complete 
	processing of the request and be able to successfully complete 
	the Status stage of the request within 50 ms.

These devices' 9.6 seconds to process a Set-Address request is a _lot_ 
longer than 50 ms.  No wonder they don't work properly.  Why on earth do 
they take so long?

Of course, xHCI controller drivers should be able to cancel an 
Address-Device TRB without waiting for it to complete.

Alan Stern

Re: HC died

[Seth Bollinger]

> Note that the USB-2.0 spec says (section 9.2.6.3, Set Address
> Processing):
>
>         After the reset/resume recovery interval, if a device receives a
>         SetAddress() request, the device must be able to complete
>         processing of the request and be able to successfully complete
>         the Status stage of the request within 50 ms.
>
> These devices' 9.6 seconds to process a Set-Address request is a _lot_
> longer than 50 ms.  No wonder they don't work properly.  Why on earth do
> they take so long?

The device can't actually respond as it's no longer present on the
bus.  The hardware is taking this long to complete the TRB when the
device disappears in the middle of the transaction (at least this is
the theory).

I'm not trying to argue that these devices aren't crappy.  However, it
does seem like there are quite a lot of crappy devices in the field.
It would be nice if the driver didn't die when encountering these
devices.

> Of course, xHCI controller drivers should be able to cancel an
> Address-Device TRB without waiting for it to complete.

Agreed.  Is there some way I could try to cancel this command ring
TRB?  The hardware seems hung enough that it's not responding to
whatever we're trying to do in the cleanup routine when the timeout
handler fires though.

>
> Alan Stern

Re: HC died

[Mathias Nyman]

On 23.2.2023 18.05, Seth Bollinger wrote:
>> Note that the USB-2.0 spec says (section 9.2.6.3, Set Address
>> Processing):
>>
>>          After the reset/resume recovery interval, if a device receives a
>>          SetAddress() request, the device must be able to complete
>>          processing of the request and be able to successfully complete
>>          the Status stage of the request within 50 ms.
>>
>> These devices' 9.6 seconds to process a Set-Address request is a _lot_
>> longer than 50 ms.  No wonder they don't work properly.  Why on earth do
>> they take so long?
> 
> The device can't actually respond as it's no longer present on the
> bus.  The hardware is taking this long to complete the TRB when the
> device disappears in the middle of the transaction (at least this is
> the theory).
> 
> I'm not trying to argue that these devices aren't crappy.  However, it
> does seem like there are quite a lot of crappy devices in the field.
> It would be nice if the driver didn't die when encountering these
> devices.
> 
>> Of course, xHCI controller drivers should be able to cancel an
>> Address-Device TRB without waiting for it to complete.
> 
> Agreed.  Is there some way I could try to cancel this command ring
> TRB?  The hardware seems hung enough that it's not responding to
> whatever we're trying to do in the cleanup routine when the timeout
> handler fires though.

xhci driver does exactly this, but fails to stop the command ring while
trying to abort the command TRB.

Does increasing the timeout for stopping command ring help?

diff --git a/drivers/usb/host/xhci-ring.c b/drivers/usb/host/xhci-ring.c
index f5b0e1ce22af..6cecbca34cca 100644
--- a/drivers/usb/host/xhci-ring.c
+++ b/drivers/usb/host/xhci-ring.c
@@ -397,7 +397,7 @@ static int xhci_abort_cmd_ring(struct xhci_hcd *xhci, unsigned long flags)
          * and try to recover a -ETIMEDOUT with a host controller reset.
          */
         ret = xhci_handshake(&xhci->op_regs->cmd_ring,
-                       CMD_RING_RUNNING, 0, 5 * 1000 * 1000);
+                       CMD_RING_RUNNING, 0, 10 * 1000 * 1000);
         if (ret < 0) {
                 xhci_err(xhci, "Abort failed to stop command ring: %d\n", ret);
                 xhci_halt(xhci);
Thanks
-Mathias

Re: HC died

[Seth Bollinger]

> xhci driver does exactly this, but fails to stop the command ring while
> trying to abort the command TRB.
>
> Does increasing the timeout for stopping command ring help?
>
> diff --git a/drivers/usb/host/xhci-ring.c b/drivers/usb/host/xhci-ring.c
> index f5b0e1ce22af..6cecbca34cca 100644
> --- a/drivers/usb/host/xhci-ring.c
> +++ b/drivers/usb/host/xhci-ring.c
> @@ -397,7 +397,7 @@ static int xhci_abort_cmd_ring(struct xhci_hcd *xhci, unsigned long flags)
>           * and try to recover a -ETIMEDOUT with a host controller reset.
>           */
>          ret = xhci_handshake(&xhci->op_regs->cmd_ring,
> -                       CMD_RING_RUNNING, 0, 5 * 1000 * 1000);
> +                       CMD_RING_RUNNING, 0, 10 * 1000 * 1000);
>          if (ret < 0) {
>                  xhci_err(xhci, "Abort failed to stop command ring: %d\n", ret);
>                  xhci_halt(xhci);

Well, for us it doesn't really help as it still ends the life of the
HC, but it doesn't solve the issue either (you can see the 10 second
timeout here).

Feb 24 13:11:53 AW24-002133 kernel: usb 3-2.4: new full-speed USB
device number 16 using xhci_hcd
Feb 24 13:12:08 AW24-002133 kernel: xhci_hcd 0002:01:00.0: Abort
failed to stop command ring: -110
Feb 24 13:12:08 AW24-002133 kernel: xhci_hcd 0002:01:00.0: xHCI host
controller not responding, assume dead
Feb 24 13:12:08 AW24-002133 kernel: xhci_hcd 0002:01:00.0: HC died; cleaning up
Feb 24 13:12:08 AW24-002133 kernel: xhci_hcd 0002:01:00.0: Timeout
while waiting for setup device command
Feb 24 13:12:08 AW24-002133 kernel: usb 3-1: USB disconnect, device number 2
Feb 24 13:12:08 AW24-002133 kernel: usb 4-1: USB disconnect, device number 2
Feb 24 13:12:08 AW24-002133 kernel: usb 4-2: USB disconnect, device number 3
Feb 24 13:12:08 AW24-002133 kernel: usb 3-2: USB disconnect, device number 3
Feb 24 13:12:09 AW24-002133 kernel: usb 3-2.4: device not accepting
address 16, error -108
Feb 24 13:12:09 AW24-002133 kernel: usb 3-2-port4: couldn't allocate usb_device

Also 10 seconds with interrupts disabled causes its own problems (5
seconds is an eternity with interrupts off in itself...).

> Thanks
> -Mathias

Re: HC died

[Mathias Nyman]

On 24.2.2023 15.16, Seth Bollinger wrote:
>> xhci driver does exactly this, but fails to stop the command ring while
>> trying to abort the command TRB.
>>
>> Does increasing the timeout for stopping command ring help?
>>
>> diff --git a/drivers/usb/host/xhci-ring.c b/drivers/usb/host/xhci-ring.c
>> index f5b0e1ce22af..6cecbca34cca 100644
>> --- a/drivers/usb/host/xhci-ring.c
>> +++ b/drivers/usb/host/xhci-ring.c
>> @@ -397,7 +397,7 @@ static int xhci_abort_cmd_ring(struct xhci_hcd *xhci, unsigned long flags)
>>            * and try to recover a -ETIMEDOUT with a host controller reset.
>>            */
>>           ret = xhci_handshake(&xhci->op_regs->cmd_ring,
>> -                       CMD_RING_RUNNING, 0, 5 * 1000 * 1000);
>> +                       CMD_RING_RUNNING, 0, 10 * 1000 * 1000);
>>           if (ret < 0) {
>>                   xhci_err(xhci, "Abort failed to stop command ring: %d\n", ret);
>>                   xhci_halt(xhci);
> 
> Well, for us it doesn't really help as it still ends the life of the
> HC, but it doesn't solve the issue either (you can see the 10 second
> timeout here).

Ok, thanks, seems that aborting the ring does not work either.

When you earlier bumped the command ring timeout did you notice if
transfer TRBs for other devices were completing normally while waiting
for the address device command TRB to complete?

If so then it could make sense to just increase the XHCI_CMD_DEFAULT_TIMEOUT
for the address device commands to 10 seconds

This can probably be quickly tested by moving a USB mouse while triggering the
address device timeout.

Thanks
Mathias

Re: HC died

[Seth Bollinger]

> Ok, thanks, seems that aborting the ring does not work either.
>
> When you earlier bumped the command ring timeout did you notice if
> transfer TRBs for other devices were completing normally while waiting
> for the address device command TRB to complete?
>
> If so then it could make sense to just increase the XHCI_CMD_DEFAULT_TIMEOUT
> for the address device commands to 10 seconds
>
> This can probably be quickly tested by moving a USB mouse while triggering the
> address device timeout.

I guess I always assumed that the other rings kept running.  :)

I just put it to the test, and that assumption was true.  The other
ports appear to run just fine (as long as they don't need to use the
command ring).

>
> Thanks
> Mathias
>