----- Original Message ----- > On Sun, Apr 10, 2011 at 08:52:13PM -0400, CAI Qian wrote: > > Hi Sarah, > > > > The following was output from the serial console during the second > > hibernate/resume. Does it help? > > > > # echo disk >/sys/power/state > > PM: Syncing filesystems ... done. > > Freezing user space processes ... Apr 10 20:46:36 ibm-x3550m3-03 > > kernel: PM: Syncing filesystems ... done. > > (elapsed 0.01 seconds) done. > > Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done. > > PM: Preallocating image memory... done (allocated 313188 pages) > > PM: Allocated 1252752 kbytes in 0.60 seconds (2087.92 MB/s) > > hub 9-1:1.0: suspend error -16 > > I think Alan said that usb9 or hub 9-0 would be the roothub, so hub > 9-1 is > most likely your VIA hub. The xHCI host was showing up as bus 8 > before, > according to your lsusb output, so on 2.6.39-rc2, the xHCI USB 2.0 > roothub would still be bus8, and the xHCI USB 3.0 roothub would be > bus9. > So the device that is failing is probably the USB 3.0 portion of your > VIA hub. Specifically the interface driver is refusing to suspend. > > > pm_op(): usb_dev_freeze+0x0/0x20 returns -16 > > usb_dev_freeze() attempts to suspend the USB device, eventually > calling > into khubd's suspend method, hub_suspend(). That looks at all the > children of the hub, making sure that udev->can_submit isn't set for > each valid usb_device. That will return -EBUSY (-16) if a device is > active. > > I wonder if it's possible the USB 3.0 hub refused the Link PM command > to > put the port into a lower power state. Can you test that hypothesis by > unloading the usb-storage driver and turning on autosuspend for the > USB > device? I.e. find the device's entry in /sys/bus/usb/ and > `echo auto > power/control`. Send me dmesg from that attempt. Sorry, I don't understand. Which device are you talking about here? As I mentioned before, my setup was, PCI-E card -> USB3 VIA Hub (9-1) -> USB3 Disk (9-1.2) # ./lsusb.py usb1 1d6b:0002 09 2.00 480MBit/s 0mA 1IFs (ehci_hcd 0000:00:1a.7) hub usb2 1d6b:0002 09 2.00 480MBit/s 0mA 1IFs (ehci_hcd 0000:00:1d.7) hub usb3 1d6b:0001 09 1.10 12MBit/s 0mA 1IFs (uhci_hcd 0000:00:1a.0) hub usb4 1d6b:0001 09 1.10 12MBit/s 0mA 1IFs (uhci_hcd 0000:00:1a.1) hub usb5 1d6b:0001 09 1.10 12MBit/s 0mA 1IFs (uhci_hcd 0000:00:1d.0) hub 5-2 04b3:4010 02 2.00 12MBit/s 100mA 2IFs (IBM RNDIS/CDC ETHER) usb6 1d6b:0001 09 1.10 12MBit/s 0mA 1IFs (uhci_hcd 0000:00:1d.1) hub usb7 1d6b:0001 09 1.10 12MBit/s 0mA 1IFs (uhci_hcd 0000:00:1d.2) hub 7-2 0624:0307 00 1.10 1.5MBit/s 100mA 2IFs (Avocent Avocent DSRIQ-USB) usb8 1d6b:0002 09 2.00 480MBit/s 0mA 1IFs (xhci_hcd 0000:1a:00.0) hub 8-1 2109:3431 09 2.00 480MBit/s 100mA 1IFs () hub usb9 1d6b:0003 09 3.005000MBit/s 0mA 1IFs (xhci_hcd 0000:1a:00.0) hub 9-1 2109:0810 09 3.005000MBit/s 2mA 1IFs (VIA Labs, Inc. 4-Port USB 3.0 Hub) hub 9-1.2 0bc2:50a0 00 3.005000MBit/s 0mA 1IFs (Seagate FA GoFlex Desk 01234567) Do you mean VIA hub? If so, that would be 9-1. So if I do, # modprobe -r usb-storage # echo auto >/sys/bus/usb/devices/9-1/power/control So in this case, I don't even need to echo disk >/sys/power/state? Anyway, here is /var/log/dmesg, http://people.redhat.com/qcai/sarah/dmesg > > PM: Device 9-1 failed to freeze async: error -16 > > hub 9-0:1.0: activate --> -22 > > hub 9-1:1.0: hub_port_status failed (err = -22) > > hub 9-1:1.0: hub_port_status failed (err = -22) > > hub 9-1:1.0: hub_port_status failed (err = -22) > > hub 9-1:1.0: hub_port_status failed (err = -22) > > hub 9-1:1.0: activate --> -22 > > -22 is -EINVAL. I think hub_activate() tried to run before the xHCI > host controller was completely restored, so the driver refused to > submit > any transfers to the USB 3.0 hub. Seems a bit odd though. > > > PM: restore of devices complete after 72.896 msecs > > Restarting tasks ... > > hub 9-1:1.0: hub_port_status failed (err = -22) > > done. > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: Freezing user space processes > > ... (elapsed 0.01 seconds) done. > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: Freezing remaining freezable > > tasks ... (elapsed 0.01 seconds) done. > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: PM: Preallocating image > > memory... done (allocated 313188 pages) > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: PM: Allocated 1252752 kbytes > > in 0.60 seconds (2087.92 MB/s) > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: hub 9-1:1.0: port 2 nyet > > suspended > > That message also appears to come from usb_dev_freeze(). Did you have > the USB 3.0 hard drive attached to port 2, or was there no device > attached? Yes, as you can see from the above setup, we have an USB3.0 device attached. > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: hub 9-1:1.0: suspend error > > -16 > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: uhci_hcd 0000:00:1d.2: > > release dev 2 ep82-INT, period 8, phase 4, 99 us > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: uhci_hcd 0000:00:1d.2: > > release dev 2 ep81-INT, period 8, phase 4, 118 us > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: hub 7-0:1.0: hub_suspend > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: usb usb7: bus suspend > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: usb usb7: suspend_rh > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: hub 5-0:1.0: hub_suspend > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: usb usb5: bus suspend > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: usb usb5: suspend_rh > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: pm_op(): > > usb_dev_freeze+0x0/0x20 returns -16 > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: PM: Device 9-1 failed to > > freeze async: error -16 > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: usb usb1: usb resume > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: ehci_hcd 0000:00:1a.7: resume > > root hub > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: usb usb2: usb resume > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: ehci_hcd 0000:00:1d.7: resume > > root hub > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: usb usb3: usb resume > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: usb usb3: wakeup_rh > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: usb usb4: usb resume > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: usb usb4: wakeup_rh > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: usb usb5: usb resume > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: usb usb5: wakeup_rh > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: usb usb6: usb resume > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: usb usb6: wakeup_rh > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: usb usb7: usb resume > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: usb usb7: wakeup_rh > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: usb usb8: usb resume > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: xhci_hcd 0000:1a:00.0: resume > > USB 2.0 root hub > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: xhci_hcd 0000:1a:00.0: > > `MEM_WRITE_DWORD(3'b000, 32'hffffc90012858020, 32'h1, 4'hf); > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: xhci_hcd 0000:1a:00.0: > > `MEM_WRITE_DWORD(3'b000, 32'hffffc90012858450, 32'h2a0, 4'hf); > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: xhci_hcd 0000:1a:00.0: > > `MEM_WRITE_DWORD(3'b000, 32'hffffc90012858440, 32'he61, 4'hf); > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: xhci_hcd 0000:1a:00.0: > > `MEM_WRITE_DWORD(3'b000, 32'hffffc90012858444, 32'h0, 4'hf); > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: xhci_hcd 0000:1a:00.0: > > `MEM_WRITE_DWORD(3'b000, 32'hffffc90012858020, 32'h5, 4'hf); > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: hub 9-0:1.0: hub_resume > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: xhci_hcd 0000:1a:00.0: get > > port status, actual port 0 status = 0x1203 > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: xhci_hcd 0000:1a:00.0: Get > > port status returned 0x203 > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: hub 9-0:1.0: port 1: status > > 0203 change 0000 > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: xhci_hcd 0000:1a:00.0: get > > port status, actual port 1 status = 0x2a0 > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: xhci_hcd 0000:1a:00.0: Get > > port status returned 0x2a0 > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: hub 9-0:1.0: activate --> -22 > > So usb_submit_urb() was failing in hub_activate() with status -EINVAL > for the xHCI USB 3.0 roothub. Usually if something goes wrong in the > xHCI roothub functions, it will return -EPIPE, so the status return is > farther up in the USB core. I'm not sure where though. > > In rh_queue_status(), it can return -EINVAL if hcd->urb is set to a > previous urb. But we should have seen a message like "not queuing rh > status urb" in that case. The only other place I see where the roothub > URB submission could have failed with -EINVAL is in rh_urb_enqueue(), > if > the endpoint type is not control or interrupt. No idea how that could > have happened. > > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: hub 9-1:1.0: hub_resume > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: xHCI xhci_urb_enqueue called > > with unaddressed device > > Hmm, ok, that's also interesting. The xHCI driver thinks that the USB > 3.0 hub doesn't have a slot context. The devices are usually disabled > during hibernate, and their slots go away. On a successful resume, > we're supposed to get them a new slot context. But the xHCI driver > isn't supposed to disable the devices until both host controllers are > suspended. So perhaps the device disconnected during hibernate? Or > disconnected when we sent it the Link PM command? > > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: hub 9-1:1.0: hub_port_status > > failed (err = -22) > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: xHCI xhci_urb_enqueue called > > with unaddressed device > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: hub 9-1:1.0: hub_port_status > > failed (err = -22) > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: hub 9-1:1.0: port 2: status > > 0000 change 0000 > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: hub 8-0:1.0: hub_resume > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: xHCI xhci_urb_enqueue called > > with unaddressed device > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: xhci_hcd 0000:1a:00.0: get > > port status, actual port 0 status = 0xe63 > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: xhci_hcd 0000:1a:00.0: Get > > port status returned 0x507 > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: hub 9-1:1.0: hub_port_status > > failed (err = -22) > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: hub 8-0:1.0: port 1: status > > 0507 change 0000 > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: xhci_hcd 0000:1a:00.0: get > > port status, actual port 1 status = 0x2a0 > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: xhci_hcd 0000:1a:00.0: Get > > port status returned 0x100 > > -bash: echo: write error: Device or resource busy > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: xhci_hcd 0000:1a:00.0: get > > port status, actual port 0 status = 0xe63 > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: xhci_hcd 0000:1a:00.0: Get > > port status returned 0x507 > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: xhci_hcd 0000:1a:00.0: clear > > USB_PORT_FEAT_SUSPEND > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: xhci_hcd 0000:1a:00.0: PORTSC > > 0e63 > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: xhci_hcd 0000:1a:00.0: > > `MEM_WRITE_DWORD(3'b000, 32'hffffc90012858440, 32'h10fe1, 4'hf); > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: xHCI xhci_urb_enqueue called > > with unaddressed device > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: hub 9-1:1.0: hub_port_status > > failed (err = -22) > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: xHCI xhci_urb_enqueue called > > with unaddressed device > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: hub 9-1:1.0: activate --> -22 > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: hub 1-0:1.0: hub_resume > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: hub 7-0:1.0: hub_resume > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: hub 5-0:1.0: hub_resume > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: hub 7-0:1.0: port 2: status > > 0303 change 0000 > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: hub 5-0:1.0: port 2: status > > 0103 change 0000 > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: hub 4-0:1.0: hub_resume > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: uhci_hcd 0000:00:1d.2: > > reserve dev 2 ep81-INT, period 8, phase 4, 118 us > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: uhci_hcd 0000:00:1d.2: > > reserve dev 2 ep82-INT, period 8, phase 4, 99 us > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: xhci_hcd 0000:1a:00.0: > > `MEM_WRITE_DWORD(3'b000, 32'hffffc90012858440, 32'h10e01, 4'hf); > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: xhci_hcd 0000:1a:00.0: > > `MEM_WRITE_DWORD(3'b000, 32'hffffc90012858804, 32'h1, 4'hf); > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: xhci_hcd 0000:1a:00.0: > > `MEM_WRITE_DWORD(3'b000, 32'hffffc90012858804, 32'h3, 4'hf); > > Apr 10 20:46:38 ibm-x3550m3-03 kernel: usb 8-1: usb resume > > Looks like the USB 2.0 portion of the VIA hub resumed fine. > > I'm still not sure exactly what's going on here. My system is still > not > hibernating properly (even with the xHCI driver blacklisted) with > 2.6.39-rc2, plus the patch revert you mentioned, so I can't test this > myself. I'll try to compile on top of Linus' latest tree tomorrow. The patch reverting is not needed any more, as it was fixed in the lastest Linus tree already. http://marc.info/?l=linux-kernel&m=130254808802179&w=2 > In the meantime, can you test the hypothesis I had about the VIA hub > refusing the link PM commands? After that, would you please test The second attempt of hibernate/resume is still refused after those modprobe -r & echo auto commands. > Andiry's one work around patch on top of Linus' tree, instead of his > five patches? It may help if the issue really is the USB 3.0 hub > refusing to accept link PM commands. Are you refering to this patch? http://marc.info/?l=linux-usb&m=130167678226265&w=2 If so, I had the same problem with this patch only. However, I have not tested it with modprobe -r & echo auto there yet. Let me know if you'd like me to test this as well. CAI Qian -- To unsubscribe from this list: send the line "unsubscribe linux-usb" in the body of a message to majordomo@xxxxxxxxxxxxxxx More majordomo info at http://vger.kernel.org/majordomo-info.html
