Arch Linux

Fedes

Member

From: Buenos Aires, Argentina

Registered: 2012-10-23

Posts: 36

Resume from sleep to RAM slow (takes 20 seconds) with kernel 3.6

Hello all,

I recently switched from Gentoo to Arch, and I have the same issue on both installations, so I think this is related to the kernel. With kernel 3.6 my laptop resume from RAM is slower than before. It takes around 20 seconds, when it used to take ~1 or 2 seconds. To confirm, I installed linux-lts package to test with an older kernel, in this case 3.0.46, and it resume takes only ~2 seconds. The only difference is that my broadcom-sta module didn't load, but I tried removing the module with kernel 3.6, and still get the same issue. I'm wondering if I'm the only one with this issue, or if this is probably an issue that other users didn't notice?

This is what I have in the journal during suspend and resum cycle using kernel 3.6.2-1-ARCH:

Oct 23 01:06:28 glarchie systemd[1]: Starting Sleep.
Oct 23 01:06:28 glarchie systemd[1]: Reached target Sleep.
Oct 23 01:06:28 glarchie systemd[1]: Starting Suspend...
Oct 23 01:06:28 glarchie systemd-sleep[7119]: /usr/lib/systemd/system-sleep/notify-upower.sh exited with exit status 1.
Oct 23 01:06:28 glarchie systemd-sleep[7119]: Suspending system...
Oct 23 01:06:30 glarchie kernel: PM: Syncing filesystems ... done.
Oct 23 01:06:30 glarchie kernel: PM: Preparing system for mem sleep
Oct 23 01:06:30 glarchie kernel: bbswitch: enabling discrete graphics
Oct 23 01:06:30 glarchie kernel: bbswitch: Result of _DSM call for ON: 00000001
Oct 23 01:06:56 glarchie kernel: Freezing user space processes ... (elapsed 0.01 seconds) done.
Oct 23 01:06:56 glarchie kernel: Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
Oct 23 01:06:56 glarchie kernel: PM: Entering mem sleep
Oct 23 01:06:56 glarchie kernel: Suspending console(s) (use no_console_suspend to debug)
Oct 23 01:06:56 glarchie kernel: ehci_hcd 0000:00:1d.0: setting latency timer to 64
Oct 23 01:06:56 glarchie kernel: sd 0:0:0:0: [sda] Synchronizing SCSI cache
Oct 23 01:06:56 glarchie kernel: sd 0:0:0:0: [sda] Stopping disk
Oct 23 01:06:56 glarchie kernel: azx_single_send_cmd: 264 callbacks suppressed
Oct 23 01:06:56 glarchie kernel: PM: suspend of devices complete after 923.176 msecs
Oct 23 01:06:56 glarchie kernel: PM: late suspend of devices complete after 0.228 msecs
Oct 23 01:06:56 glarchie kernel: ehci_hcd 0000:00:1d.0: wake-up capability enabled by ACPI
Oct 23 01:06:56 glarchie kernel: PM: noirq suspend of devices complete after 56.335 msecs
Oct 23 01:06:56 glarchie kernel: ACPI: Preparing to enter system sleep state S3
Oct 23 01:06:56 glarchie kernel: PM: Saving platform NVS memory
Oct 23 01:06:56 glarchie kernel: Disabling non-boot CPUs ...
Oct 23 01:06:56 glarchie kernel: smpboot: CPU 1 is now offline
Oct 23 01:06:56 glarchie kernel: smpboot: CPU 2 is now offline
Oct 23 01:06:56 glarchie kernel: smpboot: CPU 3 is now offline
Oct 23 01:06:56 glarchie kernel: Extended CMOS year: 2000
Oct 23 01:06:56 glarchie kernel: ACPI: Low-level resume complete
Oct 23 01:06:56 glarchie kernel: PM: Restoring platform NVS memory
Oct 23 01:06:56 glarchie kernel: Extended CMOS year: 2000
Oct 23 01:06:56 glarchie kernel: Enabling non-boot CPUs ...
Oct 23 01:06:56 glarchie kernel: smpboot: Booting Node 0 Processor 1 APIC 0x4
Oct 23 01:06:56 glarchie kernel: CPU1 is up
Oct 23 01:06:56 glarchie kernel: smpboot: Booting Node 0 Processor 2 APIC 0x1
Oct 23 01:06:56 glarchie kernel: CPU2 is up
Oct 23 01:06:56 glarchie kernel: smpboot: Booting Node 0 Processor 3 APIC 0x5
Oct 23 01:06:56 glarchie kernel: CPU3 is up
Oct 23 01:06:56 glarchie kernel: ACPI: Waking up from system sleep state S3
Oct 23 01:06:56 glarchie kernel: ehci_hcd 0000:00:1d.0: wake-up capability disabled by ACPI
Oct 23 01:06:56 glarchie kernel: PM: noirq resume of devices complete after 106.054 msecs
Oct 23 01:06:56 glarchie kernel: PM: early resume of devices complete after 0.110 msecs
Oct 23 01:06:56 glarchie kernel: i915 0000:00:02.0: setting latency timer to 64
Oct 23 01:06:56 glarchie kernel: ehci_hcd 0000:00:1a.0: setting latency timer to 64
Oct 23 01:06:56 glarchie kernel: mei 0000:00:16.0: irq 47 for MSI/MSI-X
Oct 23 01:06:56 glarchie kernel: snd_hda_intel 0000:00:1b.0: irq 49 for MSI/MSI-X
Oct 23 01:06:56 glarchie kernel: ehci_hcd 0000:00:1d.0: setting latency timer to 64
Oct 23 01:06:56 glarchie kernel: pci 0000:00:1e.0: setting latency timer to 64
Oct 23 01:06:56 glarchie kernel: ahci 0000:00:1f.2: setting latency timer to 64
Oct 23 01:06:56 glarchie kernel: snd_hda_intel 0000:01:00.1: enabling device (0000 -> 0002)
Oct 23 01:06:56 glarchie kernel: mei 0000:00:16.0: wd: failed to find the client
Oct 23 01:06:56 glarchie kernel: r8169 0000:13:00.0: eth0: link down
Oct 23 01:06:56 glarchie kernel: usb 2-1.8: reset high-speed USB device number 3 using ehci_hcd
Oct 23 01:06:56 glarchie systemd[1]: Service bluetooth.target is not needed anymore. Stopping.
Oct 23 01:06:56 glarchie systemd[1]: Stopping Bluetooth.
Oct 23 01:06:56 glarchie systemd[1]: Stopped target Bluetooth.
Oct 23 01:06:56 glarchie kernel: ata4: SATA link down (SStatus 0 SControl 300)
Oct 23 01:06:56 glarchie kernel: ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
Oct 23 01:06:56 glarchie kernel: ata3: SATA link down (SStatus 0 SControl 300)
Oct 23 01:06:56 glarchie kernel: ata6: SATA link down (SStatus 0 SControl 300)
Oct 23 01:06:56 glarchie kernel: ata5: SATA link down (SStatus 0 SControl 300)
Oct 23 01:06:56 glarchie kernel: usb 1-1.1: reset full-speed USB device number 3 using ehci_hcd
Oct 23 01:06:56 glarchie kernel: ata2.00: configured for UDMA/100
Oct 23 01:06:56 glarchie kernel: usb 1-1.1.1: reset full-speed USB device number 4 using ehci_hcd
Oct 23 01:06:56 glarchie kernel: usb 1-1.1.2: reset full-speed USB device number 5 using ehci_hcd
Oct 23 01:06:56 glarchie kernel: ata1: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Oct 23 01:06:56 glarchie kernel: ata1.00: ACPI cmd ef/5a:00:00:00:00:a0 (SET FEATURES) succeeded
Oct 23 01:06:56 glarchie kernel: ata1.00: ACPI cmd 00/00:00:00:00:00:a0 (NOP) rejected by device (Stat=0x51 Err=0x04)
Oct 23 01:06:56 glarchie kernel: ata1.00: configured for UDMA/133
Oct 23 01:06:56 glarchie kernel: sd 0:0:0:0: [sda] Starting disk
Oct 23 01:06:56 glarchie kernel: azx_single_send_cmd: 589 callbacks suppressed
Oct 23 01:06:56 glarchie kernel: azx_single_send_cmd: 791 callbacks suppressed
Oct 23 01:06:56 glarchie kernel: azx_single_send_cmd: 789 callbacks suppressed
Oct 23 01:06:56 glarchie kernel: azx_single_send_cmd: 789 callbacks suppressed
Oct 23 01:06:56 glarchie kernel: PM: resume of devices complete after 20607.166 msecs
Oct 23 01:06:56 glarchie kernel: PM: Finishing wakeup.
Oct 23 01:06:56 glarchie kernel: usb 1-1.1.3: USB disconnect, device number 10
Oct 23 01:06:56 glarchie kernel: Restarting tasks ... done.
Oct 23 01:06:56 glarchie kernel: video LNXVIDEO:00: Restoring backlight state
Oct 23 01:06:56 glarchie kernel: video LNXVIDEO:01: Restoring backlight state
Oct 23 01:06:56 glarchie kernel: bbswitch: disabling discrete graphics
Oct 23 01:06:56 glarchie kernel: bbswitch: Result of _DSM call for OFF: 00000000
Oct 23 01:06:56 glarchie systemd-sleep[7119]: System resumed.

And this is from kernel 3.0.46-1 LTS:

Oct 23 13:41:33 glarchie systemd[1]: Starting Sleep.
Oct 23 13:41:33 glarchie systemd[1]: Reached target Sleep.
Oct 23 13:41:33 glarchie systemd[1]: Starting Suspend...
Oct 23 13:41:33 glarchie systemd-sleep[1666]: /usr/lib/systemd/system-sleep/notify-upower.sh exited with exit status 1.
Oct 23 13:41:33 glarchie systemd-sleep[1666]: Suspending system...
Oct 23 13:41:46 glarchie acpid[550]: client 1277[0:0] has disconnected
Oct 23 13:41:46 glarchie bluetoothd[519]: bluetoothd[519]: HCI dev 0 down
Oct 23 13:41:46 glarchie bluetoothd[519]: bluetoothd[519]: Adapter /org/bluez/519/hci0 has been disabled
Oct 23 13:41:46 glarchie bluetoothd[519]: HCI dev 0 down
Oct 23 13:41:46 glarchie bluetoothd[519]: Adapter /org/bluez/519/hci0 has been disabled
Oct 23 13:41:46 glarchie systemd-sleep[1666]: System resumed.
Oct 23 13:41:46 glarchie logger[1770]: AC unpluged
Oct 23 13:41:46 glarchie systemd[1]: Started Suspend.
Oct 23 13:41:46 glarchie systemd[1]: Service sleep.target is not needed anymore. Stopping.
Oct 23 13:41:46 glarchie systemd[1]: Stopping Sleep.
Oct 23 13:41:46 glarchie systemd[1]: Stopped target Sleep.
Oct 23 13:41:46 glarchie systemd[1]: Starting Suspend.
Oct 23 13:41:46 glarchie systemd[1]: Reached target Suspend.

I honestly don't know how to debug this. Did anyone else notice this delay during resume with kernel 3.6?

Thanks,

Fedes

Member

From: Buenos Aires, Argentina

Registered: 2012-10-23

Posts: 36

Re: Resume from sleep to RAM slow (takes 20 seconds) with kernel 3.6

So, I have just downgraded to the latest 3.5 kernel (3.5.5-1-ARCH kernel) from ARM repos, and the resume takes only a few seconds, compared to 3.6. So, for me, I'm not seeing power issues like other users in 3.6 with my laptop, but I am seeing a long delay in the resume cycle from sleep to RAM.

Oct 24 11:25:07 glarchie kernel: ACPI: Preparing to enter system sleep state S3
Oct 24 11:25:07 glarchie kernel: PM: Saving platform NVS memory
Oct 24 11:25:07 glarchie kernel: Disabling non-boot CPUs ...
Oct 24 11:25:07 glarchie kernel: CPU 1 is now offline
Oct 24 11:25:07 glarchie kernel: CPU 2 is now offline
Oct 24 11:25:07 glarchie kernel: CPU 3 is now offline
Oct 24 11:25:07 glarchie kernel: Extended CMOS year: 2000
Oct 24 11:25:07 glarchie kernel: ACPI: Low-level resume complete
Oct 24 11:25:07 glarchie kernel: PM: Restoring platform NVS memory
Oct 24 11:25:07 glarchie kernel: Extended CMOS year: 2000
Oct 24 11:25:07 glarchie kernel: Enabling non-boot CPUs ...
Oct 24 11:25:07 glarchie kernel: Booting Node 0 Processor 1 APIC 0x4
Oct 24 11:25:07 glarchie kernel: CPU1 is up
Oct 24 11:25:07 glarchie kernel: Booting Node 0 Processor 2 APIC 0x1
Oct 24 11:25:07 glarchie kernel: CPU2 is up
Oct 24 11:25:07 glarchie kernel: Booting Node 0 Processor 3 APIC 0x5
Oct 24 11:25:07 glarchie kernel: CPU3 is up
Oct 24 11:25:07 glarchie kernel: ACPI: Waking up from system sleep state S3
Oct 24 11:25:07 glarchie kernel: ehci_hcd 0000:00:1d.0: >wake-up capability disabled by ACPI
Oct 24 11:25:07 glarchie kernel: PM: noirq resume of devices complete after 5.564 msecs
Oct 24 11:25:07 glarchie kernel: PM: early resume of devices complete after 0.255 msecs
Oct 24 11:25:07 glarchie kernel: i915 0000:00:02.0: >setting latency timer to 64
Oct 24 11:25:07 glarchie kernel: ehci_hcd 0000:00:1a.0: >setting latency timer to 64
Oct 24 11:25:07 glarchie kernel: ehci_hcd 0000:00:1d.0: >setting latency timer to 64
Oct 24 11:25:07 glarchie kernel: mei 0000:00:16.0: >irq 48 for MSI/MSI-X
Oct 24 11:25:07 glarchie kernel: pci 0000:00:1e.0: >setting latency timer to 64
Oct 24 11:25:07 glarchie kernel: snd_hda_intel 0000:00:1b.0: >irq 49 for MSI/MSI-X
Oct 24 11:25:07 glarchie kernel: ahci 0000:00:1f.2: >setting latency timer to 64
Oct 24 11:25:07 glarchie kernel: mei 0000:00:16.0: >wd: failed to find the client
Oct 24 11:25:07 glarchie kernel: usb 2-1.8: >reset high-speed USB device number 3 using ehci_hcd
Oct 24 11:25:07 glarchie kernel: ata3: SATA link down (SStatus 0 SControl 300)
Oct 24 11:25:07 glarchie kernel: ata4: SATA link down (SStatus 0 SControl 300)
Oct 24 11:25:07 glarchie kernel: ata6: SATA link down (SStatus 0 SControl 300)
Oct 24 11:25:07 glarchie kernel: ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
Oct 24 11:25:07 glarchie kernel: ata5: SATA link down (SStatus 0 SControl 300)
Oct 24 11:25:07 glarchie kernel: usb 1-1.1: >reset full-speed USB device number 3 using ehci_hcd
Oct 24 11:25:07 glarchie kernel: ata2.00: configured for UDMA/100
Oct 24 11:25:07 glarchie kernel: usb 1-1.1.1: >reset full-speed USB device number 4 using ehci_hcd
Oct 24 11:25:07 glarchie kernel: usb 1-1.1.2: >reset full-speed USB device number 5 using ehci_hcd
Oct 24 11:25:07 glarchie kernel: ata1: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Oct 24 11:25:07 glarchie kernel: ata1.00: ACPI cmd ef/5a:00:00:00:00:a0 (SET FEATURES) succeeded
Oct 24 11:25:07 glarchie kernel: ata1.00: ACPI cmd 00/00:00:00:00:00:a0 (NOP) rejected by device (Stat=0x51 Err=0x04)
Oct 24 11:25:07 glarchie kernel: ata1.00: configured for UDMA/133
Oct 24 11:25:07 glarchie kernel: sd 0:0:0:0: >[sda] Starting disk
Oct 24 11:25:07 glarchie kernel: PM: resume of devices complete after 2707.176 msecs

According the logs, it took 2.7 seconds to resume, while with kernel 3.6 takes 20 seconds. I wonder if this is related to the i915 driver, that is causing power consumption issues as well for some users.

Last edited by Fedes (2012-10-24 14:39:57)

RichardCain2

Member

Registered: 2012-04-23

Posts: 5

Re: Resume from sleep to RAM slow (takes 20 seconds) with kernel 3.6

I have also found this problem, that the system is slow (about 20s also) to resume from suspend.  I've got kernel 3.6.3-1 but as I'm still finding my way around Arch, I'll just live with it for now.

Fedes

Member

From: Buenos Aires, Argentina

Registered: 2012-10-23

Posts: 36

Re: Resume from sleep to RAM slow (takes 20 seconds) with kernel 3.6

Thanks! Somehow, I feel better knowing that I'm not the only one

live4fun

Member

Registered: 2012-10-30

Posts: 1

Re: Resume from sleep to RAM slow (takes 20 seconds) with kernel 3.6

It might not help you but I have the same problem here. So we are in the same boat. As I just installed arch 3 days ago I might not be able to come up with an solution but if i can collect debugging information let me know.

Hope somebody figures that out. I was already under the impression my notebooks power button might be going south.