Re: [linux-pm] s2ram slow (radeon) / failing (usb)

Previous thread: new thread: http://lkml.org/lkml/2010/5/3/229 by Nils Radtke on Monday, May 3, 2010 - 12:52 pm. (1 message)

Next thread: [RFC] Exposing TSC "reliability" to userland by Dan Magenheimer on Monday, May 3, 2010 - 1:21 pm. (2 messages)
From: Alan Stern
Date: Monday, May 3, 2010 - 1:11 pm

First of all, have you tried disabling async suspend?  Look at 





Suspend for the embedded hub interface.  Next we should see

	[....] usb 1-2: type suspend, may wakeup

for the embedded hub device, but we don't.  That's the problem.  It 

And here we should see

	[....] usb usb1: type suspend, may wakeup
	etc.


The 0000:00:13.0 device can't suspend until usb1 does, and usb1 can't
suspend until 1-2 does.

Can you boot the dmesg log for bootup and device detection?  It may 
indicate what we're missing.  Also include the contents of 
/sys/kernel/debug/usb/devices.

Alan Stern

--

From: Bruno Prémont
Date: Monday, May 3, 2010 - 2:11 pm

Loading usbhid on top of hid with debug=1:

[  473.786604] HID: hid_debug is now used solely for parser and driver debugging.
[  473.786610] HID: debugfs is now used for inspecting the device (report descriptor, reports)
[  477.455492] usbhid 1-2.1:1.0: usb_probe_interface
[  477.455502] usbhid 1-2.1:1.0: usb_probe_interface - got id
[  477.455510] usb 1-2.1: __pm_runtime_resume()!
[  477.455516] usb 1-2.1: __pm_runtime_resume() returns 1!
[  477.455522] usb 1-2.1: usb_autoresume_device: cnt 2 -> 1
[  477.455531] /usr/src/linux-2.6-git/drivers/hid/usbhid/hid-core.c: HID probe called for ifnum 0
[  477.463038] PM: Adding info for hid:0003:058F:9462.0001
[  477.477614] /usr/src/linux-2.6-git/drivers/hid/usbhid/hid-core.c: submitting ctrl urb: Set_Report wValue=0x0200 wIndex=0x0000 wLength=1
[  477.477829] PM: Adding info for No Bus:input4
[  477.477917] input: Multimedia USB Keyboard Multimedia USB Keyboard as /devices/pci0000:00/0000:00:13.0/usb1/1-2/1-2.1/1-2.1:1.0/input/input4
[  477.491554] usbhid 1-2.1:1.0: __pm_runtime_resume()!
[  477.491560] usbhid 1-2.1:1.0: __pm_runtime_resume() returns 1!
[  477.491566] usbhid 1-2.1:1.0: usb_autopm_get_interface: cnt 2 -> 1
[  477.491579] usbhid 1-2.1:1.0: usb_autopm_put_interface: cnt 1 -> 0
[  477.491645] PM: Adding info for No Bus:event3
[  477.491681] generic-usb 0003:058F:9462.0001: input: USB HID v1.10 Keyboard [Multimedia USB Keyboard Multimedia USB Keyboard] on usb-0000:00:13.0-2.1/input0
[  477.506754] usb 1-2.1: usb_autosuspend_device: cnt 1 -> 0
[  477.506763] usbhid 1-2.1:1.0: __pm_runtime_suspend()!
[  477.506771] usbhid 1-2.1:1.0: __pm_runtime_suspend() returns 0!
[  477.506815] usbhid 1-2.1:1.1: usb_probe_interface
[  477.506822] usbhid 1-2.1:1.1: usb_probe_interface - got id
[  477.506827] usb 1-2.1: __pm_runtime_resume()!
[  477.506831] usb 1-2.1: __pm_runtime_resume() returns 1!
[  477.506836] usb 1-2.1: usb_autoresume_device: cnt 2 -> 1
[  477.506843] /usr/src/linux-2.6-git/drivers/hid/usbhid/hid-core.c: HID probe ...
From: Oliver Neukum
Date: Monday, May 3, 2010 - 11:42 pm

Ugh. That looks like a bug in usbhid that I introduced. A fix is not trivial.
In short, I did not think the device could be undergoing a queued resumption
while suspend() is being called. I wonder why this is happening.

	Regards
		Oliver
--

From: Jiri Kosina
Date: Tuesday, May 4, 2010 - 1:37 am

Hmmm ... seems to me that in this case, the problem might be that there is 
a device hanging in the air, for which the parsing of report descriptor 
failed (interface .0002), but it's still somehow there on the bus.

It's a bit strange that we are not seeing 

	dev_err(&intf->dev, "can't add hid device: %d\n", ret);

message from usbhid_probe(), are we? That would mean, that we are 
returning ENODEV from the usb_driver->probe routine properly.

Bruno, could you, for testing purposes, check, whether the patch below 
changes the behavior you are seeing (and also check what the actual return 
value from device_add() was, see the added printk()).
Thanks.



 drivers/hid/hid-core.c        |    5 +++--
 drivers/hid/usbhid/hid-core.c |    4 ++--
 2 files changed, 5 insertions(+), 4 deletions(-)

diff --git a/drivers/hid/hid-core.c b/drivers/hid/hid-core.c
index 2e2aa75..7186f9f 100644
--- a/drivers/hid/hid-core.c
+++ b/drivers/hid/hid-core.c
@@ -1770,10 +1770,11 @@ int hid_add_device(struct hid_device *hdev)
 		     hdev->vendor, hdev->product, atomic_inc_return(&id));
 
 	ret = device_add(&hdev->dev);
+	printk(KERN_DEBUG "HID: device_add() returned %d\n", ret);
 	if (!ret)
 		hdev->status |= HID_STAT_ADDED;
-
-	hid_debug_register(hdev, dev_name(&hdev->dev));
+	else
+		hid_debug_register(hdev, dev_name(&hdev->dev));
 
 	return ret;
 }
diff --git a/drivers/hid/usbhid/hid-core.c b/drivers/hid/usbhid/hid-core.c
index 56d06cd..f33445a 100644
--- a/drivers/hid/usbhid/hid-core.c
+++ b/drivers/hid/usbhid/hid-core.c
@@ -1181,8 +1181,8 @@ static int usbhid_probe(struct usb_interface *intf, const struct usb_device_id *
 
 	ret = hid_add_device(hid);
 	if (ret) {
-		if (ret != -ENODEV)
-			dev_err(&intf->dev, "can't add hid device: %d\n", ret);
+		dev_err(&intf->dev, "can't add hid device: %d\n", ret);
+		ret = -ENODEV;
 		goto err_free;
 	}
 

-- 
Jiri Kosina
SUSE Labs, Novell Inc.
--

From: Bruno Prémont
Date: Tuesday, May 4, 2010 - 2:04 pm

Well, it's said to return 0:

[  286.872739] generic-usb 0003:058F:9462.0003: input: USB HID v1.10 Keyboard [Multimedia USB Keyboard Multimedia USB Keyboard] on usb-0000:00:13.0-2.1/input0
[  286.890136] HID: device_add() returned 0

[  286.919698] generic-usb: probe of 0003:058F:9462.0004 failed with error -22
[  286.929363] HID: device_add() returned 0

or with debug=1 for HID:
[  559.982958] /usr/src/linux-2.6-git/drivers/hid/usbhid/hid-core.c: HID probe called for ifnum 1
[  560.011698] /usr/src/linux-2.6-git/drivers/hid/hid-core.c: usage index exceeded
[  560.011704] /usr/src/linux-2.6-git/drivers/hid/hid-core.c: hid_add_usage failed
[  560.011710] /usr/src/linux-2.6-git/drivers/hid/hid-core.c: item 0 2 2 2 parsing failed
[  560.011732] /usr/src/linux-2.6-git/drivers/hid/usbhid/hid-core.c: parsing report descriptor failed
[  560.011747] generic-usb: probe of 0003:058F:9462.0006 failed with error -22
[  560.021718] HID: device_add() returned 0

Complete log of connecting keyboard is below (including hid debug, usb
debug and pm debug messages).

The patch does not change suspend behavior (as could be expected for a
return value of 0)

Thanks,
Bruno



[  558.585559] usb usb2: usb wakeup-resume
[  558.585569] usb usb2: __pm_runtime_resume()!
[  558.585578] usb usb2: usb auto-resume
[  558.585584] ehci_hcd 0000:00:13.5: resume root hub
[  558.730038] ehci_hcd 0000:00:13.5: port 2 full speed --> companion
[  558.730049] ehci_hcd 0000:00:13.5: GetStatus port 2 status 003801 POWER OWNER sig=j CONNECT
[  558.750021] usb usb2: usb_resume_device: status 0
[  558.750028] hub 2-0:1.0: hub_resume
[  558.750086] hub 2-0:1.0: usb_resume_interface: status 0
[  558.750091] usb usb2: usb_resume_both: status 0
[  558.750103] hub 2-0:1.0: state 7 ports 10 chg 0000 evt 0000
[  558.750112] usb usb2: __pm_runtime_resume() returns 0!
[  558.750121] usb usb2: usb_autoresume_device: cnt 1 -> 0
[  558.750131] usb usb2: usb_autosuspend_device: cnt 0 -> 0
[  558.750141] usb usb1: usb ...
From: Jiri Kosina
Date: Wednesday, May 5, 2010 - 5:58 am

Could you please verify with this patch? Thanks.



 drivers/hid/hid-core.c |    4 +++-
 1 files changed, 3 insertions(+), 1 deletions(-)

diff --git a/drivers/hid/hid-core.c b/drivers/hid/hid-core.c
index 2e2aa75..8df19d3 100644
--- a/drivers/hid/hid-core.c
+++ b/drivers/hid/hid-core.c
@@ -1486,8 +1486,10 @@ static int hid_device_probe(struct device *dev)
 			if (!ret)
 				ret = hid_hw_start(hdev, HID_CONNECT_DEFAULT);
 		}
-		if (ret)
+		if (ret) {
 			hdev->driver = NULL;
+			ret = -ENODEV;
+		}
 	}
 	return ret;
 }

-- 
Jiri Kosina
SUSE Labs, Novell Inc.
--

From: Bruno Prémont
Date: Wednesday, May 5, 2010 - 12:17 pm

No difference, the second interface remains registered with HID bus
and I don't spot any difference in kernel log.

Going to have a look at what probe exactly it's that returns -EINVAL
and then attempt to unroll it up to device_add() ...
Hopefully I will find the function that does not hand back the failure.

Thanks,
--

From: Bruno Prémont
Date: Wednesday, May 5, 2010 - 1:30 pm

Ok, I've been digging some further...

The hid_device_probe properly returns -ENODEV, but:

Call trace:
[ 3228.866146]  [<ffffffffa01a00e6>] hid_device_probe+0xd6/0x1f0 [hid]
    return -ENODEV
[ 3228.874594]  [<ffffffff8130995a>] driver_probe_device+0xaa/0x1d0
    calls inlined really_probe from drivers/base/dd.c
    which ALLWAYS returns 0:
     dd.c:147 /*
          148  * Ignore errors returned by ->probe so that the next driver can try
          149  * its luck.
          150  */
          151 ret = 0;
     and has on line 139 (under same failure label):
              dev->driver = NULL;
[ 3228.882758]  [<ffffffff81309b20>] ? __device_attach+0x0/0x50
[ 3228.890555]  [<ffffffff81309b6b>] __device_attach+0x4b/0x50
     lets 0 bubble up
[ 3228.898272]  [<ffffffff81308d28>] bus_for_each_drv+0x68/0x90
     lets 0 bubble up
[ 3228.906080]  [<ffffffff81309c3b>] device_attach+0x8b/0xa0
     lets 0 bubble up
[ 3228.913603]  [<ffffffff81308b15>] bus_probe_device+0x25/0x40
     returns void and does WARN_ON(device_attach() < 0)
[ 3228.921356]  [<ffffffff81307166>] device_add+0x3d6/0x610
     returns 0 here as there was no local error
[ 3228.928772]  [<ffffffffa019fc53>] hid_add_device+0x183/0x1e0 [hid]
[ 3228.937098]  [<ffffffffa01b4a77>] usbhid_probe+0x287/0x420 [usbhid]
[ 3228.945535]  [<ffffffffa005006d>] usb_probe_interface+0x14d/0x230 [usbcore]
...

So IMHO in hid_add_device() we should also check for hdev->dev.driver
when device_add() returns 0 and consider that one being NULL as a
(possible) error.

Thanks,
Bruno
--

From: Bruno Prémont
Date: Wednesday, May 5, 2010 - 1:53 pm

Something like the delow diff causes the HID registration to fail
gracefully and `echo devices > pm_test` suspend attempt to pass.

(note, to be manually applied, is edited copy from console, so does
 not preserve tabs and line numbers may not match due to debug printks
 added all over the place)


I don't know what impact it could have on auto-probing of device
if a specialized HID driver that would fix reports or whatever was
loaded later on when device is already plugged into USB.

Thanks,
Bruno


@@ -1770,11 +1779,13 @@ int hid_add_device(struct hid_device *hdev)
                     hdev->vendor, hdev->product, atomic_inc_return(&id));
 
        ret = device_add(&hdev->dev);
-       if (!ret)
+       if (ret == 0 && !hdev->dev.driver) {
+               device_del(&hdev->dev);
+               ret = -ENODEV;
+       } else {
                hdev->status |= HID_STAT_ADDED;
-
-       hid_debug_register(hdev, dev_name(&hdev->dev));
-
+               hid_debug_register(hdev, dev_name(&hdev->dev));
+       }
        return ret;
 }
 EXPORT_SYMBOL_GPL(hid_add_device);
--

From: Jiri Kosina
Date: Wednesday, May 5, 2010 - 1:55 pm

[ Jiri Slaby added to CC ]


-- 
Jiri Kosina
SUSE Labs, Novell Inc.
--

Previous thread: new thread: http://lkml.org/lkml/2010/5/3/229 by Nils Radtke on Monday, May 3, 2010 - 12:52 pm. (1 message)

Next thread: [RFC] Exposing TSC "reliability" to userland by Dan Magenheimer on Monday, May 3, 2010 - 1:21 pm. (2 messages)