LinuxQuestions.org

LinuxQuestions.org (/questions/)
-   Linux - Software (https://www.linuxquestions.org/questions/linux-software-2/)
-   -   TuxOnIce, device resume from suspend takes way too long (https://www.linuxquestions.org/questions/linux-software-2/tuxonice-device-resume-from-suspend-takes-way-too-long-895682/)

whoopie 08-05-2011 03:05 AM

TuxOnIce, device resume from suspend takes way too long
 
Greetings,

I am having trouble with a rather peculiar timeout during resume from suspension and I was wondering if any of you have encountered the error or might have some leads as to what causes the problem.

I am using Gentoo Linux with TuxOnIce patched kernel. While both hibernation and suspension works as advertised, there is a rather irritating timeout while trying to resume from suspension. Each and every time it takes about 60s for notebook to resume back to X session again, no matter what the conditions are (i.e. USB deviced plugged in, etc.)

Quote:

Originally Posted by eix
[I] sys-power/hibernate-script
Installed versions: 2.0-r3(23:57:33 07/07/11)(-vim-syntax)
[I] sys-kernel/tuxonice-sources
Installed versions: 2.6.38-r2(2.6.38-r2)!b!s(07:39:52 07/05/11)(symlink -build -deblob)

Quote:

Originally Posted by dmesg
[140632.933229] ACPI: Waking up from system sleep state S3
[140632.969506] ehci_hcd 0000:00:1a.0: restoring config space at offset 0x1 (was 0x2900006, writing 0x2900002)
[140632.969550] HDA Intel 0000:00:1b.0: restoring config space at offset 0x1 (was 0x100006, writing 0x100002)
[140632.969581] pcieport 0000:00:1c.0: restoring config space at offset 0xf (was 0x100, writing 0x1ff)
[140632.969621] pcieport 0000:00:1c.1: restoring config space at offset 0xf (was 0x200, writing 0x2ff)
[140632.969661] pcieport 0000:00:1c.4: restoring config space at offset 0xf (was 0x100, writing 0x1ff)
[140632.969701] pcieport 0000:00:1c.7: restoring config space at offset 0xf (was 0x200, writing 0x2ff)
[140632.969755] ehci_hcd 0000:00:1d.0: restoring config space at offset 0x1 (was 0x2900006, writing 0x2900002)
[140632.969785] pci 0000:00:1e.0: restoring config space at offset 0xa (was 0xffffffff, writing 0x0)
[140632.969860] ahci 0000:00:1f.2: restoring config space at offset 0x1 (was 0x2b00007, writing 0x2b00407)
[140632.969918] nvidia 0000:01:00.0: restoring config space at offset 0xf (was 0x100, writing 0x105)
[140632.969929] nvidia 0000:01:00.0: restoring config space at offset 0x3 (was 0x800010, writing 0x800000)
[140632.969933] nvidia 0000:01:00.0: restoring config space at offset 0x1 (was 0x100007, writing 0x100047)
[140632.969962] HDA Intel 0000:01:00.1: restoring config space at offset 0xf (was 0x100, writing 0x105)
[140632.969974] HDA Intel 0000:01:00.1: restoring config space at offset 0x1 (was 0x100006, writing 0x100002)
[140632.970078] r8169 0000:03:00.0: restoring config space at offset 0xf (was 0x1ff, writing 0x105)
[140632.970090] r8169 0000:03:00.0: restoring config space at offset 0xc (was 0x0, writing 0xffff0000)
[140632.970127] r8169 0000:03:00.0: restoring config space at offset 0x1 (was 0x100007, writing 0x100407)
[140632.970248] pci 0000:04:00.0: restoring config space at offset 0x9 (was 0x0, writing 0xd8100c00)
[140632.970292] pci 0000:04:00.0: restoring config space at offset 0x3 (was 0x800000, writing 0x800010)
[140632.970705] PM: early resume of devices complete after 1.396 msecs
[140632.970861] ehci_hcd 0000:00:1a.0: PCI INT A -> GSI 16 (level, low) -> IRQ 16
[140632.970879] ehci_hcd 0000:00:1a.0: setting latency timer to 64
[140632.970927] HDA Intel 0000:00:1b.0: PCI INT A -> GSI 22 (level, low) -> IRQ 22
[140632.970938] HDA Intel 0000:00:1b.0: setting latency timer to 64
[140632.970953] ehci_hcd 0000:00:1d.0: PCI INT A -> GSI 21 (level, low) -> IRQ 21
[140632.970957] pci 0000:00:1e.0: setting latency timer to 64
[140632.970960] ahci 0000:00:1f.2: setting latency timer to 64
[140632.970970] ehci_hcd 0000:00:1d.0: setting latency timer to 64
[140632.970974] pci 0000:00:1f.3: PCI INT B -> GSI 19 (level, low) -> IRQ 19
[140632.971026] HDA Intel 0000:00:1b.0: irq 47 for MSI/MSI-X
[140632.971031] HDA Intel 0000:01:00.1: PCI INT A -> GSI 16 (level, low) -> IRQ 16
[140632.971042] HDA Intel 0000:01:00.1: setting latency timer to 64
[140632.971091] wl 0000:02:00.0: PCI INT A -> GSI 16 (level, low) -> IRQ 16
[140632.971130] r8169 0000:03:00.0: wake-up capability disabled by ACPI
[140632.971139] r8169 0000:03:00.0: PME# disabled
[140632.971146] usb usb1: usb resume
[140632.971152] ehci_hcd 0000:00:1a.0: resume root hub
[140632.971155] wl 0000:02:00.0: setting latency timer to 64
[140632.971159] usb usb2: usb resume
[140632.971165] ehci_hcd 0000:00:1d.0: resume root hub
[140632.971181] sd 0:0:0:0: [sda] Starting disk
[140633.012158] hub 1-0:1.0: hub_resume
[140633.012167] hub 2-0:1.0: hub_resume
[140633.012187] hub 1-0:1.0: port 1: status 0503 change 0000
[140633.012190] hub 2-0:1.0: port 1: status 0503 change 0000
[140633.012263] hub 2-1:1.0: hub_resume
[140633.012266] hub 1-1:1.0: hub_resume
[140633.012409] hub 1-1:1.0: port 1: status 0503 change 0000
[140633.012534] hub 2-1:1.0: port 2: status 0303 change 0000
[140633.012575] hub 1-1:1.0: port 2: status 0503 change 0000
[140633.012664] hub 2-1:1.0: port 3: status 0101 change 0001
[140633.012829] hub 1-1:1.0: port 4: status 0101 change 0001
[140633.013062] hub 2-1:1.0: port 5: status 0101 change 0001
[140633.013622] hub 2-1:1.0: port 7: status 0101 change 0001
[140633.088184] i8042 kbd 00:08: wake-up capability disabled by ACPI
[140633.114103] ehci_hcd 0000:00:1a.0: reused qh ffff88013b7f4680 schedule
[140633.114107] ehci_hcd 0000:00:1d.0: reused qh ffff88013b76e300 schedule
[140633.114112] usb 1-1: link qh256-0001/ffff88013b7f4680 start 1 [1/0 us]
[140633.114116] usb 2-1: link qh256-0001/ffff88013b76e300 start 1 [1/0 us]
[140633.114422] usb 2-1.5: reset-resume
[140633.114634] usb 2-1.3: reset-resume
[140633.115068] hub 1-1.2:1.0: hub_resume
[140633.115189] usb 2-1.7: reset-resume
[140633.115283] usb 1-1.4: reset-resume
[140633.115291] hub 1-1.2:1.0: port 1: status 0503 change 0000
[140633.115498] hub 1-1.2:1.0: port 2: status 0503 change 0000
[140633.115870] hub 1-1.2:1.0: port 4: status 0503 change 0000
[140633.115876] ehci_hcd 0000:00:1a.0: reused qh ffff88010cc00e80 schedule
[140633.115880] usb 1-1.2: link qh256-0001/ffff88010cc00e80 start 3 [1/0 us]
[140633.125256] hub 2-1:1.0: port 5 not reset yet, waiting 10ms
[140633.193139] usb 2-1.5: reset high speed USB device using ehci_hcd and address 4
[140633.205147] hub 2-1:1.0: port 5 not reset yet, waiting 10ms
[140633.274945] ata5: SATA link down (SStatus 0 SControl 300)
[140633.278947] ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
[140633.281921] ata6: SATA link down (SStatus 0 SControl 300)
[140633.342034] usb 2-1.3: reset full speed USB device using ehci_hcd and address 3
[140633.353035] hub 2-1:1.0: port 3 not reset yet, waiting 10ms
[140633.359155] ata2.00: configured for UDMA/100
[140633.426787] usb 2-1.3: ep0 maxpacket = 8
[140633.437908] hub 2-1:1.0: port 7 not reset yet, waiting 10ms
[140633.499897] usb 2-1.7: reset full speed USB device using ehci_hcd and address 5
[140633.510886] hub 2-1:1.0: port 7 not reset yet, waiting 10ms
[140633.595827] hub 1-1:1.0: port 4 not reset yet, waiting 10ms
[140633.657779] usb 1-1.4: reset high speed USB device using ehci_hcd and address 3
[140633.669761] hub 1-1:1.0: port 4 not reset yet, waiting 10ms
[140635.569794] ata1: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
[140635.772329] ata1.00: configured for UDMA/100
[140693.803932] r8169 0000:03:00.0: eth0: unable to apply firmware patch
[140693.808865] r8169 0000:03:00.0: eth0: link down
[140693.815593] PM: resume of devices complete after 60902.232 msecs
[140693.815887] PM: Finishing wakeup.
[140693.815889] Restarting all filesystems ...
[140693.816159] Restarting tasks ...

Quote:

Originally Posted by /var/log/hibernate.log
Starting suspend at ...
hibernate-ram: [01] Executing CheckLastResume ...
hibernate-ram: [01] Executing CheckRunlevel ...
hibernate-ram: [01] Executing LockFileGet ...
hibernate-ram: [01] Executing NewKernelFileCheck ...
hibernate-ram: [10] Executing EnsureSysfsPowerStateCapable ...
hibernate-ram: [11] Executing XHacksSuspendHook1 ...
hibernate-ram: [59] Executing RemountXFSBootRO ...
hibernate-ram: [89] Executing SaveKernelModprobe ...
hibernate-ram: [91] Executing ModulesUnloadBlacklist ...
hibernate-ram: [95] Executing XHacksSuspendHook2 ...
hibernate-ram: [98] Executing CheckRunlevel ...
hibernate-ram: [99] Executing DoSysfsPowerStateSuspend ...
hibernate-ram: Activating sysfs power state mem ...
hibernate-ram: [90] Executing ModulesLoad ...
hibernate-ram: [89] Executing RestoreKernelModprobe ...
hibernate-ram: [85] Executing XHacksResumeHook2 ...
hibernate-ram: [70] Executing ClockRestore ...
hibernate-ram: [59] Executing RemountXFSBootRW ...
hibernate-ram: [11] Executing XHacksResumeHook1 ...
hibernate-ram: [01] Executing NoteLastResume ...
hibernate-ram: [01] Executing LockFilePut ...
Resumed at ...

EDIT: Mainly all features including variety of TuxOnIce patches and CPU scaling etc. are build-in the kernel. Here is the list of modules that were loaded during the attempts:
Quote:

Originally Posted by lsmod
Module Size Used by
coretemp 4882 0
vboxdrv 1741171 1
nvidia 11753314 122
wl 2504281 0
hp_accel 13512 0
lis3lv02d 8831 1 hp_accel

Thank you for your time :).

marco18 08-05-2011 09:02 PM

Hi there! How do you suspend your PC? Via command or from X Server Environment? Maybe you could try (if you have it) by suspending with the "s2ram" application by entering the following:

Code:

s2ram --force
Just to see if there is some problem with the default procedure.

whoopie 08-07-2011 03:07 AM

Quote:

Originally Posted by marco18 (Post 4434969)
Hi there! How do you suspend your PC? Via command or from X Server Environment? Maybe you could try (if you have it) by suspending with the "s2ram" application by entering the following:

Code:

s2ram --force
Just to see if there is some problem with the default procedure.

Hello, thank you for your reply!

I have tried a variety of ways of suspending a computer, such as s2ram, or via (q)dbus call with no change in result like at all.
It would appear that --force argument bears has no effect on the time required for a resume of devices.

No matter what userspace application is used the end-result it always the same, which makes me believe that the problem is not in the choice and configuration of userspace application, rather than in the kernel itself.

I have Google'd some older posts stating that nvidia binary drivers interfere with suspend/hibernate capability. Unlike those cases I can perform these actions, it just takes a bit longer. Do you think the drivers are responsible?

marco18 08-08-2011 07:35 AM

Quote:

[140635.569794] ata1: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
[140635.772329] ata1.00: configured for UDMA/100
[140693.803932] r8169 0000:03:00.0: eth0: unable to apply firmware patch
[140693.808865] r8169 0000:03:00.0: eth0: link down
It seems that the problem is in some patch that the kernel is trying to apply to an interface's firmware in eth0. The kernel spends approximately 60 seconds here. Check if that interface works properly or maybe it may be needing some firmware files (wireless are the most common).


All times are GMT -5. The time now is 11:04 AM.