Waking your Mac from sleep: log highlights

In macOS Sierra, problems waking from sleep have not gone away. They seem to be much less common than in El Capitan, but when they occur they are generally much harder to diagnose, as you are unable to browse past log entries using Console.

I have been looking at some log excerpts using Consolation (see the Downloads item in the above menus if you do not have a copy yet), and offer some milestones which may help guide you through diagnosis of startup problems in Sierra. In each log entry, I give just the timestamp in seconds and details of that entry, for the sake of being concise. If you want full log extracts, just ask.

It’s worth noting here that Apple considers that studying Sierra’s log to investigate sleep and wake problems is incorrect. It recommends instead using the command
pmset -g log
to view a history of wakes, sleeps, and relevant matters. This will normally result in copious output, so it’s probably best to pipe the standard output into a text file:
touch pmsetlogout.text pmset -g log > pmsetlogout.text

The first sign that you should see of waking from sleep is the kernel entry:
19.000023 kernel: PMRD: System Wake
However, as we’ll see shortly, there are some entries with earlier timestamps which normally appear later in the log, presumably because the logging system is initially shut down, and those entries cannot appear until after the first few steps in waking up. If you’re looking for the start of wake events, filtering on
processImagePath CONTAINS[c] kernel AND eventMessage CONTAINS[c] system wake
should return a list of the start of all such events.

During system sleep, the system may wake itself up periodically to perform Time Machine backups and other high-priority tasks, if Power Nap is enabled, but user events scheduled to take place via launchd are normally skipped. So if you have my tool Blowhole writing to the log every hour, those entries will normally cease during sleep.

After that initial announcement from the kernel, there is a short series of further kernel messages:
19.000112 kernel: IOConsoleUsers: gIOScreenLockState 2, hs 0, bs 0, now 1488109939, sm 0xe0000300 19.002616 kernel: (AppleRTC) RTC: PowerByCalendarDate setting ignored 19.002617 kernel: (AppleRTC) RTC: PowerByCalendarDate setting ignored

Normally, Grand Central Dispatch then cuts in:
19.001619 coreduetd: [com.apple.coreduet.admissionCheck.] modulation timer has tickled *** 19.001621 coreduetd: [com.apple.coreduet.admissionCheck.] enough time has passed move slot 68 -> 69

Following that is a long series of back-timed entries as coreduetd gets to work:
18.238974 coreduetd: [com.apple.coreduet.admissionCheck.] Modulating pool 1073741825 (variant com.apple.coreduet.budget.energy, type 0, with dailyval 0) to 18 from 18 18.238980 coreduetd: [com.apple.coreduet.admissionCheck.] Modulating pool 1073741827 (variant com.apple.coreduet.budget.network, type 0, with dailyval 13000000) to 8184696 from 8066905 18.238989 coreduetd: [com.apple.coreduet.admissionCheck.] Modulating pool 1073741828 (variant com.apple.coreduet.budget.network, type 0, with dailyval 100000000) to 62900142 from 61994051 18.239014 coreduetd: [com.apple.coreduet.admissionCheck.] Modulating pool 1 (variant com.apple.coreduet.budget.energy, type 2, with dailyval 0) to 18 from 18 18.239018 coreduetd: [com.apple.coreduet.admissionCheck.] Modulating pool 2 (variant com.apple.coreduet.budget.network, type 2, with dailyval 100000000) to 62959378 from 62053287
running up to the last pool:
19.004567 coreduetd: [com.apple.coreduet.admissionCheck.] Modulating pool 150 (variant com.apple.coreduet.budget.network, type 2, with dailyval 100000000) to 62959378 from 62053287

The kernel then makes its last entry for a while, revealing the reason for the period of sleep:
19.006041 kernel: (AppleSMC) Previous sleep cause: 5

There’s no good guide to sleep or shutdown cause numbers, I’m afraid. Generally, positive numbers indicate a software reason, negative numbers a hardware reason. A zero (0) usually signifies a protective SafeSleep when a laptop is conserving the last of its battery power. A cause of 5 means that the sleep was initiated in a normal and orderly way, either from a timer resulting from your Energy Saver settings, or a user action of putting the system to sleep.

For shutdowns, you may also encounter cause 3, which is a ‘dirty’ forced shutdown or restart, which is something you should not encounter in sleep causes.

In Consolation or log show, you can list the cause numbers of previous sleeps using a filter predicate of
processImagePath CONTAINS[c] kernel AND eventMessage CONTAINS[c] system wake

The next series of entries can appear in different orders, but show other systems starting to wake up:
19.005252 securityd: [com.apple.securityd.powerwatch] powerstates 19.005253 securityd: [com.apple.securityd.powerwatch] disk 19.005254 securityd: [com.apple.securityd.powerwatch] net 19.005255 securityd: [com.apple.securityd.powerwatch] enter DarkWake 19.005064 configd: (IPConfiguration) [com.apple.IPConfiguration.Server] IPConfiguration: Early Wake 19.006418 apsd: (CoreDaemon) power management notification 0x8019 19.006439 apsd: (CoreDaemon) <APSWakeStateManager: 0x7fbefe722980>: prepareForWakingIntoDarkWake 19.005136 mDNSResponder: [com.apple.mDNSResponder.AllINFO] SnowLeopardPowerChanged F7F00180 0 8019 CPU Network Disk 19.005540 blued: (IOBluetooth) [com.apple.bluetooth.CBManager] -> Powering to On State. 19.005543 blued: (IOBluetooth) [com.apple.bluetooth.CBManager] Capabilities: 19.005546 blued: (IOBluetooth) [com.apple.bluetooth.CBManager] disk 19.005548 blued: (IOBluetooth) [com.apple.bluetooth.CBManager] net 19.005549 blued: (IOBluetooth) [com.apple.bluetooth.CBManager] 19.005262 UserEventAgent: (com.apple.cts) [com.apple.xpc.activity.All] DarkWake:cpu disk net 19.005647 UserEventAgent: (com.apple.cts) [com.apple.xpc.activity.All] DarkWake:cpu disk net 19.006603 sharingd: [com.apple.sharing.Daemon] Power management state 32793 19.006605 sharingd: [com.apple.sharing.Daemon] Dark Wake
Note again that, according to the timestamps, some of those log entries appear out of sequence.

At this stage, you will see a long run of entries from mDNSResponder, starting with something like:
19.005458 mDNSResponder: [com.apple.mDNSResponder.AllINFO] SystemWakeForNetworkAccess: Wake On LAN: 1 19.005460 mDNSResponder: [com.apple.mDNSResponder.AllINFO] SnowLeopardPowerChanged: Waking up, Acking Wakeup, SleepLimit 0 SleepState 2 19.005461 mDNSResponder: [com.apple.mDNSResponder.AllINFO] Waking (old state 2) at 0 19.005466 mDNSResponder: [com.apple.mDNSResponder.AllINFO] mDNSCoreMachineSleep waking: NextSRVUpdate in 1000 -1476983970 19.005469 mDNSResponder: [com.apple.mDNSResponder.AllINFO] mDNSCoreMachineSleep: 32 www.everestjs.net.edgekey-staging.net. CNAME e1164.c.akamaiedge-staging.net.: Adjusted the remain ttl 12583 by 1156 seconds

There is here an odd incongruity in the privacy provided by the new log system: in many places, log entries are redacted using <private> to the point where they are almost worthless. Yet when mDNSResponder fires up here, it lists in full a large number of internet addresses which have been cached for long periods of time, and could be used when reconstructing an internet use history!

The next kernel entries occur as other hardware services are reinstated:
19.017049 kernel: (AppleThunderboltNHI) 182911405812us AppleThunderboltNHIType2::prePCIWake - power up complete - took 1 us 19.017050 kernel: (AppleThunderboltNHI) AppleThunderboltNHIType2::prePCIWake - power up complete - took 1 us 19.017303 kernel: (AirPortBrcm4360) ARPT: 182911.406066: wl0: leaveModulePoweredForOffloads: Wi-Fi will stay on. 19.017328 kernel: (AirPortBrcm4360) ARPT: 182911.406092: AirPort_Brcm43xx::syncPowerState: WWEN[disabled] 19.122543 kernel: (IOThunderboltFamily) IOThunderboltSwitch<0x0>(0x0)::listenerCallback - Thunderbolt HPD packet for route = 0x0 port = 11 unplug = 0 19.122615 kernel: (IOThunderboltFamily) IOThunderboltSwitch<0x0>(0x0)::listenerCallback - Thunderbolt HPD packet for route = 0x0 port = 12 unplug = 0 19.122574 securityd: [com.apple.securityd.powerwatch] system will power on 19.122578 securityd: [com.apple.securityd.SS] 0x7fff5b611b30 will power on 19.122629 securityd: [com.apple.securityd.powerwatch] sending no response 19.122312 configd: (CaptiveNetworkSupport) [com.apple.captive.Controller] Wake 19.123709 kernel: PMRD: full wake promotion (reason 1) 123 ms 19.123710 kernel: full wake promotion (reason 1) 123 ms 19.124244 kernel: PMRD: prevent idle sleep list: IODisplayWrangler+ (1) 19.124245 kernel: prevent idle sleep list: IODisplayWrangler+ (1) 19.123565 sharingd: [com.apple.sharing.AirDrop] Screen turned on 19.123572 sharingd: [com.apple.sharing.AirDrop] Scanning mode off: console=1, discoverable=0, screenOn=1, unlockedOnce=1 19.124541 sharingd: (CoreUtils) [com.apple.sharing.SDNearbyAgentCore] Screen state changed to on 19.124550 sharingd: (CoreUtils) [com.apple.sharing.SDNearbyAgentCore] Activity level changed 1 (Disabled) -> 7 (Screen) 19.125062 powerd: rootDomain's user activity state:1 19.125074 powerd: Display state: On 19.125084 powerd: Activity changes from 0x0 to 0x1. UseActiveState:1 19.125085 powerd: hidActive:0 displayOff:0 assertionActivityValid:1 now:0x2ca7f hid_ts:0x2c55e assertion_ts:0x2ca7f

Grand Central Dispatch components including CTS and coreduetd are usually starting to appear in log entries by now, for example:
19.124279 UserEventAgent: (com.apple.cts) [com.apple.xpc.activity.All] User <private> 19.123986 UserEventAgent: (com.apple.cts) [com.apple.xpc.activity.All] User <private> 19.124836 coreduetd: [com.apple.coreduet.admissionCheck.] Incoming using send_message_with_reply 19.124842 coreduetd: [com.apple.coreduet.admissionCheck.] Received [CDDProtocolMessageTypeTAttributeOccurred] message, msgtype = [52], from clientId [10]... 19.124854 coreduetd: [com.apple.coreduet.admissionCheck.] Attribute with Id [45064] occurred with value [<private>], rising edge [1], falling edge [0] 19.125751 UserEventAgent: (BluetoothUserAgent-Plugin) [com.apple.bluetooth.User Agent] [BTUserEventAgentController hostControllerPoweredOn] on = 0 off = 14718 19.125752 UserEventAgent: (BluetoothUserAgent-Plugin) [com.apple.bluetooth.User Agent] [BTUserEventAgentController messageTracerEventDriven] hostControllerPoweredOn 19.125753 UserEventAgent: (BluetoothUserAgent-Plugin) [com.apple.bluetooth.User Agent] [BTUserEventAgentController messageTracerEventDriven]

With these come entries concerning Bluetooth, AirDrop, and the widening range of services which are being reinstated.

Hopefully this has given you a broad overview of what you can expect to see in the first 130 milliseconds after the start of a system wake, and it will help you identify any problems which may have occurred then.

4Comments

Add yours

1

S convey on March 3, 2017 at 2:34 am

Hello there! I came across this post when looking into a boot issue I am having with 10.12.2 which I explain in detail here:

https://forums.macrumors.com/threads/imac-wont-fully-boot-black-screen-spinning.2035237/#post-24361731

Any suggestions would be greatly appreciated!

LikeLike
- 2
  
  hoakley on March 3, 2017 at 6:18 am
  
  First, run hardware diagnostics as detailed here.
  If they check out fine, I’d made a bootable installer USB memory stick with 10.12.3 installer on it, and start up from that. If it won’t start up from that, it suggests a firmware or hardware problem, which really needs an Apple engineer to run their more advanced diagnostics on.
  If it boots from that, run Disk Utility from there, First Aid to startup disk, and install 10.12.3 from the USB stick.
  I wish you success,
  Howard.
  
  LikeLike
  - 3
    
    S convey on March 5, 2017 at 10:09 pm
    
    Thx for the suggestion… I couldn’t get it to start in diagnostic mode but I did run an Apple ASD on it and it all passed… As such I cloned the HD using disk utility and then did a clean install and things seem to be on the up and up now…. thx again and fingers crossed.
    
    LikeLike
    - 4
      
      hoakley on March 5, 2017 at 10:15 pm
      
      Well done: I hope that has fixed it.
      Howard.
      
      LikeLike

Share this:

Related