[arch-general] pm-suspend stuck at uhci_hcd

Mon May 21 16:41:03 EDT 2012

On 05/20/2012 08:13 PM, Leonid Isaev wrote:
> On Sun, 20 May 2012 12:36:16 +0200
> Manne Merak<mannemerak at gmail.com>  wrote:
>
>> On 05/17/2012 01:11 AM, Leonid Isaev wrote:
>>> On Wed, 16 May 2012 23:50:06 +0200
>>> Manne Merak<mannemerak at gmail.com>   wrote:
>>>
>>>> Hi,
>>>> Couple of updates ago suspend to RAM stopped working.
>>>> Looking at the pm-suspend.log (below) file shows that it gets stuck at
>>>> unloading uhci_hcd?
>>>> I can unload and load the module by hand just fine.
>>>> Anyone else have this?
>>> Hmm, 75modules should print something like "done" or "fail". What do you
>>> mean by stopped working? What configuration do you have
>>> in /etc/pm/config.d/*?
>>>
>> Ok, some more debugging.
>> The first suspend-RAM works file.  Checked the pm-suspend.log and all
>> gets unloaded just fine.
>> On second suspend, I get the mentioned stuck at unloading uhci_hcd
>> (leaving it a while gives):
>>
>> -------
>> Running hook /usr/lib/pm-utils/sleep.d/75modules suspend suspend:
>> Unloading kernel module uhci_hcd.../usr/lib/pm-utils/functions: line 84:
>> 26341 Killed                  modprobe -r "$1"
> I am puzzled by this... really. Do you get anything at all in syslog after
> this? Or syslog is already stopped at this point?
>
>> /usr/lib/pm-utils/functions: line 89: log: command not found
> WTF??? This is a 2 year old bug in pm-utils. OpenSUSE 11.3 fixed that in
> 1.3.0. Please see if this fix gets rid of the "log" error:
> <http://lists.freedesktop.org/archives/pm-utils/2010-September/002219.html>.
>
>> Failed.
>> Unloading kernel module ehci_hcd...
>> ----
>>
>> Now stuck at unloading ehci_hcd.
>>
>> I get the same behaviour trying to unload uhci_hcd or ehci_hcd after the
>> first successfull suspend and restore.
> You mean "unload manually", right?
>
>> There's more; a "oops" in the system log:
>>
>> [209624.386398] BUG: unable to handle kernel paging request at 6d0d0000
>> [209624.386404] IP: [<c04ad62a>] _raw_spin_lock_irqsave+0x2a/0x50
>> [209624.386412] *pde = 00000000
>> [209624.386414] Oops: 0002 [#1] PREEMPT SMP
>> [209624.386418] Modules linked in: uhci_hcd(-) ehci_hcd usb_storage uas
>> rfcomm btusb hidp bnep bluetooth fuse vboxnetadp(O) vboxnetflt(O) usbhid
>> uvcvideo hid videobuf2_vmalloc videobuf2_memops videobuf2_core videodev
>> media nvidia(PO) snd_hda_codec_idt snd_hda_intel firewire_ohci joydev
>> b44 snd_hda_codec r852 sm_common nand snd_pcm nand_ecc nand_ids arc4
>> iwl3945 iwlegacy ssb snd_page_alloc r592 mtd iTCO_wdt firewire_core
>> crc_itu_t pcmcia mii pcmcia_core mac80211 sdhci_pci intel_agp sdhci
>> intel_gtt mmc_core cfg80211 agpgart i2c_i801 i2c_core snd_hwdep
>> snd_timer snd memstick iTCO_vendor_support serio_raw dell_wmi psmouse
>> sparse_keymap soundcore wmi dell_laptop usbcore usb_common rfkill evdev
>> thermal dcdbas button battery ac video vboxdrv(O) cpufreq_powersave
>> acpi_cpufreq mperf processor ext4 crc16 jbd2 mbcache sr_mod sd_mod cdrom
>> pata_acpi ata_generic ata_piix ahci libahci libata scsi_mod [last
>> unloaded: ehci_hcd]
>> [209624.386476]
>> [209624.386479] Pid: 26341, comm: modprobe Tainted: P           O
>> 3.3.6-1-ARCH #1 Dell Inc. Vostro 1700                     /0HX767
>> [209624.386483] EIP: 0060:[<c04ad62a>] EFLAGS: 00010002 CPU: 0
>> [209624.386486] EIP is at _raw_spin_lock_irqsave+0x2a/0x50
>> [209624.386488] EAX: 00000100 EBX: 6d0d0000 ECX: 6d0d0000 EDX: e002dd10
>> [209624.386490] ESI: 00000206 EDI: f24ca4b4 EBP: e002dcf0 ESP: e002dce8
>> [209624.386492]  DS: 007b ES: 007b FS: 00d8 GS: 00e0 SS: 0068
>> [209624.386494] Process modprobe (pid: 26341, ti=e002c000 task=c5aeca80
>> task.ti=e002c000)
>> [209624.386496] Stack:
>> [209624.386497]  6d0d0000 6d0d0000 e002dd08 c0142d39 e002dd10 f24ca4a8
>> 00000000 ffffffff
>> [209624.386503]  e002dd20 c0142eca f8af756a f24ca400 00000000 ecdfbc94
>> e002dd38 f8af7461
>> [209624.386508]  ecdfbc94 f24ca400 ecdfbcd8 ecdfbc94 e002dd58 f8af7694
>> ecdfb808 ecdfb808
>> [209624.386513] Call Trace:
>> [209624.386519]  [<c0142d39>] lock_timer_base.isra.33+0x29/0x50
>> [209624.386522]  [<c0142eca>] del_timer+0x2a/0xe0
>> [209624.386529]  [<f8af756a>] ? hci_conn_del+0x12a/0x1f0 [bluetooth]
>> [209624.386534]  [<f8af7461>] hci_conn_del+0x21/0x1f0 [bluetooth]
>> [209624.386538]  [<f8af7694>] hci_conn_hash_flush+0x64/0xb0 [bluetooth]
>> [209624.386543]  [<f8af3746>] hci_dev_do_close+0x96/0x290 [bluetooth]
>> [209624.386548]  [<f8af5958>] hci_unregister_dev+0x48/0x140 [bluetooth]
>> [209624.386551]  [<f8a9ab4f>] btusb_disconnect+0x4f/0xb0 [btusb]
>> [209624.386559]  [<f8ec0a5c>] usb_unbind_interface+0x3c/0x140 [usbcore]
>> [209624.386564]  [<c038801d>] __device_release_driver+0x5d/0xb0
>> [209624.386566]  [<c0388094>] device_release_driver+0x24/0x40
>> [209624.386569]  [<c0387bf5>] bus_remove_device+0xa5/0xd0
>> [209624.386572]  [<c0385d55>] device_del+0xe5/0x150
>> [209624.386578]  [<f8ebeb19>] usb_disable_device+0x89/0x1a0 [usbcore]
>> [209624.386584]  [<f8eb8030>] usb_disconnect+0x70/0xe0 [usbcore]
>> [209624.386590]  [<f8eb801f>] usb_disconnect+0x5f/0xe0 [usbcore]
>> [209624.386595]  [<f8eb801f>] usb_disconnect+0x5f/0xe0 [usbcore]
>> [209624.386602]  [<f8eba94c>] usb_remove_hcd+0x9c/0x120 [usbcore]
>> [209624.386608]  [<f8ec8d78>] usb_hcd_pci_remove+0x48/0xb0 [usbcore]
>> [209624.386611]  [<c02fdbff>] pci_device_remove+0x2f/0xe0
>> [209624.386614]  [<c038801d>] __device_release_driver+0x5d/0xb0
>> [209624.386616]  [<c038864f>] driver_detach+0x8f/0xa0
>> [209624.386619]  [<c0387ef2>] bus_remove_driver+0x62/0xa0
>> [209624.386621]  [<c0388b49>] driver_unregister+0x49/0x80
>> [209624.386624]  [<c02febd2>] pci_unregister_driver+0x32/0x80
>> [209624.386627]  [<f8070ce0>] uhci_hcd_cleanup+0xd/0x35 [uhci_hcd]
>> [209624.386632]  [<c018e5af>] sys_delete_module+0x11f/0x280
>> [209624.386635]  [<c022b920>] ? fput+0x130/0x1d0
>> [209624.386639]  [<c0227984>] ? filp_close+0x54/0x80
>> [209624.386642]  [<c0227a22>] ? sys_close+0x72/0xc0
>> [209624.386645]  [<c04ae69f>] sysenter_do_call+0x12/0x28
>> [209624.386647] Code: 00 55 89 e5 56 53 3e 8d 74 26 00 89 c1 9c 58 8d 74
>> 26 00 89 c6 fa 90 8d 74 26 00 89 e0 25 00 e0 ff ff 83 40 14 01 b8 00 01
>> 00 00<f0>  66 0f c1 01 0f b6 dc 38 c3 74 0b 66 90 f3 90 0f b6 11 38 da
>> [209624.386677] EIP: [<c04ad62a>] _raw_spin_lock_irqsave+0x2a/0x50
>> SS:ESP 0068:e002dce8
>> [209624.386680] CR2: 000000006d0d0000
>> [209624.386683] ---[ end trace 2d604d3b1307f2ba ]---
>> [209624.386686] note: modprobe[26341] exited with preempt_count 1
>>
> Seems like some kind of IRQ problem. Perhaps someone more knowledgeable can
> tell whether this is kernel's or kmod's fault...
>
> Finally, have you actually tried to remove *_hcd from MODULE_SUSPEND and see
> if it works?
>

Yes, removing the *_hcd modules leaves the resumed machine without 
working USB.
Trying then to unload the modules manually doesnt work, rmmod never 
comes back.  I see rmmod crash traces in syslog.

This definitely came with a kernel (module) update.  I will wait it out 
and see if it gets resolved at the next round of updates.

Manne