[arch-general] pm-suspend stuck at uhci_hcd
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? Manne ------- Wed May 16 21:06:10 SAST 2012: Running hooks for suspend. Running hook /usr/lib/pm-utils/sleep.d/00logging suspend suspend: Linux hanslaptop 3.3.6-1-ARCH #1 SMP PREEMPT Sun May 13 09:59:18 UTC 2012 i686 GNU/Linux Module Size Used by fuse 59284 2 vboxnetadp 6727 0 vboxnetflt 16787 0 hidp 11791 1 rfcomm 28730 8 bnep 7254 2 usbhid 31477 0 btusb 10047 4 bluetooth 150114 28 btusb,bnep,rfcomm,hidp hid 66633 2 usbhid,hidp uvcvideo 60797 0 videobuf2_vmalloc 1736 1 uvcvideo videobuf2_memops 1562 1 videobuf2_vmalloc videobuf2_core 18103 1 uvcvideo videodev 72205 1 uvcvideo media 8513 2 videodev,uvcvideo snd_hda_codec_idt 48318 1 nvidia 10925239 44 snd_hda_intel 20080 2 arc4 1118 2 iwl3945 49250 0 iwlegacy 42390 1 iwl3945 b44 22954 0 ssb 41732 1 b44 joydev 7663 0 snd_hda_codec 79405 2 snd_hda_intel,snd_hda_codec_idt uhci_hcd 19712 0 mac80211 336883 2 iwlegacy,iwl3945 firewire_ohci 27283 0 firewire_core 44257 1 firewire_ohci r852 9032 0 sm_common 6510 1 r852 nand 42135 2 sm_common,r852 nand_ecc 3192 1 nand nand_ids 3629 1 nand dell_wmi 1217 0 sparse_keymap 2532 1 dell_wmi ehci_hcd 38640 0 serio_raw 3709 0 pcmcia 31438 1 ssb mii 3439 1 b44 iTCO_wdt 10773 0 mtd 26317 2 nand,sm_common snd_pcm 60499 2 snd_hda_codec,snd_hda_intel snd_page_alloc 5901 2 snd_pcm,snd_hda_intel sdhci_pci 8683 0 cfg80211 153196 3 mac80211,iwlegacy,iwl3945 sdhci 20362 1 sdhci_pci mmc_core 73191 3 sdhci,sdhci_pci,ssb i2c_i801 6992 0 psmouse 69902 0 i2c_core 16845 3 i2c_i801,nvidia,videodev wmi 7259 1 dell_wmi dell_laptop 9400 0 iTCO_vendor_support 1545 1 iTCO_wdt crc_itu_t 1095 1 firewire_core usbcore 122751 6 ehci_hcd,uhci_hcd,uvcvideo,btusb,usbhid pcmcia_core 10241 1 pcmcia snd_hwdep 4970 1 snd_hda_codec intel_agp 8688 0 intel_gtt 11193 1 intel_agp agpgart 22159 3 intel_gtt,intel_agp,nvidia r592 10291 0 snd_timer 15158 1 snd_pcm snd 45013 10 snd_timer,snd_hwdep,snd_pcm,snd_hda_codec,snd_hda_intel,snd_hda_codec_idt memstick 5616 1 r592 soundcore 4986 1 snd usb_common 622 1 usbcore rfkill 12600 4 dell_laptop,cfg80211,bluetooth dcdbas 4340 1 dell_laptop evdev 7310 21 thermal 6563 0 battery 5053 0 button 3614 0 ac 1796 0 video 9819 0 vboxdrv 195748 2 vboxnetflt,vboxnetadp cpufreq_powersave 674 0 acpi_cpufreq 5145 1 mperf 1027 1 acpi_cpufreq processor 23476 3 acpi_cpufreq ext4 384604 1 crc16 1091 2 ext4,bluetooth jbd2 60590 1 ext4 mbcache 4345 1 ext4 sd_mod 25867 3 sr_mod 13148 0 cdrom 30504 1 sr_mod pata_acpi 2388 0 ata_generic 2391 0 ahci 17689 2 libahci 16783 1 ahci ata_piix 18616 0 libata 145743 5 ata_piix,libahci,ahci,ata_generic,pata_acpi scsi_mod 112765 3 libata,sr_mod,sd_mod total used free shared buffers cached Mem: 2067496 1125712 941784 0 83492 693888 -/+ buffers/cache: 348332 1719164 Swap: 2104508 0 2104508 /usr/lib/pm-utils/sleep.d/00logging suspend suspend: success. Running hook /usr/lib/pm-utils/sleep.d/00powersave suspend suspend: /usr/lib/pm-utils/sleep.d/00powersave suspend suspend: success. Running hook /usr/lib/pm-utils/sleep.d/01grub suspend suspend: /usr/lib/pm-utils/sleep.d/01grub suspend suspend: success. Running hook /usr/lib/pm-utils/sleep.d/01laptop-mode suspend suspend: /usr/lib/pm-utils/sleep.d/01laptop-mode suspend suspend: success. Running hook /usr/lib/pm-utils/sleep.d/11netcfg suspend suspend: /usr/lib/pm-utils/sleep.d/11netcfg suspend suspend: success. Running hook /usr/lib/pm-utils/sleep.d/49bluetooth suspend suspend: /usr/lib/pm-utils/sleep.d/49bluetooth suspend suspend: success. Running hook /etc/pm/sleep.d/50-hdparm_pm suspend suspend: /etc/pm/sleep.d/50-hdparm_pm suspend suspend: success. Running hook /usr/lib/pm-utils/sleep.d/55wicd suspend suspend: /usr/lib/pm-utils/sleep.d/55wicd suspend suspend: success. Running hook /usr/lib/pm-utils/sleep.d/75modules suspend suspend: Unloading kernel module uhci_hcd...
On Wed, 16 May 2012 23:50:06 +0200 Manne Merak <mannemerak@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/*?
Manne
-------
Wed May 16 21:06:10 SAST 2012: Running hooks for suspend. Running hook /usr/lib/pm-utils/sleep.d/00logging suspend suspend: Linux hanslaptop 3.3.6-1-ARCH #1 SMP PREEMPT Sun May 13 09:59:18 UTC 2012 i686 GNU/Linux Module Size Used by fuse 59284 2 vboxnetadp 6727 0 vboxnetflt 16787 0 hidp 11791 1 rfcomm 28730 8 bnep 7254 2 usbhid 31477 0 btusb 10047 4 bluetooth 150114 28 btusb,bnep,rfcomm,hidp hid 66633 2 usbhid,hidp uvcvideo 60797 0 videobuf2_vmalloc 1736 1 uvcvideo videobuf2_memops 1562 1 videobuf2_vmalloc videobuf2_core 18103 1 uvcvideo videodev 72205 1 uvcvideo media 8513 2 videodev,uvcvideo snd_hda_codec_idt 48318 1 nvidia 10925239 44 snd_hda_intel 20080 2 arc4 1118 2 iwl3945 49250 0 iwlegacy 42390 1 iwl3945 b44 22954 0 ssb 41732 1 b44 joydev 7663 0 snd_hda_codec 79405 2 snd_hda_intel,snd_hda_codec_idt uhci_hcd 19712 0 mac80211 336883 2 iwlegacy,iwl3945 firewire_ohci 27283 0 firewire_core 44257 1 firewire_ohci r852 9032 0 sm_common 6510 1 r852 nand 42135 2 sm_common,r852 nand_ecc 3192 1 nand nand_ids 3629 1 nand dell_wmi 1217 0 sparse_keymap 2532 1 dell_wmi ehci_hcd 38640 0 serio_raw 3709 0 pcmcia 31438 1 ssb mii 3439 1 b44 iTCO_wdt 10773 0 mtd 26317 2 nand,sm_common snd_pcm 60499 2 snd_hda_codec,snd_hda_intel snd_page_alloc 5901 2 snd_pcm,snd_hda_intel sdhci_pci 8683 0 cfg80211 153196 3 mac80211,iwlegacy,iwl3945 sdhci 20362 1 sdhci_pci mmc_core 73191 3 sdhci,sdhci_pci,ssb i2c_i801 6992 0 psmouse 69902 0 i2c_core 16845 3 i2c_i801,nvidia,videodev wmi 7259 1 dell_wmi dell_laptop 9400 0 iTCO_vendor_support 1545 1 iTCO_wdt crc_itu_t 1095 1 firewire_core usbcore 122751 6 ehci_hcd,uhci_hcd,uvcvideo,btusb,usbhid pcmcia_core 10241 1 pcmcia snd_hwdep 4970 1 snd_hda_codec intel_agp 8688 0 intel_gtt 11193 1 intel_agp agpgart 22159 3 intel_gtt,intel_agp,nvidia r592 10291 0 snd_timer 15158 1 snd_pcm snd 45013 10 snd_timer,snd_hwdep,snd_pcm,snd_hda_codec,snd_hda_intel,snd_hda_codec_idt memstick 5616 1 r592 soundcore 4986 1 snd usb_common 622 1 usbcore rfkill 12600 4 dell_laptop,cfg80211,bluetooth dcdbas 4340 1 dell_laptop evdev 7310 21 thermal 6563 0 battery 5053 0 button 3614 0 ac 1796 0 video 9819 0 vboxdrv 195748 2 vboxnetflt,vboxnetadp cpufreq_powersave 674 0 acpi_cpufreq 5145 1 mperf 1027 1 acpi_cpufreq processor 23476 3 acpi_cpufreq ext4 384604 1 crc16 1091 2 ext4,bluetooth jbd2 60590 1 ext4 mbcache 4345 1 ext4 sd_mod 25867 3 sr_mod 13148 0 cdrom 30504 1 sr_mod pata_acpi 2388 0 ata_generic 2391 0 ahci 17689 2 libahci 16783 1 ahci ata_piix 18616 0 libata 145743 5 ata_piix,libahci,ahci,ata_generic,pata_acpi scsi_mod 112765 3 libata,sr_mod,sd_mod total used free shared buffers cached Mem: 2067496 1125712 941784 0 83492 693888 -/+ buffers/cache: 348332 1719164 Swap: 2104508 0 2104508
/usr/lib/pm-utils/sleep.d/00logging suspend suspend: success. Running hook /usr/lib/pm-utils/sleep.d/00powersave suspend suspend:
/usr/lib/pm-utils/sleep.d/00powersave suspend suspend: success. Running hook /usr/lib/pm-utils/sleep.d/01grub suspend suspend:
/usr/lib/pm-utils/sleep.d/01grub suspend suspend: success. Running hook /usr/lib/pm-utils/sleep.d/01laptop-mode suspend suspend:
/usr/lib/pm-utils/sleep.d/01laptop-mode suspend suspend: success. Running hook /usr/lib/pm-utils/sleep.d/11netcfg suspend suspend:
/usr/lib/pm-utils/sleep.d/11netcfg suspend suspend: success. Running hook /usr/lib/pm-utils/sleep.d/49bluetooth suspend suspend:
/usr/lib/pm-utils/sleep.d/49bluetooth suspend suspend: success. Running hook /etc/pm/sleep.d/50-hdparm_pm suspend suspend:
/etc/pm/sleep.d/50-hdparm_pm suspend suspend: success. Running hook /usr/lib/pm-utils/sleep.d/55wicd suspend suspend:
/usr/lib/pm-utils/sleep.d/55wicd suspend suspend: success. Running hook /usr/lib/pm-utils/sleep.d/75modules suspend suspend: Unloading kernel module uhci_hcd...
-- Leonid Isaev GnuPG key: 0x164B5A6D Fingerprint: C0DF 20D0 C075 C3F1 E1BE 775A A7AE F6CB 164B 5A6D
On 05/17/2012 01:11 AM, Leonid Isaev wrote:
On Wed, 16 May 2012 23:50:06 +0200 Manne Merak<mannemerak@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/*?
Wouldn't know, I have never had problems with suspend-to-RAM on this Vostro 1700 and Arch. My /etc/pm/config.d contains one file, "modules" with contents: SUSPEND_MODULES="uhci_hcd ehci_hcd" I think I placed it there years ago after installing pm-utils I think the problems started with Kernel 3.3 Also have laptop_mode installed. Manne
On 05/17/2012 01:11 AM, Leonid Isaev wrote:
On Wed, 16 May 2012 23:50:06 +0200 Manne Merak<mannemerak@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" /usr/lib/pm-utils/functions: line 89: log: command not found 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. 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
On Sun, 20 May 2012 12:36:16 +0200 Manne Merak <mannemerak@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@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? -- Leonid Isaev GnuPG key: 0x164B5A6D Fingerprint: C0DF 20D0 C075 C3F1 E1BE 775A A7AE F6CB 164B 5A6D
On 05/20/2012 08:13 PM, Leonid Isaev wrote:
On Sun, 20 May 2012 12:36:16 +0200 Manne Merak<mannemerak@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@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
On 05/21/2012 10:41 PM, Manne Merak wrote:
On 05/20/2012 08:13 PM, Leonid Isaev wrote:
On Sun, 20 May 2012 12:36:16 +0200 Manne Merak<mannemerak@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@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
So, after some more debugging I found disabling bluetoothd fixes suspend. Now to figure out what changed in the bloutooth modules the last couple of months. I have always used a bt mouse with this machine, working fine. Manne
participants (2)
-
Leonid Isaev
-
Manne Merak