Arch Linux

ewanduck

Member

Registered: 2024-03-12

Posts: 1

System fails to suspend, returns control to user after ~20sec

Hi all, this is my first time posting so sorry if I don't include all that might be needed.
I've been trying to diagnose this issue and have had no luck so far.

Here is the journal:

Mar 15 11:33:05 satsuki systemd-logind[3600]: The system will suspend and later hibernate now!
Mar 15 11:33:05 satsuki NetworkManager[3549]: <info>  [1710516785.1134] manager: sleep: sleep requested (sleeping: no  enabled: yes)
Mar 15 11:33:05 satsuki NetworkManager[3549]: <info>  [1710516785.1144] device (enp0s13f0u1u3): state change: unavailable -> unmanaged (reason 'sleeping', sys-iface-state: 'managed')
Mar 15 11:33:05 satsuki NetworkManager[3549]: <info>  [1710516785.1286] device (4C:2E:5E:7E:70:F2): state change: disconnected -> unmanaged (reason 'sleeping', sys-iface-state: 'managed')
Mar 15 11:33:05 satsuki NetworkManager[3549]: <info>  [1710516785.1291] device (p2p-dev-wlo1): state change: disconnected -> unmanaged (reason 'sleeping', sys-iface-state: 'managed')
Mar 15 11:33:05 satsuki NetworkManager[3549]: <info>  [1710516785.1292] manager: NetworkManager state is now ASLEEP
Mar 15 11:33:05 satsuki NetworkManager[3549]: <info>  [1710516785.1294] device (wlo1): state change: activated -> deactivating (reason 'sleeping', sys-iface-state: 'managed')
Mar 15 11:33:05 satsuki sway[6832]: 01:30:34.000 [ERROR] [wlr] [backend/drm/atomic.c:73] connector DP-1: Atomic commit failed: Device or resource busy
Mar 15 11:33:05 satsuki systemd[1]: Starting Network Manager Script Dispatcher Service...
Mar 15 11:33:05 satsuki systemd[1]: Started Network Manager Script Dispatcher Service.
Mar 15 11:33:05 satsuki kernel: wlo1: deauthenticating from fc:5b:39:a1:bc:3f by local choice (Reason: 3=DEAUTH_LEAVING)
Mar 15 11:33:05 satsuki wpa_supplicant[4196]: wlo1: CTRL-EVENT-DISCONNECTED bssid=fc:5b:39:a1:bc:3f reason=3 locally_generated=1
Mar 15 11:33:05 satsuki wpa_supplicant[4196]: wlo1: CTRL-EVENT-DSCP-POLICY clear_all
Mar 15 11:33:05 satsuki NetworkManager[3549]: <info>  [1710516785.3089] device (wlo1): supplicant interface state: completed -> disconnected
Mar 15 11:33:05 satsuki NetworkManager[3549]: <info>  [1710516785.3090] device (wlo1): state change: deactivating -> disconnected (reason 'sleeping', sys-iface-state: 'managed')
Mar 15 11:33:05 satsuki avahi-daemon[3561]: Withdrawing address record for fe80::4b79:bd72:16c7:5ba7 on wlo1.
Mar 15 11:33:05 satsuki avahi-daemon[3561]: Leaving mDNS multicast group on interface wlo1.IPv6 with address fe80::4b79:bd72:16c7:5ba7.
Mar 15 11:33:05 satsuki NetworkManager[3549]: <info>  [1710516785.3093] dhcp4 (wlo1): canceled DHCP transaction
Mar 15 11:33:05 satsuki NetworkManager[3549]: <info>  [1710516785.3093] dhcp4 (wlo1): activation: beginning transaction (timeout in 45 seconds)
Mar 15 11:33:05 satsuki avahi-daemon[3561]: Interface wlo1.IPv6 no longer relevant for mDNS.
Mar 15 11:33:05 satsuki NetworkManager[3549]: <info>  [1710516785.3093] dhcp4 (wlo1): state changed no lease
Mar 15 11:33:05 satsuki avahi-daemon[3561]: Interface wlo1.IPv4 no longer relevant for mDNS.
Mar 15 11:33:05 satsuki avahi-daemon[3561]: Leaving mDNS multicast group on interface wlo1.IPv4 with address 100.82.46.226.
Mar 15 11:33:05 satsuki NetworkManager[3549]: <info>  [1710516785.3257] device (wlo1): set-hw-addr: set MAC address to 92:13:EA:12:4B:6F (scanning)
Mar 15 11:33:05 satsuki avahi-daemon[3561]: Withdrawing address record for 100.82.46.226 on wlo1.
Mar 15 11:33:05 satsuki avahi-daemon[3561]: Joining mDNS multicast group on interface wlo1.IPv4 with address 100.82.46.226.
Mar 15 11:33:05 satsuki avahi-daemon[3561]: New relevant interface wlo1.IPv4 for mDNS.
Mar 15 11:33:05 satsuki avahi-daemon[3561]: Registering new address record for 100.82.46.226 on wlo1.IPv4.
Mar 15 11:33:05 satsuki systemd-resolved[3167]: wlo1: Bus client set default route setting: no
Mar 15 11:33:05 satsuki systemd-resolved[3167]: wlo1: Bus client reset DNS server list.
Mar 15 11:33:05 satsuki systemd-resolved[3167]: Switching to fallback DNS server 1.1.1.1#cloudflare-dns.com.
Mar 15 11:33:05 satsuki avahi-daemon[3561]: Withdrawing address record for 100.82.46.226 on wlo1.
Mar 15 11:33:05 satsuki avahi-daemon[3561]: Leaving mDNS multicast group on interface wlo1.IPv4 with address 100.82.46.226.
Mar 15 11:33:05 satsuki avahi-daemon[3561]: Interface wlo1.IPv4 no longer relevant for mDNS.
Mar 15 11:33:05 satsuki NetworkManager[3549]: <info>  [1710516785.3853] device (wlo1): state change: disconnected -> unmanaged (reason 'sleeping', sys-iface-state: 'managed')
Mar 15 11:33:05 satsuki sway[6832]: 01:30:34.334 [ERROR] [wlr] [backend/drm/atomic.c:73] connector DP-1: Atomic commit failed: Device or resource busy
Mar 15 11:33:05 satsuki sway[6832]: 01:30:34.360 [ERROR] [wlr] [backend/drm/atomic.c:73] connector DP-1: Atomic commit failed: Device or resource busy
Mar 15 11:33:05 satsuki NetworkManager[3549]: <info>  [1710516785.5353] device (wlo1): set-hw-addr: reset MAC address to 7C:50:79:00:B7:39 (unmanage)
Mar 15 11:33:05 satsuki systemd[1]: Reached target Sleep.
Mar 15 11:33:05 satsuki systemd[1]: Starting System Suspend then Hibernate...
Mar 15 11:33:05 satsuki wpa_supplicant[4196]: p2p-dev-wlo1: CTRL-EVENT-DSCP-POLICY clear_all
Mar 15 11:33:05 satsuki wpa_supplicant[4196]: p2p-dev-wlo1: CTRL-EVENT-DSCP-POLICY clear_all
Mar 15 11:33:05 satsuki wpa_supplicant[4196]: nl80211: deinit ifname=p2p-dev-wlo1 disabled_11b_rates=0
Mar 15 11:33:05 satsuki systemd-sleep[47938]: Performing sleep operation 'suspend'...
Mar 15 11:33:05 satsuki kernel: PM: suspend entry (s2idle)
Mar 15 11:33:05 satsuki wpa_supplicant[4196]: wlo1: CTRL-EVENT-DSCP-POLICY clear_all
Mar 15 11:33:05 satsuki kernel: Filesystems sync: 0.058 seconds
Mar 15 11:33:05 satsuki seatd[3597]: 01:31:12.663 [INFO] [seatd/seat.c:560] Disabling client 1 on seat0
Mar 15 11:33:05 satsuki wpa_supplicant[4196]: wlo1: CTRL-EVENT-DSCP-POLICY clear_all
Mar 15 11:33:05 satsuki wpa_supplicant[4196]: nl80211: deinit ifname=wlo1 disabled_11b_rates=0
Mar 15 11:33:25 satsuki kernel: Freezing user space processes
Mar 15 11:33:25 satsuki kernel: Freezing user space processes completed (elapsed 0.056 seconds)
Mar 15 11:33:25 satsuki kernel: OOM killer disabled.
Mar 15 11:33:25 satsuki kernel: Freezing remaining freezable tasks
Mar 15 11:33:25 satsuki kernel: Freezing remaining freezable tasks failed after 20.009 seconds (0 tasks refusing to freeze, wq_busy=1):
Mar 15 11:33:25 satsuki kernel: Showing freezable workqueues that are still busy:
Mar 15 11:33:25 satsuki kernel: workqueue events_freezable: flags=0x4
Mar 15 11:33:25 satsuki kernel:   pwq 6: cpus=3 node=0 flags=0x0 nice=0 active=0/0 refcnt=2
Mar 15 11:33:25 satsuki kernel:     inactive: pci_pme_list_scan
Mar 15 11:33:25 satsuki kernel: workqueue pm: flags=0x4
Mar 15 11:33:25 satsuki kernel:   pwq 12: cpus=6 node=0 flags=0x0 nice=0 active=1/0 refcnt=2
Mar 15 11:33:25 satsuki kernel:     in-flight: 46262:pm_runtime_work
Mar 15 11:33:25 satsuki kernel: Restarting kernel threads ... done.
Mar 15 11:33:25 satsuki kernel: OOM killer enabled.
Mar 15 11:33:25 satsuki rtkit-daemon[6260]: The canary thread is apparently starving. Taking action.
Mar 15 11:33:25 satsuki kernel: Restarting tasks ... done.
Mar 15 11:33:25 satsuki kernel: random: crng reseeded on system resumption
Mar 15 11:33:25 satsuki rtkit-daemon[6260]: Demoting known real-time threads.
Mar 15 11:33:25 satsuki rtkit-daemon[6260]: Demoted 0 threads.
Mar 15 11:33:25 satsuki joycond[4243]: epoll_pwait failure
Mar 15 11:33:25 satsuki systemd[1]: NetworkManager-dispatcher.service: Deactivated successfully.
Mar 15 11:33:25 satsuki bluetoothd[3562]: Controller resume with wake event 0x0
Mar 15 11:33:25 satsuki seatd[3597]: 01:31:32.898 [ERROR] [seatd/seat.c:536] Could not disable client: client is not active
Mar 15 11:33:25 satsuki kernel: PM: suspend exit
Mar 15 11:33:25 satsuki kernel: PM: suspend entry (s2idle)
Mar 15 11:33:25 satsuki kernel: Filesystems sync: 0.001 seconds
Mar 15 11:33:45 satsuki kernel: Freezing user space processes
Mar 15 11:33:45 satsuki kernel: Freezing user space processes completed (elapsed 0.020 seconds)
Mar 15 11:33:45 satsuki kernel: OOM killer disabled.
Mar 15 11:33:45 satsuki kernel: Freezing remaining freezable tasks
Mar 15 11:33:45 satsuki kernel: Freezing remaining freezable tasks failed after 20.003 seconds (0 tasks refusing to freeze, wq_busy=1):
Mar 15 11:33:45 satsuki kernel: Showing freezable workqueues that are still busy:
Mar 15 11:33:45 satsuki kernel: workqueue events_freezable: flags=0x4
Mar 15 11:33:45 satsuki kernel:   pwq 6: cpus=3 node=0 flags=0x0 nice=0 active=0/0 refcnt=2
Mar 15 11:33:45 satsuki kernel:     inactive: pci_pme_list_scan
Mar 15 11:33:45 satsuki kernel: workqueue pm: flags=0x4
Mar 15 11:33:45 satsuki kernel:   pwq 12: cpus=6 node=0 flags=0x0 nice=0 active=1/0 refcnt=2
Mar 15 11:33:45 satsuki kernel:     in-flight: 46262:pm_runtime_work
Mar 15 11:33:45 satsuki kernel: Restarting kernel threads ... done.
Mar 15 11:33:45 satsuki kernel: OOM killer enabled.
Mar 15 11:33:45 satsuki kernel: Restarting tasks ... done.
Mar 15 11:33:45 satsuki kernel: random: crng reseeded on system resumption
Mar 15 11:33:45 satsuki joycond[4243]: epoll_pwait failure
Mar 15 11:33:45 satsuki rtkit-daemon[6260]: The canary thread is apparently starving. Taking action.
Mar 15 11:33:45 satsuki rtkit-daemon[6260]: Demoting known real-time threads.
Mar 15 11:33:45 satsuki rtkit-daemon[6260]: Demoted 0 threads.
Mar 15 11:33:45 satsuki bluetoothd[3562]: Controller resume with wake event 0x0
Mar 15 11:33:45 satsuki systemd-sleep[47938]: Failed to put system to sleep. System resumed again: Device or resource busy
Mar 15 11:33:45 satsuki kernel: PM: suspend exit
Mar 15 11:33:45 satsuki systemd[1]: systemd-suspend-then-hibernate.service: Main process exited, code=exited, status=1/FAILURE
Mar 15 11:33:45 satsuki systemd[1]: systemd-suspend-then-hibernate.service: Failed with result 'exit-code'.
Mar 15 11:33:45 satsuki systemd[1]: Failed to start System Suspend then Hibernate.
Mar 15 11:33:45 satsuki systemd[1]: Dependency failed for Suspend; Hibernate if not used for a period of time.
Mar 15 11:33:45 satsuki systemd[1]: suspend-then-hibernate.target: Job suspend-then-hibernate.target/start failed with result 'dependency'.
Mar 15 11:33:45 satsuki systemd[1]: systemd-suspend-then-hibernate.service: Consumed 2.818s CPU time.
Mar 15 11:33:45 satsuki systemd[1]: Stopped target Sleep.
Mar 15 11:33:45 satsuki systemd-logind[3600]: Operation 'suspend-then-hibernate' finished.

The problem seems to be with a busy workqueue.
I tried enabling tracing in /sys/kernel/debug/tracing/events/workqueue/ to identify why pm_runtime_work was hanging and found the following:

 irq/169-AudioDS-3455    [006] d..2.  5485.414243: workqueue_queue_work: work struct=0000000068dea0eb function=pm_runtime_work workqueue=pm req_cpu=320 cpu=6
 irq/169-AudioDS-3455    [006] d..2.  5485.414244: workqueue_activate_work: work struct 0000000068dea0eb
     kworker/6:1-46262   [006] .....  5485.414250: workqueue_execute_start: work struct 0000000068dea0eb: function pm_runtime_work

And indeed, only after waiting 20 seconds and failing to suspend we get

     kworker/6:1-46262   [006] .....  5529.971078: workqueue_execute_end: work struct 0000000068dea0eb: function pm_runtime_work

I'm on an HP Envy 13 laptop, which has an intel i7-1165G7 processor with integrated graphics Intel TigerLake-LP GT2 [Iris Xe Graphics].
This is an Optimus laptop with a second GPU, NVIDIA GeForce MX450.
I'm running sway but this exact issue still occurs under X, say running i3.

I'm running the latest linux kernel, 6.7.9-arch1-1, with the Nvidia driver from the nvidia package.
Interestingly, if I uninstall nvidia, so the relevant kernel modules aren't loaded, this issue with suspending does not arise.

I'm using PRIME as detailed at https://wiki.archlinux.org/title/PRIME# … er_offload.
Namely, I'm using the following udev rules

# Enable runtime PM for NVIDIA VGA/3D controller devices on driver bind
ACTION=="bind", SUBSYSTEM=="pci", ATTR{vendor}=="0x10de", ATTR{class}=="0x030000", TEST=="power/control", ATTR{power/control}="auto"
ACTION=="bind", SUBSYSTEM=="pci", ATTR{vendor}=="0x10de", ATTR{class}=="0x030200", TEST=="power/control", ATTR{power/control}="auto"

# Disable runtime PM for NVIDIA VGA/3D controller devices on driver unbind
ACTION=="unbind", SUBSYSTEM=="pci", ATTR{vendor}=="0x10de", ATTR{class}=="0x030000", TEST=="power/control", ATTR{power/control}="on"
ACTION=="unbind", SUBSYSTEM=="pci", ATTR{vendor}=="0x10de", ATTR{class}=="0x030200", TEST=="power/control", ATTR{power/control}="on"

together with the kernel module options

options nvidia NVreg_DynamicPowerManagement=0x02
options nvidia_drm modeset=1
options nvidia_drm fbdev=1
options nvidia NVreg_PreserveVideoMemoryAllocations=1
options nvidia NVreg_TemporaryFilePath=/var/tmp

What is "irq/169-AudioDS-3455" and how should I go about debugging this issue with it?