Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1752220AbbKYPmb (ORCPT ); Wed, 25 Nov 2015 10:42:31 -0500 Received: from iolanthe.rowland.org ([192.131.102.54]:55528 "HELO iolanthe.rowland.org" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with SMTP id S1750967AbbKYPm3 (ORCPT ); Wed, 25 Nov 2015 10:42:29 -0500 Date: Wed, 25 Nov 2015 10:42:28 -0500 (EST) From: Alan Stern X-X-Sender: stern@iolanthe.rowland.org To: Daniel J Blueman , Mathias Nyman cc: USB list , Linux Kernel Subject: Re: [4.3] kworker busy in pm_runtime_work In-Reply-To: Message-ID: MIME-Version: 1.0 Content-Type: TEXT/PLAIN; charset=US-ASCII Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Length: 4852 Lines: 109 On Wed, 25 Nov 2015, Daniel J Blueman wrote: > On 23 November 2015 at 23:52, Alan Stern wrote: > > On Sun, 22 Nov 2015, Daniel J Blueman wrote: > > > >> On 16 November 2015 at 23:22, Alan Stern 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 It's time to get some assistance from the xhci-hcd maintainer. Mathias, Daniel's machine is spinning, trying to suspend the root hub on the xHCI HS/FS/LS bus and failing, over and over again. It looks like either bus_state->resuming_ports or bus_state->port_remote_wakeup is nonzero when it shouldn't be. The information we have is all above. Can you help Daniel debug this? Alan Stern -- To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/