| lm317t |
05-26-2006 09:40 AM |
Hibernate Resume Hangs for long time
I am using Ubuntu on a laptop. The problem is hibernate nearly always hangs on resume. It freezes so that the mouse and keyboard do nothing. I get my Gnome background on the screen during this time but none of Gnome's icons.
I have recompiled my kernel to support hibernation and high speed disk access. It does read and write the HDD very quickly upon suspend/resume.
The problem seems to be kernel related.
root@ubuntu_laptop:~# uname -r
2.6.12
none of my logs tip me off as to what may be hanging, but maybe someone out there sees something I don't:
here is the messages log:
Code:
root@ubuntu_laptop:~# tail -n 200 /var/log/messages
May 26 09:26:31 localhost kernel: [4737988.929000] wlan0: ndiswrapper ethernet device 00:90:4b:94:fc:61 using driver bcmwl5, configuration file 14E4:4320:103C:12F4.5.conf
May 26 09:26:31 localhost kernel: [4737988.929000] wlan0: encryption modes supported: WEP, WPA with TKIP, WPA with AES/CCMP
May 26 09:39:57 localhost -- MARK --
May 26 09:49:24 localhost kernel: [4739241.332000] eth0: link up, 100Mbps, full-duplex, lpa 0x45E1
May 26 09:59:57 localhost -- MARK --
May 26 10:03:50 localhost kernel: [4740107.883000] Resume block device is cff60040.
May 26 10:03:50 localhost kernel: [4740107.883000] Resume block device is cff60040.
May 26 10:03:50 localhost kernel: [4740107.884000] Resume block device is cff60040.
May 26 10:03:50 localhost last message repeated 4 times
May 26 10:03:50 localhost kernel: [4740107.885000] Resume block device is cff60040.
May 26 10:03:50 localhost last message repeated 4 times
May 26 10:03:51 localhost kernel: [4740108.062000] ehci_hcd 0000:00:02.2: remove, state 1
May 26 10:03:51 localhost kernel: [4740108.062000] usb usb1: USB disconnect, address 1
May 26 10:03:51 localhost kernel: [4740108.098000] ehci_hcd 0000:00:02.2: USB bus 1 deregistered
May 26 10:03:51 localhost kernel: [4740108.117000] ACPI: PCI interrupt for device 0000:00:02.2 disabled
May 26 10:03:51 localhost kernel: [4740108.200000] ohci_hcd 0000:00:02.0: remove, state 1
May 26 10:03:51 localhost kernel: [4740108.200000] usb usb2: USB disconnect, address 1
May 26 10:03:51 localhost kernel: [4740108.200000] usb 2-1: USB disconnect, address 2
May 26 10:03:51 localhost kernel: [4740108.263000] ohci_hcd 0000:00:02.0: USB bus 2 deregistered
May 26 10:03:51 localhost kernel: [4740108.294000] ACPI: PCI interrupt for device 0000:00:02.0 disabled
May 26 10:03:51 localhost kernel: [4740108.294000] ohci_hcd 0000:00:02.1: remove, state 1
May 26 10:03:51 localhost kernel: [4740108.294000] usb usb3: USB disconnect, address 1
May 26 10:03:51 localhost kernel: [4740108.397000] ohci_hcd 0000:00:02.1: USB bus 3 deregistered
May 26 10:03:51 localhost kernel: [4740108.427000] ACPI: PCI interrupt for device 0000:00:02.1 disabled
May 26 10:03:52 localhost kernel: [4740108.983000] ndiswrapper: device wlan0 removed
May 26 10:03:52 localhost kernel: [4740109.085000] ACPI: PCI interrupt for device 0000:02:02.0 disabled
May 26 10:03:52 localhost kernel: [4740109.473000] Resume block device is cff60040.
May 26 10:03:52 localhost kernel: [4740109.474000] Resume block device is cff60040.
May 26 10:03:52 localhost kernel: [4740109.474000] Resume block device is cff60040.
May 26 10:03:52 localhost kernel: [4740109.475000] Resume block device is cff60040.
May 26 10:03:52 localhost kernel: [4740109.477000] Resume block device is cff60040.
May 26 10:03:52 localhost kernel: [4740109.477000] Resume block device is cff60040.
May 26 10:03:52 localhost kernel: [4740109.480000] Resume block device is cff60040.
May 26 10:03:52 localhost last message repeated 2 times
May 26 10:03:52 localhost kernel: [4740109.481000] Resume block device is cff60040.
May 26 10:03:52 localhost kernel: [4740109.481000] Resume block device is cff60040.
May 26 10:03:52 localhost kernel: [4740109.482000] Resume block device is cff60040.
May 26 10:03:52 localhost kernel: [4740109.493000] Resume block device is cff60040.
May 26 10:03:52 localhost kernel: [4740109.493000] Resume block device is cff60040.
May 26 10:03:52 localhost kernel: [4740109.493000] Software Suspend 2.1.9.9: Initiating a software suspend cycle.
May 26 10:04:42 localhost kernel: [4740120.210000] eth0: link down
May 26 10:04:42 localhost kernel: [4740120.342000] ACPI: PCI interrupt for device 0000:02:04.1 disabled
May 26 10:04:42 localhost kernel: [4740120.343000] ACPI: PCI interrupt for device 0000:02:04.0 disabled
May 26 10:04:42 localhost kernel: [4740120.354000] ACPI: PCI interrupt for device 0000:00:06.0 disabled
May 26 10:04:42 localhost kernel: [4740150.093000] ACPI: PCI Interrupt 0000:00:06.0[A] -> Link [LACI] -> GSI 21 (level, low) -> IRQ 21
May 26 10:04:42 localhost kernel: [4740150.105000] eth0: link down
May 26 10:04:42 localhost kernel: [4740150.105000] ACPI: PCI Interrupt 0000:02:04.0[A] -> Link [LNK1] -> GSI 18 (level, low) -> IRQ 18
May 26 10:04:42 localhost kernel: [4740150.105000] ACPI: PCI Interrupt 0000:02:04.1[B] -> Link [LNK2] -> GSI 19 (level, low) -> IRQ 19
May 26 10:04:42 localhost kernel: [4740159.787000] Resume block device is cff60040.
May 26 10:04:42 localhost kernel: [4740159.787000] Resume block device is cff60040.
May 26 10:04:42 localhost kernel: [4740159.940000] ACPI: PCI Interrupt 0000:00:02.2[C] -> Link [LUS2] -> GSI 22 (level, low) -> IRQ 22
May 26 10:04:42 localhost kernel: [4740159.940000] ehci_hcd 0000:00:02.2: nVidia Corporation nForce3 USB 2.0
May 26 10:04:42 localhost kernel: [4740159.997000] ehci_hcd 0000:00:02.2: new USB bus registered, assigned bus number 1
May 26 10:04:42 localhost kernel: [4740159.997000] ehci_hcd 0000:00:02.2: irq 22, io mem 0xe8004000
May 26 10:04:42 localhost kernel: [4740159.997000] ehci_hcd 0000:00:02.2: park 0
May 26 10:04:42 localhost kernel: [4740159.997000] ehci_hcd 0000:00:02.2: USB 2.0 initialized, EHCI 1.00, driver 10 Dec 2004
May 26 10:04:42 localhost kernel: [4740160.222000] hub 1-0:1.0: USB hub found
May 26 10:04:42 localhost kernel: [4740160.222000] hub 1-0:1.0: 6 ports detected
May 26 10:04:43 localhost kernel: [4740160.388000] eth0: link up, 100Mbps, full-duplex, lpa 0x45E1
May 26 10:04:43 localhost kernel: [4740160.745000] input: AT Translated Set 2 keyboard on isa0060/serio0
May 26 10:04:43 localhost kernel: [4740160.775000] atkbd.c: Spurious ACK on isa0060/serio0. Some program, like XFree86, might be trying access hardware directly.
May 26 10:04:43 localhost kernel: [4740160.779000] atkbd.c: Spurious ACK on isa0060/serio0. Some program, like XFree86, might be trying access hardware directly.
May 26 10:04:43 localhost kernel: [4740160.783000] atkbd.c: Spurious ACK on isa0060/serio0. Some program, like XFree86, might be trying access hardware directly.
May 26 10:04:43 localhost kernel: [4740160.788000] atkbd.c: Spurious ACK on isa0060/serio0. Some program, like XFree86, might be trying access hardware directly.
May 26 10:04:43 localhost kernel: [4740160.792000] atkbd.c: Spurious ACK on isa0060/serio0. Some program, like XFree86, might be trying access hardware directly.
May 26 10:04:43 localhost kernel: [4740160.795000] atkbd.c: Spurious ACK on isa0060/serio0. Some program, like XFree86, might be trying access hardware directly.
May 26 10:04:43 localhost kernel: [4740160.800000] atkbd.c: Spurious ACK on isa0060/serio0. Some program, like XFree86, might be trying access hardware directly.
May 26 10:04:43 localhost kernel: [4740160.804000] atkbd.c: Spurious ACK on isa0060/serio0. Some program, like XFree86, might be trying access hardware directly.
May 26 10:04:43 localhost kernel: [4740160.807000] atkbd.c: Spurious ACK on isa0060/serio0. Some program, like XFree86, might be trying access hardware directly.
May 26 10:04:43 localhost kernel: [4740160.812000] atkbd.c: Spurious ACK on isa0060/serio0. Some program, like XFree86, might be trying access hardware directly.
May 26 10:04:43 localhost kernel: [4740160.815000] atkbd.c: Spurious ACK on isa0060/serio0. Some program, like XFree86, might be trying access hardware directly.
May 26 10:04:43 localhost kernel: [4740160.819000] atkbd.c: Spurious ACK on isa0060/serio0. Some program, like XFree86, might be trying access hardware directly.
May 26 10:04:43 localhost kernel: [4740160.824000] atkbd.c: Spurious ACK on isa0060/serio0. Some program, like XFree86, might be trying access hardware directly.
May 26 10:04:43 localhost kernel: [4740160.827000] atkbd.c: Spurious ACK on isa0060/serio0. Some program, like XFree86, might be trying access hardware directly.
May 26 10:04:43 localhost kernel: [4740160.831000] atkbd.c: Spurious ACK on isa0060/serio0. Some program, like XFree86, might be trying access hardware directly.
May 26 10:04:43 localhost kernel: [4740160.836000] atkbd.c: Spurious ACK on isa0060/serio0. Some program, like XFree86, might be trying access hardware directly.
May 26 10:04:43 localhost kernel: [4740160.839000] atkbd.c: Spurious ACK on isa0060/serio0. Some program, like XFree86, might be trying access hardware directly.
May 26 10:04:43 localhost kernel: [4740160.842000] atkbd.c: Spurious ACK on isa0060/serio0. Some program, like XFree86, might be trying access hardware directly.
May 26 10:04:43 localhost kernel: [4740160.847000] atkbd.c: Spurious ACK on isa0060/serio0. Some program, like XFree86, might be trying access hardware directly.
May 26 10:04:43 localhost kernel: [4740160.851000] atkbd.c: Spurious ACK on isa0060/serio0. Some program, like XFree86, might be trying access hardware directly.
May 26 10:04:43 localhost kernel: [4740160.854000] atkbd.c: Spurious ACK on isa0060/serio0. Some program, like XFree86, might be trying access hardware directly.
May 26 10:04:43 localhost kernel: [4740160.859000] atkbd.c: Spurious ACK on isa0060/serio0. Some program, like XFree86, might be trying access hardware directly.
May 26 10:04:43 localhost kernel: [4740160.862000] atkbd.c: Spurious ACK on isa0060/serio0. Some program, like XFree86, might be trying access hardware directly.
May 26 10:04:43 localhost kernel: [4740160.866000] atkbd.c: Spurious ACK on isa0060/serio0. Some program, like XFree86, might be trying access hardware directly.
May 26 10:04:43 localhost kernel: [4740160.871000] atkbd.c: Spurious ACK on isa0060/serio0. Some program, like XFree86, might be trying access hardware directly.
May 26 10:04:43 localhost kernel: [4740160.874000] atkbd.c: Spurious ACK on isa0060/serio0. Some program, like XFree86, might be trying access hardware directly.
May 26 10:04:43 localhost kernel: [4740160.878000] atkbd.c: Spurious ACK on isa0060/serio0. Some program, like XFree86, might be trying access hardware directly.
May 26 10:04:43 localhost kernel: [4740160.883000] atkbd.c: Spurious ACK on isa0060/serio0. Some program, like XFree86, might be trying access hardware directly.
May 26 10:04:43 localhost kernel: [4740160.883000] ACPI: PCI Interrupt 0000:00:02.0[A] -> Link [LUS0] -> GSI 21 (level, low) -> IRQ 21
May 26 10:04:43 localhost kernel: [4740160.884000] ohci_hcd 0000:00:02.0: nVidia Corporation nForce3 USB 1.1
May 26 10:04:43 localhost kernel: [4740161.086000] atkbd.c: Spurious ACK on isa0060/serio0. Some program, like XFree86, might be trying access hardware directly.
May 26 10:04:43 localhost kernel: [4740161.109000] ohci_hcd 0000:00:02.0: new USB bus registered, assigned bus number 2
May 26 10:04:43 localhost kernel: [4740161.109000] ohci_hcd 0000:00:02.0: irq 21, io mem 0xe8000000
May 26 10:04:43 localhost usb.agent[14677]: usbcore: already loaded
May 26 10:04:43 localhost input.agent[14705]: evdev: already loaded
May 26 10:04:43 localhost kernel: [4740161.309000] hub 2-0:1.0: USB hub found
May 26 10:04:43 localhost kernel: [4740161.309000] hub 2-0:1.0: 3 ports detected
May 26 10:04:44 localhost input.agent[14699]: evdev: already loaded
May 26 10:04:44 localhost kernel: [4740161.437000] ACPI: PCI Interrupt 0000:00:02.1[B] -> Link [LUS1] -> GSI 20 (level, low) -> IRQ 20
May 26 10:04:44 localhost kernel: [4740161.437000] ohci_hcd 0000:00:02.1: nVidia Corporation nForce3 USB 1.1 (#2)
May 26 10:04:44 localhost kernel: [4740161.667000] ohci_hcd 0000:00:02.1: new USB bus registered, assigned bus number 3
May 26 10:04:44 localhost kernel: [4740161.667000] ohci_hcd 0000:00:02.1: irq 20, io mem 0xe8001000
May 26 10:04:44 localhost kernel: [4740161.746000] hub 3-0:1.0: USB hub found
May 26 10:04:44 localhost kernel: [4740161.746000] hub 3-0:1.0: 3 ports detected
May 26 10:04:44 localhost kernel: [4740161.824000] usb 2-1: new low speed USB device using ohci_hcd and address 2
May 26 10:04:44 localhost usb.agent[14826]: usbcore: already loaded
May 26 10:04:44 localhost kernel: [4740161.916000] ACPI: Power Button (FF) [PWRF]
May 26 10:04:44 localhost kernel: [4740161.916000] ACPI: Power Button (CM) [PWRB]
May 26 10:04:44 localhost kernel: [4740161.916000] ACPI: Lid Switch [LID]
May 26 10:04:44 localhost kernel: [4740161.957000] input: USB HID v1.10 Mouse [Logitech USB Mouse] on usb-0000:00:02.0-1
May 26 10:04:44 localhost kernel: [4740162.074000] ndiswrapper version 1.1 loaded (preempt=no,smp=no)
May 26 10:04:44 localhost kernel: [4740162.105000] ndiswrapper: driver bcmwl5 (Broadcom,06/26/2004, 3.70.17.0) loaded
May 26 10:04:44 localhost kernel: [4740162.105000] ACPI: PCI Interrupt 0000:02:02.0[A] -> Link [LNK3] -> GSI 17 (level, low) -> IRQ 17
May 26 10:04:44 localhost kernel: [4740162.110000] ndiswrapper: using irq 17
May 26 10:04:45 localhost input.agent[14900]: tsdev: already loaded
May 26 10:04:45 localhost input.agent[14900]: mousedev: already loaded
May 26 10:04:45 localhost input.agent[14900]: evdev: already loaded
May 26 10:04:45 localhost usb.agent[14896]: usbcore: already loaded
May 26 10:04:45 localhost usb.agent[15010]: usbhid: already loaded
May 26 10:04:45 localhost kernel: [4740162.716000] wlan0: ndiswrapper ethernet device 00:90:4b:94:fc:61 using driver bcmwl5, configuration file 14E4:4320:103C:12F4.5.conf
May 26 10:04:45 localhost kernel: [4740162.716000] wlan0: encryption modes supported: WEP, WPA with TKIP, WPA with AES/CCMP
May 26 10:04:45 localhost input.agent[15068]: evdev: already loaded
May 26 10:04:45 localhost input.agent[15065]: evdev: already loaded
May 26 10:04:45 localhost input.agent[15060]: evdev: already loaded
Here is the hibernate log:
Code:
root@ubuntu_laptop:~# tail -n40 /var/log/hibernate.log
hibernate: [00] Executing RemoveSwsuspProcCruft ...
Resumed at Thu May 25 19:12:29 EDT 2006
Starting suspend at Thu May 25 22:48:00 EDT 2006
hibernate: [01] Executing CheckLastResume ...
hibernate: [01] Executing LockFileGet ...
hibernate: [01] Executing NewKernelFileCheck ...
hibernate: [10] Executing EnsureSwsusp2Capable ...
hibernate: [89] Executing SaveKernelModprobe ...
hibernate: [91] Executing ModulesUnloadBlacklist ...
hibernate: [97] Executing ChangeToSwsuspVT ...
hibernate: [98] Executing Swsusp2ConfigSet ...
hibernate: [99] Executing DoSwsusp2 ...
hibernate: Activating suspend ...
hibernate: [97] Executing ChangeFromSwsuspVT ...
hibernate: [90] Executing ModulesLoad ...
hibernate: [89] Executing RestoreKernelModprobe ...
hibernate: [70] Executing ClockRestore ...
hibernate: [01] Executing NoteLastResume ...
hibernate: [01] Executing LockFilePut ...
hibernate: [00] Executing RemoveSwsuspProcCruft ...
Resumed at Fri May 26 09:28:33 EDT 2006
Starting suspend at Fri May 26 10:03:50 EDT 2006
hibernate: [01] Executing CheckLastResume ...
hibernate: [01] Executing LockFileGet ...
hibernate: [01] Executing NewKernelFileCheck ...
hibernate: [10] Executing EnsureSwsusp2Capable ...
hibernate: [89] Executing SaveKernelModprobe ...
hibernate: [91] Executing ModulesUnloadBlacklist ...
hibernate: [97] Executing ChangeToSwsuspVT ...
hibernate: [98] Executing Swsusp2ConfigSet ...
hibernate: [99] Executing DoSwsusp2 ...
hibernate: Activating suspend ...
hibernate: [97] Executing ChangeFromSwsuspVT ...
hibernate: [90] Executing ModulesLoad ...
hibernate: [89] Executing RestoreKernelModprobe ...
hibernate: [70] Executing ClockRestore ...
hibernate: [01] Executing NoteLastResume ...
hibernate: [01] Executing LockFilePut ...
hibernate: [00] Executing RemoveSwsuspProcCruft ...
Resumed at Fri May 26 10:06:47 EDT 2006
|
