I've had this problem now and then for a couple of months: On system
resume, my laptop will appear frozen for more than 30 seconds before
finally responding. No keypress or other external input seems to have
any effect. Pressing e.g. CapsLock will not lit the LED. But when the
laptop finally comes to life, every keypress is replayed.
I have tried to find out how to reliably trigger this, but haven't been
successful. It happens too infrequently for bisect to be effective.
But what I have discovered is that it is related to problems with the
internal USB webcam. Whenever there is one of these delays, I also see
this in the kernel log, always from the webcam device:
Sep 1 12:32:39 nemi kernel: [174042.120072] usb 1-6: device descriptor read/64, error -110
Sep 1 12:32:39 nemi kernel: [174057.336066] usb 1-6: device descriptor read/64, error -110
Sep 1 12:32:39 nemi kernel: [174057.552069] usb 1-6: reset high-speed USB device number 11 using ehci-pci
Sep 1 12:32:39 nemi kernel: [174072.664067] usb 1-6: device descriptor read/64, error -110
Sep 1 12:32:39 nemi kernel: [174087.880154] usb 1-6: device descriptor read/64, error -110
Sep 1 12:32:39 nemi kernel: [174088.096131] usb 1-6: reset high-speed USB device number 11 using ehci-pci
Sep 1 12:32:39 nemi kernel: [174093.116266] usb 1-6: device descriptor read/8, error -110
Sep 1 12:32:39 nemi kernel: [174098.236333] usb 1-6: device descriptor read/8, error -110
Sep 1 12:32:39 nemi kernel: [174098.452066] usb 1-6: reset high-speed USB device number 11 using ehci-pci
Sep 1 12:32:39 nemi kernel: [174103.472272] usb 1-6: device descriptor read/8, error -110
Sep 1 12:32:39 nemi kernel: [174108.592328] usb 1-6: device descriptor read/8, error -110
Sep 1 12:32:39 nemi kernel: [174108.808090] usb 4-2: reset full-speed USB device number 2 using uhci_hcd
Sep 1 12:32:39 nemi kernel: [174109.052051] usb 7-1: reset full-speed USB device number 2 using uhci_hcd
Sep 1 12:32:39 nemi kernel: [174109.204966] PM: resume of devices complete after 82555.697 msecs
As you can see from the last line, resuming devices takes ridiculously
long time. Normally it would take approximately on second on this old
laptop.
The device connected to 1-6 is a Lenovo UVC webcam, and it seems the
problem is related to this device somehow. As can be seen above, the
webcam fails completely when this happens and just disappears - as
expected when you cannot read the device descriptor. But simply
suspending and resuming again will always(?) fix the problem, so it is
not a major issue. The real annoyance is the delay.
I did two changes which I guess could be important in the days before
this problem started:
1) upgraded from v3.10-rc6 to v3.10-rc7
2) installed an Intel wlan card with a USB bluetooth device in one of
the internal mini-PCIe slots
I have never had any USB device in that mini-PCIe slot before, so the
last change can potentionally reveal USB wiring problems which has
always been there. AFAIK the slot is not documented or officially
supported as USB capable, although the bluetooth device seems to work
fine.
This is how my bus layout normally looks when the webcam is working (the
mini-PCIe bluetooth device is the one on bus 7):
bjorn@nemi:~$ lsusb -t
/: Bus 08.Port 1: Dev 1, Class=root_hub, Driver=uhci_hcd/2p, 12M
/: Bus 07.Port 1: Dev 1, Class=root_hub, Driver=uhci_hcd/2p, 12M
|__ Port 1: Dev 2, If 0, Class=Wireless, Driver=btusb, 12M
|__ Port 1: Dev 2, If 1, Class=Wireless, Driver=btusb, 12M
/: Bus 06.Port 1: Dev 1, Class=root_hub, Driver=uhci_hcd/2p, 12M
/: Bus 05.Port 1: Dev 1, Class=root_hub, Driver=uhci_hcd/2p, 12M
/: Bus 04.Port 1: Dev 1, Class=root_hub, Driver=uhci_hcd/2p, 12M
|__ Port 2: Dev 2, If 0, Class=Wireless, Driver=btusb, 12M
|__ Port 2: Dev 2, If 1, Class=Wireless, Driver=btusb, 12M
|__ Port 2: Dev 2, If 2, Class=Vendor Specific Class, Driver=, 12M
|__ Port 2: Dev 2, If 3, Class=Application Specific Interface, Driver=, 12M
/: Bus 03.Port 1: Dev 1, Class=root_hub, Driver=ehci-pci/6p, 480M
|__ Port 4: Dev 46, If 12, Class=Communications, Driver=cdc_mbim, 480M
|__ Port 4: Dev 46, If 13, Class=CDC Data, Driver=cdc_mbim, 480M
/: Bus 02.Port 1: Dev 1, Class=root_hub, Driver=uhci_hcd/2p, 12M
/: Bus 01.Port 1: Dev 1, Class=root_hub, Driver=ehci-pci/6p, 480M
|__ Port 6: Dev 13, If 0, Class=Video, Driver=uvcvideo, 480M
|__ Port 6: Dev 13, If 1, Class=Video, Driver=uvcvideo, 480M
Is there any smart way to find out how the UHCI and EHCI ports are
related to each other? Unloading ehci-pci results in this tree, which
seems to imply that the two mini-PCIe slots are connected to one port
each on the same UHCI bus, while the webcam seems unrelated on another
controller:
bjorn@nemi:~$ lsusb -t
/: Bus 08.Port 1: Dev 1, Class=root_hub, Driver=uhci_hcd/2p, 12M
/: Bus 07.Port 1: Dev 1, Class=root_hub, Driver=uhci_hcd/2p, 12M
|__ Port 1: Dev 2, If 0, Class=Wireless, Driver=btusb, 12M
|__ Port 1: Dev 2, If 1, Class=Wireless, Driver=btusb, 12M
|__ Port 2: Dev 3, If 12, Class=Communications, Driver=cdc_mbim, 12M
|__ Port 2: Dev 3, If 13, Class=CDC Data, Driver=cdc_mbim, 12M
/: Bus 06.Port 1: Dev 1, Class=root_hub, Driver=uhci_hcd/2p, 12M
/: Bus 05.Port 1: Dev 1, Class=root_hub, Driver=uhci_hcd/2p, 12M
|__ Port 2: Dev 14, If 0, Class=Video, Driver=uvcvideo, 12M
|__ Port 2: Dev 14, If 1, Class=Video, Driver=uvcvideo, 12M
/: Bus 04.Port 1: Dev 1, Class=root_hub, Driver=uhci_hcd/2p, 12M
|__ Port 2: Dev 2, If 0, Class=Wireless, Driver=btusb, 12M
|__ Port 2: Dev 2, If 1, Class=Wireless, Driver=btusb, 12M
|__ Port 2: Dev 2, If 2, Class=Vendor Specific Class, Driver=, 12M
|__ Port 2: Dev 2, If 3, Class=Application Specific Interface, Driver=, 12M
/: Bus 02.Port 1: Dev 1, Class=root_hub, Driver=uhci_hcd/2p, 12M
I really don't know where to go from here, and am posting this in the
hope that anyone has some suggestion. Or at least to document my
problem in Google in case there are others with similar issues...
To give an impression of the frequency, here are the device resume times
from the last two weeks:
Aug 15 09:06:01 nemi kernel: [59072.295812] PM: resume of devices complete after 679.927 msecs
Aug 15 18:19:34 nemi kernel: [84634.875816] PM: resume of devices complete after 1015.826 msecs
Aug 16 09:42:03 nemi kernel: [98171.739459] PM: resume of devices complete after 1083.512 msecs
Aug 16 17:23:54 nemi kernel: [13726.376240] PM: resume of devices complete after 1020.293 msecs
Aug 18 15:29:04 nemi kernel: [27756.459423] PM: resume of devices complete after 1007.270 msecs
Aug 18 18:14:43 nemi kernel: [32972.978600] PM: resume of devices complete after 31554.571 msecs
Aug 18 19:40:56 nemi kernel: [33401.507797] PM: resume of devices complete after 791.892 msecs
Aug 18 19:54:55 nemi kernel: [33730.423779] PM: resume of devices complete after 1035.826 msecs
Aug 19 07:22:05 nemi kernel: [46983.291706] PM: resume of devices complete after 1051.671 msecs
Aug 19 07:40:21 nemi kernel: [47864.975731] PM: resume of devices complete after 1011.414 msecs
Aug 19 07:55:13 nemi kernel: [47877.072600] PM: resume of devices complete after 1012.658 msecs
Aug 19 08:51:30 nemi kernel: [ 100.867818] PM: resume of devices complete after 1095.125 msecs
Aug 19 09:11:37 nemi kernel: [ 1099.745234] PM: resume of devices complete after 1028.547 msecs
Aug 19 17:31:30 nemi kernel: [26047.034282] PM: resume of devices complete after 992.917 msecs
Aug 20 08:02:38 nemi kernel: [ 88.623079] PM: resume of devices complete after 997.497 msecs
Aug 20 08:41:45 nemi kernel: [ 1134.641144] PM: resume of devices complete after 1015.566 msecs
Aug 20 09:24:20 nemi kernel: [ 133.739398] PM: resume of devices complete after 1019.752 msecs
Aug 20 09:24:35 nemi kernel: [ 146.213255] PM: resume of devices complete after 1013.533 msecs
Aug 20 16:59:45 nemi kernel: [22028.670608] PM: resume of devices complete after 1006.923 msecs
Aug 21 09:13:48 nemi kernel: [23268.075130] PM: resume of devices complete after 1007.483 msecs
Aug 21 18:44:26 nemi kernel: [54070.454945] PM: resume of devices complete after 1015.268 msecs
Aug 21 19:23:39 nemi kernel: [55840.163158] PM: resume of devices complete after 1031.485 msecs
Aug 22 08:53:40 nemi kernel: [65631.908460] PM: resume of devices complete after 792.798 msecs
Aug 22 20:46:47 nemi kernel: [91274.110594] PM: resume of devices complete after 1006.786 msecs
Aug 23 08:23:21 nemi kernel: [93662.006498] PM: resume of devices complete after 1034.802 msecs
Aug 23 09:06:49 nemi kernel: [96096.158599] PM: resume of devices complete after 1006.966 msecs
Aug 23 16:27:25 nemi kernel: [119040.342877] PM: resume of devices complete after 1047.160 msecs
Aug 24 14:19:02 nemi kernel: [167331.806379] PM: resume of devices complete after 1006.685 msecs
Aug 25 00:29:37 nemi kernel: [167784.791296] PM: resume of devices complete after 82571.593 msecs
Aug 25 12:51:10 nemi kernel: [167853.602723] PM: resume of devices complete after 999.131 msecs
Aug 25 23:24:53 nemi kernel: [185032.190634] PM: resume of devices complete after 1011.054 msecs
Aug 26 10:38:17 nemi kernel: [ 7786.186904] PM: resume of devices complete after 1019.244 msecs
Aug 26 11:48:10 nemi kernel: [ 8922.090653] PM: resume of devices complete after 1035.079 msecs
Aug 26 18:12:56 nemi kernel: [28494.687041] PM: resume of devices complete after 1007.412 msecs
Aug 27 10:52:48 nemi kernel: [31852.846402] PM: resume of devices complete after 1018.785 msecs
Aug 27 17:02:47 nemi kernel: [50497.394679] PM: resume of devices complete after 1011.065 msecs
Aug 27 17:18:33 nemi kernel: [51141.542162] PM: resume of devices complete after 1014.547 msecs
Aug 27 20:20:36 nemi kernel: [51631.199105] PM: resume of devices complete after 1007.568 msecs
Aug 28 08:14:04 nemi kernel: [57173.216237] PM: resume of devices complete after 31536.701 msecs
Aug 28 09:00:43 nemi kernel: [57822.552577] PM: resume of devices complete after 744.991 msecs
Aug 28 17:07:27 nemi kernel: [80735.256678] PM: resume of devices complete after 985.032 msecs
Aug 29 07:51:36 nemi kernel: [82840.104739] PM: resume of devices complete after 997.148 msecs
Aug 29 10:05:50 nemi kernel: [88293.401022] PM: resume of devices complete after 985.402 msecs
Aug 29 12:00:32 nemi kernel: [94817.969444] PM: resume of devices complete after 989.841 msecs
Aug 30 08:51:04 nemi kernel: [108478.612810] PM: resume of devices complete after 989.219 msecs
Aug 30 16:19:00 nemi kernel: [132874.908573] PM: resume of devices complete after 988.944 msecs
Aug 30 17:57:45 nemi kernel: [134758.912589] PM: resume of devices complete after 992.971 msecs
Aug 30 19:18:02 nemi kernel: [135700.301588] PM: resume of devices complete after 990.040 msecs
Aug 31 11:42:13 nemi kernel: [143617.780648] PM: resume of devices complete after 992.994 msecs
Aug 31 18:49:39 nemi kernel: [159369.772652] PM: resume of devices complete after 989.159 msecs
Aug 31 19:46:51 nemi kernel: [160798.324334] PM: resume of devices complete after 31572.768 msecs
Aug 31 21:44:12 nemi kernel: [164674.040424] PM: resume of devices complete after 735.087 msecs
Sep 1 10:21:35 nemi kernel: [172979.136429] PM: resume of devices complete after 999.122 msecs
As you can see, there are typically 10+ successful resumes between every
failure. I am also noticing that the delays are not random. They are
either 31.5 seconds or 82.5 seconds. I guess this is explained by some
fixed timouts somewhere?
Bjørn
--
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
