[SOLVED] Slow suspend with systemd 220

jlindgren · 2015-05-31 19:11:49

I have my laptop configured to suspend when the power button is pressed ("HandlePowerKey=suspend" in /etc/systemd/logind.conf). This was working fine up to systemd 219. After updating to version 220, I am seeing a 5 second delay between the time I press the power button and the time the system suspends. It's not a complete hang; the whole system (mouse, keyboard, XFCE desktop) is still usable for those 5 seconds.

Oddly, "systemctl suspend" still suspends the system immediately.

The system log (journalctl) from 219:

May 31 14:41:45 pandorica systemd-logind[202]: Power key pressed.
May 31 14:41:45 pandorica systemd-logind[202]: Suspending...
May 31 14:41:45 pandorica NetworkManager[228]: <info>  sleep requested (sleeping: no  enabled: yes)
May 31 14:41:45 pandorica NetworkManager[228]: <info>  sleeping...
May 31 14:41:45 pandorica NetworkManager[228]: <info>  (enp12s0): device state change: unavailable -> unmanaged (reason 'sleeping') [20 10 37]
May 31 14:41:45 pandorica NetworkManager[228]: <info>  (wlp2s0): device state change: activated -> unmanaged (reason 'sleeping') [100 10 37]
May 31 14:41:45 pandorica NetworkManager[228]: <info>  (wlp2s0): deactivating device (reason 'sleeping') [37]
May 31 14:41:45 pandorica kernel: IPv6: ADDRCONF(NETDEV_UP): enp12s0: link is not ready
May 31 14:41:45 pandorica NetworkManager[228]: <info>  (wlp2s0): canceled DHCP transaction, DHCP client pid 402
May 31 14:41:45 pandorica NetworkManager[228]: <info>  (wlp2s0): DHCPv4 state changed bound -> done
May 31 14:41:45 pandorica kernel: wlp2s0: deauthenticating from 74:9d:dc:00:6d:f9 by local choice (Reason: 3=DEAUTH_LEAVING)
May 31 14:41:45 pandorica kernel: cfg80211: Calling CRDA for country: US
May 31 14:41:45 pandorica NetworkManager[228]: <info>  NetworkManager state is now ASLEEP
May 31 14:41:45 pandorica kernel: IPv6: ADDRCONF(NETDEV_UP): wlp2s0: link is not ready
May 31 14:41:45 pandorica systemd[1]: Reached target Sleep.
May 31 14:41:45 pandorica systemd[1]: Starting Sleep.
May 31 14:41:45 pandorica systemd[1]: Starting Suspend...
May 31 14:41:45 pandorica systemd-sleep[494]: Suspending system...

And from 220:

May 31 14:39:45 pandorica systemd-logind[227]: Power key pressed.
May 31 14:39:45 pandorica systemd-logind[227]: Suspending...
May 31 14:39:45 pandorica NetworkManager[203]: <info>  sleep requested (sleeping: no  enabled: yes)
May 31 14:39:45 pandorica NetworkManager[203]: <info>  sleeping...
May 31 14:39:45 pandorica NetworkManager[203]: <info>  (enp12s0): device state change: unavailable -> unmanaged (reason 'sleeping') [20 10 37]
May 31 14:39:45 pandorica NetworkManager[203]: <info>  (wlp2s0): device state change: activated -> unmanaged (reason 'sleeping') [100 10 37]
May 31 14:39:45 pandorica NetworkManager[203]: <info>  (wlp2s0): deactivating device (reason 'sleeping') [37]
May 31 14:39:45 pandorica kernel: IPv6: ADDRCONF(NETDEV_UP): enp12s0: link is not ready
May 31 14:39:45 pandorica NetworkManager[203]: <info>  (wlp2s0): canceled DHCP transaction, DHCP client pid 639
May 31 14:39:45 pandorica NetworkManager[203]: <info>  (wlp2s0): DHCPv4 state changed bound -> done
May 31 14:39:45 pandorica avahi-daemon[692]: Withdrawing address record for 2602:306:335d:c680:6267:20ff:fe7b:acfc on wlp2s0.
May 31 14:39:45 pandorica avahi-daemon[692]: Registering new address record for fe80::6267:20ff:fe7b:acfc on wlp2s0.*.
May 31 14:39:45 pandorica avahi-daemon[692]: Withdrawing address record for fe80::6267:20ff:fe7b:acfc on wlp2s0.
May 31 14:39:45 pandorica avahi-daemon[692]: Withdrawing address record for 192.168.1.66 on wlp2s0.
May 31 14:39:45 pandorica avahi-daemon[692]: Leaving mDNS multicast group on interface wlp2s0.IPv4 with address 192.168.1.66.
May 31 14:39:45 pandorica kernel: wlp2s0: deauthenticating from 74:9d:dc:00:6d:f9 by local choice (Reason: 3=DEAUTH_LEAVING)
May 31 14:39:45 pandorica avahi-daemon[692]: Interface wlp2s0.IPv4 no longer relevant for mDNS.
May 31 14:39:45 pandorica kernel: cfg80211: Calling CRDA to update world regulatory domain
May 31 14:39:45 pandorica NetworkManager[203]: <info>  NetworkManager state is now ASLEEP
May 31 14:39:45 pandorica kernel: IPv6: ADDRCONF(NETDEV_UP): wlp2s0: link is not ready
May 31 14:39:45 pandorica dbus[204]: [system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispatcher.service'
May 31 14:39:45 pandorica systemd[1]: org.cups.cupsd.socket: Cannot add dependency job, ignoring: Unit org.cups.cupsd.socket failed to load: No such file or directory.
May 31 14:39:45 pandorica systemd[1]: Starting Network Manager Script Dispatcher Service...
May 31 14:39:45 pandorica dbus[204]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
May 31 14:39:45 pandorica systemd[1]: Started Network Manager Script Dispatcher Service.
May 31 14:39:50 pandorica systemd[1]: Reached target Sleep.
May 31 14:39:50 pandorica systemd[1]: Starting Sleep.
May 31 14:39:50 pandorica systemd[1]: Starting Suspend...
May 31 14:39:50 pandorica systemd-sleep[756]: Suspending system...

So from the previous log message, 5 seconds elapsed before "Reached target Sleep", but there is nothing in the log to indicate what caused the delay. How would I go about debugging this?

Last edited by jlindgren (2015-06-26 23:30:56)

mauritiusdadd · 2015-06-01 06:05:22

Same behaviour here. The culprit seems to be NetworManager, in fact if you stop its service

systemctl stop NetworkManager

then the machine sleeps almost instantly.

jlindgren · 2015-06-24 23:56:34

systemd bug reports:
https://bugs.archlinux.org/task/45450
https://github.com/systemd/systemd/issues/360

Arch Linux

#1 2015-05-31 19:11:49

[SOLVED] Slow suspend with systemd 220

#2 2015-06-01 06:05:22

Re: [SOLVED] Slow suspend with systemd 220

#3 2015-06-24 23:56:34

Re: [SOLVED] Slow suspend with systemd 220

Board footer