Re: kworker/0:3+pm hogging CPU

[Mathias Nyman]

On 29.8.2020 18.59, Alan Stern wrote:
> On Sat, Aug 29, 2020 at 11:50:03AM +0200, Salvatore Bonaccorso wrote:
>> Hi Alan,
>>
>> I'm following up on this thread because a user in Debian (Dirk, Cc'ed)
>> as well encountered the same/similar issue:
>>
>> On Tue, Jul 21, 2020 at 10:33:25AM -0400, Alan Stern wrote:
>>> On Tue, Jul 21, 2020 at 07:59:17AM +0200, Michal Hocko wrote:
>>>>> Sorry, my mistake.  The module name needs to be "xhci_hcd" with an '_' 
>>>>> character, not a '-' character -- the same as what shows up in the lsmod 
>>>>> output.
>>>>
>>>>
>>>> [14766.973734] xhci_hcd 0000:00:14.0: Get port status 2-1 read: 0xe000088, return 0x88
>>>> [14766.973738] xhci_hcd 0000:00:14.0: Get port status 2-2 read: 0xe000088, return 0x88
>>>> [14766.973742] xhci_hcd 0000:00:14.0: Get port status 2-3 read: 0xe0002a0, return 0x2a0
>>>> [14766.973746] xhci_hcd 0000:00:14.0: Get port status 2-4 read: 0xe0002a0, return 0x2a0
>>>> [14766.973750] xhci_hcd 0000:00:14.0: Get port status 2-5 read: 0xe0002a0, return 0x2a0
>>>> [14766.973754] xhci_hcd 0000:00:14.0: Get port status 2-6 read: 0xe0002a0, return 0x2a0
>>>> [14766.973759] xhci_hcd 0000:00:14.0: Get port status 2-1 read: 0xe000088, return 0x88
>>>> [14766.973763] xhci_hcd 0000:00:14.0: Get port status 2-2 read: 0xe000088, return 0x88
>>>
>>> According to the xHCI specification, those 02a0 values are normal and 
>>> the 0088 values indicate the port is disabled and has an over-current 
>>> condition.  I don't know about the e000 bits in the upper part of the 
>>> word; according to my copy of the spec those bits should be 0.

That's a 0x0e000088 where the 0e00 bits are the wake bits. Leading zeroes are not shown. 

>>>
>>> If your machine has only two physical SuperSpeed (USB-3) ports then 
>>> perhaps the other four ports are internally wired in a way that creates 
>>> a permanent over-current indication.
>>>
>>>> [14766.973771] xhci_hcd 0000:00:14.0: set port remote wake mask, actual port 0 status  = 0xe000088
>>>> [14766.973780] xhci_hcd 0000:00:14.0: set port remote wake mask, actual port 1 status  = 0xe000088
>>>> [14766.973789] xhci_hcd 0000:00:14.0: set port remote wake mask, actual port 2 status  = 0xe0002a0
>>>> [14766.973798] xhci_hcd 0000:00:14.0: set port remote wake mask, actual port 3 status  = 0xe0002a0
>>>> [14766.973807] xhci_hcd 0000:00:14.0: set port remote wake mask, actual port 4 status  = 0xe0002a0
>>>> [14766.973816] xhci_hcd 0000:00:14.0: set port remote wake mask, actual port 5 status  = 0xe0002a0
>>>> [14766.973830] xhci_hcd 0000:00:14.0: Bus suspend bailout, port over-current detected
>>>>
>>>> Repeating again and again. The last message suggests a HW problem? But
>>>> why does the kernel try the same thing over and over?
>>>
>>> Because over-current is supposed to be a transient condition that goes 
>>> away quickly.  It means there's a short circuit or something similar.
>>
>> Dirk exprienced the same issue aand enabled dynamic debugging showed
>> similar pattern. His dmesg excerpt is attached.
>>
>> The Debian report is at https://bugs.debian.org/966703
>>
>> What could be tracked down is that the issue is uncovered since
>> e9fb08d617bf ("xhci: prevent bus suspend if a roothub port detected a
>> over-current condition") which was applied in 5.7-rc3 and backported
>> to several stable releases (v5.6.8, v5.4.36 and v4.19.119).
>>
>> Dirk found additionally:
>>
>>> I just found out, that if none of the two USB ports is connected, there
>>> are two kworker processes with permanently high CPU load, if one USB
>>> port is connected and the other not, there is one such kworker process,
>>> and if both USB ports are connected, there is no kworker process with
>>> high CPU load.
>>> I think, this supports your suspicion that these kworker processes are
>>> connected with the overcurrent condition for both USB ports that I also
>>> see in the dmesg output.
>>
>> Reverting the above commit covers the problem again. But I'm not
>> exprienced enough here to claim if this is a HW issue or if the Kernel
>> should handle the situation otherwise. Is there anything else Dirk can
>> provide?
> 
> It is undoubtedly a hardware issue.  The dmesg extract shows that ports 
> 1-10, 1-11, and 2-5 (which is probably the same port as one of the 
> others) have overcurrent conditions; I'm guessing that these are the 
> ports which have external connections.
> 
> What were the devices Dirk plugged in that got rid of the kworker 
> processes?  In particular, were they USB-2 or USB-3?  (The dmesg log for 
> when the devices were first attached can answer these questions.)
> 
> As far as I know, there is no way for the kernel to work around this 
> problem.  Preventing the controller from going into runtime suspend is 
> probably the best solution.
> 
> Perhaps Mathias (the xhci-hcd maintainer) will have more suggestions.

In the original case the over-current condition was always quickly
resolved and returning -EBUSY did the trick.

xhci specs say that over-current active bit shall cleared by hardware once
the over-current condition is no longer present, it's not much the driver can do.
(xhci 5.4.8 - Port status and control register)

I can't come up with any good solution to this right now.
Only bad ideas such as
a. Add a sleep to the over-current case, 
   doesn't solve anything else than the ~100% cpu hogging part of the problem 
b. After some retry limit of returning -EBUSY we return success and just hope
   for the best the xHC won't hang in this case.

Not sure how much additional complex code it is worth doing because of a couple cases
that seems to be broken hardware. If we get more cases, or can  
point to some specific setup with broken design we can create a quirk for it.

-Mathias