Bug 218634 - Hibernate fails with "Wakeup event detected during hibernation, rolling back"
Summary: Hibernate fails with "Wakeup event detected during hibernation, rolling back"
Status: NEW
Alias: None
Product: Power Management
Classification: Unclassified
Component: Hibernation/Suspend (show other bugs)
Hardware: Intel Linux
: P3 high
Assignee: Rafael J. Wysocki
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2024-03-24 11:50 UTC by Mattia Orlandi
Modified: 2024-04-21 10:51 UTC (History)
8 users (show)

See Also:
Kernel Version:
Subsystem:
Regression: No
Bisected commit-id:


Attachments
dmesg of the working setup (kernel 6.6.22) (92.32 KB, text/plain)
2024-03-24 21:43 UTC, Mattia Orlandi
Details
dmesg of the faulty setup (kernel 6.8.1) (106.38 KB, text/plain)
2024-03-24 21:44 UTC, Mattia Orlandi
Details
dmesg of the ThinkPad (kernel 6.8.1) (114.64 KB, text/plain)
2024-03-24 21:58 UTC, Mattia Orlandi
Details
Ignore power-button-up while entering sleep state (1.22 KB, patch)
2024-03-31 23:56 UTC, Enrik Berkhan
Details | Diff
xps 9380 systemd hibernate kernel v6.7.9 (5.93 KB, text/plain)
2024-04-14 23:25 UTC, Jonathan Colon
Details
xps 9380 dmesg after ACPI debugging (9.05 KB, text/plain)
2024-04-17 13:50 UTC, Jonathan Colon
Details
dmesg of the XPS 9500 on kernel 6.8.7 (working) (93.41 KB, text/plain)
2024-04-21 10:51 UTC, Mattia Orlandi
Details

Description Mattia Orlandi 2024-03-24 11:50:11 UTC
System
------
- Dell XPS 15 9500
- 6.8.1 kernel (Arch)

Problem description
-------------------
Whenever I try to hibernate the system, hibernation fails with the message "PM: hibernation: Wakeup event detected during hibernation, rolling back." (and, as a side effect, the NVIDIA GPU becomes unresponsive).

This is likely a regression bug since, with the LTS kernel 6.6.22, everything works as expected.

Here's the link to the Arch forum where we were discussing the issue: https://bbs.archlinux.org/viewtopic.php?id=294111
Comment 1 Artem S. Tashkinov 2024-03-24 15:30:09 UTC
Please attach full dmesg.

Make sure you're running the latest BIOS version.
Comment 2 Mattia Orlandi 2024-03-24 21:43:50 UTC
Created attachment 306032 [details]
dmesg of the working setup (kernel 6.6.22)
Comment 3 Mattia Orlandi 2024-03-24 21:44:22 UTC
Created attachment 306033 [details]
dmesg of the faulty setup (kernel 6.8.1)
Comment 4 Mattia Orlandi 2024-03-24 21:51:21 UTC
(In reply to Artem S. Tashkinov from comment #1)
> Please attach full dmesg.
> 
> Make sure you're running the latest BIOS version.

I checked with fwupd and confirm I'm on the latest BIOS version (1.27.0). I've attached the dmesg of both kernel versions.
Comment 5 Mattia Orlandi 2024-03-24 21:58:09 UTC
Created attachment 306034 [details]
dmesg of the ThinkPad (kernel 6.8.1)

I also confirm that the issue is hardware-specific. I've just tested another laptop (a ThinkPad T14) running the kernel 6.8.1, and hibernation works.
Comment 6 Joern Koerner 2024-03-26 18:43:17 UTC
Same problem on Dell XPS 9520, also with latest BIOS, kernel Linux XPS9520 6.8.1-arch1-1

Mär 26 19:35:36 XPS9520 kernel: PM: hibernation: Wakeup event detected during hibernation, rolling back.
Mär 26 19:35:36 XPS9520 kernel: printk: Suspending console(s) (use no_console_suspend to debug)
Mär 26 19:35:36 XPS9520 kernel: PM: S|
Mär 26 19:35:36 XPS9520 kernel: PM: hibernation: Wrote 9406880 kbytes in 8.08 seconds (1164.21 MB/s)
Mär 26 19:35:36 XPS9520 kernel: PM: Image saving done
Mär 26 19:35:36 XPS9520 kernel: PM: Image saving progress:  90%
Mär 26 19:35:36 XPS9520 kernel: PM: Image saving progress:  80%
Mär 26 19:35:36 XPS9520 kernel: PM: Image saving progress:  70%
Mär 26 19:35:36 XPS9520 kernel: PM: Image saving progress:  60%
Mär 26 19:35:36 XPS9520 kernel: PM: Image saving progress:  50%
Mär 26 19:35:36 XPS9520 kernel: PM: Image saving progress:  40%
Mär 26 19:35:36 XPS9520 kernel: PM: Image saving progress:  30%
Mär 26 19:35:36 XPS9520 kernel: PM: Image saving progress:  20%
Mär 26 19:35:36 XPS9520 kernel: PM: Image saving progress:  10%
Mär 26 19:35:36 XPS9520 kernel: PM: Image saving progress:   0%
Mär 26 19:35:36 XPS9520 kernel: PM: Compressing and saving image data (2351720 pages)...
Mär 26 19:35:36 XPS9520 kernel: PM: Using 3 thread(s) for compression
Comment 7 Joern Koerner 2024-03-27 17:24:10 UTC
(In reply to Mattia Orlandi from comment #5)
> Created attachment 306034 [details]
> dmesg of the ThinkPad (kernel 6.8.1)
> 
> I also confirm that the issue is hardware-specific. I've just tested another
> laptop (a ThinkPad T14) running the kernel 6.8.1, and hibernation works.

Strange.
I can confirm that the problem is not hardware-specific. On my desktop, the system freezes completely just before shutting down. Sleep works on both.

I have rolled back to kernel 6.7.9 and everything works perfectly again.
Comment 8 Siddhant 2024-03-29 17:28:31 UTC
I'm getting the same problem on a Dell Latitude, on 6.8.1-arch1-1. Rolling back to 6.7.9 fixes it. Suspend works, hibernate doesn't.

When I set HibernateMode to shutdown in systemd-sleep, the system powered off anyway after the hibernate failed. When I powered it back on, it seemingly resumed successfully (the tty had a blinking cursor), but no input devices or network devices worked. I had to do a hard shutdown.
Comment 9 Enrik Berkhan 2024-03-30 07:53:32 UTC
I'm having the exact same problem with a Dell Inspiron 16 (7640) BIOS 1.3.0.

Staying with 6.7.9 for now.
Comment 10 Julian 2024-03-30 14:10:36 UTC
Same error on Dell XPS 9510 on Kernel 6.8.2.arch1-1. Switching to the latest lts release (6.6.23-1-lts) fixed this issue.
Comment 11 Enrik Berkhan 2024-03-31 23:55:47 UTC
I did some debugging of the issue based on the arch linux 6.8.2 kernel.

The first observation is that the changes introduced by commit 0c4cae1bc00d31c78858c184ede351baea232bdb, which now check the return value of hibernation_platform_enter(), lead to the cancellation of the hibernation request. But these changes are not the root cause, they make sense.

Closer to the root cause seems to be a kind of spurious 0xCF (power button up) event from the Intel 5 button device that seems to be generated / handled / whatever when the actual hibernation state is entered through platform / ACPI methods. This is nothing new AFAICT and may have been there for a long time. It's not easily visible in the logs when hibernation works, as this happens just after the hibernation has been generated. (At least this is my limited understanding of the hibernation process.)

If I change the code in drivers/platform/x86/intel/hid.c:notify_handler() to ignore this "power button up", hibernation works again. (see attached patch 0001-WIP-Ignore-power-button-up-while-entering-sleep-stat.patch)

However, there might be a much better way to fix the issue by e.g. not having the "platform" generate this event, at all.
Comment 12 Enrik Berkhan 2024-03-31 23:56:51 UTC
Created attachment 306071 [details]
Ignore power-button-up while entering sleep state
Comment 13 David Rosenstrauch 2024-04-03 22:25:58 UTC
FYI, same error on a Dell Inspiron 5406 2n1 running kernel 6.8.2-arch2-1
Comment 14 Tamás Németh 2024-04-04 13:08:56 UTC
The same problem occurs on my laptop:

OS: openSUSE Tumbleweed x86_64
Host: Latitude 3420
Kernel: 6.8.1-1-default
Comment 15 Enrik Berkhan 2024-04-04 17:42:08 UTC
There is already a fix in the queue:

https://lore.kernel.org/platform-driver-x86/878r1tpd6u.fsf_-_@gmail.com/

You might want helping to test it. It also applies to 6.8.2.
Comment 16 Jonathan Colon 2024-04-14 18:33:27 UTC
Hi,

I have installed kernel 6.8.6 that includes the patch but i still can't hibernate with my laptop:

OS: Archlinux x86_64
Host: Dell XPS 9380
Kernel: 6.8.6-arch1-1 (Core-Testing)

https://git.kernel.org/pub/scm/linux/kernel/git/stable/linux.git/diff/drivers/platform/x86/intel/hid.c?id=v6.8.6&id2=v6.8.5

Apr 14 14:02:05 ACMEPC systemd[1]: Reached target Sleep.
Apr 14 14:02:05 ACMEPC systemd[1]: Starting System Hibernate...
Apr 14 14:02:05 ACMEPC rtkit-daemon[859]: Successfully made thread 1825 of process 1795 owned by '1000' high priority at nice level 0.
Apr 14 14:02:05 ACMEPC rtkit-daemon[859]: Supervising 7 threads of 5 processes of 1 users.
Apr 14 14:02:05 ACMEPC rtkit-daemon[859]: Supervising 6 threads of 4 processes of 1 users.
Apr 14 14:02:05 ACMEPC rtkit-daemon[859]: Supervising 6 threads of 4 processes of 1 users.
Apr 14 14:02:05 ACMEPC rtkit-daemon[859]: Successfully made thread 1825 of process 1795 owned by '1000' RT at priority 20.
Apr 14 14:02:05 ACMEPC rtkit-daemon[859]: Supervising 7 threads of 5 processes of 1 users.
Apr 14 14:02:05 ACMEPC systemd-sleep[5369]: Performing sleep operation 'hibernate'...
Apr 14 14:02:05 ACMEPC kernel: PM: hibernation: hibernation entry
Apr 14 14:02:13 ACMEPC kernel: Filesystems sync: 0.002 seconds
Apr 14 14:02:13 ACMEPC kernel: Freezing user space processes
Apr 14 14:02:13 ACMEPC kernel: Freezing user space processes completed (elapsed 0.001 seconds)
Apr 14 14:02:13 ACMEPC kernel: OOM killer disabled.
Apr 14 14:02:13 ACMEPC kernel: PM: hibernation: Marking nosave pages: [mem 0x00000000-0x00000fff]
Apr 14 14:02:13 ACMEPC kernel: PM: hibernation: Marking nosave pages: [mem 0x0009e000-0x0009efff]
Apr 14 14:02:13 ACMEPC kernel: PM: hibernation: Marking nosave pages: [mem 0x000a0000-0x000fffff]
Apr 14 14:02:13 ACMEPC kernel: PM: hibernation: Marking nosave pages: [mem 0x2b871000-0x2b872fff]
Apr 14 14:02:13 ACMEPC kernel: PM: hibernation: Marking nosave pages: [mem 0x35941000-0x359b4fff]
Apr 14 14:02:13 ACMEPC kernel: PM: hibernation: Marking nosave pages: [mem 0x3a551000-0x3fffefff]
Apr 14 14:02:13 ACMEPC kernel: PM: hibernation: Marking nosave pages: [mem 0x40000000-0x47ffffff]
Apr 14 14:02:13 ACMEPC kernel: PM: hibernation: Marking nosave pages: [mem 0x48e00000-0xffffffff]
Apr 14 14:02:13 ACMEPC kernel: PM: hibernation: Basic memory bitmaps created
Apr 14 14:02:13 ACMEPC kernel: PM: hibernation: Preallocating image memory
Apr 14 14:02:13 ACMEPC kernel: PM: hibernation: Allocated 749300 pages for snapshot
Apr 14 14:02:13 ACMEPC kernel: PM: hibernation: Allocated 2997200 kbytes in 3.77 seconds (795.01 MB/s)
Apr 14 14:02:13 ACMEPC kernel: Freezing remaining freezable tasks
Apr 14 14:02:13 ACMEPC kernel: Freezing remaining freezable tasks completed (elapsed 0.778 seconds)
Apr 14 14:02:13 ACMEPC kernel: printk: Suspending console(s) (use no_console_suspend to debug)
Apr 14 14:02:13 ACMEPC kernel: ACPI: EC: interrupt blocked
Apr 14 14:02:13 ACMEPC kernel: ACPI: PM: Preparing to enter system sleep state S4
Apr 14 14:02:13 ACMEPC kernel: ACPI: EC: event blocked
Apr 14 14:02:13 ACMEPC kernel: ACPI: EC: EC stopped
Apr 14 14:02:13 ACMEPC kernel: ACPI: PM: Saving platform NVS memory
Apr 14 14:02:13 ACMEPC kernel: Disabling non-boot CPUs ...
Apr 14 14:02:13 ACMEPC kernel: smpboot: CPU 1 is now offline
Apr 14 14:02:13 ACMEPC kernel: smpboot: CPU 2 is now offline
Apr 14 14:02:13 ACMEPC kernel: smpboot: CPU 3 is now offline
Apr 14 14:02:13 ACMEPC kernel: smpboot: CPU 4 is now offline
Apr 14 14:02:13 ACMEPC kernel: smpboot: CPU 5 is now offline
Apr 14 14:02:13 ACMEPC kernel: smpboot: CPU 6 is now offline
Apr 14 14:02:13 ACMEPC kernel: smpboot: CPU 7 is now offline
Apr 14 14:02:13 ACMEPC kernel: PM: hibernation: Creating image:
Apr 14 14:02:13 ACMEPC kernel: PM: hibernation: Need to copy 717514 pages
Apr 14 14:02:13 ACMEPC kernel: PM: hibernation: Normal pages needed: 717514 + 1024, available pages: 1287420
Apr 14 14:02:13 ACMEPC kernel: PM: hibernation: Image created (650205 pages copied, 67309 zero pages)
Apr 14 14:02:13 ACMEPC kernel: ACPI: PM: Restoring platform NVS memory
Apr 14 14:02:13 ACMEPC kernel: ACPI: EC: EC started
Apr 14 14:02:13 ACMEPC kernel: Enabling non-boot CPUs ...
Apr 14 14:02:13 ACMEPC kernel: smpboot: Booting Node 0 Processor 1 APIC 0x2
Apr 14 14:02:13 ACMEPC kernel: CPU1 is up
Apr 14 14:02:13 ACMEPC kernel: smpboot: Booting Node 0 Processor 2 APIC 0x4
Apr 14 14:02:13 ACMEPC kernel: CPU2 is up
Apr 14 14:02:13 ACMEPC kernel: smpboot: Booting Node 0 Processor 3 APIC 0x6
Apr 14 14:02:13 ACMEPC kernel: CPU3 is up
Apr 14 14:02:13 ACMEPC kernel: smpboot: Booting Node 0 Processor 4 APIC 0x1
Apr 14 14:02:13 ACMEPC kernel: CPU4 is up
Apr 14 14:02:13 ACMEPC kernel: smpboot: Booting Node 0 Processor 5 APIC 0x3
Apr 14 14:02:13 ACMEPC kernel: CPU5 is up
Apr 14 14:02:13 ACMEPC kernel: smpboot: Booting Node 0 Processor 6 APIC 0x5
Apr 14 14:02:13 ACMEPC kernel: CPU6 is up
Apr 14 14:02:13 ACMEPC kernel: smpboot: Booting Node 0 Processor 7 APIC 0x7
Apr 14 14:02:13 ACMEPC kernel: CPU7 is up
Apr 14 14:02:13 ACMEPC kernel: ACPI: PM: Waking up from system sleep state S4
Apr 14 14:02:13 ACMEPC kernel: ACPI: EC: interrupt unblocked
Apr 14 14:02:13 ACMEPC kernel: ACPI: EC: event unblocked
Apr 14 14:02:13 ACMEPC kernel: nvme nvme0: 8/0/0 default/read/poll queues
Apr 14 14:02:13 ACMEPC kernel: PM: Using 3 thread(s) for compression
Apr 14 14:02:13 ACMEPC kernel: PM: Compressing and saving image data (651607 pages)...
Apr 14 14:02:13 ACMEPC kernel: PM: Image saving progress:   0%
Apr 14 14:02:13 ACMEPC kernel: mei_hdcp 0000:00:16.0-b638ab7e-94e2-4ea2-a552-d1c54b627f04: bound 0000:00:02.0 (ops i915_hdcp_ops [i915])
Apr 14 14:02:13 ACMEPC kernel: PM: Image saving progress:  10%
Apr 14 14:02:13 ACMEPC kernel: PM: Image saving progress:  20%
Apr 14 14:02:13 ACMEPC kernel: PM: Image saving progress:  30%
Apr 14 14:02:13 ACMEPC kernel: PM: Image saving progress:  40%
Apr 14 14:02:13 ACMEPC kernel: PM: Image saving progress:  50%
Apr 14 14:02:13 ACMEPC kernel: PM: Image saving progress:  60%
Apr 14 14:02:13 ACMEPC kernel: PM: Image saving progress:  70%
Apr 14 14:02:13 ACMEPC kernel: PM: Image saving progress:  80%
Apr 14 14:02:13 ACMEPC kernel: PM: Image saving progress:  90%
Apr 14 14:02:13 ACMEPC kernel: PM: Image saving progress: 100%
Apr 14 14:02:13 ACMEPC kernel: PM: Image saving done
Apr 14 14:02:13 ACMEPC kernel: PM: hibernation: Wrote 2606428 kbytes in 2.12 seconds (1229.44 MB/s)
Apr 14 14:02:13 ACMEPC kernel: PM: S|
Apr 14 14:02:13 ACMEPC kernel: printk: Suspending console(s) (use no_console_suspend to debug)
Apr 14 14:02:13 ACMEPC kernel: PM: hibernation: Wakeup event detected during hibernation, rolling back.
Apr 14 14:02:13 ACMEPC kernel: PM: hibernation: Basic memory bitmaps freed
Apr 14 14:02:13 ACMEPC kernel: pci_bus 0000:05: Allocating resources
Apr 14 14:02:13 ACMEPC kernel: pci_bus 0000:39: Allocating resources
Apr 14 14:02:13 ACMEPC kernel: OOM killer enabled.
Apr 14 14:02:13 ACMEPC kernel: Restarting tasks ... done.
Apr 14 14:02:13 ACMEPC rtkit-daemon[859]: The canary thread is apparently starving. Taking action.
Apr 14 14:02:13 ACMEPC rtkit-daemon[859]: Demoting known real-time threads.
Apr 14 14:02:13 ACMEPC rtkit-daemon[859]: Successfully demoted thread 1825 of process 1795.
Apr 14 14:02:13 ACMEPC rtkit-daemon[859]: Successfully demoted thread 3048 of process 3030.
Apr 14 14:02:13 ACMEPC rtkit-daemon[859]: Successfully demoted thread 2337 of process 2327.
Apr 14 14:02:13 ACMEPC rtkit-daemon[859]: Successfully demoted thread 2327 of process 2327.
Apr 14 14:02:13 ACMEPC rtkit-daemon[859]: Successfully demoted thread 2325 of process 2325.
Apr 14 14:02:13 ACMEPC rtkit-daemon[859]: Successfully demoted thread 2329 of process 2312.
Apr 14 14:02:13 ACMEPC rtkit-daemon[859]: Successfully demoted thread 2312 of process 2312.
Apr 14 14:02:13 ACMEPC rtkit-daemon[859]: Demoted 7 threads.
Apr 14 14:02:13 ACMEPC kernel: PM: hibernation: hibernation exit
Apr 14 14:02:13 ACMEPC systemd-sleep[5369]: System returned from sleep operation 'hibernate'.
Apr 14 14:02:13 ACMEPC systemd[1]: systemd-hibernate.service: Deactivated successfully.
Apr 14 14:02:13 ACMEPC systemd[1]: Finished System Hibernate.
Apr 14 14:02:13 ACMEPC systemd[1]: systemd-hibernate.service: Consumed 4.762s CPU time.
Apr 14 14:02:13 ACMEPC systemd[1]: Reached target System Hibernation.
Apr 14 14:02:13 ACMEPC systemd[1]: Stopped target Sleep.
Apr 14 14:02:13 ACMEPC systemd-logind[589]: Operation 'hibernate' finished.
Apr 14 14:02:13 ACMEPC systemd[1]: Stopped target System Hibernation.

Best regards,
Comment 17 Enrik Berkhan 2024-04-14 20:18:53 UTC
Using

Kernel: 6.8.6-arch1-1 (Core-Testing)

makes hibernation on the Dell Inspiron 16 (7640) work again.
Comment 18 Enrik Berkhan 2024-04-14 20:59:25 UTC
Ok, 6.8.6 doesn't work fully for me, either.

systemctl hibernate: OK
power button (via systemd): OK
Gnome menu entries: NOT OK

Will try to investigate as soon as time permits.
Comment 19 Jonathan Colon 2024-04-14 23:01:49 UTC
(In reply to Enrik Berkhan from comment #18)
> Ok, 6.8.6 doesn't work fully for me, either.
> 
> systemctl hibernate: OK
> power button (via systemd): OK
> Gnome menu entries: NOT OK
> 
> Will try to investigate as soon as time permits.

I have performed the test using all the methods without success:

systemctl hibernate: NOT OK
power button (via systemd): NOT OK
Gnome menu entries: NOT OK

I will be testing with kernel v6.7.9 to validate that my system is not the cause.

Thank you for your help!
Comment 20 Jonathan Colon 2024-04-14 23:25:04 UTC
Created attachment 306150 [details]
xps 9380 systemd hibernate kernel v6.7.9
Comment 21 Jonathan Colon 2024-04-14 23:27:35 UTC
Tested with kernel v6.7.9 with good results.

Linux ACMEPC 6.7.9-arch1-1 #1 SMP PREEMPT_DYNAMIC Fri, 08 Mar 2024 01:59:01 +0000 x86_64 GNU/Linux

systemctl hibernate: OK
power button (via systemd): OK
Gnome menu entries: OK
Comment 22 Tamás Németh 2024-04-15 19:27:54 UTC
(In reply to Jonathan Colon from comment #16)
> Hi,
> 
> I have installed kernel 6.8.6 that includes the patch but i still can't
> hibernate with my laptop:
> 
> OS: Archlinux x86_64
> Host: Dell XPS 9380
> Kernel: 6.8.6-arch1-1 (Core-Testing)
> 
> https://git.kernel.org/pub/scm/linux/kernel/git/stable/linux.git/diff/
> drivers/platform/x86/intel/hid.c?id=v6.8.6&id2=v6.8.5
> 
> Apr 14 14:02:05 ACMEPC systemd[1]: Reached target Sleep.
> Apr 14 14:02:05 ACMEPC systemd[1]: Starting System Hibernate...
> Apr 14 14:02:05 ACMEPC rtkit-daemon[859]: Successfully made thread 1825 of
> process 1795 owned by '1000' high priority at nice level 0.
> Apr 14 14:02:05 ACMEPC rtkit-daemon[859]: Supervising 7 threads of 5
> processes of 1 users.
> Apr 14 14:02:05 ACMEPC rtkit-daemon[859]: Supervising 6 threads of 4
> processes of 1 users.
> Apr 14 14:02:05 ACMEPC rtkit-daemon[859]: Supervising 6 threads of 4
> processes of 1 users.
> Apr 14 14:02:05 ACMEPC rtkit-daemon[859]: Successfully made thread 1825 of
> process 1795 owned by '1000' RT at priority 20.
> Apr 14 14:02:05 ACMEPC rtkit-daemon[859]: Supervising 7 threads of 5
> processes of 1 users.
> Apr 14 14:02:05 ACMEPC systemd-sleep[5369]: Performing sleep operation
> 'hibernate'...
> Apr 14 14:02:05 ACMEPC kernel: PM: hibernation: hibernation entry
> Apr 14 14:02:13 ACMEPC kernel: Filesystems sync: 0.002 seconds
> Apr 14 14:02:13 ACMEPC kernel: Freezing user space processes
> Apr 14 14:02:13 ACMEPC kernel: Freezing user space processes completed
> (elapsed 0.001 seconds)
> Apr 14 14:02:13 ACMEPC kernel: OOM killer disabled.
> Apr 14 14:02:13 ACMEPC kernel: PM: hibernation: Marking nosave pages: [mem
> 0x00000000-0x00000fff]
> Apr 14 14:02:13 ACMEPC kernel: PM: hibernation: Marking nosave pages: [mem
> 0x0009e000-0x0009efff]
> Apr 14 14:02:13 ACMEPC kernel: PM: hibernation: Marking nosave pages: [mem
> 0x000a0000-0x000fffff]
> Apr 14 14:02:13 ACMEPC kernel: PM: hibernation: Marking nosave pages: [mem
> 0x2b871000-0x2b872fff]
> Apr 14 14:02:13 ACMEPC kernel: PM: hibernation: Marking nosave pages: [mem
> 0x35941000-0x359b4fff]
> Apr 14 14:02:13 ACMEPC kernel: PM: hibernation: Marking nosave pages: [mem
> 0x3a551000-0x3fffefff]
> Apr 14 14:02:13 ACMEPC kernel: PM: hibernation: Marking nosave pages: [mem
> 0x40000000-0x47ffffff]
> Apr 14 14:02:13 ACMEPC kernel: PM: hibernation: Marking nosave pages: [mem
> 0x48e00000-0xffffffff]
> Apr 14 14:02:13 ACMEPC kernel: PM: hibernation: Basic memory bitmaps created
> Apr 14 14:02:13 ACMEPC kernel: PM: hibernation: Preallocating image memory
> Apr 14 14:02:13 ACMEPC kernel: PM: hibernation: Allocated 749300 pages for
> snapshot
> Apr 14 14:02:13 ACMEPC kernel: PM: hibernation: Allocated 2997200 kbytes in
> 3.77 seconds (795.01 MB/s)
> Apr 14 14:02:13 ACMEPC kernel: Freezing remaining freezable tasks
> Apr 14 14:02:13 ACMEPC kernel: Freezing remaining freezable tasks completed
> (elapsed 0.778 seconds)
> Apr 14 14:02:13 ACMEPC kernel: printk: Suspending console(s) (use
> no_console_suspend to debug)
> Apr 14 14:02:13 ACMEPC kernel: ACPI: EC: interrupt blocked
> Apr 14 14:02:13 ACMEPC kernel: ACPI: PM: Preparing to enter system sleep
> state S4
> Apr 14 14:02:13 ACMEPC kernel: ACPI: EC: event blocked
> Apr 14 14:02:13 ACMEPC kernel: ACPI: EC: EC stopped
> Apr 14 14:02:13 ACMEPC kernel: ACPI: PM: Saving platform NVS memory
> Apr 14 14:02:13 ACMEPC kernel: Disabling non-boot CPUs ...
> Apr 14 14:02:13 ACMEPC kernel: smpboot: CPU 1 is now offline
> Apr 14 14:02:13 ACMEPC kernel: smpboot: CPU 2 is now offline
> Apr 14 14:02:13 ACMEPC kernel: smpboot: CPU 3 is now offline
> Apr 14 14:02:13 ACMEPC kernel: smpboot: CPU 4 is now offline
> Apr 14 14:02:13 ACMEPC kernel: smpboot: CPU 5 is now offline
> Apr 14 14:02:13 ACMEPC kernel: smpboot: CPU 6 is now offline
> Apr 14 14:02:13 ACMEPC kernel: smpboot: CPU 7 is now offline
> Apr 14 14:02:13 ACMEPC kernel: PM: hibernation: Creating image:
> Apr 14 14:02:13 ACMEPC kernel: PM: hibernation: Need to copy 717514 pages
> Apr 14 14:02:13 ACMEPC kernel: PM: hibernation: Normal pages needed: 717514
> + 1024, available pages: 1287420
> Apr 14 14:02:13 ACMEPC kernel: PM: hibernation: Image created (650205 pages
> copied, 67309 zero pages)
> Apr 14 14:02:13 ACMEPC kernel: ACPI: PM: Restoring platform NVS memory
> Apr 14 14:02:13 ACMEPC kernel: ACPI: EC: EC started
> Apr 14 14:02:13 ACMEPC kernel: Enabling non-boot CPUs ...
> Apr 14 14:02:13 ACMEPC kernel: smpboot: Booting Node 0 Processor 1 APIC 0x2
> Apr 14 14:02:13 ACMEPC kernel: CPU1 is up
> Apr 14 14:02:13 ACMEPC kernel: smpboot: Booting Node 0 Processor 2 APIC 0x4
> Apr 14 14:02:13 ACMEPC kernel: CPU2 is up
> Apr 14 14:02:13 ACMEPC kernel: smpboot: Booting Node 0 Processor 3 APIC 0x6
> Apr 14 14:02:13 ACMEPC kernel: CPU3 is up
> Apr 14 14:02:13 ACMEPC kernel: smpboot: Booting Node 0 Processor 4 APIC 0x1
> Apr 14 14:02:13 ACMEPC kernel: CPU4 is up
> Apr 14 14:02:13 ACMEPC kernel: smpboot: Booting Node 0 Processor 5 APIC 0x3
> Apr 14 14:02:13 ACMEPC kernel: CPU5 is up
> Apr 14 14:02:13 ACMEPC kernel: smpboot: Booting Node 0 Processor 6 APIC 0x5
> Apr 14 14:02:13 ACMEPC kernel: CPU6 is up
> Apr 14 14:02:13 ACMEPC kernel: smpboot: Booting Node 0 Processor 7 APIC 0x7
> Apr 14 14:02:13 ACMEPC kernel: CPU7 is up
> Apr 14 14:02:13 ACMEPC kernel: ACPI: PM: Waking up from system sleep state S4
> Apr 14 14:02:13 ACMEPC kernel: ACPI: EC: interrupt unblocked
> Apr 14 14:02:13 ACMEPC kernel: ACPI: EC: event unblocked
> Apr 14 14:02:13 ACMEPC kernel: nvme nvme0: 8/0/0 default/read/poll queues
> Apr 14 14:02:13 ACMEPC kernel: PM: Using 3 thread(s) for compression
> Apr 14 14:02:13 ACMEPC kernel: PM: Compressing and saving image data (651607
> pages)...
> Apr 14 14:02:13 ACMEPC kernel: PM: Image saving progress:   0%
> Apr 14 14:02:13 ACMEPC kernel: mei_hdcp
> 0000:00:16.0-b638ab7e-94e2-4ea2-a552-d1c54b627f04: bound 0000:00:02.0 (ops
> i915_hdcp_ops [i915])
> Apr 14 14:02:13 ACMEPC kernel: PM: Image saving progress:  10%
> Apr 14 14:02:13 ACMEPC kernel: PM: Image saving progress:  20%
> Apr 14 14:02:13 ACMEPC kernel: PM: Image saving progress:  30%
> Apr 14 14:02:13 ACMEPC kernel: PM: Image saving progress:  40%
> Apr 14 14:02:13 ACMEPC kernel: PM: Image saving progress:  50%
> Apr 14 14:02:13 ACMEPC kernel: PM: Image saving progress:  60%
> Apr 14 14:02:13 ACMEPC kernel: PM: Image saving progress:  70%
> Apr 14 14:02:13 ACMEPC kernel: PM: Image saving progress:  80%
> Apr 14 14:02:13 ACMEPC kernel: PM: Image saving progress:  90%
> Apr 14 14:02:13 ACMEPC kernel: PM: Image saving progress: 100%
> Apr 14 14:02:13 ACMEPC kernel: PM: Image saving done
> Apr 14 14:02:13 ACMEPC kernel: PM: hibernation: Wrote 2606428 kbytes in 2.12
> seconds (1229.44 MB/s)
> Apr 14 14:02:13 ACMEPC kernel: PM: S|
> Apr 14 14:02:13 ACMEPC kernel: printk: Suspending console(s) (use
> no_console_suspend to debug)
> Apr 14 14:02:13 ACMEPC kernel: PM: hibernation: Wakeup event detected during
> hibernation, rolling back.
> Apr 14 14:02:13 ACMEPC kernel: PM: hibernation: Basic memory bitmaps freed
> Apr 14 14:02:13 ACMEPC kernel: pci_bus 0000:05: Allocating resources
> Apr 14 14:02:13 ACMEPC kernel: pci_bus 0000:39: Allocating resources
> Apr 14 14:02:13 ACMEPC kernel: OOM killer enabled.
> Apr 14 14:02:13 ACMEPC kernel: Restarting tasks ... done.
> Apr 14 14:02:13 ACMEPC rtkit-daemon[859]: The canary thread is apparently
> starving. Taking action.
> Apr 14 14:02:13 ACMEPC rtkit-daemon[859]: Demoting known real-time threads.
> Apr 14 14:02:13 ACMEPC rtkit-daemon[859]: Successfully demoted thread 1825
> of process 1795.
> Apr 14 14:02:13 ACMEPC rtkit-daemon[859]: Successfully demoted thread 3048
> of process 3030.
> Apr 14 14:02:13 ACMEPC rtkit-daemon[859]: Successfully demoted thread 2337
> of process 2327.
> Apr 14 14:02:13 ACMEPC rtkit-daemon[859]: Successfully demoted thread 2327
> of process 2327.
> Apr 14 14:02:13 ACMEPC rtkit-daemon[859]: Successfully demoted thread 2325
> of process 2325.
> Apr 14 14:02:13 ACMEPC rtkit-daemon[859]: Successfully demoted thread 2329
> of process 2312.
> Apr 14 14:02:13 ACMEPC rtkit-daemon[859]: Successfully demoted thread 2312
> of process 2312.
> Apr 14 14:02:13 ACMEPC rtkit-daemon[859]: Demoted 7 threads.
> Apr 14 14:02:13 ACMEPC kernel: PM: hibernation: hibernation exit
> Apr 14 14:02:13 ACMEPC systemd-sleep[5369]: System returned from sleep
> operation 'hibernate'.
> Apr 14 14:02:13 ACMEPC systemd[1]: systemd-hibernate.service: Deactivated
> successfully.
> Apr 14 14:02:13 ACMEPC systemd[1]: Finished System Hibernate.
> Apr 14 14:02:13 ACMEPC systemd[1]: systemd-hibernate.service: Consumed
> 4.762s CPU time.
> Apr 14 14:02:13 ACMEPC systemd[1]: Reached target System Hibernation.
> Apr 14 14:02:13 ACMEPC systemd[1]: Stopped target Sleep.
> Apr 14 14:02:13 ACMEPC systemd-logind[589]: Operation 'hibernate' finished.
> Apr 14 14:02:13 ACMEPC systemd[1]: Stopped target System Hibernation.
> 
> Best regards,


I compiled intel-hid.ko for both 6.8.4 and 6.8.5 with this patch applied on OpenSuSE Tumbleweed and it seems to work. I can hibernate.
Comment 23 Tamás Németh 2024-04-15 19:43:55 UTC
(In reply to Enrik Berkhan from comment #15)
> There is already a fix in the queue:
> 
> https://lore.kernel.org/platform-driver-x86/878r1tpd6u.fsf_-_@gmail.com/
> 
> You might want helping to test it. It also applies to 6.8.2.

Sorry, replying to the wrong comment. So:

I compiled intel-hid.ko for both 6.8.4 and 6.8.5 with this patch applied on OpenSuSE Tumbleweed and it seems to work. I can hibernate.
Comment 24 Tamás Németh 2024-04-16 07:37:43 UTC
(In reply to Tamás Németh from comment #23)
> (In reply to Enrik Berkhan from comment #15)
> > There is already a fix in the queue:
> > 
> > https://lore.kernel.org/platform-driver-x86/878r1tpd6u.fsf_-_@gmail.com/
> > 
> > You might want helping to test it. It also applies to 6.8.2.
> 
> Sorry, replying to the wrong comment. So:
> 
> I compiled intel-hid.ko for both 6.8.4 and 6.8.5 with this patch applied on
> OpenSuSE Tumbleweed and it seems to work. I can hibernate.

...but it doesn't work always. Sometimes(!) my laptop bounces back from hibernation just like before the patch :-(
Comment 25 Jonathan Colon 2024-04-16 13:27:47 UTC
I compiled a vanilla kernel 6.8.5 only with the patch but I still can't hibernate with my laptop. Additionally I performed the "Per sub-system hibernate testing" procedures but in every result I never receive the message "Wakeup event detected during hibernation, rolling back" as if everything were working fine.

https://wiki.ubuntu.com/DebuggingKernelHibernate
Comment 26 Enrik Berkhan 2024-04-16 15:53:56 UTC
After adding some kernel logs telling me when there are events from the "five button device", I maybe got some insight, which might well be specific for my machine.

If and only if AC is plugged and I enter hibernate via software (like using the Gnome menu or 'systemctl hibernate'), I see 0xCE (Power button down) events while the driver is in the wakeup_mode == 1 state. These events are not (yet) suppressed by the existing patch, which made it into 6.8.6 BTW. These events seem to be the root cause for cancelling hibernation in my case.

When on battery, I only see 0xCF (Power button up) events. These are now filtered having the fix applied.

Maybe Dell uses the different events depending on AC connected or not to do some magic? No idea ...

Anyone else seeing different behavior depending on AC connected?
Comment 27 Jonathan Colon 2024-04-16 17:54:17 UTC
Did the test on battery with same results.

systemctl hibernate: NOT OK
power button (via systemd): NOT OK
Gnome menu entries: NOT OK

How can i get the events generate by the kernel?

Thanks!
Comment 28 Enrik Berkhan 2024-04-16 19:03:44 UTC
I added this line

  dev_info(&device->dev, "event 0x%x wakeup_mode %d", event, priv->wakeup_mode);

in drivers/platform/x86/intel/hid.c at the top of notify_handler() to get dmesg output for the "Intel HID" events.

However, I'm following a new strategy right now: blacklisting the intel_hid
module from the kernel command line. In this case (unloading the module after
it had been loaded once does not work!), the ACPI BIOS seems to send "classic"
power button events that can be used e.g. to enter hibernate mode and there
will be no more "five button" (ACPI BIOS simulated?) events that puzzle the
code.

YMMV, e.g. for hardware that actually has fancy extra buttons ...
Comment 29 Enrik Berkhan 2024-04-17 07:59:03 UTC
(In reply to Enrik Berkhan from comment #28)
> I added this line
> 
>   dev_info(&device->dev, "event 0x%x wakeup_mode %d", event,
> priv->wakeup_mode);
> 
> in drivers/platform/x86/intel/hid.c at the top of notify_handler() to get
> dmesg output for the "Intel HID" events.

Another option not needing a kernel rebuild is to enable some runtime ACPI debugging, e.g. to see event notifications:

echo 4 > /sys/module/acpi/parameters/debug_layer

You should also verify that at least ACPI_LV_INFO is enabled in /sys/module/acpi/parameters/debug_level.
Comment 30 Jonathan Colon 2024-04-17 13:49:11 UTC
Enabled the debugging on ACPI.

[root@ACMEPC rebelinux]# cat /sys/module/acpi/parameters/debug_layer | grep [*]
ACPI_EVENTS              	0x00000004 [*]
debug_layer = 0x00000004 ( * = enabled)
[root@ACMEPC rebelinux]# cat /sys/module/acpi/parameters/debug_level | grep [*]
ACPI_LV_INFO             	0x00000004 [*]
debug_level = 0x00000004 (* = enabled)
[root@ACMEPC rebelinux]#
Comment 31 Jonathan Colon 2024-04-17 13:50:41 UTC
Created attachment 306174 [details]
xps 9380 dmesg after ACPI debugging
Comment 32 Enrik Berkhan 2024-04-17 20:35:14 UTC
(In reply to Jonathan Colon from comment #31)
> Created attachment 306174 [details]
> xps 9380 dmesg after ACPI debugging

I think these are the interesting lines, logged when the system comes back from the ephemeral S4 state that had been entered for image creation, before writing the hibernation image out to disk:

[ 2934.829876] ACPI: PM: Waking up from system sleep state S4                                                                                                                                                                                                 
[ 2934.830050]    evmisc-0132 ev_queue_notify_reques: Dispatching Notify on [PBTN] (Device) Value 0x02 (Device Wake) Node 00000000b9046256                                                                                                                    

The firmware of your notebook sends a (spurious?) Power Button Wakeup. This wakeup is very likely the root cause for cancelling the hibernation process.

This also explains why the patch does not work for you: the patch only addresses similar behavior when it comes from the "5 button device" power button. (The "5 button device", when present, takes over the power button functionality and disables the "classic" power button when its driver is loaded.)

Maybe a more general solution for this issue is to ignore all wakeup events that arrive between the "waking up from S4 to save the data to disk" and the actual power down. I guess this needs to be discussed on the x86 platform kernel mailing list.
Comment 33 Jonathan Colon 2024-04-17 21:19:38 UTC
Adding to the conversation if I put the module intel_hid on the blacklist I can do the hibernate without problem.

module_blacklist=intel_hid

thanks for your time and help!
Comment 34 Tamás Németh 2024-04-18 08:46:23 UTC
(In reply to Enrik Berkhan from comment #26)
> Maybe Dell uses the different events depending on AC connected or not to do
> some magic? No idea ...
> 
> Anyone else seeing different behavior depending on AC connected?

Maybe... I couldn't find the exact causality. Sometimes (probably if I load the newly compiled intel_hid while AC is plugged in?) hibernation still bounces back on my Dell Latitude 3420 laptop. But it mostly works.
Comment 35 Mattia Orlandi 2024-04-21 10:51:43 UTC
Created attachment 306188 [details]
dmesg of the XPS 9500 on kernel 6.8.7 (working)

I've just tested hibernation on the XPS 15 9500 and hibernation seems to work again with kernel 6.8.7.

Note You need to log in before you can comment on or make changes to this bug.