Exploring Sierra 10.12.5 sleep and wake in the log 1

Log messages during the processes of going to sleep and waking from sleep have changed with Sierra’s unified log, and have evolved further with successive updates to Sierra. This article provides the latest information available, running Sierra 10.12.5 on an iMac17,1, with system and display sleep enabled, disk sleep turned off, and Power Nap enabled.

This should help you diagnose crashes and other problems which occur when going to sleep or (more commonly) when waking up. If you don’t know what to expect, you cannot know what is abnormal.

Make a logarchive

The best way to investigate any sleep or wake event is to make a logarchive covering the last thirty seconds or so prior to sleeping/waking, and the first minute or so after the sleep/wake itself.

Although logarchive format is currently proprietary, and consists of a bundle within which are large numbers of nested folders, Consolation 2.2, Console, and Terminal’s log command all work with logarchives. They preserve all log entries indefinitely, and are much better than trying to work with a live system log.

Leave your Mac for a minute after sleep/wake, open Consolation 2.2, set a Period of, say, 2 minutes – long enough to capture the whole state change, then click on the Write logarchive button to create and save the logarchive to disk.

Finding the sleep and wake times

One of the best waypoints to indicate the start of preparations for sleep is apsd, the Apple Push Notification service daemon, which writes to the log early in the process:
power management notification 0x00
<APSWakeStateManager: 0x7fad2de1e380>: prepareForSleep

Preparations complete with a series of messages from the kernel, the last of which contains the system ticks just before sleep takes place:
gIOLastWakeAbsTime: 378688664461414
This makes gIOLastWakeAbsTime a good term to search for when looking for the moment that sleep is established. That can occur more than 7 seconds after the start of preparations for sleep.

Waking is marked by two messages from the kernel:
PMRD: System Wake
IOConsoleUsers: gIOScreenLockState 2, hs 0, bs 0, now 1496590499, sm 0xe0000300

making System Wake a good term to search for when looking for the first sign of waking up.

Preparing to sleep

The imminent onset of sleep is quickly propagated to all tasks and activities, so that each can prepare for the change in state.

One of the first is CTS, which reports
Sleep:<off>
twice, and DAS reports similarly. I will examine the behaviour of DAS and CTS in detail in a subsequent article.

Bluetooth is quick to react, as is mDNSResponder. Then apsd and mDNSResponder perform a lot of housekeeping tasks in preparation for sleep, what apsd refers to as ‘recreating the courier state’. Once complete, mDNSResponder reports
AllowSleepNow: IOPMConnectionAcknowledgeEventWithOptions(5) ready for sleep at 4066628859 (4989 ticks remaining)
which prompts the kernel to record:
PM response took 5020 ms (82, powerd)

Almost all the remaining entries come from the kernel. An initial series records AirPort being shut down, then the en0 Ethernet link. Some third-party kernel extensions, such as the PromiseSTEX KEXT to support Promise external RAID systems, go through a sleep routine too, normally completing with an entry such as
setPowerState done

The kernel then puts successive hardware systems to sleep:
PMRD: System Sleep
IOCPUSleepKernel
IOPlatformSleepAction -> AppleSMC
IOPlatformSleepAction -> AppleSMBusControllerICH
IOPlatformSleepAction -> AppleThunderboltHAL

after which there may be entries about AppleThunderboltNHI and AppleACPIPlatform, then wake actions are set
IOPlatformWakeAction -> AppleThunderboltHAL
IOPlatformWakeAction -> AppleSMBusControllerICH
IOPlatformWakeAction -> AppleRTC
IOPlatformWakeAction -> AppleKeyStore
IOPlatformWakeAction -> AppleSMC

The last entries before sleep most probably shut processor cores down apart from the first, although they refer to Started cpu, then the kernel writes
gIOLastWakeAbsTime: 378688664461414
followed by log silence.

Waking up

Once the kernel is awake, macOS starts to reverse all the changes that took place when preparing to sleep. Early risers include Bluetooth, AirDrop, and securityd. apsd kicks in with
power management notification 0x8019
<APSWakeStateManager: 0x7fad2de1e380>: prepareForWakingIntoDarkWake

and CTS with
DarkWake:cpu disk net
twice.

mDNSResponder then gets to work restoring its DNS information. During this, the kernel should pronounce the previous sleep cause code, with
Previous sleep cause: 5
Cause codes are detailed here.

Other hardware systems are restored, notably AirPort and Thunderbolt. Expect to see sequences of messages from the kernel, such as
full wake promotion (reason 1) 125 ms
prevent idle sleep list: IODisplayWrangler+ (1)

CTS will then declare
User Active
twice.

Many other systems wake up and get ready for use, and there are long series of entries from mDNSResponder. Third-party kernel extensions which require waking up, such as the PromiseSTEX KEXT for Promise RAID systems, may not wake up for a second or so, but should then make a series of log entries. These are followed by many CoreAudio messages.

The Ethernet link on en0 is also a relatively slow starter, and may not appear in the log for nearly two seconds after the start of waking up. apsd then works through its list of topics to ‘recreate the courier state’, which sets everything back to waking order. Those are followed by messages relating to iCloud services which have been restored, and many messages from coreduetd.

Throughout these entries, you should see evidence of individual apps being woken from sleep, and getting back on track again.

Log entries made by the dispatching system of DAS and CTS are particularly interesting, as they give further insights into how this system works. I will work through these in detail in a later article, although I cannot guarantee to be able to explain why CTS keeps entering its messages into the log twice!