Received-SPF: pass (google.com: domain of linux-kernel-owner@vger.kernel.org designates 23.128.96.18 as permitted sender) client-ip=23.128.96.18;
Date:   Mon, 20 Jul 2020 09:58:57 -0400
From:   Alan Stern <stern@rowland.harvard.edu>
To:     Michal Hocko <mhocko@kernel.org>
Cc:     LKML <linux-kernel@vger.kernel.org>,
        Greg KH <gregkh@linuxfoundation.org>,
        linux-usb@vger.kernel.org, "Rafael J. Wysocki" <rjw@rjwysocki.net>
Subject: Re: kworker/0:3+pm hogging CPU
Message-ID: <20200720135857.GB1228057@rowland.harvard.edu>
References: <20200720083956.GA4074@dhcp22.suse.cz>
MIME-Version: 1.0
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline
In-Reply-To: <20200720083956.GA4074@dhcp22.suse.cz>
User-Agent: Mutt/1.10.1 (2018-07-13)
Sender: linux-kernel-owner@vger.kernel.org
Precedence: bulk

On Mon, Jul 20, 2020 at 10:39:56AM +0200, Michal Hocko wrote:
> Hi,
> I am not sure when this started happening but at least 5.6, 5.7 and
> 5.8-rc6 all exhibit this problem. Please note that the this is happining
> on a laptop which is not completely healthy. The BIOS complains that the
> Battery cannot be charged because the power supply cannot be recognized.
> This is somehting I have for a longer time without noticing the
> kworker/0:3+pm problem so I do not think they are related but who knows.
> 
> Anyway, kworker/0:3+pm is hogging CPU. /proc/<pid>/0:3+pm is very often
> empty so I suspect it just schedules very often and performs only small
> amount of work. Here are few backtraces I've managed to catch
> 
> [<0>] preempt_schedule_thunk+0x16/0x18
> [<0>] usb_hcd_submit_urb+0x686/0x773
> [<0>] usb_start_wait_urb+0x59/0xc8
> [<0>] usb_control_msg+0xd4/0x10d
> [<0>] get_port_status+0x51/0x6f
> [<0>] hub_port_status+0x41/0xa3
> [<0>] hub_activate+0x230/0x4ee
> [<0>] hub_resume+0x20/0x9a
> [<0>] usb_resume_interface.isra.0+0xb0/0xd0
> [<0>] usb_suspend_both+0xf6/0x20c
> [<0>] usb_runtime_suspend+0x32/0x62
> [<0>] __rpm_callback+0x70/0xd4
> [<0>] rpm_callback+0x55/0x6b
> [<0>] rpm_suspend+0x2af/0x440
> [<0>] __pm_runtime_suspend+0x48/0x62
> [<0>] usb_runtime_idle+0x26/0x2d
> [<0>] __rpm_callback+0x70/0xd4
> [<0>] rpm_idle+0x179/0x1df
> [<0>] pm_runtime_work+0x6b/0x81
> [<0>] process_one_work+0x1bd/0x2c6
> [<0>] worker_thread+0x19c/0x240
> [<0>] kthread+0x11b/0x123
> [<0>] ret_from_fork+0x22/0x30
> 
> [<0>] slab_pre_alloc_hook+0x15/0x46
> [<0>] __kmalloc+0x148/0x15a
> [<0>] usb_hcd_submit_urb+0x5c6/0x773
> [<0>] usb_start_wait_urb+0x59/0xc8
> [<0>] usb_control_msg+0xd4/0x10d
> [<0>] get_port_status+0x51/0x6f
> [<0>] hub_port_status+0x41/0xa3
> [<0>] hub_activate+0x230/0x4ee
> [<0>] hub_resume+0x20/0x9a
> [<0>] usb_resume_interface.isra.0+0xb0/0xd0
> [<0>] usb_suspend_both+0xf6/0x20c
> 
> [<0>] slab_pre_alloc_hook+0x15/0x46
> [<0>] __kmalloc+0x148/0x15a
> [<0>] usb_hcd_submit_urb+0x5c6/0x773
> [<0>] usb_start_wait_urb+0x59/0xc8
> [<0>] usb_control_msg+0xd4/0x10d
> [<0>] set_port_feature+0x33/0x38
> [<0>] hub_suspend+0x15c/0x16a
> [<0>] usb_suspend_both+0x91/0x20c
> [<0>] usb_runtime_suspend+0x32/0x62
> [<0>] __rpm_callback+0x70/0xd4
> [<0>] rpm_callback+0x55/0x6b
> [<0>] rpm_suspend+0x2af/0x440
> [<0>] __pm_runtime_suspend+0x48/0x62
> [<0>] usb_runtime_idle+0x26/0x2d
> [<0>] __rpm_callback+0x70/0xd4
> [<0>] rpm_idle+0x179/0x1df
> [<0>] pm_runtime_work+0x6b/0x81
> [<0>] process_one_work+0x1bd/0x2c6
> [<0>] worker_thread+0x19c/0x240
> [<0>] kthread+0x11b/0x123
> [<0>] ret_from_fork+0x22/0x30
> 
> Is this something known or something I can give more information about?
> From a very quick look into the code it sounds as if the system wanted
> to suspend an USB device/controller but that keeps failing again and
> again.

Yes, that's what it looks like to me too.  Or maybe the suspend succeeds 
but then the device/controller immediately gets woken up again.

Can you provide the contents of /sys/kernel/debug/usb/devices and also a 
usbmon trace showing a few rounds of this recurring activity?  Perhaps a 
section of the dmesg log with dynamic debugging enabled for the usbcore 
module, as well.

Alan Stern