linux-kernel - Re: [4.3] kworker busy in pm_runtime

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: <CAMVG2stJTSFE45C6e=E9PuCiOTXF6htO2WuQ_n1JmO63xsjfGw@mail.gmail.com>
Date:	Wed, 25 Nov 2015 06:23:02 +0800
From:	Daniel J Blueman <daniel@...ra.org>
To:	Alan Stern <stern@...land.harvard.edu>
Cc:	USB list <linux-usb@...r.kernel.org>,
	Linux Kernel <linux-kernel@...r.kernel.org>
Subject: Re: [4.3] kworker busy in pm_runtime_work

On 23 November 2015 at 23:52, Alan Stern <stern@...land.harvard.edu> wrote:
> On Sun, 22 Nov 2015, Daniel J Blueman wrote:
>
>> On 16 November 2015 at 23:22, Alan Stern <stern@...land.harvard.edu> wrote:
>> > On Mon, 16 Nov 2015, Daniel J Blueman wrote:
>> >
>> >> Tuning USB suspend [1] in 4.3 on a Dell XPS 15 9553 (Skylake), I see a
>> >> kworker thread spinning in rpm_suspend [2].
>> >>
>> >> What is the most useful debug to get here beyond the immediate [3]?
>> >
>> > You can try doing:
>> >
>> >         echo 'module usbcore =p' >/sys/kernel/debug/dynamic_debug/control
>>
>> kworker and ksoftirqd spinning occurs when I echo 'auto' to all the
>> USB control entries. Using Alan's excellent tip, we see this being
>> logged repeatedly at a high rate:
>> [  353.245180] usb usb1-port4: status 0107 change 0000
>> [  353.245194] usb usb1-port12: status 0507 change 0000
>> [  353.245202] hub 1-0:1.0: state 7 ports 16 chg 0000 evt 0000
>> [  353.245203] hub 1-0:1.0: hub_suspend
>> [  353.245205] usb usb1: bus auto-suspend, wakeup 1
>> [  353.245206] usb usb1: bus suspend fail, err -16
>> [  353.245207] hub 1-0:1.0: hub_resume
>> ...
>>
>> So, EBUSY. Both the webcam is not open, and the bluetooth interface
>> [1] is rfkill'd; the situation occurs even if I unload all related
>> modules.
>>
>> What further debug would be useful?
>>
>> Thanks!
>>   Daniel
>>
>> -- [1]
>>
>> Bus 002 Device 001: ID 1d6b:0003 Linux Foundation 3.0 root hub
>> Bus 001 Device 002: ID 0a5c:6410 Broadcom Corp.
>> Bus 001 Device 003: ID 1bcf:2b95 Sunplus Innovation Technology Inc.
>> Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
>
> Since bus 1 uses an xHCI controller, you should do:
>
>         echo 'module xhci-hcd =p' >/sys/kernel/debug/dynamic_debug/control
>
> I'm reasonably sure this will end up printing "suspend failed
> because a port is resuming", since that's the only place where
> xhci_bus_suspend() fails with -EBUSY, but you should try it to confirm
> this.

I had to use:
echo 'module xhci_hcd =p' >/sys/kernel/debug/dynamic_debug/control

and indeed we see:
[29172.246221] xhci_hcd 0000:00:14.0: get port status, actual port 11
status  = 0xe63
[29172.246222] xhci_hcd 0000:00:14.0: Get port status returned 0x507
[29172.246224] xhci_hcd 0000:00:14.0: get port status, actual port 12
status  = 0x2a0
[29172.246228] xhci_hcd 0000:00:14.0: get port status, actual port 13
status  = 0x2a0
[29172.246228] xhci_hcd 0000:00:14.0: Get port status returned 0x100
[29172.246231] xhci_hcd 0000:00:14.0: get port status, actual port 14
status  = 0x2a0
[29172.246232] xhci_hcd 0000:00:14.0: Get port status returned 0x100
[29172.246235] xhci_hcd 0000:00:14.0: Get port status returned 0x100
[29172.246248] xhci_hcd 0000:00:14.0: Get port status returned 0x100
[29172.246254] xhci_hcd 0000:00:14.0: Get port status returned 0x100
[29172.246264] xhci_hcd 0000:00:14.0: Get port status returned 0x100
[29172.246275] xhci_hcd 0000:00:14.0: Get port status returned 0x100
[29172.246285] xhci_hcd 0000:00:14.0: Get port status returned 0x507
[29172.246294] xhci_hcd 0000:00:14.0: get port status, actual port 14
status  = 0x2a0
[29172.246302] xhci_hcd 0000:00:14.0: suspend failed because a port is resuming
[29172.246321] xhci_hcd 0000:00:14.0: Get port status returned 0x107
[29172.246332] xhci_hcd 0000:00:14.0: get port status, actual port 6
status  = 0x2a0
[29172.246346] xhci_hcd 0000:00:14.0: Get port status returned 0x100
[29172.246359] xhci_hcd 0000:00:14.0: get port status, actual port 13
status  = 0x2a0
[29172.246364] xhci_hcd 0000:00:14.0: Get port status returned 0x100
[29172.246366] xhci_hcd 0000:00:14.0: get port status, actual port 15
status  = 0x2a0
[29172.246371] xhci_hcd 0000:00:14.0: suspend failed because a port is resuming
[29172.246380] xhci_hcd 0000:00:14.0: Get port status returned 0x100
[29172.246382] xhci_hcd 0000:00:14.0: get port status, actual port 1
status  = 0x2a0
[29172.246383] xhci_hcd 0000:00:14.0: Get port status returned 0x100
...
-- 
Daniel J Blueman
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@...r.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/