Re: v3.16-rc1 regression? unexpected usb_autopm_get_interface error

Re: v3.16-rc1 regression? unexpected usb_autopm_get_interface error

[Bjørn Mork]

[adding the linux-pm list as I suspect this is a more generic issue
affecting usb, quoting all I previously sent to linux-usb for context]

Bjørn Mork <bjorn@mork.no> writes:

> I just booted v3.16-rc1 on my laptop and ended up with an error I've
> never encountered before.  Which makes me suspect that it is related to
> changes in v3.16.  Haven't yet spent any time trying to debug it.  Just
> posting in case it is an already known problem.
>
> I got this in the log:
>
> [  268.689677] usb usb3-port4: not suspended yet
> [  268.696603] cdc_mbim 3-4:1.0: Error autopm - -16
>
> And looking at the latter driver (which I should know ;-), I see that
> this is logged if we get an error from usb_autopm_get_interface when
> attempting to open the chardev:
>
> static int wdm_open(struct inode *inode, struct file *file)
> {
> ..
>         rv = usb_autopm_get_interface(desc->intf);
>         if (rv < 0) {
>                 dev_err(&desc->intf->dev, "Error autopm - %d\n", rv);
>                 goto out;
>         }
>
>
>
> But we shouldn't really hit this, and I cannot remember ever seeing it
> before.  Looking at the device power state, I note that the
> runtime_status is 'error':
>
> bjorn@nemi:~$  grep . /sys/bus/usb/devices/3-4/power/*
> /sys/bus/usb/devices/3-4/power/active_duration:4284
> /sys/bus/usb/devices/3-4/power/async:enabled
> /sys/bus/usb/devices/3-4/power/autosuspend:2
> /sys/bus/usb/devices/3-4/power/autosuspend_delay_ms:2000
> /sys/bus/usb/devices/3-4/power/connected_duration:1523832
> /sys/bus/usb/devices/3-4/power/control:auto
> /sys/bus/usb/devices/3-4/power/level:auto
> /sys/bus/usb/devices/3-4/power/persist:1
> /sys/bus/usb/devices/3-4/power/runtime_active_kids:0
> /sys/bus/usb/devices/3-4/power/runtime_active_time:4040
> /sys/bus/usb/devices/3-4/power/runtime_enabled:enabled
> /sys/bus/usb/devices/3-4/power/runtime_status:error
> /sys/bus/usb/devices/3-4/power/runtime_suspended_time:1519548
> /sys/bus/usb/devices/3-4/power/runtime_usage:0
> /sys/bus/usb/devices/3-4/power/wakeup:disabled
>
>
> Known problem?  Or any suggestions where I start debugging this?
>
> FWIW, I've been using this device with all the latest and greatest
> changes to cdc_mbim for a few weeks already, so I'm pretty sure it isn't
> (only) those changes which trigger this.  I beleive it has to be
> something related to the usb and/or pm core.
>
> If it matters, this device is connected to an internal (mini-PCIe)
> laptop port.  The port state looks OK to me:
>
> bjorn@nemi:~$ cat /sys/bus/usb/devices/3-4/port/connect_type 
> hardwired
> bjorn@nemi:~$ grep . /sys/bus/usb/devices/3-4/port/power/*
> /sys/bus/usb/devices/3-4/port/power/async:enabled
> grep: /sys/bus/usb/devices/3-4/port/power/autosuspend_delay_ms: Input/output error
> /sys/bus/usb/devices/3-4/port/power/control:auto
> /sys/bus/usb/devices/3-4/port/power/runtime_active_kids:0
> /sys/bus/usb/devices/3-4/port/power/runtime_active_time:0
> /sys/bus/usb/devices/3-4/port/power/runtime_enabled:disabled
> /sys/bus/usb/devices/3-4/port/power/runtime_status:unsupported
> /sys/bus/usb/devices/3-4/port/power/runtime_suspended_time:0
> /sys/bus/usb/devices/3-4/port/power/runtime_usage:1


Some more experimenting reveals that this isn't limited to a single
device, or to builtin devices.  I have the exact same problem with *all*
USB devices.  Any USB device which is runtime suspended before it is
used becomes non-functional with a permanent(?) 'error' runtime_status:

nemi:/home/bjorn# grep . /sys/bus/usb/devices/?-?/power/runtime_status
/sys/bus/usb/devices/1-1/power/runtime_status:error
/sys/bus/usb/devices/1-6/power/runtime_status:error
/sys/bus/usb/devices/3-2/power/runtime_status:error
/sys/bus/usb/devices/5-1/power/runtime_status:error
/sys/bus/usb/devices/5-4/power/runtime_status:error
/sys/bus/usb/devices/7-1/power/runtime_status:error

Suspending and resuming the system resets the state temporarily:

nemi:/home/bjorn# grep . /sys/bus/usb/devices/?-?/power/runtime_status
/sys/bus/usb/devices/1-1/power/runtime_status:suspended
/sys/bus/usb/devices/1-6/power/runtime_status:suspended
/sys/bus/usb/devices/3-2/power/runtime_status:suspended
/sys/bus/usb/devices/5-1/power/runtime_status:suspended
/sys/bus/usb/devices/5-4/power/runtime_status:active
/sys/bus/usb/devices/7-1/power/runtime_status:suspended


This doesn't really help though.  Attempting to activate these devices
by opening their respective character devices etc return them to the
same error state:

nemi:/home/bjorn# cat /dev/ttyUSB0
cat: /dev/ttyUSB0: Device or resource busy
nemi:/home/bjorn# grep . /sys/bus/usb/devices/?-?/power/runtime_status
/sys/bus/usb/devices/1-1/power/runtime_status:suspended
/sys/bus/usb/devices/1-6/power/runtime_status:suspended
/sys/bus/usb/devices/3-2/power/runtime_status:suspended
/sys/bus/usb/devices/5-1/power/runtime_status:error
/sys/bus/usb/devices/5-4/power/runtime_status:suspended
/sys/bus/usb/devices/7-1/power/runtime_status:suspended
nemi:/home/bjorn# cat /dev/ttyACM0 
cat: /dev/ttyACM0: Input/output error
nemi:/home/bjorn# grep . /sys/bus/usb/devices/?-?/power/runtime_status
/sys/bus/usb/devices/1-1/power/runtime_status:suspended
/sys/bus/usb/devices/1-6/power/runtime_status:suspended
/sys/bus/usb/devices/3-2/power/runtime_status:suspended
/sys/bus/usb/devices/5-1/power/runtime_status:error
/sys/bus/usb/devices/5-4/power/runtime_status:error
/sys/bus/usb/devices/7-1/power/runtime_status:suspended


But if a device is opened (i.e. marked it "in use") *before* it is
runtime suspended for the first time, then this device will continue to
work.  Also after being runtime suspended.

So the problem is related to runtime suspend before first use. I
strongly suspect 

 aae4518b3124 PM / sleep: Mechanism to avoid resuming runtime-suspended devices unnecessarily

but I haven't been able to verify this yet as it doesn't revert
cleanly.  Will continue to look at it, but any help and/or hint is
appreciated.



Bjørn

Re: v3.16-rc1 regression? unexpected usb_autopm_get_interface error

[Bjørn Mork]

Bjørn Mork <bjorn@mork.no> writes:

> So the problem is related to runtime suspend before first use. I
> strongly suspect 
>
>  aae4518b3124 PM / sleep: Mechanism to avoid resuming runtime-suspended devices unnecessarily

Nope, that was not it. So if blind guessing isn't going to work, then I
guess there is no way around a bisect :-)


Bjørn

Re: v3.16-rc1 regression? unexpected usb_autopm_get_interface error

[Alan Stern]

On Mon, 16 Jun 2014, Bjørn Mork wrote:

> Bjørn Mork <bjorn@mork.no> writes:
> 
> > So the problem is related to runtime suspend before first use. I
> > strongly suspect 
> >
> >  aae4518b3124 PM / sleep: Mechanism to avoid resuming runtime-suspended devices unnecessarily
> 
> Nope, that was not it. So if blind guessing isn't going to work, then I
> guess there is no way around a bisect :-)

You could simply wait for someone who knows the code to answer the 
question.  :-)

I'm pretty sure this resulted from one of Dan Williams's changes to USB 
port runtime PM.  A whole bunch of them were added in 3.15-rc1.

Alan Stern

Re: v3.16-rc1 regression? unexpected usb_autopm_get_interface error

[Bjørn Mork]

Alan Stern <stern@rowland.harvard.edu> writes:
> On Mon, 16 Jun 2014, Bjørn Mork wrote:
>> Bjørn Mork <bjorn@mork.no> writes:
>> 
>> > So the problem is related to runtime suspend before first use. I
>> > strongly suspect 
>> >
>> >  aae4518b3124 PM / sleep: Mechanism to avoid resuming runtime-suspended devices unnecessarily
>> 
>> Nope, that was not it. So if blind guessing isn't going to work, then I
>> guess there is no way around a bisect :-)
>
> You could simply wait for someone who knows the code to answer the 
> question.  :-)

Wait? Do I look like I'm patient :-)

Besides, it was actually relieving to bisect a reliably reproducible
non-crashing bug for once ;-)

> I'm pretty sure this resulted from one of Dan Williams's changes to USB 
> port runtime PM.  A whole bunch of them were added in 3.15-rc1.

You are *so* much better at guessing than me:

9262c19d14c433a6a1ba25c3ff897cb89e412309 is the first bad commit
commit 9262c19d14c433a6a1ba25c3ff897cb89e412309
Author: Dan Williams <dan.j.williams@intel.com>
Date:   Tue May 20 18:08:12 2014 -0700

    usb: disable port power control if not supported in wHubCharacteristics
    
    A hub indicates whether it supports per-port power control via the
    wHubCharacteristics field in its descriptor.  If it is not supported
    a hub will still emulate ClearPortPower(PORT_POWER) requests by
    stopping the link state machine.  However, since this does not save
    power do not bother suspending.
    
    This also consolidates support checks into a
    hub_is_port_power_switchable() helper.
    
    Acked-by: Alan Stern <stern@rowland.harvard.edu>
    Signed-off-by: Dan Williams <dan.j.williams@intel.com>
    Signed-off-by: Greg Kroah-Hartman <gregkh@linuxfoundation.org>

:040000 040000 d4a0ba9da62e47951b60332f69d73931727ecab9 faf9138355178acda4bd0bb0077c520bf46bb10c M      drivers


And the "git bisect log":

# bad: [7171511eaec5bf23fb06078f59784a3a0626b38f] Linux 3.16-rc1
# good: [1860e379875dfe7271c649058aeddffe5afd9d0d] Linux 3.15
git bisect start 'v3.16-rc1' 'v3.15'
# bad: [aaeb2554337217dfa4eac2fcc90da7be540b9a73] Merge branch 'v4l_for_linus' of git://git.kernel.org/pub/scm/linux/kernel/git/mchehab/linux-media into next
git bisect bad aaeb2554337217dfa4eac2fcc90da7be540b9a73
# good: [5142c33ed86acbcef5c63a63d2b7384b9210d39f] Merge tag 'staging-3.16-rc1' of git://git.kernel.org/pub/scm/linux/kernel/git/gregkh/staging into next
git bisect good 5142c33ed86acbcef5c63a63d2b7384b9210d39f
# bad: [b05d59dfceaea72565b1648af929b037b0f96d7f] Merge tag 'for-linus' of git://git.kernel.org/pub/scm/virt/kvm/kvm into next
git bisect bad b05d59dfceaea72565b1648af929b037b0f96d7f
# bad: [e13cccfd86481bd4c0499577f44c570d334da79b] Merge tag 'spi-v3.16' of git://git.kernel.org/pub/scm/linux/kernel/git/broonie/spi into next
git bisect bad e13cccfd86481bd4c0499577f44c570d334da79b
# bad: [4a95b1fce97756d0333f8232eb7ed6974e93b054] usb: hub_handle_remote_wakeup() only exists for CONFIG_PM=y
git bisect bad 4a95b1fce97756d0333f8232eb7ed6974e93b054
# good: [54969ed6c4d0b9eb7fa68a909be231f383f0c406] usb: ohci-exynos: Use struct device instead of platform_device
git bisect good 54969ed6c4d0b9eb7fa68a909be231f383f0c406
# good: [0943d8ead30e9474034cc5e92225ab0fd29fd0d4] USB: cdc-acm: use tty-port dtr_rts
git bisect good 0943d8ead30e9474034cc5e92225ab0fd29fd0d4
# good: [657d898a9320a7cdb9b94565d75ecf75c25cbf0a] usb: usb5303: add support for reference clock specified in device tree
git bisect good 657d898a9320a7cdb9b94565d75ecf75c25cbf0a
# bad: [5c79a1e303363d46082408fd306cdea6d33013fc] usb: introduce port status lock
git bisect bad 5c79a1e303363d46082408fd306cdea6d33013fc
# bad: [d8521afe35862f4fbe3ccd6ca37897c0a304edf3] usb: assign default peer ports for root hubs
git bisect bad d8521afe35862f4fbe3ccd6ca37897c0a304edf3
# good: [342a74934197386e065e8ef00014e6f0cb5effe6] usb: pci_quirks: fix sparse 'symbol not declared' warning
git bisect good 342a74934197386e065e8ef00014e6f0cb5effe6
# bad: [9262c19d14c433a6a1ba25c3ff897cb89e412309] usb: disable port power control if not supported in wHubCharacteristics
git bisect bad 9262c19d14c433a6a1ba25c3ff897cb89e412309
# good: [600856c231ccb0cbf8afcf09066a8ab2a93ab03d] USB: mutual exclusion for resetting a hub and power-managing a port
git bisect good 600856c231ccb0cbf8afcf09066a8ab2a93ab03d




Bjørn

Re: v3.16-rc1 regression? unexpected usb_autopm_get_interface error

[Bjørn Mork]

[-- Attachment #1: Type: text/plain, Size: 1163 bytes --]

Bjørn Mork <bjorn@mork.no> writes:
> Alan Stern <stern@rowland.harvard.edu> writes:
>> On Mon, 16 Jun 2014, Bjørn Mork wrote:
>>> Bjørn Mork <bjorn@mork.no> writes:
>>> 
>>> > So the problem is related to runtime suspend before first use. I
>>> > strongly suspect 
>>> >
>>> >  aae4518b3124 PM / sleep: Mechanism to avoid resuming runtime-suspended devices unnecessarily
>>> 
>>> Nope, that was not it. So if blind guessing isn't going to work, then I
>>> guess there is no way around a bisect :-)
>>
>> You could simply wait for someone who knows the code to answer the 
>> question.  :-)
>
> Wait? Do I look like I'm patient :-)
>
> Besides, it was actually relieving to bisect a reliably reproducible
> non-crashing bug for once ;-)
>
>> I'm pretty sure this resulted from one of Dan Williams's changes to USB 
>> port runtime PM.  A whole bunch of them were added in 3.15-rc1.
>
> You are *so* much better at guessing than me:
>
> 9262c19d14c433a6a1ba25c3ff897cb89e412309 is the first bad commit

And for completeness, I just tried the following partial revert on top
of v3.16-rc1 and can confirm that it works fine for me:


[-- Attachment #2: 0001-usb-fix-port-runtime-pm-regression.patch --]
[-- Type: text/x-diff, Size: 1736 bytes --]

>From f8cba987220ae6cca98d662704256839968c6a61 Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Bj=C3=B8rn=20Mork?= <bjorn@mork.no>
Date: Mon, 16 Jun 2014 17:26:05 +0200
Subject: [PATCH] usb: fix port runtime pm regression
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8bit

This is a partial revert of commit 9262c19d14c4 ("usb: disable port
power control if not supported in wHubCharacteristics")

Fixes: 9262c19d14c4 ("usb: disable port power control if not supported in wHubCharacteristics")
Signed-off-by: Bjørn Mork <bjorn@mork.no>
---
 drivers/usb/core/port.c |   13 +++++--------
 1 file changed, 5 insertions(+), 8 deletions(-)

diff --git a/drivers/usb/core/port.c b/drivers/usb/core/port.c
index 62036faf56c0..13a2ffb4b18a 100644
--- a/drivers/usb/core/port.c
+++ b/drivers/usb/core/port.c
@@ -411,15 +411,12 @@ int usb_hub_create_port_device(struct usb_hub *hub, int port1)
 
 	pm_runtime_set_active(&port_dev->dev);
 
-	/*
-	 * Do not enable port runtime pm if the hub does not support
-	 * power switching.  Also, userspace must have final say of
-	 * whether a port is permitted to power-off.  Do not enable
-	 * runtime pm if we fail to expose pm_qos_no_power_off.
+	/* It would be dangerous if user space couldn't
+	 * prevent usb device from being powered off. So don't
+	 * enable port runtime pm if failed to expose port's pm qos.
 	 */
-	if (hub_is_port_power_switchable(hub)
-			&& dev_pm_qos_expose_flags(&port_dev->dev,
-			PM_QOS_FLAG_NO_POWER_OFF) == 0)
+	if (!dev_pm_qos_expose_flags(&port_dev->dev,
+			PM_QOS_FLAG_NO_POWER_OFF))
 		pm_runtime_enable(&port_dev->dev);
 
 	device_enable_async_suspend(&port_dev->dev);
-- 
1.7.10.4


[-- Attachment #3: Type: text/plain, Size: 162 bytes --]



But I'm not submitting that patch as I assume Dan wants to fix this up
properly.  Whatever that is... I don't understand any of the port magic.


Bjørn

Re: v3.16-rc1 regression? unexpected usb_autopm_get_interface error

[Alan Stern]

On Mon, 16 Jun 2014, Bjørn Mork wrote:

> >> I'm pretty sure this resulted from one of Dan Williams's changes to USB 
> >> port runtime PM.  A whole bunch of them were added in 3.15-rc1.
> >
> > You are *so* much better at guessing than me:
> >
> > 9262c19d14c433a6a1ba25c3ff897cb89e412309 is the first bad commit
> 
> And for completeness, I just tried the following partial revert on top
> of v3.16-rc1 and can confirm that it works fine for me:

I'm not up-to-date on the most recent few releases, so I'll let Dan
take care of this.  In general, it looks like the problem stems from
the fact that when a device is disabled for runtime PM, a
pm_runtime_get_sync() or pm_runtime_resume() call won't succeed, even
if the device is currently at full power.  Maybe we should change this 
in the PM core.

Dan, the warning message in hub_suspend() should mention that the child 
device isn't suspended yet.  Currently it looks like it's saying that 
the port isn't suspended, which gives the wrong impression.

Alan Stern