On Wednesday, 13 September 2006 20:38, Alan Stern wrote:
> On Wed, 13 Sep 2006, Rafael J. Wysocki wrote:
>
> > Well, I have reproduced it with gregkh-usb-usbcore-remove-usb_suspend_root_hub.patch
> > reverted too.
> >
> > Attached is the output of dmesg from the failing case with USB_DEBUG set.
> > It covers two attempts to suspend to disk, the second one being unsuccessful,
> > with reloading the ohci_hcd module in between. [This kernel also has your
> > other patch to prevent the second suspend from failing applied, but it doesn't
> > help.]
>
> Okay. Your problem, and probably Mattia's too, is something other than
> what that recent patch addressed. I can't tell from the dmesg log exactly
> what went wrong, but I can tell you where to look.
>
> In drivers/usb/core/driver.c, resume_device() is not succeeding. That is,
> the lines near the end which do
>
> if (status == 0)
> udev->dev.power.power_state.event = PM_EVENT_ON;
>
> aren't running during the first resume. You can see this in the dmesg
> log; lines 1173-1175 say
>
> usb usb1: resuming
> usbdev1.1_ep00: PM: resume from 0, parent usb1 still 1
> hub 1-0:1.0: PM: resume from 0, parent usb1 still 1
>
> If power_state.event had gotten set to PM_EVENT_ON then the parent state
> would be 0, not 1. This is the source of your problem. During your
> second suspend attempt, usb1 didn't get handled correctly because its
> state was set wrong. (I suspect the mishandling took place in usbcore
> rather than the PM core, but it doesn't matter. The state should not have
> been wrong to begin with.) Consequently its parent device 0000:00:13.2
> refused to freeze, which aborted the suspend attempt.
>
> For the usb1 device, udriver->resume should point to the generic_resume()
> routine in drivers/usb/core/generic.c. In fact, this should be true for
> every device that driver.c:resume_device() sees. But generic_resume()
> simply calls usb_port_resume() in hub.c, and the log doesn't contain any
> of the USB debugging messages that usb_port_resume() would produce. So I
> can't tell what happened.
>
> The patch below will add some extra debugging information. We need to
> find out why the resume didn't succeed. Oh -- and of course, you should
> reinstate all those autosuspend patches. Otherwise this patch won't
> apply!

OK

Attached is a dmesg output from 2.6.18-rc6-mm2 with the patch applied.
It covers two consecutive attempts to suspend (the second one obviously
failed).

Greetings,
Rafael

--
You never change things by fighting the existing reality.
R. Buckminster Fuller

Attachments:

(No filename) (2.55 kB)
dmesg-debug.log.gz (14.46 kB)
Download all attachments

2006-09-13 20:39:44

by Mattia Dongili

[permalink] [raw]

Subject: Re: [linux-usb-devel] 2.6.18-rc6-mm1 (-mm2): ohci resume problem

On Wed, Sep 13, 2006 at 02:38:35PM -0400, Alan Stern wrote:
> On Wed, 13 Sep 2006, Rafael J. Wysocki wrote:
>
> > Well, I have reproduced it with gregkh-usb-usbcore-remove-usb_suspend_root_hub.patch
> > reverted too.
> >
> > Attached is the output of dmesg from the failing case with USB_DEBUG set.
> > It covers two attempts to suspend to disk, the second one being unsuccessful,
> > with reloading the ohci_hcd module in between. [This kernel also has your
> > other patch to prevent the second suspend from failing applied, but it doesn't
> > help.]
>
> Okay. Your problem, and probably Mattia's too, is something other than
> what that recent patch addressed. I can't tell from the dmesg log exactly
> what went wrong, but I can tell you where to look.
>
> In drivers/usb/core/driver.c, resume_device() is not succeeding. That is,
> the lines near the end which do
>
> if (status == 0)
> udev->dev.power.power_state.event = PM_EVENT_ON;
>
> aren't running during the first resume. You can see this in the dmesg
> log; lines 1173-1175 say
>
> usb usb1: resuming
> usbdev1.1_ep00: PM: resume from 0, parent usb1 still 1
> hub 1-0:1.0: PM: resume from 0, parent usb1 still 1
>
> If power_state.event had gotten set to PM_EVENT_ON then the parent state
> would be 0, not 1. This is the source of your problem. During your
> second suspend attempt, usb1 didn't get handled correctly because its
> state was set wrong. (I suspect the mishandling took place in usbcore
> rather than the PM core, but it doesn't matter. The state should not have
> been wrong to begin with.) Consequently its parent device 0000:00:13.2
> refused to freeze, which aborted the suspend attempt.
>
> For the usb1 device, udriver->resume should point to the generic_resume()
> routine in drivers/usb/core/generic.c. In fact, this should be true for
> every device that driver.c:resume_device() sees. But generic_resume()
> simply calls usb_port_resume() in hub.c, and the log doesn't contain any
> of the USB debugging messages that usb_port_resume() would produce. So I
> can't tell what happened.
>
> The patch below will add some extra debugging information. We need to
> find out why the resume didn't succeed. Oh -- and of course, you should
> reinstate all those autosuspend patches. Otherwise this patch won't
> apply!

ok, with USB_DEBUG=y and this is with your first patch still applied
http://oioio.altervista.org/linux/dmesg-2.6.18-rc6-mm1-verbose-usb-try2

this is without it:
http://oioio.altervista.org/linux/dmesg-2.6.18-rc6-mm1-verbose-usb-try3

I hope I'm not mixing thing too much with Rafael :)

Thanks
--
mattia
:wq!

2006-09-13 20:54:15

by Alan Stern

[permalink] [raw]

Subject: Re: [linux-usb-devel] 2.6.18-rc6-mm1 (-mm2): ohci resume problem

On Wed, 13 Sep 2006, Mattia Dongili wrote:

> > The patch below will add some extra debugging information. We need to
> > find out why the resume didn't succeed. Oh -- and of course, you should
> > reinstate all those autosuspend patches. Otherwise this patch won't
> > apply!
>
> ok, with USB_DEBUG=y and this is with your first patch still applied
> http://oioio.altervista.org/linux/dmesg-2.6.18-rc6-mm1-verbose-usb-try2
>
> this is without it:
> http://oioio.altervista.org/linux/dmesg-2.6.18-rc6-mm1-verbose-usb-try3
>
> I hope I'm not mixing thing too much with Rafael :)

No. But this log doesn't include the debugging output in the patch from
my previous message.

Alan Stern

2006-09-13 21:01:13

by Alan Stern

[permalink] [raw]

Subject: Re: [linux-usb-devel] 2.6.18-rc6-mm1 (-mm2): ohci resume problem

On Wed, 13 Sep 2006, Rafael J. Wysocki wrote:

> > The patch below will add some extra debugging information. We need to
> > find out why the resume didn't succeed. Oh -- and of course, you should
> > reinstate all those autosuspend patches. Otherwise this patch won't
> > apply!
>
> OK
>
> Attached is a dmesg output from 2.6.18-rc6-mm2 with the patch applied.
> It covers two consecutive attempts to suspend (the second one obviously
> failed).

Hmm... The patch didn't yield any output. Unlike Mattia's log, yours
doesn't include any lines saying "usb usb1: wakeup_rh" so I can't be sure
whether the patch code should have run or not.

Try this patch instead. It looks for problems occurring a little earlier
in the call chain.

Alan Stern

Index: mm/drivers/usb/core/hcd-pci.c
===================================================================
--- mm.orig/drivers/usb/core/hcd-pci.c
+++ mm/drivers/usb/core/hcd-pci.c
@@ -406,6 +406,8 @@ int usb_hcd_pci_resume (struct pci_dev *
usb_hc_died (hcd);
}
}
+ dev_dbg(&dev->dev, "Controller %p state after resume %d\n",
+ &dev->dev, dev->dev.power.power_state.event);

return retval;
}
Index: mm/drivers/usb/core/driver.c
===================================================================
--- mm.orig/drivers/usb/core/driver.c
+++ mm/drivers/usb/core/driver.c
@@ -1060,6 +1060,8 @@ int usb_resume_both(struct usb_device *u
struct usb_interface *intf;
struct usb_device *parent = udev->parent;

+ dev_dbg(&udev->dev, "Device state before resume %d\n", udev->state);
+
cancel_delayed_work(&udev->autosuspend);
if (udev->state == USB_STATE_NOTATTACHED)
return -ENODEV;
@@ -1072,6 +1074,9 @@ int usb_resume_both(struct usb_device *u
status = usb_resume_both(parent);
} else {

+ dev_dbg(&udev->dev, "Parent %p PM state %d\n",
+ udev->dev.parent, udev->dev.parent->power.power_state.event);
+
/* We can't progagate beyond the USB subsystem,
* so if a root hub's controller is suspended
* then we're stuck. */
@@ -1094,7 +1099,7 @@ int usb_resume_both(struct usb_device *u
}
}

- // dev_dbg(&udev->dev, "%s: status %d\n", __FUNCTION__, status);
+ dev_dbg(&udev->dev, "%s: status %d\n", __FUNCTION__, status);
return status;
}

2006-09-13 21:33:44

On Wednesday, 13 September 2006 23:55, Alan Stern wrote:
> On Wed, 13 Sep 2006, Rafael J. Wysocki wrote:
>
> > > Try this patch instead. It looks for problems occurring a little earlier
> > > in the call chain.
> >
> > I've applied both patches at a time (I hope they don't conflict).
> >
> > The dmesg output is attached.
>
> The dmesg output shows the root-hub device state is set wrong.
>
> I have to leave now, so I can't give you another patch to try. You can
> experiment as follows...
>
> Look in drivers/usb/host/ehci-pci.c, at ehci_pci_resume(). The part of
> interest is everything following the "restart:" statement label.
>
> Try adding some ehci_dbg() lines in there (copy the form of the line just
> after restart:). We want to follow the value of
> hcd->self.root_hub->state. Initially it should be equal to
> USB_STATE_SUSPENDED (= 8), and it shouldn't change. But somewhere it is
> getting set to USB_STATE_CONFIGURED (= 7). I don't know where, but almost
> certainly somewhere in this routine. If you can find out where that
> happens, I'd appreciate it.

Done, but it shows hcd->self.root_hub->state is already 7 right after restart.

I've used the following patch to verify this:

---
drivers/usb/host/ehci-pci.c | 8 ++++++++
1 file changed, 8 insertions(+)

Index: linux-2.6.18-rc6-mm2/drivers/usb/host/ehci-pci.c
===================================================================
--- linux-2.6.18-rc6-mm2.orig/drivers/usb/host/ehci-pci.c
+++ linux-2.6.18-rc6-mm2/drivers/usb/host/ehci-pci.c
@@ -291,14 +291,19 @@ static int ehci_pci_resume(struct usb_hc

restart:
ehci_dbg(ehci, "lost power, restarting\n");
+ ehci_dbg(ehci, "root hub state: %d\n", hcd->self.root_hub->state);
usb_root_hub_lost_power(hcd->self.root_hub);
+ ehci_dbg(ehci, "root hub state: %d\n", hcd->self.root_hub->state);

/* Else reset, to cope with power loss or flush-to-storage
* style "resume" having let BIOS kick in during reboot.
*/
(void) ehci_halt(ehci);
+ ehci_dbg(ehci, "root hub state: %d\n", hcd->self.root_hub->state);
(void) ehci_reset(ehci);
+ ehci_dbg(ehci, "root hub state: %d\n", hcd->self.root_hub->state);
(void) ehci_pci_reinit(ehci, pdev);
+ ehci_dbg(ehci, "root hub state: %d\n", hcd->self.root_hub->state);

/* emptying the schedule aborts any urbs */
spin_lock_irq(&ehci->lock);
@@ -306,12 +311,15 @@ restart:
ehci->reclaim_ready = 1;
ehci_work(ehci, NULL);
spin_unlock_irq(&ehci->lock);
+ ehci_dbg(ehci, "root hub state: %d\n", hcd->self.root_hub->state);

/* restart; khubd will disconnect devices */
retval = ehci_run(hcd);
+ ehci_dbg(ehci, "root hub state: %d\n", hcd->self.root_hub->state);

/* here we "know" root ports should always stay powered */
ehci_port_power(ehci, 1);
+ ehci_dbg(ehci, "root hub state: %d\n", hcd->self.root_hub->state);

return retval;
}

The output of dmesg is attached.

Greetings,
Rafael

--
You never change things by fighting the existing reality.
R. Buckminster Fuller

Attachments:

(No filename) (2.93 kB)
dmesg-debug-3.log.gz (14.73 kB)
Download all attachments

2006-09-14 14:09:28

by Rafael J. Wysocki

[permalink] [raw]

Subject: Re: [linux-usb-devel] 2.6.18-rc6-mm1 (-mm2): ohci resume problem

On Thursday, 14 September 2006 15:14, Rafael J. Wysocki wrote:
> On Wednesday, 13 September 2006 23:55, Alan Stern wrote:
> > On Wed, 13 Sep 2006, Rafael J. Wysocki wrote:
> >
> > > > Try this patch instead. It looks for problems occurring a little earlier
> > > > in the call chain.
> > >
> > > I've applied both patches at a time (I hope they don't conflict).
> > >
> > > The dmesg output is attached.
> >
> > The dmesg output shows the root-hub device state is set wrong.
> >
> > I have to leave now, so I can't give you another patch to try. You can
> > experiment as follows...
> >
> > Look in drivers/usb/host/ehci-pci.c, at ehci_pci_resume(). The part of
> > interest is everything following the "restart:" statement label.
> >
> > Try adding some ehci_dbg() lines in there (copy the form of the line just
> > after restart:). We want to follow the value of
> > hcd->self.root_hub->state. Initially it should be equal to
> > USB_STATE_SUSPENDED (= 8), and it shouldn't change. But somewhere it is
> > getting set to USB_STATE_CONFIGURED (= 7). I don't know where, but almost
> > certainly somewhere in this routine. If you can find out where that
> > happens, I'd appreciate it.
>
> Done, but it shows hcd->self.root_hub->state is already 7 right after restart.

BTW, all of the systems on which the problem shows up seem to be 64-bit.

If you can't reproduce it on a 32-bit system, some type casting may be wrong
somewhere.

Greetings,
Rafael

--
You never change things by fighting the existing reality.
R. Buckminster Fuller

2006-09-14 15:04:50

by Alan Stern

[permalink] [raw]

Subject: Re: [linux-usb-devel] 2.6.18-rc6-mm1 (-mm2): ohci resume problem

On Thu, 14 Sep 2006, Rafael J. Wysocki wrote:

> > > Try adding some ehci_dbg() lines in there (copy the form of the line just
> > > after restart:). We want to follow the value of
> > > hcd->self.root_hub->state. Initially it should be equal to
> > > USB_STATE_SUSPENDED (= 8), and it shouldn't change. But somewhere it is
> > > getting set to USB_STATE_CONFIGURED (= 7). I don't know where, but almost
> > > certainly somewhere in this routine. If you can find out where that
> > > happens, I'd appreciate it.
> >
> > Done, but it shows hcd->self.root_hub->state is already 7 right after restart.
>
> BTW, all of the systems on which the problem shows up seem to be 64-bit.
>
> If you can't reproduce it on a 32-bit system, some type casting may be wrong
> somewhere.

I realized last night what the problem must be. It's extremely obvious in
retrospect, but I happen to have a blind spot in this particular area.

All you guys must have CONFIG_USB_SUSPEND turned off. Mattis certainly
does; I checked his .config. Now I hardly ever do any testing without
CONFIG_USB_SUSPEND, since there's not much point working on power
management code if your kernel isn't set up to actually suspend devices.
As a result I missed seeing the problems caused by the autosuspend
changes.

Now of course, the autosuspend stuff has to work properly no matter what
the kernel configuration is. I'll go back and rebuild the drivers with
USB_SUSPEND turned off and see what happens. With any luck I'll have a
fix ready in the near future.

Alan Stern

2006-09-14 16:17:24

by Alan Stern

[permalink] [raw]

Subject: Re: [linux-usb-devel] 2.6.18-rc6-mm1 (-mm2): ohci resume problem

On Thu, 14 Sep 2006, Alan Stern wrote:

> Now of course, the autosuspend stuff has to work properly no matter what
> the kernel configuration is. I'll go back and rebuild the drivers with
> USB_SUSPEND turned off and see what happens. With any luck I'll have a
> fix ready in the near future.

This should start fixing things, but I'm not certain it will solve the
entire problem. If it doesn't work, send another dmesg log.

Alan Stern

Index: mm/drivers/usb/core/driver.c
===================================================================
--- mm.orig/drivers/usb/core/driver.c
+++ mm/drivers/usb/core/driver.c
@@ -813,7 +813,7 @@ static int suspend_device(struct usb_dev
status = udriver->suspend(udev, msg);

done:
- // dev_dbg(&udev->dev, "%s: status %d\n", __FUNCTION__, status);
+ dev_dbg(&udev->dev, "%s: status %d\n", __FUNCTION__, status);
if (status == 0)
udev->dev.power.power_state.event = msg.event;
return status;
@@ -839,7 +839,7 @@ static int resume_device(struct usb_devi
status = udriver->resume(udev);

done:
- // dev_dbg(&udev->dev, "%s: status %d\n", __FUNCTION__, status);
+ dev_dbg(&udev->dev, "%s: status %d\n", __FUNCTION__, status);
if (status == 0)
udev->dev.power.power_state.event = PM_EVENT_ON;
return status;
@@ -876,7 +876,7 @@ static int suspend_interface(struct usb_
}

done:
- // dev_dbg(&intf->dev, "%s: status %d\n", __FUNCTION__, status);
+ dev_dbg(&intf->dev, "%s: status %d\n", __FUNCTION__, status);
if (status == 0)
intf->dev.power.power_state.event = msg.event;
return status;
@@ -917,7 +917,7 @@ static int resume_interface(struct usb_i
}

done:
- // dev_dbg(&intf->dev, "%s: status %d\n", __FUNCTION__, status);
+ dev_dbg(&intf->dev, "%s: status %d\n", __FUNCTION__, status);
if (status == 0)
intf->dev.power.power_state.event = PM_EVENT_ON;
return status;
@@ -1021,7 +1021,7 @@ int usb_suspend_both(struct usb_device *
} else if (parent)
usb_autosuspend_device(parent, 0);

- // dev_dbg(&udev->dev, "%s: status %d\n", __FUNCTION__, status);
+ dev_dbg(&udev->dev, "%s: status %d\n", __FUNCTION__, status);
return status;
}

@@ -1079,11 +1079,12 @@ int usb_resume_both(struct usb_device *u
PM_EVENT_ON)
status = -EHOSTUNREACH;
}
- if (status == 0 && udev->state == USB_STATE_SUSPENDED)
+ if (status == 0)
status = resume_device(udev);
if (parent)
mutex_unlock(&parent->pm_mutex);
- }
+ } else
+ status = resume_device(udev);

/* Now the parent won't suspend until we are finished */

@@ -1094,7 +1095,7 @@ int usb_resume_both(struct usb_device *u
}
}

- // dev_dbg(&udev->dev, "%s: status %d\n", __FUNCTION__, status);
+ dev_dbg(&udev->dev, "%s: status %d\n", __FUNCTION__, status);
return status;
}

Index: mm/drivers/usb/core/hub.c
===================================================================
--- mm.orig/drivers/usb/core/hub.c
+++ mm/drivers/usb/core/hub.c
@@ -1898,6 +1898,8 @@ static int hub_suspend(struct usb_interf
if (bus) {
int status = hcd_bus_suspend (bus);

+ dev_dbg(&hdev->dev, "bus_suspend %d\n", status);
+
if (status != 0) {
dev_dbg(&hdev->dev, "'global' suspend %d\n",
status);
@@ -1923,6 +1925,9 @@ static int hub_resume(struct usb_interfa
struct usb_bus *bus = hdev->bus;
if (bus) {
status = hcd_bus_resume (bus);
+
+ dev_dbg(&hdev->dev, "bus_resume %d\n", status);
+
if (status) {
dev_dbg(&intf->dev, "'global' resume %d\n",
status);

2006-09-14 16:49:49

by Rafael J. Wysocki

[permalink] [raw]

Subject: Re: [linux-usb-devel] 2.6.18-rc6-mm1 (-mm2): ohci resume problem

On Thursday, 14 September 2006 17:04, Alan Stern wrote:
> On Thu, 14 Sep 2006, Rafael J. Wysocki wrote:
>
> > > > Try adding some ehci_dbg() lines in there (copy the form of the line just
> > > > after restart:). We want to follow the value of
> > > > hcd->self.root_hub->state. Initially it should be equal to
> > > > USB_STATE_SUSPENDED (= 8), and it shouldn't change. But somewhere it is
> > > > getting set to USB_STATE_CONFIGURED (= 7). I don't know where, but almost
> > > > certainly somewhere in this routine. If you can find out where that
> > > > happens, I'd appreciate it.
> > >
> > > Done, but it shows hcd->self.root_hub->state is already 7 right after restart.
> >
> > BTW, all of the systems on which the problem shows up seem to be 64-bit.
> >
> > If you can't reproduce it on a 32-bit system, some type casting may be wrong
> > somewhere.
>
> I realized last night what the problem must be. It's extremely obvious in
> retrospect, but I happen to have a blind spot in this particular area.
>
> All you guys must have CONFIG_USB_SUSPEND turned off. Mattis certainly
> does; I checked his .config. Now I hardly ever do any testing without
> CONFIG_USB_SUSPEND, since there's not much point working on power
> management code if your kernel isn't set up to actually suspend devices.
> As a result I missed seeing the problems caused by the autosuspend
> changes.

Well, on my box the USB suspend also doesn't work with USB_SUSPEND set,
but the reason is different:

sb usb2: 'global' suspend -16
hub 2-0:1.0: suspend error -16
suspend_device(): usb_suspend+0x0/0x5b [usbcore]() returns -16
Could not suspend device usb2: error -16

The .config and full dmesg output (with the three debug patches applied) are
attached.

Greetings,
Rafael

--
You never change things by fighting the existing reality.
R. Buckminster Fuller

Attachments:

(No filename) (1.82 kB)
dmesg-usb-suspend.log.gz (15.11 kB)
kernel-config.gz (12.63 kB)
Download all attachments

2006-09-14 17:09:08

On Sat, 16 Sep 2006, Mattia Dongili wrote:

> Yay! this patch fixes the issue. It already survived 3 susp/resume
> cycles.
> Log is here:
> http://oioio.altervista.org/linux/dmesg-2.6.18-rc6-mm1-usb-susp
>
> Do you want to see a test run with USB_SUSPEND=y? (well I'll try it out
> anyway)

Then so far it looks good... I'll submit this patch early next week.

Alan Stern