acidanthera / bugtracker

Acidanthera Bugtracker
386 stars 45 forks source link

HibernationFixup v. 1.4.4 hibernatemode 3 #1810

Closed profzei closed 3 years ago

profzei commented 3 years ago

@lvs1974

I know very well this is not a forum, but I opened this thread for reporting a possible issue with latest Hibernation.kext.

I'm trying to use your latest commit for HibernationFixup.kext in order to get a real MacBookPro's sleep behavior under standard hibernate mode 3 on battery.

My laptop is Huawei Matebook X Pro 2018

Premise:

If I set in my config.plist Misc -> Boot -> HibernateMode key to NVRAM value and hibernatemode 25 then hibernation is working fine without or with boot-args hbfx-ahbm=1 (I have to resume my machine with power button which is normal according to my understanding...)

If I set hibernatemode 3 without using boot-args hbfx-ahbm=1, then sleep is working fine with a discharging rate of about 1% at every 2 hours (which seems a normal behavior in Hackintosh community)

If I set hibernatemode 3 without using boot-args hbfx-ahbm=1 AND I modify standbydelaylow/high according to the following

System-wide power settings:
Currently in use:
 standby              1
 halfdim              1
 hibernatefile        /var/vm/sleepimage
 proximitywake        0
 powernap             0
 gpuswitch            2
 disksleep            10
 standbydelayhigh     300
 sleep                1 (sleep prevented by sharingd)
 hibernatemode        3
 ttyskeepawake        1
 displaysleep         3
 tcpkeepalive         0
 highstandbythreshold 50
 acwake               0
 standbydelaylow      300

then there is no visible change i.e. sleep is working fine with the same exact discharging rate BUT after fixed 300 seconds (5 minutes) my machine doesn't hibernate (saving battery). My machine continues its sleep phase until a key is pressed (obviously for a time longer than 5 minutes...)

I also guess this is a normal behavior for Hackintosh laptops (...till now)

Current situation:

If my understanding is right, with latest HibernationFixup.kext and adding in boot-args hbfx-ahbm=1, regular sleep should be replaced by hibernation after 300 seconds (obviously using my settings for standbydelaylow/high and hibernatemode 3), isn't it right?

Instead, using hibernatemode 3 AND standbydelaylow 300 + standbydelayhigh 300 AND hbfx-ahbm=1, my machine breaks its sleep phase exactly after 300 seconds...

What does it mean? According to my understanding, latest HibernationFixup.kext tries to trigger the passage from regular sleep to hibernation state (like in a real MacBookPro) but it fails... what do you think about this?

The result of pmset -g assertions command is not useful since it is the classic message:

Assertion status system-wide:
   BackgroundTask                 0
   ApplePushServiceTask           0
   UserIsActive                   1
   PreventUserIdleDisplaySleep    0
   PreventSystemSleep             0
   ExternalMedia                  0
   PreventUserIdleSystemSleep     0
   NetworkClientActive            0
Listed by owning process:
   pid 141(WindowServer): [0x0000031c00098303] 00:00:00 UserIsActive named: "com.apple.iohideventsystem.queue.tickle serviceID:100000436 name:IOHIDEventDriver product:Keyboard eventType:3"  
    Timeout will fire in 180 secs Action=TimeoutActionRelease
No kernel assertions.
Idle sleep preventers: IODisplayWrangler
lvs1974 commented 3 years ago

@profzei: most likely your issue is not related to the latest commit (and version 1.4.4), you can check it with the latest release version 1.4.3. The change made in 1.4.4 are active only if one of bits WhenBatteryIsAtWarnLevel or WhenBatteryAtCriticalLevel is set in hbfx-ahbm. In your case only one bit is set, so these changes are inactive. In your case regular sleep cannot be replaced with a standby sleep, and the reason you should look in system log. For example, bit DisableStimulusDarkWakeActivityTickle deactivates on of those possible reasons, but there can be something different.

profzei commented 3 years ago

@lvs1974 I'm using latest official DEBUG version i.e. HibernationFixup v. 1.4.4

I resume relevant info I wrote In my previous post: in Hackintosh community my laptop is considered a well-working Hackintosh since

In Hackintosh community there is no guide for getting a fully working hibernatemode 3 i.e. a machine which is capable to switch from a standby to a hibernation sleep at a (user-)fixed threshold...

Do you agree with the latest statement?

The latter is what I'm trying to get using your commits to HibernationFixup project... I think it would be a great improvement for all community...

If you could help/guide me, I think I'm not so far from the aim...

My actual settings: config.plist

<key>HibernateMode</key>
<string>Auto</string>
<key>boot-args</key>
<string>-v keepsyms=1 debug=0x100 msgbuf=10485760 -liludbgall liludump=60 -hbfxdbg hbfx-ahbm=129</string>

pmset -g live

System-wide power settings:
Currently in use:
 standby              1
 halfdim              1
 hibernatefile        /var/vm/sleepimage
 proximitywake        0
 powernap             0
 gpuswitch            2
 disksleep            10
 standbydelayhigh     300
 sleep                1 (sleep prevented by sharingd)
 hibernatemode        3
 ttyskeepawake        1
 displaysleep         3
 tcpkeepalive         0
 highstandbythreshold 50
 acwake               0
 standbydelaylow      300

hbfx_129.txt

As you can see I'm using hbfx-ahbm=129 i.e. I'm setting ON only two bits EnableAutoHibernation + DisableStimulusDarkWakeActivityTickle

What did it happen?

What does it mean? Hibernation-sleep is somewhat triggered after a partial resuming of my machine...??? Sorry for my bad English... I don't know if I explained well my point...

In a separate thread you said

Why machine did not go into hibernation - it is a different, there can be many reasons, full system log is needed.

Could you tell me what commands I'm supposed to run in Terminal for getting useful information?

lvs1974 commented 3 years ago

@profzei: in your last log hbfx_129.txt I can see at least one attempt to hibernate (hibernate now). It means HBFX did its job. But this log contains only events logged by HibernationFixup, so I don't know why your laptop did not go into hibernation. I need full system log. You can use dmesg or show log, anything - there must be a reason why it did not work.

profzei commented 3 years ago

@lvs1974

Here there are some logs:

sudo dmesg | grep HBFX > ~/desktop/hbfx.txt hbfx.txt

log show --predicate 'process == "kernel"' --style syslog --source --debug --last boot > sys_log_hbfx.txt Please see that 300 seconds gap occurs at 20:08:47 to 20:13:47 range sys_log_hbfx.txt

log show --style syslog --source --debug --last boot > log_complete.txt log_complete.txt.zip

I don't know if these logs could be useful...

lvs1974 commented 3 years ago

@profzei: can you explain please, why do you use "| grep HBFX" if I needed a full system log, not only for HBFX?

lvs1974 commented 3 years ago

@profzei: at 2021-10-09 20:13:47.883432+0200 I see: system wake events: RTC - so it was dark wake (maintenance sleep), and at 2021-10-09 20:14:35.806510+0200 macOS started to prepare /var/vm/sleepimage, and then Opened file /var/vm/sleepimage, size 1073741824, extents 5, maxio 20000 ssd 1 And later: DebugEnhancer DBGENH: @ IOHibernateSystemSleep is called, result is: 0 So, after those lines macOS must be hibernated... I don't see any reasons why it did not happen...

PS: I would also recommend you to increase standby time from 300 to 615, I saw that hibernation does not happen (sometimes) when standby interval less than 600.

profzei commented 3 years ago

why do you use "| grep HBFX" if I needed a full system log, not only for HBFX?

@lvs1974 I'm sorry... I'm dumb sometimes...

So, after those lines macOS must be hibernated... I don't see any reasons why it did not happen...

You are right! After those lines macOS hibernated itself successfully!

The issue is before those lines... Please see the following:

2021-10-09 20:08:47.918521+0200  localhost kernel[0]: (AppleACPIPlatform) <AppleACPIPlatform`AppleACPIPlatformExpert::publishWakeAssertions(OSArray*)> AppleACPIPlatformPower Wake reason: RTC (Alarm)
2021-10-09 20:08:47.918688+0200  localhost kernel[0]: IOPlatformWakeAction -> AppleSMBusControllerICH
2021-10-09 20:08:47.918697+0200  localhost kernel[0]: IOPlatformWakeAction -> AppleRTC
2021-10-09 20:08:47.918722+0200  localhost kernel[0]: (AppleRTC) <AppleRTC`AppleRTC::callPlatformFunction(OSSymbol const*, bool, void*, void*, void*, void*)> RTC: Maintenance 2021/10/9 18:13:47, sleep 2021/10/9 18:08:48
2021-10-09 20:08:47.918730+0200  localhost kernel[0]: IOPlatformWakeAction -> AppleKeyStore
2021-10-09 20:08:47.918737+0200  localhost kernel[0]: IOPlatformWakeAction -> AppleSMC
2021-10-09 20:08:47.919325+0200  localhost kernel[0]: [  277.660143]: ucode: Re-applying update after wake (CPU #2)
2021-10-09 20:08:47.919326+0200  localhost kernel[0]: [  277.660391]: TSC sync for cpu 2: 0x000000002b3109a4 delta 0xa6 (166)
2021-10-09 20:08:47.919789+0200  localhost kernel[0]: [  277.660604]: ucode: Re-applying update after wake (CPU #4)
2021-10-09 20:08:47.919790+0200  localhost kernel[0]: [  277.660857]: TSC sync for cpu 4: 0x000000002b3f3c24 delta 0xb2 (178)
2021-10-09 20:08:47.920253+0200  localhost kernel[0]: [  277.661070]: ucode: Re-applying update after wake (CPU #6)
2021-10-09 20:08:47.920254+0200  localhost kernel[0]: [  277.661322]: TSC sync for cpu 6: 0x000000002b4d5d7f delta 0xbc (188)
2021-10-09 20:08:47.920726+0200  localhost kernel[0]: [  277.661533]: ucode: Re-applying update after wake (CPU #1)
2021-10-09 20:08:47.920729+0200  localhost kernel[0]: [  277.661789]: TSC sync for cpu 1: 0x000000002b5b817e delta 0x1c (28)
2021-10-09 20:08:47.921184+0200  localhost kernel[0]: [  277.661994]: ucode: Re-applying update after wake (CPU #3)
2021-10-09 20:08:47.921185+0200  localhost kernel[0]: [  277.662249]: TSC sync for cpu 3: 0x000000002b698833 delta 0xac (172)
2021-10-09 20:08:47.921644+0200  localhost kernel[0]: [  277.662454]: ucode: Re-applying update after wake (CPU #5)
2021-10-09 20:08:47.921646+0200  localhost kernel[0]: [  277.662709]: TSC sync for cpu 5: 0x000000002b778563 delta 0xb6 (182)
2021-10-09 20:08:47.922105+0200  localhost kernel[0]: [  277.662917]: ucode: Re-applying update after wake (CPU #7)
2021-10-09 20:08:47.922106+0200  localhost kernel[0]: [  277.663171]: TSC sync for cpu 7: 0x000000002b858dcd delta 0xca (202)
2021-10-09 20:08:47.922113+0200  localhost kernel[0]: IOCPUSleepKernel exit
2021-10-09 20:08:47.922117+0200  localhost kernel[0]: gIOLastWakeAbsTime: 277663198209
2021-10-09 20:08:47.922149+0200  localhost kernel[0]: (SMCLightSensor) <compose failure [UUID]>
2021-10-09 20:08:47.922161+0200  localhost kernel[0]: (SMCLightSensor) <compose failure [UUID]>
2021-10-09 20:08:47.922169+0200  localhost kernel[0]: (SMCLightSensor) <compose failure [UUID]>
2021-10-09 20:08:47.922178+0200  localhost kernel[0]: (SMCLightSensor) <compose failure [UUID]>
2021-10-09 20:13:47.001330+0200  localhost kernel[0]: [  576.742362]: time_slept (299 s 78985 u)
2021-10-09 20:13:47.001903+0200  localhost kernel[0]: IOConsoleUsers: gIOScreenLockState 3, hs 0, bs 0, now 1633803227, sm 0xe0000300
2021-10-09 20:13:47.002209+0200  localhost kernel[0]: (IOBluetoothFamily) <IOBluetoothFamily`IOBluetoothHCIUserClient::SimpleDispatchWL(IOBluetoothHCIDispatchParams*)> [IOBluetoothHCIUserClient][SimpleDispatchWL] -- bluetoothd (132) -- IOReturnOffline -- routine index 1 (HCI Request Delete) -- configState = 0x0 (On Line) (Need to be 0 -- On Line) powerState = 0x0 (Need to be 1) -- mIsDaemon = TRUE
2021-10-09 20:13:47.004188+0200  localhost kernel[0]: (AppleACPIButtons) <AppleACPIButtons`AppleACPILid::message(unsigned int, IOService*, void*)> ACPI lid state changed: 1
2021-10-09 20:13:47.004397+0200  localhost kernel[0]: (IOGraphicsFamily) <IOGraphicsFamily`IOFramebuffer::systemPowerChange(void*, void*, unsigned int, IOService*, void*, unsigned long)> GTrace synchronization point 107
2021-10-09 20:13:47.005071+0200  localhost kernel[0]: (IOBluetoothFamily) <IOBluetoothFamily`IOBluetoothHCIUserClient::SimpleDispatchWL(IOBluetoothHCIDispatchParams*)> [IOBluetoothHCIUserClient][SimpleDispatchWL] -- PerfPowerService (126) -- IOReturnOffline -- routine index 0 (HCI Request Create) -- configState = 0x0 (On Line) (Need to be 0 -- On Line) powerState = 0x0 (Need to be 1) -- mIsDaemon = FALSE
2021-10-09 20:13:47.005297+0200  localhost kernel[0]: (IOBluetoothHostControllerTransport) <IOBluetoothHostControllerTransport`IOBluetoothHostControllerTransport::powerStateWillChangeTo(unsigned long, unsigned long, IOService*)> **** [IOBluetoothHostControllerTransport][powerStateWillChangeTo] -- System Wake -- SleepType is kIOPMSleepTypeNormalSleep ****
2021-10-09 20:13:47.005328+0200  localhost kernel[0]: Dark wake display tickle
Backtrace 0xffffff80009df7e3 0xffffff7f9b13d307 0xffffff8000a5a39a 0xffffff80009e32af 0xffffff80009ecf5e 0xffffff80009ec546 0xffffff800023113e
2021-10-09 20:13:47.005341+0200  localhost kernel[0]:       Kernel Extensions in backtrace:
2021-10-09 20:13:47.005365+0200  localhost kernel[0]:          com.apple.iokit.IOGraphicsFamily(585.1)[240F08CD-4BC4-3093-8832-0E899EFC14F4]@0xffffff7f9b135000->0xffffff7f9b163fff
2021-10-09 20:13:47.005389+0200  localhost kernel[0]:             dependency: com.apple.iokit.IOPCIFamily(2.9)[4E85D41F-6AD7-3C24-911C-A8B80B599F86]@0xffffff8002d6c000->0xffffff8002d94fff
2021-10-09 20:13:47.005621+0200  localhost kernel[0]: (AppleRTC) <AppleRTC`AppleRTC::handlePMSettingNotification(OSSymbol const*, OSObject*, OSObject*)> RTC: PowerByCalendarDate setting ignored
2021-10-09 20:13:47.005652+0200  localhost kernel[0]: (SMCLightSensor) <compose failure [UUID]>
2021-10-09 20:13:47.005668+0200  localhost kernel[0]: (SMCLightSensor) <compose failure [UUID]>

From 2021-10-09 20:08:47.922178 to 2021-10-09 20:13:47.001330 we have the 300 seconds period when laptop goes for standby-sleep and then it wakes up (only backlight for keyboard and NOT the screen) till 2021-10-09 20:14:35.806510+0200 macOS started to prepare /var/vm/sleepimage when macOS successfully hibernated itself...

PS: I would also recommend you to increase standby time from 300 to 615, I saw that hibernation does not happen (sometimes) when standby interval less than 600

I'll follow your suggestion and let you know results! Thank you very much!

profzei commented 3 years ago

@lvs1974

Same issue setting standbydelaylow and standbydelayhigh to value 660

sudo dmesg > ~/desktop/hbfx_660.txt hbfx_660.txt

log show --predicate 'process == "kernel"' --style syslog --source --debug --last boot > sys_log_hbfx.txt sys_log_hbfx.txt

log show --style syslog --source --debug --last boot > log_complete.txt log_complete.txt.zip

If you look into new sys_log_hbfx.txt you could see 2021-10-10 18:10:35.000014+0200 localhost kernel[0]: [ 963.407827]: time_slept (659 s 213725 u):

2021-10-10 17:59:35.548971+0200  localhost kernel[0]: IOCPUSleepKernel enter
2021-10-10 17:59:35.549152+0200  localhost kernel[0]: IOPlatformSleepAction -> AppleSMC
2021-10-10 17:59:35.549221+0200  localhost kernel[0]: IOPlatformSleepAction -> AppleSMBusControllerICH
2021-10-10 17:59:35.752060+0200  localhost kernel[0]: [  304.144965]: ACPI switch to MemPool
2021-10-10 17:59:35.752063+0200  localhost kernel[0]: [  304.144998]: acpi_sleep_kernel hib=0, cpu=0
2021-10-10 17:59:35.752064+0200  localhost kernel[0]: [  304.145024]: ucode: Re-applying update after wake (CPU #0)
2021-10-10 17:59:35.752065+0200  localhost kernel[0]: [  304.149305]: fpu_state: AVX, state_size: 832
2021-10-10 17:59:35.752066+0200  localhost kernel[0]: [  304.149345]: ret from acpi_sleep_cpu hib=0
2021-10-10 17:59:35.752235+0200  localhost kernel[0]: (SMCLightSensor) <compose failure [UUID]>
2021-10-10 17:59:35.752252+0200  localhost kernel[0]: (SMCLightSensor) <compose failure [UUID]>
2021-10-10 17:59:35.752262+0200  localhost kernel[0]: (SMCLightSensor) <compose failure [UUID]>
2021-10-10 17:59:35.752269+0200  localhost kernel[0]: (SMCLightSensor) <compose failure [UUID]>
2021-10-10 17:59:35.752537+0200  localhost kernel[0]: (SMCLightSensor) <compose failure [UUID]>
2021-10-10 17:59:35.782470+0200  localhost kernel[0]: (AppleACPIPlatform) <AppleACPIPlatform`AppleACPIPlatformExpert::publishWakeAssertions(OSArray*)> AppleACPIPlatformPower Wake reason: RTC (Alarm)
2021-10-10 17:59:35.782630+0200  localhost kernel[0]: IOPlatformWakeAction -> AppleSMBusControllerICH
2021-10-10 17:59:35.782638+0200  localhost kernel[0]: IOPlatformWakeAction -> AppleRTC
2021-10-10 17:59:35.782663+0200  localhost kernel[0]: (AppleRTC) <AppleRTC`AppleRTC::callPlatformFunction(OSSymbol const*, bool, void*, void*, void*, void*)> RTC: Maintenance 2021/10/10 16:10:35, sleep 2021/10/10 15:59:36
2021-10-10 17:59:35.782670+0200  localhost kernel[0]: IOPlatformWakeAction -> AppleKeyStore
2021-10-10 17:59:35.782680+0200  localhost kernel[0]: IOPlatformWakeAction -> AppleSMC
2021-10-10 17:59:35.783263+0200  localhost kernel[0]: [  304.190862]: ucode: Re-applying update after wake (CPU #2)
2021-10-10 17:59:35.783264+0200  localhost kernel[0]: [  304.191111]: TSC sync for cpu 2: 0x000000002bb9b624 delta 0xb4 (180)
2021-10-10 17:59:35.783776+0200  localhost kernel[0]: [  304.191325]: ucode: Re-applying update after wake (CPU #4)
2021-10-10 17:59:35.783777+0200  localhost kernel[0]: [  304.191577]: TSC sync for cpu 4: 0x000000002bc7ea15 delta 0x8c (140)
2021-10-10 17:59:35.784203+0200  localhost kernel[0]: [  304.191802]: ucode: Re-applying update after wake (CPU #6)
2021-10-10 17:59:35.784204+0200  localhost kernel[0]: [  304.192054]: TSC sync for cpu 6: 0x000000002bd6675b delta 0xb4 (180)
2021-10-10 17:59:35.784676+0200  localhost kernel[0]: [  304.192263]: ucode: Re-applying update after wake (CPU #1)
2021-10-10 17:59:35.784677+0200  localhost kernel[0]: [  304.192520]: TSC sync for cpu 1: 0x000000002be47c46 delta 0x18 (24)
2021-10-10 17:59:35.785130+0200  localhost kernel[0]: [  304.192724]: ucode: Re-applying update after wake (CPU #3)
2021-10-10 17:59:35.785131+0200  localhost kernel[0]: [  304.192978]: TSC sync for cpu 3: 0x000000002bf27d9d delta 0xbf (191)
2021-10-10 17:59:35.785589+0200  localhost kernel[0]: [  304.193184]: ucode: Re-applying update after wake (CPU #5)
2021-10-10 17:59:35.785590+0200  localhost kernel[0]: [  304.193438]: TSC sync for cpu 5: 0x000000002c0079bd delta 0xb2 (178)
2021-10-10 17:59:35.786051+0200  localhost kernel[0]: [  304.193647]: ucode: Re-applying update after wake (CPU #7)
2021-10-10 17:59:35.786052+0200  localhost kernel[0]: [  304.193900]: TSC sync for cpu 7: 0x000000002c0e8668 delta 0xb6 (182)
2021-10-10 17:59:35.786060+0200  localhost kernel[0]: IOCPUSleepKernel exit
2021-10-10 17:59:35.786064+0200  localhost kernel[0]: gIOLastWakeAbsTime: 304193923015
2021-10-10 17:59:35.786097+0200  localhost kernel[0]: (SMCLightSensor) <compose failure [UUID]>
2021-10-10 17:59:35.786108+0200  localhost kernel[0]: (SMCLightSensor) <compose failure [UUID]>
2021-10-10 17:59:35.786119+0200  localhost kernel[0]: (SMCLightSensor) <compose failure [UUID]>
2021-10-10 17:59:35.786128+0200  localhost kernel[0]: (SMCLightSensor) <compose failure [UUID]>
2021-10-10 18:10:35.000014+0200  localhost kernel[0]: [  963.407827]: time_slept (659 s 213725 u)
2021-10-10 18:10:35.000399+0200  localhost kernel[0]: IOConsoleUsers: gIOScreenLockState 3, hs 0, bs 0, now 1633882235, sm 0xe0000300
2021-10-10 18:10:35.000730+0200  localhost kernel[0]: (IOBluetoothFamily) <IOBluetoothFamily`IOBluetoothHCIUserClient::SimpleDispatchWL(IOBluetoothHCIDispatchParams*)> [IOBluetoothHCIUserClient][SimpleDispatchWL] -- bluetoothd (132) -- IOReturnOffline -- routine index 1 (HCI Request Delete) -- configState = 0x0 (On Line) (Need to be 0 -- On Line) powerState = 0x0 (Need to be 1) -- mIsDaemon = TRUE
2021-10-10 18:10:35.001964+0200  localhost kernel[0]: (SMCLightSensor) <compose failure [UUID]>
2021-10-10 18:10:35.003191+0200  localhost kernel[0]: (IOGraphicsFamily) <IOGraphicsFamily`IOFramebuffer::systemPowerChange(void*, void*, unsigned int, IOService*, void*, unsigned long)> GTrace synchronization point 106
2021-10-10 18:10:35.003291+0200  localhost kernel[0]: (SMCLightSensor) <compose failure [UUID]>
2021-10-10 18:10:35.003333+0200  localhost kernel[0]: (AppleACPIButtons) <AppleACPIButtons`AppleACPILid::message(unsigned int, IOService*, void*)> ACPI lid state changed: 1
2021-10-10 18:10:35.003896+0200  localhost kernel[0]: Dark wake display tickle
Backtrace 0xffffff80009df7e3 0xffffff7f9b13d307 0xffffff8000a5a39a 0xffffff80009e32af 0xffffff80009ecf5e 0xffffff80009ec546 0xffffff800023113e
2021-10-10 18:10:35.003914+0200  localhost kernel[0]:       Kernel Extensions in backtrace:
2021-10-10 18:10:35.003938+0200  localhost kernel[0]:          com.apple.iokit.IOGraphicsFamily(585.1)[240F08CD-4BC4-3093-8832-0E899EFC14F4]@0xffffff7f9b135000->0xffffff7f9b163fff
2021-10-10 18:10:35.003961+0200  localhost kernel[0]:             dependency: com.apple.iokit.IOPCIFamily(2.9)[4E85D41F-6AD7-3C24-911C-A8B80B599F86]@0xffffff8002d6c000->0xffffff8002d94fff
2021-10-10 18:10:35.004213+0200  localhost kernel[0]: (SMCLightSensor) <compose failure [UUID]>
2021-10-10 18:10:35.004227+0200  localhost kernel[0]: (IOBluetoothHostControllerTransport) <IOBluetoothHostControllerTransport`IOBluetoothHostControllerTransport::powerStateWillChangeTo(unsigned long, unsigned long, IOService*)> **** [IOBluetoothHostControllerTransport][powerStateWillChangeTo] -- System Wake -- SleepType is kIOPMSleepTypeNormalSleep ****

then the hibernation process started well here...

2021-10-10 18:11:24.119748+0200  localhost kernel[0]: [ 1011.137958]: PMRD: hibernateMode 0x3
2021-10-10 18:11:24.119750+0200  localhost kernel[0]: [ 1011.137963]: hibernate image path: /var/vm/sleepimage
2021-10-10 18:11:24.119751+0200  localhost kernel[0]: [ 1011.138114]: hib bank[0]: 0x0000 end 0x57fff
2021-10-10 18:11:24.119751+0200  localhost kernel[0]: [ 1011.138116]: hib bank[1]: 0x59000 end 0x9dfff
2021-10-10 18:11:24.119752+0200  localhost kernel[0]: [ 1011.138118]: hib bank[2]: 0x100000 end 0x21699fff
2021-10-10 18:11:24.119752+0200  localhost kernel[0]: [ 1011.138121]: hib bank[3]: 0x2169b000 end 0x56bb3fff
2021-10-10 18:11:24.119753+0200  localhost kernel[0]: [ 1011.138123]: hib bank[4]: 0x56bb5000 end 0x58387fff
2021-10-10 18:11:24.119753+0200  localhost kernel[0]: [ 1011.138126]: hib bank[5]: 0x58c88000 end 0x6ee9dfff
2021-10-10 18:11:24.119753+0200  localhost kernel[0]: [ 1011.138128]: hib bank[6]: 0x6f88e000 end 0x6ff7dfff
2021-10-10 18:11:24.119754+0200  localhost kernel[0]: [ 1011.138130]: hib bank[7]: 0x6fffe000 end 0x6fffefff
2021-10-10 18:11:24.119754+0200  localhost kernel[0]: [ 1011.138132]: hib bank[8]: 0x100000000 end 0x281ffffff
2021-10-10 18:11:24.119755+0200  localhost kernel[0]: [ 1011.138134]: efi pagecount 1777
2021-10-10 18:11:24.119755+0200  localhost kernel[0]: [ 1011.138331]: hibernate_page_list_setall(preflight 1) start
2021-10-10 18:11:24.119756+0200  localhost kernel[0]: [ 1011.320264]: hibernate_page_list_setall time: 181 ms
2021-10-10 18:11:24.119756+0200  localhost kernel[0]: [ 1011.320271]: pages 1209665, wire 367289, act 269294, inact 64304, cleaned 0 spec 0, zf 1483, throt 0, compr 0, xpmapped 0
2021-10-10 18:11:24.119757+0200  localhost kernel[0]:   could discard act 63248 inact 255127 purgeable 63171 spec 125749 cleaned 0
2021-10-10 18:11:24.119757+0200  localhost kernel[0]: [ 1011.320279]: hibernate_page_list_setall preflight pageCount 408249 est comp 50 setfile 935329792 min 1073741824
2021-10-10 18:11:24.119758+0200  localhost kernel[0]: [ 1011.320870]: kern_direct_file(/var/vm/sleepimage): vp size 1073741824, alloc 1073741824, mp free 186170474496, keep free 0
2021-10-10 18:11:24.119758+0200  localhost kernel[0]: [ 1011.320885]: kern_direct_file(/var/vm/sleepimage): wbc 0
2021-10-10 18:11:24.119759+0200  localhost kernel[0]: [ 1011.321149]: max io 0x20000 bytes
2021-10-10 18:11:24.119759+0200  localhost kernel[0]: [ 1011.321165]: kern_open_file_for_direct_io(<ptr>, 0)
2021-10-10 18:11:24.119760+0200  localhost kernel[0]: [ 1011.321170]: kern_open_file_for_direct_io took 0 ms
2021-10-10 18:11:24.119760+0200  localhost kernel[0]: [ 1011.321177]: Opened file /var/vm/sleepimage, size 1073741824, extents 5, maxio 20000 ssd 1
2021-10-10 18:11:24.119761+0200  localhost kernel[0]: [ 1011.321245]: polled file major 1, minor 0, blocksize 4096, pollers 3
2021-10-10 18:11:24.119761+0200  localhost kernel[0]: [ 1012.450554]: vm_compressor_record_warmup (0 - 0)
2021-10-10 18:11:24.119762+0200  localhost kernel[0]: [ 1012.450557]: vm_compressor_flush - starting
2021-10-10 18:11:24.119762+0200  localhost kernel[0]: [ 1012.450891]: vm_compressor_flush completed - took 0 msecs - vm_num_swap_files = 1, vm_num_pinned_swap_files = 0, vm_swappin_enabled = 0
2021-10-10 18:11:24.119763+0200  localhost kernel[0]: [ 1012.527420]: hibernate_flush_memory: buffer_cache_gc freed up 44487 wired pages
2021-10-10 18:11:24.119763+0200  localhost kernel[0]: [ 1012.527423]: hibernate_flush_memory() considered(842382) reentered_on_q(575436) found_dirty(266946)
2021-10-10 18:11:24.119764+0200  localhost kernel[0]: [ 1012.527425]:    skipped_cleaning(0) skipped_transient(0) skipped_precious(0) skipped_external(0) queue_nolock(0)
2021-10-10 18:11:24.119764+0200  localhost kernel[0]: [ 1012.527427]:    queue_paused(40) throttled(1017) throttle_timeout(0) drained(2) drain_timeout(0)
2021-10-10 18:11:24.119765+0200  localhost kernel[0]: [ 1012.527433]: hibernate_alloc_pages act 130268, inact 319427, anon 461, throt 0, spec 125751, wire 387814, wireinit 205227
2021-10-10 18:11:24.119765+0200  localhost kernel[0]: [ 1012.527437]: hibernate_setup(0) took 1205 ms, swapPin(1) ssd(1)
2021-10-10 18:11:24.119766+0200  localhost kernel[0]: [ 1012.527537]: DebugEnhancer    DBGENH: @ IOHibernateSystemSleep is called, result is: 0

This means that from 2021-10-10 18:10:35.000014 to 2021-10-10 18:11:24.119748+0200 we have about 1 minute during which laptop wake-up itself only partially (laptop screen remains off) for switching from standby sleep to hibernation sleep? Did your laptop/desktop suffer the same issue? Could this be avoidable?

lvs1974 commented 3 years ago

@profzei:

we have about 1 minute during which laptop wake-up itself only partially (laptop screen remains off) for switching from standby sleep to hibernation sleep? Did your laptop/desktop suffer the same issue? Could this be avoidable?

it is standard behaviour, all macs use maintenance wake (dark wake - display remains off) to switch laptop from regular sleep into hibernation. It is not an issue.

profzei commented 3 years ago

it is standard behaviour, all macs use maintenance wake (dark wake - display remains off) to switch laptop from regular sleep into hibernation. It is not an issue.

Thank you very much for your insight! It's just my opinion, but this is a great improvement for Hackintosh laptops