Trace what is causing *unwanted* Suspends?

eduncan911 · 2016-01-29 13:51:15

I have an old install of arch (kept updated, it's on Tip now and all packages) on this laptop. But for the life of me, i can't remember what all I setup to suspend.

I think I have conflicting services forcing sleep after all the upgrades.

How would I trace what is causing suspends in journalctl? I've been eye balling it for days and can't seem to trace down what is causing suspend. Systemd just announces "starting suspend" as the only key. There doesn't seem to be any Dbus messages related to forcing suspend. But, I can't find anything in systemd that is forcing a suspend. And, the suspend seems to be triggered with Gnome/GDM actions.

Arch (on tip)
GDM/Gnome 3.18.2

The system is going to sleep at unwanted times:

* When switching users, the system goes to sleep. Powering back on shows me my desktop, and then it logs me out and returns me to the GDM screen.

^- this is the most tale-tale sign i can find that something is suspending the system before Gnome even has the ability to log me out, or even attempt to lock my screen or try to display the GDM.

* When selecting Log Off, the system goes to sleep - not returning to GDM. Powering back on has me at the GDM login screen.

* When Blank Display is triggered, on either BAT or AC, the system goes to Sleep instead of just blanking the display. When powering back on, I am often times still at the desktop - and the system goes right back to sleep again a second or two later. Waking up a 2nd time has me at the "Slide to Unlock" screen.

* On reboot, sometimes the system logs me off and goes into suspend. Other times, it does reboot.

My goal/objective overall is:

GNOME ON AC
* Blank display after 20 minutes.
* Sleep after 2 hours.

GNOME ON BAT
* Blank display after 2 minutes, unless something is fullscreen or app blocks suspend requests.
* Sleep after 5 minutes.

GDM ON AC/BAT
* Blank display/Sleep after 30 seconds

The gnome sleep settings seem to have changed in dconf over time. They are now:

org.gnome.settings-daemon.plugins.power
- sleep-inactive-ac-timeout 1200
- sleep-inactive-ac-type blank (setting to nothing keeps it from suspending, but also no longer "blanks" the screen)
- sleep-inactive-battery-timeout 120
- sleep-inactive-battery-type blank

# systemctl status suspend.target
● suspend.target - Suspend
   Loaded: loaded (/usr/lib/systemd/system/suspend.target; static; vendor preset: disabled)
   Active: inactive (dead)
     Docs: man:systemd.special(7)

There is only 1 sleep.wants, and it is a suspend-to-hibernate timer service that after 6 hours it wakes the system up and puts it into hibernate. I have verified this is working fine.

Thanks!

Last edited by eduncan911 (2016-01-29 15:19:38)

eduncan911 · 2016-01-29 15:17:36

A bit more monitoring of journalctl...

During the times of "sleep" triggited by inactivity, it goes to sleep. I press a button to wake up, it wakes up and flashes the display screen for ONE second and goes right back to sleep, all I can see are kernel messages for suspending... Note the "1 second" statement as this is shown in the logs below.

During the first unwanted sleep, which should not be suspending (it should remain on):

(a bunch of gnome error messages, but nothing tale-tale that it is causing sleep) 
Jan 29 09:52:16 kodiak systemd[1]: Reached target Sleep.
Jan 29 09:52:16 kodiak systemd[1]: Starting Suspend...
Jan 29 09:52:16 kodiak systemd-sleep[2859]: Suspending system...

I wait about 25 secondsd and wake it up..

Note that several of the messages may belong to the previous sleep attempt. Maybe there was a flush of messages on resume? Also note that it tries to go right back to sleep, if that's not the case:

Jan 29 09:52:43 kodiak kernel: PM: Syncing filesystems ... done.
Jan 29 09:52:43 kodiak kernel: PM: Preparing system for sleep (mem)
Jan 29 09:52:43 kodiak kernel: Freezing user space processes ... (elapsed 0.326 seconds) done.
Jan 29 09:52:43 kodiak kernel: Freezing remaining freezable tasks ... (elapsed 0.001 seconds) done.
Jan 29 09:52:43 kodiak kernel: PM: Suspending system (mem)
Jan 29 09:52:43 kodiak kernel: Suspending console(s) (use no_console_suspend to debug)
Jan 29 09:52:43 kodiak kernel: sd 0:0:0:0: [sda] Synchronizing SCSI cache
Jan 29 09:52:43 kodiak kernel: sd 0:0:0:0: [sda] Stopping disk
Jan 29 09:52:43 kodiak kernel: PM: suspend of devices complete after 383.020 msecs
Jan 29 09:52:43 kodiak kernel: PM: late suspend of devices complete after 13.377 msecs
Jan 29 09:52:43 kodiak kernel: ehci-pci 0000:00:1d.0: System wakeup enabled by ACPI
Jan 29 09:52:43 kodiak kernel: ehci-pci 0000:00:1a.0: System wakeup enabled by ACPI
Jan 29 09:52:43 kodiak kernel: xhci_hcd 0000:00:14.0: System wakeup enabled by ACPI
Jan 29 09:52:43 kodiak kernel: PM: noirq suspend of devices complete after 13.271 msecs
Jan 29 09:52:43 kodiak kernel: ACPI: Preparing to enter system sleep state S3
Jan 29 09:52:43 kodiak kernel: ACPI : EC: EC stopped
Jan 29 09:52:43 kodiak kernel: PM: Saving platform NVS memory
Jan 29 09:52:43 kodiak kernel: Disabling non-boot CPUs ...
Jan 29 09:52:43 kodiak kernel: smpboot: CPU 1 is now offline
Jan 29 09:52:43 kodiak kernel: smpboot: CPU 2 is now offline
Jan 29 09:52:43 kodiak kernel: smpboot: CPU 3 is now offline
Jan 29 09:52:43 kodiak kernel: ACPI: Low-level resume complete
Jan 29 09:52:43 kodiak kernel: ACPI : EC: EC started
Jan 29 09:52:43 kodiak kernel: PM: Restoring platform NVS memory
Jan 29 09:52:43 kodiak kernel: Enabling non-boot CPUs ...
Jan 29 09:52:43 kodiak kernel: x86: Booting SMP configuration:
Jan 29 09:52:43 kodiak kernel: smpboot: Booting Node 0 Processor 1 APIC 0x1
Jan 29 09:52:43 kodiak kernel:  cache: parent cpu1 should not be sleeping
Jan 29 09:52:43 kodiak kernel: CPU1 is up
Jan 29 09:52:43 kodiak kernel: smpboot: Booting Node 0 Processor 2 APIC 0x2
Jan 29 09:52:43 kodiak kernel:  cache: parent cpu2 should not be sleeping
Jan 29 09:52:43 kodiak kernel: CPU2 is up
Jan 29 09:52:43 kodiak kernel: smpboot: Booting Node 0 Processor 3 APIC 0x3
Jan 29 09:52:43 kodiak kernel:  cache: parent cpu3 should not be sleeping
Jan 29 09:52:43 kodiak kernel: CPU3 is up
Jan 29 09:52:43 kodiak kernel: ACPI: Waking up from system sleep state S3
Jan 29 09:52:43 kodiak kernel: ehci-pci 0000:00:1a.0: System wakeup disabled by ACPI
Jan 29 09:52:43 kodiak kernel: ehci-pci 0000:00:1d.0: System wakeup disabled by ACPI
Jan 29 09:52:43 kodiak kernel: xhci_hcd 0000:00:14.0: System wakeup disabled by ACPI
Jan 29 09:52:43 kodiak kernel: PM: noirq resume of devices complete after 15.156 msecs
Jan 29 09:52:43 kodiak kernel: PM: early resume of devices complete after 0.349 msecs
Jan 29 09:52:43 kodiak kernel: rtc_cmos 00:02: System wakeup disabled by ACPI
Jan 29 09:52:43 kodiak kernel: sd 0:0:0:0: [sda] Starting disk
Jan 29 09:52:43 kodiak kernel: usb 2-1.6: reset full-speed USB device number 5 using ehci-pci
Jan 29 09:52:43 kodiak kernel: usb 1-1.1: reset full-speed USB device number 3 using ehci-pci
Jan 29 09:52:43 kodiak kernel: ata1: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
Jan 29 09:52:43 kodiak kernel: ata1.00: ACPI cmd ef/02:00:00:00:00:a0 (SET FEATURES) succeeded
Jan 29 09:52:43 kodiak kernel: ata1.00: ACPI cmd f5/00:00:00:00:00:a0 (SECURITY FREEZE LOCK) filtered out
Jan 29 09:52:43 kodiak kernel: ata1.00: ACPI cmd ef/10:03:00:00:00:a0 (SET FEATURES) filtered out
Jan 29 09:52:43 kodiak kernel: ata1.00: ACPI cmd ef/02:00:00:00:00:a0 (SET FEATURES) succeeded
Jan 29 09:52:43 kodiak kernel: ata1.00: ACPI cmd f5/00:00:00:00:00:a0 (SECURITY FREEZE LOCK) filtered out
Jan 29 09:52:43 kodiak kernel: ata1.00: ACPI cmd ef/10:03:00:00:00:a0 (SET FEATURES) filtered out
Jan 29 09:52:43 kodiak kernel: ata1.00: configured for UDMA/100
Jan 29 09:52:43 kodiak kernel: usb 2-1.5: reset full-speed USB device number 4 using ehci-pci
Jan 29 09:52:43 kodiak kernel: usb 1-1.4: reset full-speed USB device number 4 using ehci-pci
Jan 29 09:52:43 kodiak kernel: psmouse serio1: synaptics: queried max coordinates: x [..5052], y [..3598]
Jan 29 09:52:43 kodiak kernel: usb 2-1.3: reset high-speed USB device number 3 using ehci-pci
Jan 29 09:52:43 kodiak kernel: usb 1-1.6: reset high-speed USB device number 5 using ehci-pci
Jan 29 09:52:43 kodiak kernel: psmouse serio1: synaptics: queried min coordinates: x [1024..], y [1024..]
Jan 29 09:52:43 kodiak kernel: psmouse serio1: synaptics: quirked min/max coordinates: x [1024..5052], y [2258..4832]
Jan 29 09:52:43 kodiak kernel: PM: resume of devices complete after 926.843 msecs
Jan 29 09:52:43 kodiak kernel: PM: Finishing wakeup.
Jan 29 09:52:43 kodiak kernel: Restarting tasks ... done.
Jan 29 09:52:43 kodiak kernel: Bluetooth: hci0: BCM: chip id 63
Jan 29 09:52:43 kodiak kernel: Bluetooth: hci0: BCM20702A1 (001.002.014) build 0000
Jan 29 09:52:43 kodiak kernel: bluetooth hci0: Direct firmware load for brcm/BCM20702A1-0a5c-21e6.hcd failed with error -2
Jan 29 09:52:43 kodiak kernel: Bluetooth: hci0: BCM: Patch brcm/BCM20702A1-0a5c-21e6.hcd not found
Jan 29 09:52:43 kodiak systemd[1]: Time has been changed

And after it wakes up, and goes right back to sleep again after a second.

Notice the time difference, just 1 second after it woke up:

Jan 29 09:52:44 kodiak systemd[1]: Reached target Sleep.
Jan 29 09:52:44 kodiak systemd[1]: Starting Suspend...
Jan 29 09:52:44 kodiak systemd-sleep[3046]: Suspending system...

And when I try to wake it up a 2nd time...

Jan 29 09:52:50 kodiak kernel: PM: Syncing filesystems ... done.
Jan 29 09:52:50 kodiak kernel: PM: Preparing system for sleep (mem)
Jan 29 09:52:50 kodiak kernel: Freezing user space processes ... (elapsed 0.024 seconds) done.
Jan 29 09:52:50 kodiak kernel: Freezing remaining freezable tasks ... (elapsed 0.001 seconds) done.
Jan 29 09:52:50 kodiak kernel: PM: Suspending system (mem)
Jan 29 09:52:50 kodiak kernel: Suspending console(s) (use no_console_suspend to debug)
Jan 29 09:52:50 kodiak kernel: sd 0:0:0:0: [sda] Synchronizing SCSI cache
Jan 29 09:52:50 kodiak kernel: sd 0:0:0:0: [sda] Stopping disk
Jan 29 09:52:50 kodiak kernel: PM: suspend of devices complete after 383.719 msecs
Jan 29 09:52:50 kodiak kernel: PM: late suspend of devices complete after 13.369 msecs
Jan 29 09:52:50 kodiak kernel: ehci-pci 0000:00:1d.0: System wakeup enabled by ACPI
Jan 29 09:52:50 kodiak kernel: ehci-pci 0000:00:1a.0: System wakeup enabled by ACPI
Jan 29 09:52:50 kodiak kernel: xhci_hcd 0000:00:14.0: System wakeup enabled by ACPI
Jan 29 09:52:50 kodiak kernel: PM: noirq suspend of devices complete after 13.232 msecs
Jan 29 09:52:50 kodiak kernel: ACPI: Preparing to enter system sleep state S3
Jan 29 09:52:50 kodiak kernel: ACPI : EC: EC stopped
Jan 29 09:52:50 kodiak kernel: PM: Saving platform NVS memory
Jan 29 09:52:50 kodiak kernel: Disabling non-boot CPUs ...
Jan 29 09:52:50 kodiak kernel: smpboot: CPU 1 is now offline
Jan 29 09:52:50 kodiak kernel: smpboot: CPU 2 is now offline
Jan 29 09:52:50 kodiak kernel: smpboot: CPU 3 is now offline
Jan 29 09:52:50 kodiak kernel: ACPI: Low-level resume complete
Jan 29 09:52:50 kodiak kernel: ACPI : EC: EC started
Jan 29 09:52:50 kodiak kernel: PM: Restoring platform NVS memory
Jan 29 09:52:50 kodiak kernel: Enabling non-boot CPUs ...
Jan 29 09:52:50 kodiak kernel: x86: Booting SMP configuration:
Jan 29 09:52:50 kodiak kernel: smpboot: Booting Node 0 Processor 1 APIC 0x1
Jan 29 09:52:50 kodiak kernel:  cache: parent cpu1 should not be sleeping
Jan 29 09:52:50 kodiak kernel: CPU1 is up
Jan 29 09:52:50 kodiak kernel: smpboot: Booting Node 0 Processor 2 APIC 0x2
Jan 29 09:52:50 kodiak kernel:  cache: parent cpu2 should not be sleeping
Jan 29 09:52:50 kodiak kernel: CPU2 is up
Jan 29 09:52:50 kodiak kernel: smpboot: Booting Node 0 Processor 3 APIC 0x3
Jan 29 09:52:50 kodiak kernel:  cache: parent cpu3 should not be sleeping
Jan 29 09:52:50 kodiak kernel: CPU3 is up
Jan 29 09:52:50 kodiak kernel: ACPI: Waking up from system sleep state S3
Jan 29 09:52:50 kodiak kernel: ehci-pci 0000:00:1d.0: System wakeup disabled by ACPI
Jan 29 09:52:50 kodiak kernel: ehci-pci 0000:00:1a.0: System wakeup disabled by ACPI
Jan 29 09:52:50 kodiak kernel: xhci_hcd 0000:00:14.0: System wakeup disabled by ACPI
Jan 29 09:52:50 kodiak kernel: PM: noirq resume of devices complete after 15.248 msecs
Jan 29 09:52:50 kodiak kernel: PM: early resume of devices complete after 0.459 msecs
Jan 29 09:52:50 kodiak kernel: rtc_cmos 00:02: System wakeup disabled by ACPI
Jan 29 09:52:50 kodiak kernel: sd 0:0:0:0: [sda] Starting disk
Jan 29 09:52:50 kodiak kernel: usb 1-1.1: reset full-speed USB device number 3 using ehci-pci
Jan 29 09:52:50 kodiak kernel: usb 2-1.5: reset full-speed USB device number 4 using ehci-pci
Jan 29 09:52:50 kodiak kernel: ata1: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
Jan 29 09:52:50 kodiak kernel: ata1.00: ACPI cmd ef/02:00:00:00:00:a0 (SET FEATURES) succeeded
Jan 29 09:52:50 kodiak kernel: ata1.00: ACPI cmd f5/00:00:00:00:00:a0 (SECURITY FREEZE LOCK) filtered out
Jan 29 09:52:50 kodiak kernel: ata1.00: ACPI cmd ef/10:03:00:00:00:a0 (SET FEATURES) filtered out
Jan 29 09:52:50 kodiak kernel: ata1.00: ACPI cmd ef/02:00:00:00:00:a0 (SET FEATURES) succeeded
Jan 29 09:52:50 kodiak kernel: ata1.00: ACPI cmd f5/00:00:00:00:00:a0 (SECURITY FREEZE LOCK) filtered out
Jan 29 09:52:50 kodiak kernel: ata1.00: ACPI cmd ef/10:03:00:00:00:a0 (SET FEATURES) filtered out
Jan 29 09:52:50 kodiak kernel: ata1.00: configured for UDMA/100
Jan 29 09:52:50 kodiak kernel: usb 2-1.3: reset high-speed USB device number 3 using ehci-pci
Jan 29 09:52:50 kodiak kernel: usb 1-1.6: reset high-speed USB device number 5 using ehci-pci
Jan 29 09:52:50 kodiak kernel: psmouse serio1: synaptics: queried max coordinates: x [..5052], y [..3598]
Jan 29 09:52:50 kodiak kernel: psmouse serio1: synaptics: queried min coordinates: x [1024..], y [1024..]
Jan 29 09:52:50 kodiak kernel: psmouse serio1: synaptics: quirked min/max coordinates: x [1024..5052], y [2258..4832]
Jan 29 09:52:50 kodiak kernel: usb 2-1.6: reset full-speed USB device number 5 using ehci-pci
Jan 29 09:52:50 kodiak kernel: usb 1-1.4: reset full-speed USB device number 4 using ehci-pci
Jan 29 09:52:50 kodiak kernel: PM: resume of devices complete after 800.024 msecs
Jan 29 09:52:50 kodiak kernel: PM: Finishing wakeup.
Jan 29 09:52:50 kodiak kernel: Restarting tasks ... 
Jan 29 09:52:50 kodiak kernel: Bluetooth: hci0: BCM: chip id 63
Jan 29 09:52:50 kodiak kernel: done.
Jan 29 09:52:50 kodiak kernel: Bluetooth: hci0: BCM20702A1 (001.002.014) build 0000
Jan 29 09:52:50 kodiak kernel: bluetooth hci0: Direct firmware load for brcm/BCM20702A1-0a5c-21e6.hcd failed with error -2
Jan 29 09:52:50 kodiak kernel: Bluetooth: hci0: BCM: Patch brcm/BCM20702A1-0a5c-21e6.hcd not found
Jan 29 09:52:50 kodiak systemd[1]: Time has been changed

So yeah, there seems to be a flushing of the log messages on resume; so, the kernel's sleep messages intermix with the kernel's resume messages.

Before all of this, at the same time down to the second, what starts the "suspend" log messages is a 100+ gnome-session errors and warnings, mostly that i cannot bind to a ID or alike. Nothing that is a tale-tale of what is causing/starting the sleep that I can see.

Any help would be appreciated tracking down what is causing unwanted sleeps. The most annoying is when the screen blanks and on Switching Users, which I do a lot for my kid.

charli3 · 2016-01-29 17:37:52

I'm not sure I understand fully what the behavior is...

So without any input from you your system suspends unprompted and when in use? For example when you log out and try to login again under a different user? Or are you doing something to suspend the system such as clicking suspend in gnome but then upon resume it cycles suspend a few times? Or both?

Have you tried

$ systemctl suspend

to see if it behaves the same way upon resume?

Last edited by charli3 (2016-01-29 17:38:17)

eduncan911 · 2016-01-29 22:19:40

Thanks for replying and sorry i wasn't clear.

The system suspends both when unprompted, and when I issue an action. To consolidate the original issues:

(My actions that aren't supposed to make it go to sleep)
* When switching users, the system goes to sleep.
* When selecting Log Off, the system goes to sleep - not returning to GDM immediately.
* On reboot, sometimes the system logs me off and goes into suspend. Other times, it does reboot.

(idle/no actions that makes it go to sleep when it is not supposed to)
* When Blank Display is triggered, on either BAT or AC, the system goes to Sleep instead of just blanking the display.
* On AC, there is nothing set to go to sleep in 2 minutes.. But yet, the system goes to sleep after 2 minutes. gnome settings are stated above: 20 minutes.

All the extract info was saying that when it does suspend, odd things happen when I "wake it up". For example, when I wake up from trying to Switch users, the screen actually shows me my desktop - which then logs me off. Remember, I did not tell it to suspend - I told it to just "Switch User." And remember, the desktop and "log off" process is shown/displayed only AFTER i resume it.

$ systemctl suspend

^- Just tried this and it provides some bit of extra logs. But, for the most part, it looks the same. I did notice it officially locks my screen, which is a first.. It typically has me on my desktop and only locks after i resume.

So, I would fathom that "systemctl suspend" actually is acting normally and properly without any of the other funny business. And, this may very well be Gnome related.

I just know anywhere else to look.

Last edited by eduncan911 (2016-01-29 22:21:21)

tangyuq · 2016-03-20 00:16:33

Any progress? I am having the same problem on with antergos on Lenovo Lavie Z 360 using gnome and gdm.

My attempt:
After I run:
sudo systemctl mask sleep.target suspend.target hibernate.target hybrid-sleep.target
if I log off gnome or lock screen, the screen goes to the boot log display. At this time, if I press ctrl + alt + f# to switch to tty, it keeps showing the boot log display while I can still type in the tty but it misses my key typing occasionally. It seems that there is some sort to event which is kept being firing in the background 1) when switching to gdm session/login screen, **OR** 2) when gnome going to lock screen (I highly suspect that it is the gnome going to lock screen causing the problem).

Last edited by tangyuq (2016-03-20 00:18:07)

WorMzy · 2016-03-20 00:34:27

tangyuq, please ask on the Antergos forums. Your distribution may configure things differently to Arch, so we are unable to help with any Antergos-specific problems. Feel free to continue to monitor this thread to see if a distro-agnostic solution presents itself, however.

https://wiki.archlinux.org/index.php/Fo … pport_ONLY

Arch Linux

#1 2016-01-29 13:51:15