Sleep interrupted by "DarkWake" repeating every minute

Question

Level 1

39 points

Sleep interrupted by "DarkWake" repeating every minute

My Mac mini (mid-2011) is exhibiting strange sleep behavior. I'm not sure how long it's been doing this, as I only noticed it recently, but I suspect it's been quite a while. Basically, if I manually put it to sleep, it does go to sleep after a few seconds, and the tiny power-indicator LED begins its "breathing" mode. But within 2–3 more seconds, it goes solid-bright again, and I can hear the internal HD spinning up… though it doesn't fully waken, as no video signal gets sent to my two displays. (I've read that this is known as "DarkWake" mode.) The LED remains solid-bright for almost a minute, and then the computer goes back to normal sleep again… for 2–3 seconds. And then the cycle repeats, ad infinitum, every 56 seconds.

I've been troubleshooting this problem by looking at the system log in Console. The following is the contents of the system log corresponding to one iteration of the DarkWake cycle:

1/29/15 5:23:50.000 PM kernel[0]: Wake reason: EHC1

1/29/15 5:23:50.000 PM kernel[0]: AirPort_Brcm43xx::powerChange: System Wake - Full Wake/ Dark Wake / Maintenance wake

1/29/15 5:23:50.000 PM kernel[0]: AirPort_Brcm43xx::checkInterfacePowerState: Check _pwrOffThreadCall!

1/29/15 5:23:50.000 PM kernel[0]: Previous Sleep Cause: 5

1/29/15 5:23:50.000 PM kernel[0]: The USB device HubDevice (Port 1 of Hub at 0xfd000000) may have caused a wake by issuing a remote wakeup (2)

1/29/15 5:23:50.000 PM kernel[0]: AppleThunderboltHAL::earlyWake - complete - took 1 milliseconds

1/29/15 5:23:50.000 PM kernel[0]: Thunderbolt Self-Reset Count = 0xedefbe00

1/29/15 5:23:50.000 PM kernel[0]: TBT W (1): 0 [x]

1/29/15 5:23:50.000 PM kernel[0]: **** [IOBluetoothHostControllerUSBTransport][SuspendDevice] -- Resume -- suspendDeviceCallResult = 0x0000 (kIOReturnSuccess) -- 0x6400 ****

1/29/15 5:23:53.000 PM kernel[0]: No interval found for . Using 8000000

1/29/15 5:23:55.000 PM kernel[0]: Ethernet [AppleBCM5701Ethernet]: Link up on en0, 100-Megabit, Full-duplex, Symmetric flow-control, Debug [796d,0301,0de1,0300,4de1,0000]

1/29/15 5:23:56.079 PM ntpd[5952]: ntpd: wake time set +0.434174 s

1/29/15 5:23:56.147 PM com.apple.time[164]: Interval maximum value is 946100000 seconds (specified value: 9223372036854775807).

1/29/15 5:23:56.154 PM com.apple.time[164]: Interval maximum value is 946100000 seconds (specified value: 9223372036854775807).

1/29/15 5:23:56.222 PM com.apple.time[164]: Interval maximum value is 946100000 seconds (specified value: 9223372036854775807).

1/29/15 5:24:06.313 PM AirPlayUIAgent[857]: 2015-01-29 05:24:06.312825 PM [AirPlayUIAgent] Changed PIN pairing: no

1/29/15 5:24:06.362 PM AirPlayUIAgent[857]: 2015-01-29 05:24:06.361999 PM [AirPlayUIAgent] Changed PIN pairing: no

1/29/15 5:24:16.564 PM WindowServer[127]: _CGXHWCaptureWindowList: No capable active display found.

1/29/15 5:24:31.000 PM kernel[0]: **** [IOBluetoothHostControllerUSBTransport][SuspendDevice] -- Suspend -- suspendDeviceCallResult = 0x0000 (kIOReturnSuccess) -- 0x6400 ****

1/29/15 5:24:35.000 PM kernel[0]: pci pause: SDXC

1/29/15 5:24:38.691 PM ntpd[5952]: ntpd: wake time set -0.844827 s

1/29/15 5:24:38.000 PM kernel[0]: AirPort_Brcm43xx::powerChange: System Sleep

————[ begin repeat x3 ]————

1/29/15 5:24:38.000 PM kernel[0]: Sound assertion in AppleHDAPath at line 1100

1/29/15 5:24:38.000 PM kernel[0]: Sound assertion in AppleHDAPathSet at line 1120

1/29/15 5:24:38.000 PM kernel[0]: Sound assertion in AppleHDAEngine at line 14993

1/29/15 5:24:38.000 PM kernel[0]: Sound assertion in AppleHDADriver at line 5202

1/29/15 5:24:38.000 PM kernel[0]: Sound assertion in AppleHDADriver at line 5174

1/29/15 5:24:38.000 PM kernel[0]: Sound assertion in AppleHDADriver at line 4721

1/29/15 5:24:38.000 PM kernel[0]: Sound assertion in AppleHDADriver at line 4745

————[ end repeat x3 ]————

1/29/15 5:24:38.798 PM com.apple.time[164]: Interval maximum value is 946100000 seconds (specified value: 9223372036854775807).

1/29/15 5:24:38.808 PM com.apple.time[164]: Interval maximum value is 946100000 seconds (specified value: 9223372036854775807).

1/29/15 5:24:38.915 PM com.apple.time[164]: Interval maximum value is 946100000 seconds (specified value: 9223372036854775807).

1/29/15 5:24:39.000 PM kernel[0]: **** [IOBluetoothHostControllerUSBTransport][SuspendDevice] -- Resume -- suspendDeviceCallResult = 0x0000 (kIOReturnSuccess) -- 0x6400 ****

1/29/15 5:24:41.000 PM kernel[0]: AppleThunderboltHAL::earlyWake - complete - took 0 milliseconds

1/29/15 5:24:41.000 PM kernel[0]: **** [IOBluetoothHostControllerUSBTransport][SuspendDevice] -- Suspend -- suspendDeviceCallResult = 0x0000 (kIOReturnSuccess) -- 0x6400 ****

1/29/15 5:24:41.000 PM kernel[0]: AppleBCM5701Ethernet [en0]: Link down (womp enabled, proxy 357)

1/29/15 5:24:41.000 PM kernel[0]: Thunderbolt Self-Reset Count = 0xedefbe00

————[ begin next cycle ]————

1/29/15 5:24:44.000 PM kernel[0]: Wake reason: EHC1

Any help in determining and resolving the cause of the problem would be appreciated.

--

Mac mini (Mid 2011) 2.3 GHz Core i5-OTHER, OS X Mavericks (10.9.5), 8 GB RAM, Intel HD Graphics 3000

Posted on Feb 3, 2015 1:37 PM

Reply

Answer 1

Linc Davis

Level 10

209,961 points

Feb 3, 2015 6:28 PM in response to jdmcmurtry

Disconnect all USB devices, if any, and see whether there's an improvement.

Reply

Answer 2

jdmcmurtry Author

Level 1

39 points

Feb 5, 2015 1:48 PM in response to Linc Davis

Well, it's not happening now. Since the last time it was, I disabled the Mavericks-native ntpd and pacemaker daemons, which are infamously problematic, and replaced them with the pristine, un-crippled ntpd (v4.2.8p1) distributed by ntp.org. However, this is only a correlation, not necessarily a causation.

A week ago (Thu Feb 29), I put the system to sleep at 7:20pm, and when I woke it up three hours later and checked the logs, I found that it had been DarkWake-cycling every 56 seconds, as I expected. In the powermanagement logs (which record the activity of the powerd daemon), each iteration of the cycle left a series of log entries like this:

Jan 29 22:08:27 Justins-Mac-mini.local powerd[16] <Notice>: PID 16(powerd) Created InternalPreventSleep "PM configd - Wait for Device enumeration" 00:00:00  id:0xe0000257e [System: SRPrevSleep kCPU]
Jan 29 22:08:27 Justins-Mac-mini.local powerd[16] <Notice>: DarkWake [CDN] due to EHC1/: Using AC
Jan 29 22:08:27 Justins-Mac-mini.local powerd[16] <Notice>: PID 16(powerd) Created InternalPreventSleep "com.apple.powermanagement.acwakelinger" 00:00:00  id:0xe0000257f [System: SRPrevSleep kCPU]
Jan 29 22:08:33 Justins-Mac-mini.local powerd[16] <Notice>: PID 16(powerd) Released InternalPreventSleep "PM configd - Wait for Device enumeration" 00:00:05  id:0xe0000257e [System: BGTask SRPrevSleep kCPU]
Jan 29 22:09:13 Justins-Mac-mini.local powerd[16] <Notice>: PID 16(powerd) TimedOut InternalPreventSleep "com.apple.powermanagement.acwakelinger" 00:00:46  id:0xe0000257f [System: SRPrevSleep kCPU]
Jan 29 22:09:13 Justins-Mac-mini.local powerd[16] <Notice>: PID 16(powerd) Released InternalPreventSleep "com.apple.powermanagement.acwakelinger" 00:00:46  id:0xe0000257f [System: SRPrevSleep kCPU]
Jan 29 22:09:13 Justins-Mac-mini.local powerd[16] <Notice>: Maintenance Sleep: Using AC
Jan 29 22:09:14 Justins-Mac-mini.local powerd[16] <Notice>: PMConnection: Response from com.apple.apsd is slow (powercaps:0x0)
Jan 29 22:09:14 Justins-Mac-mini.local powerd[16] <Notice>: Clients requested wake events: [proc=mDNSResponder request=Maintenance inDelta=7200]
Jan 29 22:09:14 Justins-Mac-mini.local powerd[16] <Notice>: PM scheduled RTC wake event: MaintenanceImmediate inDelta=7199.66

I then did some experimenting with unplugging my USB mouse and keyboard. I found that the cycling still happened if I unplugged the mouse, but not if I unplugged the keyboard. I replugged the keyboard, and the cycling still didn't happen. So I left both the mouse and keyboard plugged in, and put the computer to sleep for the night at 11:01pm.

I woke the computer at 8:22am the next morning and examined the logs. I found that its sleep had been undisturbed, except for a brief scheduled DarkWakes requested by the mDNSResponder process. These DarkWakes happened at 1:01am, 3:02am, 5:03am, and 7:04am, exactly two hours apart. The powermanagement log entries for each of these looked like this:

Jan 30 01:01:46 Justins-Mac-mini.local powerd[16] <Notice>: DarkWake [CDN] due to RTC/Maintenance: Using AC
Jan 30 01:01:46 Justins-Mac-mini.local powerd[16] <Notice>: Kernel: Response from powerd is slow (powercaps:0x0)
Jan 30 01:01:46 Justins-Mac-mini.local powerd[16] <Notice>: PID 16(powerd) Created InternalPreventSleep "com.apple.powermanagement.acwakelinger" 00:00:00  id:0xe00002690 [System: BGTask SRPrevSleep kCPU]
Jan 30 01:01:57 Justins-Mac-mini.local powerd[16] <Notice>: Summary- [System: SRPrevSleep kCPU] Using AC
Jan 30 01:02:32 Justins-Mac-mini.local powerd[16] <Notice>: PID 16(powerd) TimedOut InternalPreventSleep "com.apple.powermanagement.acwakelinger" 00:00:45  id:0xe00002690 [System: SRPrevSleep kCPU]
Jan 30 01:02:32 Justins-Mac-mini.local powerd[16] <Notice>: PID 16(powerd) Released InternalPreventSleep "com.apple.powermanagement.acwakelinger" 00:00:45  id:0xe00002690 [System: SRPrevSleep kCPU]
Jan 30 01:02:32 Justins-Mac-mini.local powerd[16] <Notice>: Summary- [System: No Assertions] Using AC
Jan 30 01:02:32 Justins-Mac-mini.local powerd[16] <Notice>: Maintenance Sleep: Using AC
Jan 30 01:02:34 Justins-Mac-mini.local powerd[16] <Notice>: PMConnection: Response from com.apple.apsd is slow (powercaps:0x0)
Jan 30 01:02:34 Justins-Mac-mini.local powerd[16] <Notice>: Clients requested wake events: [proc=mDNSResponder request=Maintenance inDelta=7198]
Jan 30 01:02:34 Justins-Mac-mini.local powerd[16] <Notice>: PM scheduled RTC wake event: MaintenanceImmediate inDelta=7198.02

But then, something changed. Fifteen seconds after the 7:04am DarkWake for mDNSResponder ended, the familiar cycling started up again. The powermanagement log entries for the first iteration were identical to those from the day before:

Jan 30 07:05:22 Justins-Mac-mini.local powerd[16] <Notice>: PID 16(powerd) Created InternalPreventSleep "PM configd - Wait for Device enumeration" 00:00:00  id:0xe000026b2 [System: SRPrevSleep kCPU]
Jan 30 07:05:22 Justins-Mac-mini.local powerd[16] <Notice>: DarkWake [CDN] due to EHC1/: Using AC
Jan 30 07:05:22 Justins-Mac-mini.local powerd[16] <Notice>: PID 16(powerd) Created InternalPreventSleep "com.apple.powermanagement.acwakelinger" 00:00:00  id:0xe000026b3 [System: SRPrevSleep kCPU]
Jan 30 07:05:28 Justins-Mac-mini.local powerd[16] <Notice>: PID 16(powerd) Released InternalPreventSleep "PM configd - Wait for Device enumeration" 00:00:06  id:0xe000026b2 [System: SRPrevSleep kCPU]
Jan 30 07:06:09 Justins-Mac-mini.local powerd[16] <Notice>: PID 16(powerd) TimedOut InternalPreventSleep "com.apple.powermanagement.acwakelinger" 00:00:46  id:0xe000026b3 [System: SRPrevSleep kCPU]
Jan 30 07:06:09 Justins-Mac-mini.local powerd[16] <Notice>: PID 16(powerd) Released InternalPreventSleep "com.apple.powermanagement.acwakelinger" 00:00:46  id:0xe000026b3 [System: SRPrevSleep kCPU]
Jan 30 07:06:09 Justins-Mac-mini.local powerd[16] <Notice>: Maintenance Sleep: Using AC
Jan 30 07:06:11 Justins-Mac-mini.local powerd[16] <Notice>: PMConnection: Response from com.apple.apsd is slow (powercaps:0x0)
Jan 30 07:06:11 Justins-Mac-mini.local powerd[16] <Notice>: Clients requested wake events: [proc=mDNSResponder request=Maintenance inDelta=7198]
Jan 30 07:06:11 Justins-Mac-mini.local powerd[16] <Notice>: PM scheduled RTC wake event: MaintenanceImmediate inDelta=7198.01

The cycling continued like this until I woke the computer up at 8:02am. Curiously, the periods of each cycle were more variable than before; whereas they had previously had a consistent period of 56 seconds, they now were varying between 54 and 70 seconds (most often alternating between 55 and 70).

I examined the system log for the same period; there were no significant differences among the log entries for the four mDNSResponder-requested DarkWakes. The last entry of the last of these was timestamped at 07:05:11.000; the next entry, which marked the beginning of the first cycle iteration, was timestamped at 07:05:15.000 and was a kernel message saying "Wake reason: EHC1", the same as all the other cycle iterations I've observed.

In other words, the powermanagement and system logs had no separate entry identifying a condition or event that triggered the reappearance of the DarkWake cycles; the cycles simply started up again.

Reply