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:
- first unlock FileVault at an EFI lock screen; and then
- 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
