MacOS – How has it suddenly become so much faster to wake OS X from “safe sleep”

filevaultmacossleep-wake

Because I'm super paranoid about security, I configure my MacBook to always "safe sleep" and destroy its FileVault key on entering standby:

$ sudo pmset -a hibernatemode 25 DestroyFVKeyOnStandby 1

As explained under pmset(1):

hibernatemode = 25 (binary 0001 1001) is only settable via pmset. The system will store a copy of memory to persistent storage (the disk), and will remove power to memory. The system will restore from disk image. If you want "hibernation" – slower sleeps, slower wakes, and better battery life, you should use this setting.

and:

destroyfvkeyonstandby – Destroy File Vault Key when going to standby mode. By default File vault keys are retained even when system goes to standby. If the keys are destroyed, user will be prompted to enter the password while coming out of standby mode.(value: 1 – Destroy, 0 – Retain)

Consequently, when the machine wakes from sleep one must:

  1. first unlock FileVault at an EFI lock screen; and then
  2. unlock OS X at a login window.

Historically, there was an understandable delay between these two steps, as OS X has to restore from disk image (copying the hibernatefile into RAM) before it's able to do anything else. Whilst this was happening, the display would show the login window overlaid by a semi-transparent covering together with a progress bar.

However, I no longer witness any delay between steps 1 and 2. It appears that OS X is able to resume almost as soon as FileVault is unlocked, which suggests to me that power may not have been removed from RAM as promised by hibernatemode 25.

What's going on? Have, as the logs below suggest, Apple found some magical way to restore gigabytes of RAM from disk image impercetably fast (and, if so, wouldn't every laptop user prefer to "safe sleep", perhaps without destroying FileVault keys, rather than keeping RAM powered and wasting battery)? Or, more likely(?), is my MacBook no longer really entering "safe sleep"? If the latter, why—and how can I fix it?

$ sw_vers
ProductName:    Mac OS X
ProductVersion: 10.11.3
BuildVersion:   15D21

$ pmset -g
System-wide power settings:
 SleepDisabled      0
 DestroyFVKeyOnStandby      1
Active Profiles:
Battery Power       -1
AC Power        -1*
Currently in use:
 standbydelay         10800
 standby              1
 womp                 0
 halfdim              1
 hibernatefile        /var/vm/sleepimage
 powernap             0
 gpuswitch            2
 networkoversleep     0
 disksleep            10
 sleep                1
 autopoweroffdelay    14400
 hibernatemode        25
 autopoweroff         0
 ttyskeepawake        1
 displaysleep         10
 acwake               0
 lidwake              1

$ cat /var/log/system.log
Feb  5 01:19:35 eggyal PowerChime[622]: 53728.262434: GOING TO SLEEP: kStateDarkWake -> kStateAsleep
Feb  5 01:19:35 eggyal PowerChime[622]: 53728.262821: Calling goingToSleepBlock
Feb  5 01:19:38 eggyal kernel[0]: PM response took 3072 ms (57, powerd)
Feb  5 01:19:38 eggyal kernel[0]: AppleCamIn::systemWakeCall - messageType = 0xE0000280
Feb  5 01:19:38 eggyal kernel[0]: AppleCamIn::systemWakeCall - messageType = 0xE0000340
Feb  5 01:19:38 eggyal kernel[0]: kern_open_file_for_direct_io(0)
Feb  5 01:19:38 eggyal kernel[0]: kern_open_file_for_direct_io took 24 ms
Feb  5 01:19:38 eggyal kernel[0]: Opened file /var/log/SleepWakeStacks.bin, size 172032, extents 1, maxio 40000 ssd 1
Feb  5 01:19:38 eggyal kernel[0]: polled file major 1, minor 0, blocksize 4096, pollers 3
Feb  5 07:52:38 eggyal kernel[0]: hibernate image path: /var/vm/sleepimage
Feb  5 07:52:38 eggyal kernel[0]: efi pagecount 72
Feb  5 07:52:38 eggyal kernel[0]: hibernate_page_list_setall(preflight 1) start
Feb  5 07:52:38 eggyal kernel[0]: hibernate_page_list_setall time: 292 ms
Feb  5 07:52:38 eggyal kernel[0]: pages 1229108, wire 262730, act 464069, inact 1872, cleaned 0 spec 10, zf 3948, throt 0, compr 155445, xpmapped 40000
Feb  5 07:52:38 eggyal kernel[0]: could discard act 169997 inact 38206 purgeable 85433 spec 47398 cleaned 0
Feb  5 07:52:38 eggyal kernel[0]: WARNING: hibernate_page_list_setall skipped 10768 xpmapped pages
Feb  5 07:52:38 eggyal kernel[0]: hibernate_page_list_setall preflight pageCount 262730 est comp 39 setfile 491782144 min 1073741824
Feb  5 07:52:38 eggyal kernel[0]: kern_open_file_for_direct_io(0)
Feb  5 07:52:38 eggyal kernel[0]: kern_open_file_for_direct_io took 21 ms
Feb  5 07:52:38 eggyal kernel[0]: Opened file /var/vm/sleepimage, size 1073741824, extents 2, maxio 40000 ssd 1
Feb  5 07:52:38 eggyal kernel[0]: polled file major 1, minor 0, blocksize 4096, pollers 3
Feb  5 07:52:38 eggyal kernel[0]: vm_compressor_record_warmup (29246 - 32193)
Feb  5 07:52:38 eggyal kernel[0]: vm_compressor_flush - starting
Feb  5 07:52:38 eggyal kernel[0]: vm_compressor_flush completed - took 7834 msecs
Feb  5 07:52:38 eggyal kernel[0]: hibernate_flush_memory: buffer_cache_gc freed up 13242 wired pages
Feb  5 07:52:38 eggyal kernel[0]: hibernate_alloc_pages act 261470, inact 39096, anon 11567, throt 0, spec 47402, wire 274180, wireinit 32085
Feb  5 07:52:38 eggyal kernel[0]: hibernate_setup(0) took 9624 ms
Feb  5 07:52:38 eggyal kernel[0]: AppleCamIn::systemWakeCall - messageType = 0xE0000340
Feb  5 01:19:49 eggyal kernel[0]: hibernate_page_list_setall(preflight 0) start
Feb  5 07:52:38 eggyal kernel[0]: hibernate_teardown started
Feb  5 07:52:38 eggyal kernel[0]: hibernate_teardown: wired_pages 274183, free_pages 1766704, active_pages 40000, inactive_pages 0, speculative_pages 0, cleaned_pages 0, compressor_pages 80
Feb  5 07:52:38 eggyal kernel[0]: hibernate_teardown_pmap_structs done: last_valid_compact_indx 181266
Feb  5 07:52:38 eggyal kernel[0]: hibernate_teardown: mark_as_unneeded_pages 2048, 26515, 18518
Feb  5 07:52:38 eggyal kernel[0]: hibernate_teardown completed - discarded 47081
Feb  5 07:52:38 eggyal kernel[0]: hibernate_page_list_setall time: 649 ms
Feb  5 07:52:38 eggyal kernel[0]: pages 550280, wire 202232, act 40000, inact 0, cleaned 0 spec 0, zf 0, throt 0, compr 80, xpmapped 40000
Feb  5 07:52:38 eggyal kernel[0]: did discard act 136037 inact 39096 purgeable 85433 spec 47402 cleaned 0
Feb  5 07:52:38 eggyal kernel[0]: WARNING: hibernate_page_list_setall skipped 16430 xpmapped pages
Feb  5 07:52:38 eggyal kernel[0]: hibernate_page_list_setall found pageCount 242312
Feb  5 07:52:38 eggyal kernel[0]: IOHibernatePollerOpen, ml_get_interrupts_enabled 0
Feb  5 07:52:38 eggyal kernel[0]: IOHibernatePollerOpen(0)
Feb  5 07:52:38 eggyal kernel[0]: encryptStart 14010
Feb  5 07:52:38 eggyal kernel[0]: bitmap_size 0x3f444, previewSize 0x4028, writing 241958 pages @ 0x5747c
Feb  5 07:52:38 eggyal kernel[0]: hibernate_rebuild started
Feb  5 07:52:38 eggyal kernel[0]: hibernate_rebuild_pmap_structs done: last_valid_compact_indx 181266
Feb  5 07:52:38 eggyal kernel[0]: hibernate_rebuild completed - took 51 msecs
Feb  5 07:52:38 eggyal kernel[0]: booter start at 1073 ms smc 0 ms, [17, 0, 0] total 16393 ms, dsply 0, 0 ms, tramp 544 ms
Feb  5 07:52:38 eggyal kernel[0]: hibernate_machine_init: state 2, image pages 202019, sum was be127fc2, imageSize 0x17cb5000, image1Size 0xecb6000, conflictCount 2498, nextFree acf
Feb  5 07:52:38 eggyal kernel[0]: hibernate_newruntime_map time: 0 ms, IOPolledFilePollersOpen(), ml_get_interrupts_enabled 0
Feb  5 07:52:38 eggyal kernel[0]: IOPolledFilePollersOpen(0) 1 ms
Feb  5 07:52:38 eggyal kernel[0]: hibernate_machine_init reading
Feb  5 07:52:38 eggyal kernel[0]: PMStats: Hibernate read took 281 ms
Feb  5 07:52:38 eggyal kernel[0]: hibernate_machine_init pagesDone 242099 sum2 91d0cb87, time: 281 ms, disk(0x20000) 512 Mb/s, comp bytes: 47316992 time: 36 ms 1232 Mb/s, crypt bytes: 150990848 time: 38 ms 3702 Mb/s

Best Answer

If you have Filevault enabled and don't get the EFI authentication screen (apple.com > HT204156), you're not waking from standby. You should be prompted for creds twice: once by EFI for Filevault, then a progress bar as the Filevault volume is mounted and hibernation image restored, then a second authentication from the OS to log back in.

sudo pmset -f log may help to confirm what's going on.

For what it's worth, I've also found that the hibernatemode=25 option seems broken. Testing on a 2013 MacbookAir6,2 / A1466 running 10.11.5 with hibernatemode=25 (direct-to-standby, skip sleep), the machine did hibernate on closing the lid after I'd first enabled this option. However it's not done it again. (I did update to 10.11.5 in the interim...)

Apple's documentation https://support.apple.com/en-us/HT202124 says, "Notebooks need to be running on battery power [and] must not have any external connections (such as Ethernet, USB, Thunderbolt, SD card, displays, Bluetooth, and so on)" in order to go into standby.

Paying attention to the above conditions, I've tested this a few times and my machine will only go into standby (and thus, destroy the Filevault key if destroyfvkeyonstandby is enabled) when the battery is fully depleted.

i.e. hibernatemode=25 doesn't actually work as documented in pmset(1).

Related Question