linux-kernel - Re: kworker/0:3+pm hogging CPU

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives
Hash Suite: Windows password security audit tool. GUI, reports in PDF.
[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]
Message-ID: <20200721055917.GD4061@dhcp22.suse.cz>
Date:   Tue, 21 Jul 2020 07:59:17 +0200
From:   Michal Hocko <mhocko@...nel.org>
To:     Alan Stern <stern@...land.harvard.edu>
Cc:     LKML <linux-kernel@...r.kernel.org>,
        Greg KH <gregkh@...uxfoundation.org>,
        linux-usb@...r.kernel.org, "Rafael J. Wysocki" <rjw@...ysocki.net>
Subject: Re: kworker/0:3+pm hogging CPU

On Mon 20-07-20 16:02:43, Alan Stern wrote:
> On Mon, Jul 20, 2020 at 08:16:05PM +0200, Michal Hocko wrote:
> > On Mon 20-07-20 13:48:12, Alan Stern wrote:
> > > On Mon, Jul 20, 2020 at 07:45:30PM +0200, Michal Hocko wrote:
> > > > On Mon 20-07-20 13:38:07, Alan Stern wrote:
> > > > > On Mon, Jul 20, 2020 at 06:33:55PM +0200, Michal Hocko wrote:
> > > > > > On Mon 20-07-20 11:12:55, Alan Stern wrote:
> > > > > > [...]
> > > > > > > 	sudo echo 'module usbcore =p' >/debug/dynamic_debug/control
> > > > > > > 
> > > > > > > Then wait long enough for some interesting messages to appear in the 
> > > > > > > kernel log (it should only take a few seconds if the worker thread is as 
> > > > > > > busy as you say) and collect the output from the dmesg command.
> > > > > > > 
> > > > > > > To turn dynamic debugging back off when you're finished, use the same 
> > > > > > > command with "=p" changed to "-p".
> > > > > > 
> > > > > > [   95.395815] hub 2-0:1.0: state 7 ports 6 chg 0006 evt 0000
> > > > > > [   95.395824] usb usb2-port1: status 0088, change 0000, 5.0 Gb/s
> > > > > > [   95.395838] usb usb2-port2: status 0088, change 0000, 5.0 Gb/s
> > > > > > [   95.396016] hub 2-0:1.0: hub_suspend
> > > > > > [   95.396023] usb usb2: bus auto-suspend, wakeup 1
> > > > > > [   95.396029] usb usb2: bus suspend fail, err -16
> > > > > 
> > > > > Okay, that's the problem.  You may get more specific information about 
> > > > > the suspend failure if you turn on dynamic debugging for the xhci-hcd 
> > > > > module (same command as above but with xhci-hcd instead of usbcore).
> > > > 
> > > > Would that help to pinpoint the problem down?
> > > 
> > > It might.  I can't say for sure without seeing the output.
> > 
> > echo 'module xhci-hcd =p' >/sys/kernel/debug/dynamic_debug/control
> > 
> > doesn't yield to any output. I have tried both with and without usbcore
> > debug output enabled. In the former there is no new output and for the
> > later I get the same I have posted earlier.
> 
> 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
[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?

> You could also try collect a usbmon trace from the .../2u file.  It does 
> seem that bus 2 is where the problem occurs.

a random sample

ffff8882447743c0 2551256361 S Ii:2:001:1 -115:2048 4 <
ffff888040808cc0 2551256367 C Ci:2:001:0 0 4 = 88000000
ffff888040808cc0 2551256373 C Ci:2:001:0 0 4 = 88000000
ffff888040808cc0 2551256377 S Co:2:001:0 s 23 03 001b 0701 0000 0
ffff888040808cc0 2551256384 C Co:2:001:0 0 0
ffff888040808cc0 2551256432 C Co:2:001:0 0 0
ffff888040808cc0 2551256482 C Co:2:001:0 0 0
ffff888040808cc0 2551256531 C Co:2:001:0 0 0
ffff888040808cc0 2551256535 S Co:2:001:0 s 23 03 001b 0705 0000 0
ffff888040808cc0 2551256542 C Co:2:001:0 0 0
ffff888040808cc0 2551256551 C Co:2:001:0 0 0
ffff8882447743c0 2551256555 C Ii:2:001:1 -2:2048 0
ffff888040808cc0 2551256562 S Ci:2:001:0 s a3 00 0000 0001 0004 4 <
ffff888040808cc0 2551256566 C Ci:2:001:0 0 4 = 88000000
ffff888040808cc0 2551256568 S Ci:2:001:0 s a3 00 0000 0002 0004 4 <
ffff888040808cc0 2551256573 S Ci:2:001:0 s a3 00 0000 0003 0004 4 <
ffff888040808cc0 2551256579 S Ci:2:001:0 s a3 00 0000 0004 0004 4 <
ffff888040808cc0 2551256584 S Ci:2:001:0 s a3 00 0000 0005 0004 4 <
ffff888040808cc0 2551256625 S Ci:2:001:0 s a3 00 0000 0006 0004 4 <
ffff888040808cc0 2551256686 S Ci:2:001:0 s a3 00 0000 0001 0004 4 <
ffff888040808cc0 2551256689 C Ci:2:001:0 0 4 = 88000000
ffff888040808cc0 2551256735 C Ci:2:001:0 0 4 = 88000000
ffff888040808cc0 2551256745 C Co:2:001:0 0 0
ffff888040808cc0 2551256748 S Co:2:001:0 s 23 03 001b 0702 0000 0
ffff888040808cc0 2551256755 C Co:2:001:0 0 0
ffff888040808cc0 2551256757 S Co:2:001:0 s 23 03 001b 0703 0000 0
ffff888040808cc0 2551256764 C Co:2:001:0 0 0
ffff888040808cc0 2551256802 C Co:2:001:0 0 0
ffff888040808cc0 2551256843 C Co:2:001:0 0 0
ffff888040808cc0 2551256871 C Co:2:001:0 0 0
ffff8882447743c0 2551256914 C Ii:2:001:1 -2:2048 0
ffff888040808cc0 2551256922 S Ci:2:001:0 s a3 00 0000 0001 0004 4 <
ffff888040808cc0 2551256925 C Ci:2:001:0 0 4 = 88000000
ffff888040808cc0 2551256927 S Ci:2:001:0 s a3 00 0000 0002 0004 4 <
ffff888040808cc0 2551256933 S Ci:2:001:0 s a3 00 0000 0003 0004 4 <
ffff888040808cc0 2551256936 C Ci:2:001:0 0 4 = a0020000
ffff888040808cc0 2551256942 C Ci:2:001:0 0 4 = a0020000
ffff8882447743c0 2551257018 S Ii:2:001:1 -115:2048 4 <
ffff888040808cc0 2551257070 S Ci:2:001:0 s a3 00 0000 0002 0004 4 <
ffff888040808cc0 2551257106 C Co:2:001:0 0 0
ffff888040808cc0 2551257115 C Co:2:001:0 0 0
ffff888040808cc0 2551257125 C Co:2:001:0 0 0
ffff888040808cc0 2551257288 C Co:2:001:0 0 0
ffff888040808cc0 2551257290 S Co:2:001:0 s 23 03 001b 0706 0000 0
ffff888040808cc0 2551257297 C Co:2:001:0 0 0
ffff8882447743c0 2551257300 C Ii:2:001:1 -2:2048 0
ffff888040808cc0 2551257329 S Ci:2:001:0 s a3 00 0000 0001 0004 4 <
ffff888040808cc0 2551257367 S Ci:2:001:0 s a3 00 0000 0002 0004 4 <
ffff888040808cc0 2551257408 S Ci:2:001:0 s a3 00 0000 0004 0004 4 <
ffff888040808cc0 2551257461 C Ci:2:001:0 0 4 = a0020000
ffff8882447743c0 2551257762 S Ii:2:001:1 -115:2048 4 <
ffff888040808cc0 2551257815 S Co:2:001:0 s 23 03 001b 0701 0000 0
ffff888040808cc0 2551257823 C Co:2:001:0 0 0
ffff888040808cc0 2551257839 C Co:2:001:0 0 0
ffff888040808cc0 2551257877 C Co:2:001:0 0 0
ffff888040808cc0 2551257947 C Co:2:001:0 0 0
ffff888040808cc0 2551257996 S Ci:2:001:0 s a3 00 0000 0001 0004 4 <
ffff888040808cc0 2551258005 S Ci:2:001:0 s a3 00 0000 0003 0004 4 <
ffff888040808cc0 2551258017 C Ci:2:001:0 0 4 = a0020000
ffff888040808cc0 2551258057 S Ci:2:001:0 s a3 00 0000 0001 0004 4 <
ffff888040808cc0 2551258140 C Co:2:001:0 0 0
ffff888040808cc0 2551258179 C Co:2:001:0 0 0
ffff888040808cc0 2551258257 C Co:2:001:0 0 0
ffff888040808cc0 2551258265 C Co:2:001:0 0 0
ffff888040808cc0 2551258273 C Co:2:001:0 0 0
ffff888040808cc0 2551258286 C Ci:2:001:0 0 4 = 88000000
ffff888040808cc0 2551258294 C Ci:2:001:0 0 4 = a0020000
ffff888040808cc0 2551258391 C Ci:2:001:0 0 4 = a0020000
ffff888040808cc0 2551258448 C Ci:2:001:0 0 4 = 88000000
ffff888040808cc0 2551258462 C Co:2:001:0 0 0
ffff888040808cc0 2551258470 C Co:2:001:0 0 0
ffff888040808cc0 2551258486 C Co:2:001:0 0 0
-- 
Michal Hocko
SUSE Labs