Since Ubuntu 16.04, I've had the problem that suspend sometimes fails (about 1/2 of time). In XFCE4, choosing the suspend option seems to shut down everything but then the login window immediately appears. I've tested quite a few fixes for this from time-to-time. I've been narrowing down possible causes, various drivers.
Now I'm frustrated because I can't understand what the kernel logs are telling me. First, here is output from a successful suspend (last night) and resume (today) from kern.log. The important point, which I had not noticed, is that when the system goes into suspend, it has not written out all of its messages. After the system wakes up later, then it finishes writing suspend messages. Note the entries from Dec. 2 end in the middle of the suspend, and after the wakeup on Dec. 3, we see the completion of the suspend from last night:
Dec 2 22:49:28 delllap-16 NetworkManager[1035]: <info> [1480740568.5891] dhcp4 (wlp2s0): state changed bound -> done
Dec 2 22:49:28 delllap-16 kernel: [ 2431.649579] wlp2s0: deauthenticating from c4:e9:84:9f:ab:0d by local choice (Reason: 3=DEAUTH_LEAVING)
Dec 2 22:49:28 delllap-16 NetworkManager[1035]: <info> [1480740568.6012] dns-mgr: Writing DNS information to /sbin/resolvconf
Dec 2 22:49:28 delllap-16 NetworkManager[1035]: <warn> [1480740568.6159] sup-iface[0x562a34a140a0,wlp2s0]: connection disconnected (reason -3)
Dec 2 22:49:28 delllap-16 NetworkManager[1035]: <info> [1480740568.6162] device (wlp2s0): supplicant interface state: completed -> disconnected
Dec 2 22:49:28 delllap-16 NetworkManager[1035]: <info> [1480740568.6171] device (wlp2s0): state change: disconnected -> unmanaged (reason 'sleeping') [30 10 37]
Dec 2 22:49:38 delllap-16 kernel: [ 2441.741616] PM: Syncing filesystems ... done.
Dec 2 22:49:38 delllap-16 kernel: [ 2441.753950] PM: Preparing system for sleep (mem)
Dec 3 11:12:17 delllap-16 kernel: [ 2442.102084] Freezing user space processes ... (elapsed 0.021 seconds) done.
Dec 3 11:12:17 delllap-16 kernel: [ 2442.123705] Double checking all user space processes after OOM killer disable... (elapsed 0.000 seconds)
Dec 3 11:12:17 delllap-16 kernel: [ 2442.123801] Freezing remaining freezable tasks ... (elapsed 0.023 seconds) done.
Dec 3 11:12:17 delllap-16 kernel: [ 2442.147706] PM: Suspending system (mem)
Dec 3 11:12:17 delllap-16 kernel: [ 2442.147765] Suspending console(s) (use no_console_suspend to debug)
Dec 3 11:12:17 delllap-16 kernel: [ 2442.149078] sd 1:0:0:0: [sda] Synchronizing SCSI cache
Dec 3 11:12:17 delllap-16 kernel: [ 2442.149238] sd 1:0:0:0: [sda] Stopping disk
Dec 3 11:12:17 delllap-16 kernel: [ 2444.169662] PM: suspend of devices complete after 2021.505 msecs
Dec 3 11:12:17 delllap-16 kernel: [ 2444.191582] PM: late suspend of devices complete after 21.915 msecs
Dec 3 11:12:17 delllap-16 kernel: [ 2444.267486] PM: noirq suspend of devices complete after 75.899 msecs
Dec 3 11:12:17 delllap-16 kernel: [ 2444.268477] ACPI: Preparing to enter system sleep state S3
Dec 3 11:12:17 delllap-16 kernel: [ 2444.311889] ACPI : EC: EC stopped
Dec 3 11:12:17 delllap-16 kernel: [ 2444.311891] PM: Saving platform NVS memory
Dec 3 11:12:17 delllap-16 kernel: [ 2444.311979] Disabling non-boot CPUs ...
Dec 3 11:12:17 delllap-16 kernel: [ 2444.312570] Broke affinity for irq 134
Dec 3 11:12:17 delllap-16 kernel: [ 2444.314682] smpboot: CPU 1 is now offline
Dec 3 11:12:17 delllap-16 kernel: [ 2444.329202] Broke affinity for irq 134
Dec 3 11:12:17 delllap-16 kernel: [ 2444.330303] smpboot: CPU 2 is now offline
Dec 3 11:12:17 delllap-16 kernel: [ 2444.356988] Broke affinity for irq 124
Dec 3 11:12:17 delllap-16 kernel: [ 2444.357000] Broke affinity for irq 134
Dec 3 11:12:17 delllap-16 kernel: [ 2444.358109] smpboot: CPU 3 is now offline
Dec 3 11:12:17 delllap-16 kernel: [ 2444.380849] Broke affinity for irq 124
Dec 3 11:12:17 delllap-16 kernel: [ 2444.380857] Broke affinity for irq 133
Dec 3 11:12:17 delllap-16 kernel: [ 2444.380861] Broke affinity for irq 134
Dec 3 11:12:17 delllap-16 kernel: [ 2444.381968] smpboot: CPU 4 is now offline
Dec 3 11:12:17 delllap-16 kernel: [ 2444.404670] Broke affinity for irq 124
Dec 3 11:12:17 delllap-16 kernel: [ 2444.404674] Broke affinity for irq 126
Dec 3 11:12:17 delllap-16 kernel: [ 2444.404679] Broke affinity for irq 133
Dec 3 11:12:17 delllap-16 kernel: [ 2444.404682] Broke affinity for irq 134
Dec 3 11:12:17 delllap-16 kernel: [ 2444.405768] smpboot: CPU 5 is now offline
Dec 3 11:12:17 delllap-16 kernel: [ 2444.424659] Broke affinity for irq 16
Dec 3 11:12:17 delllap-16 kernel: [ 2444.424676] Broke affinity for irq 124
In this, it seems important to me that the last recorded message before suspend is this:
Dec 2 22:49:38 delllap-16 kernel: [ 2441.753950] PM: Preparing system for sleep (mem)
This means to me that when suspend fails, the problem has to show up around "PM: Preparing system for sleep (mem)". Do you think that's correct?
Yesterday, I tried to suspend and the system woke up immediately and came to the login screen. This has been happening for months. After that, I can neither reboot nor suspend. A process "pm-suspend" is still running and the system refuses to quit. The only way out is to find the process number and kill it. That causes an immediate suspend, as you see at the very end of the next kernel log. The session after that is usually wonky, with video static or failed networking.
Here is the kernel log from yesterday, when I tried to suspend at 16:08
Dec 2 16:08:37 delllap-16 NetworkManager[24749]: <info> [1480716517.3396] plen 21 (255.255.248.0)
Dec 2 16:08:37 delllap-16 NetworkManager[24749]: <info> [1480716517.3397] gateway 10.88.143.254
Dec 2 16:08:37 delllap-16 NetworkManager[24749]: <info> [1480716517.3397] server identifier 129.237.19.41
Dec 2 16:08:37 delllap-16 NetworkManager[24749]: <info> [1480716517.3397] lease time 1800
Dec 2 16:08:37 delllap-16 NetworkManager[24749]: <info> [1480716517.3398] nameserver '129.237.133.1'
Dec 2 16:08:37 delllap-16 NetworkManager[24749]: <info> [1480716517.3398] nameserver '129.237.32.1'
Dec 2 16:08:37 delllap-16 NetworkManager[24749]: <info> [1480716517.3398] domain search 'all.iospub.ku.edu.'
Dec 2 16:08:37 delllap-16 NetworkManager[24749]: <info> [1480716517.3398] dhcp4 (wlp2s0): state changed bound -> bound
Dec 2 16:10:20 delllap-16 gvfsd-network[8370]: Couldn't create directory monitor on smb://x-gnome-default-workgroup/. Error: Operation not supported by backend
Dec 2 16:11:07 delllap-16 gvfsd-network[8370]: message repeated 3 times: [ Couldn't create directory monitor on smb://x-gnome-default-workgroup/. Error: Operation not supported by backend]
Dec 2 16:11:07 delllap-16 colord[1111]: failed to get session [pid 6355]: No such device or address
Dec 2 16:11:13 delllap-16 gvfsd-network[8370]: Couldn't create directory monitor on smb://x-gnome-default-workgroup/. Error: Operation not supported by backend
Dec 2 16:13:21 delllap-16 kernel: [242076.701468] vgaarb: this pci device is not a vga device
Dec 2 16:11:13 delllap-16 gvfsd-network[8370]: Couldn't create directory monitor on smb://x-gnome-default-workgroup/. Error: Operation not supported by backend
Dec 2 16:13:30 delllap-16 kernel: [242086.500910] vgaarb: this pci device is not a vga device
Dec 2 16:14:14 delllap-16 kernel: [242129.914982] [drm:drm_edid_block_valid [drm]] *ERROR* EDID checksum is invalid, remainder is 38
Dec 2 16:14:14 delllap-16 kernel: [242129.914984] Raw EDID:
Dec 2 16:14:14 delllap-16 kernel: [242129.914986] 00 ff ff ff ff ff ff 00 10 ac 16 f0 4c 54 4b 47
Dec 2 16:14:14 delllap-16 kernel: [242129.914987] 1e 1e 14 01 03 80 34 20 78 ea 1e c5 ae 4f 34 b1
Dec 2 16:14:14 delllap-16 kernel: [242129.914987] 26 0e 50 54 a5 4b 00 81 80 a9 40 d1 00 71 4f 01
Dec 2 16:14:14 delllap-16 kernel: [242129.914988] 01 01 01 01 01 01 01 28 3c 80 a0 70 b0 23 40 30
Dec 2 16:14:14 delllap-16 kernel: [242129.914989] 20 36 00 06 44 21 00 00 1a 00 00 00 ff 00 43 35
Dec 2 16:14:14 delllap-16 kernel: [242129.914990] 39 32 4d 30 37 4b 47 4b 54 4c 0a 00 00 00 fc 00
Dec 2 16:14:14 delllap-16 kernel: [242129.914991] 44 45 4c 4c 20 55 32 34 31 30 0a 20 20 00 00 00
Dec 2 16:14:14 delllap-16 kernel: [242129.914991] fd 00 38 4c 1e 51 11 00 0a 20 20 20 20 20 20 01
Dec 2 16:14:36 delllap-16 gvfsd-network[8370]: Couldn't create directory monitor on smb://x-gnome-default-workgroup/. Error: Operation not supported by backend
Dec 2 16:14:50 delllap-16 NetworkManager[24749]: <info> [1480716890.4456] manager: sleep requested (sleeping: no enabled: yes)
Dec 2 16:14:50 delllap-16 NetworkManager[24749]: <info> [1480716890.4456] manager: sleeping...
Dec 2 16:14:50 delllap-16 NetworkManager[24749]: <info> [1480716890.4458] manager: NetworkManager state is now ASLEEP
Dec 2 16:14:50 delllap-16 NetworkManager[24749]: <info> [1480716890.4464] device (wlp2s0): state change: activated -> deactivating (reason 'sleeping') [100 110 37]
Dec 2 16:14:50 delllap-16 NetworkManager[24749]: <info> [1480716890.4524] device (wlp2s0): state change: deactivating -> disconnected (reason 'sleeping') [110 30 37]
Dec 2 16:14:50 delllap-16 NetworkManager[24749]: <info> [1480716890.4848] dhcp4 (wlp2s0): canceled DHCP transaction, DHCP client pid 5096
Dec 2 16:14:50 delllap-16 NetworkManager[24749]: <info> [1480716890.4848] dhcp4 (wlp2s0): state changed bound -> done
Dec 2 16:14:50 delllap-16 kernel: [242166.208753] wlp2s0: deauthenticating from 04:da:d2:b2:8b:af by local choice (Reason: 3=DEAUTH_LEAVING)
Dec 2 16:14:50 delllap-16 gvfsd-network[8370]: Couldn't create directory monitor on smb://x-gnome-default-workgroup/. Error: Operation not supported by backend
Dec 2 16:14:50 delllap-16 gvfsd-network[8370]: Couldn't create directory monitor on smb://x-gnome-default-workgroup/. Error: Operation not supported by backend
Dec 2 16:14:50 delllap-16 NetworkManager[24749]: <info> [1480716890.4998] dns-mgr: Writing DNS information to /sbin/resolvconf
Dec 2 16:14:50 delllap-16 NetworkManager[24749]: <warn> [1480716890.5240] sup-iface[0x5605e51e1a10,wlp2s0]: connection disconnected (reason -3)
Dec 2 16:14:50 delllap-16 NetworkManager[24749]: <info> [1480716890.5241] device (wlp2s0): supplicant interface state: completed -> disconnected
Dec 2 16:14:50 delllap-16 NetworkManager[24749]: <info> [1480716890.5247] device (wlp2s0): state change: disconnected -> unmanaged (reason 'sleeping') [30 10 37]
Dec 2 16:15:00 delllap-16 kernel: [242176.419147] PM: Syncing filesystems ... done.
Dec 2 16:15:00 delllap-16 kernel: [242176.437462] PM: Preparing system for sleep (mem)
Dec 2 16:15:01 delllap-16 kernel: [242177.276724] vgaarb: this pci device is not a vga device
Dec 2 16:15:01 delllap-16 kernel: [242177.280053] nvidia-modeset: Allocated GPU:0 (GPU-e6b5cc1c-4011-80f8-3081-d2193ae9fff9) @ PCI:0000:01:00.0
Dec 2 16:15:01 delllap-16 kernel: [242177.280261] nvidia-modeset: Freed GPU:0 (GPU-e6b5cc1c-4011-80f8-3081-d2193ae9fff9) @ PCI:0000:01:00.0
Dec 2 16:15:01 delllap-16 kernel: [242177.283666] vgaarb: this pci device is not a vga device
Dec 2 16:15:02 delllap-16 kernel: [242178.601770] [drm:intel_cpu_fifo_underrun_irq_handler [i915]] *ERROR* CPU pipe B FIFO underrun
Dec 2 16:15:02 delllap-16 kernel: [242178.602355] [drm:intel_cpu_fifo_underrun_irq_handler [i915]] *ERROR* CPU pipe C FIFO underrun
Dec 2 16:15:06 delllap-16 kernel: [242182.681261] usb 3-1: USB disconnect, device number 2
Dec 2 16:15:06 delllap-16 kernel: [242182.681266] usb 3-1.1: USB disconnect, device number 3
Dec 2 16:15:06 delllap-16 kernel: [242182.681269] usb 3-1.1.2: USB disconnect, device number 21
Dec 2 16:15:06 delllap-16 kernel: [242182.681272] usb 3-1.1.2.1: USB disconnect, device number 22
Dec 2 16:15:06 delllap-16 kernel: [242182.681275] usb 3-1.1.2.1.1: USB disconnect, device number 23
Dec 2 16:15:07 delllap-16 kernel: [242182.774080] xhci_hcd 0000:3e:00.0: remove, state 4
Dec 2 16:15:07 delllap-16 kernel: [242182.774085] usb usb4: USB disconnect, device number 1
Dec 2 16:15:07 delllap-16 kernel: [242182.774293] xhci_hcd 0000:3e:00.0: Host not halted after 16000 microseconds.
Dec 2 16:15:07 delllap-16 kernel: [242182.775289] xhci_hcd 0000:3e:00.0: USB bus 4 deregistered
Dec 2 16:15:07 delllap-16 kernel: [242182.775298] xhci_hcd 0000:3e:00.0: remove, state 1
Dec 2 16:15:07 delllap-16 kernel: [242182.775306] usb usb3: USB disconnect, device number 1
Dec 2 16:15:07 delllap-16 kernel: [242182.791008] usb 3-1.1.3: USB disconnect, device number 6
Dec 2 16:15:07 delllap-16 kernel: [242183.009330] usb 3-1.1.4: USB disconnect, device number 8
Dec 2 16:15:07 delllap-16 kernel: [242183.061636] usb 3-1.3: USB disconnect, device number 4
Dec 2 16:15:07 delllap-16 kernel: [242183.062110] xhci_hcd 0000:3e:00.0: USB bus 3 deregistered
Dec 2 16:15:07 delllap-16 kernel: [242183.081352] pcieport 0000:07:00.0: Refused to change power state, currently in D3
Dec 2 16:15:07 delllap-16 kernel: [242183.082594] pci_bus 0000:08: busn_res: [bus 08] is released
Dec 2 16:15:07 delllap-16 kernel: [242183.082641] pci_bus 0000:09: busn_res: [bus 09-3d] is released
Dec 2 16:15:07 delllap-16 kernel: [242183.109360] pci_bus 0000:3e: busn_res: [bus 3e] is released
Dec 2 16:15:07 delllap-16 kernel: [242183.109399] pci_bus 0000:07: busn_res: [bus 07-3e] is released
Dec 2 16:15:13 delllap-16 kernel: [242189.540764] usb 1-1: USB disconnect, device number 12
Dec 2 16:15:23 delllap-16 lightdm[1207]: Error using VT_WAITACTIVE 7 on /dev/tty0: Interrupted system call
The very last line is entered when I run "kill -9 nnnnn" where nnnnn is the process number of pm-suspend.
Trying to figure out the cause of the failure to suspend, then, I look for then I look for "PM: Preparing system for sleep (mem)". Right after that, what do I see?
Dec 2 16:15:01 delllap-16 kernel: [242177.276724] vgaarb: this pci device is not a vga device
Dec 2 16:15:01 delllap-16 kernel: [242177.280053] nvidia-modeset: Allocated GPU:0 (GPU-e6b5cc1c-4011-80f8-3081-d2193ae9fff9) @ PCI:0000:01:00.0
If my guess about how to understand the logs is accurate, this is pointing the finger at video, probably the Nvidia proprietary driver.
But there might be other problems, I notice in these logs I have chronic messages from gvfs-smb. There are separate bug reports about them in Debian. I'm perplexed that pm-suspend.log has no entries after Dec. 1.
What info about this system will help? Dell Precision 5510
$ uname -a
Linux delllap-16 4.8.0-27-generic #29-Ubuntu SMP Thu Oct 20 21:03:13 UTC 2016 x86_64 x86_64 x86_64 GNU/Linux
$ dpkg -l | grep nvidia
ii nvidia-367 367.57-0ubuntu3 amd64 NVIDIA binary driver - version 367.57
ii nvidia-opencl-icd-367 367.57-0ubuntu3 amd64 NVIDIA OpenCL ICD
ii nvidia-prime 0.8.4 amd64 Tools to enable NVIDIA's Prime
ii nvidia-settings 370.28-0ubuntu0~gpu16.04.1 amd64 Tool for configuring the NVIDIA graphics driver
