X-Git-Url: https://git.saurik.com/apple/xnu.git/blobdiff_plain/813fb2f63a553c957e917ede5f119b021d6ce391..9d749ea394c01276fa19e397e70f46858e849c76:/iokit/Kernel/IOPMrootDomain.cpp diff --git a/iokit/Kernel/IOPMrootDomain.cpp b/iokit/Kernel/IOPMrootDomain.cpp index 90ece1e80..be3dabe71 100644 --- a/iokit/Kernel/IOPMrootDomain.cpp +++ b/iokit/Kernel/IOPMrootDomain.cpp @@ -1,5 +1,5 @@ /* - * Copyright (c) 1998-2008 Apple Inc. All rights reserved. + * Copyright (c) 1998-2017 Apple Inc. All rights reserved. * * @APPLE_OSREFERENCE_LICENSE_HEADER_START@ * @@ -57,6 +57,8 @@ #include #include #include +#include +#include #include #include "IOServicePrivate.h" // _IOServiceInterestNotifier @@ -83,14 +85,23 @@ __END_DECLS #define LOG(x...) \ do { kprintf(LOG_PREFIX x); } while (false) +#if DEVELOPMENT #define DLOG(x...) do { \ if (kIOLogPMRootDomain & gIOKitDebug) \ kprintf(LOG_PREFIX x); \ + else \ + os_log(OS_LOG_DEFAULT, LOG_PREFIX x); \ } while (false) +#else +#define DLOG(x...) do { \ + if (kIOLogPMRootDomain & gIOKitDebug) \ + kprintf(LOG_PREFIX x); \ +} while (false) +#endif #define DMSG(x...) do { \ if (kIOLogPMRootDomain & gIOKitDebug) { \ - kprintf(LOG_PREFIX x); IOLog(x); \ + kprintf(LOG_PREFIX x); \ } \ } while (false) @@ -185,7 +196,7 @@ static const OSSymbol *sleepMessagePEFunction = NULL; #define kIOPMSystemCapabilitiesKey "System Capabilities" #define kIORequestWranglerIdleKey "IORequestIdle" -#define kDefaultWranglerIdlePeriod 25 // in milliseconds +#define kDefaultWranglerIdlePeriod 1000 // in milliseconds #define kIOSleepWakeDebugKey "Persistent-memory-note" #define kIOEFIBootRomFailureKey "wake-failure" @@ -307,6 +318,14 @@ static UInt32 gWillShutdown = 0; static UInt32 gPagingOff = 0; static UInt32 gSleepWakeUUIDIsSet = false; static uint32_t gAggressivesState = 0; +static uint32_t gHaltTimeMaxLog; +static uint32_t gHaltTimeMaxPanic; +IOLock * gHaltLogLock; +static char * gHaltLog; +enum { kHaltLogSize = 2048 }; +static size_t gHaltLogPos; +static uint64_t gHaltStartTime; + uuid_string_t bootsessionuuid_string; @@ -349,10 +368,10 @@ enum { kInformableCount = 2 }; -const OSSymbol *gIOPMStatsApplicationResponseTimedOut; -const OSSymbol *gIOPMStatsApplicationResponseCancel; -const OSSymbol *gIOPMStatsApplicationResponseSlow; -const OSSymbol *gIOPMStatsApplicationResponsePrompt; +const OSSymbol *gIOPMStatsResponseTimedOut; +const OSSymbol *gIOPMStatsResponseCancel; +const OSSymbol *gIOPMStatsResponseSlow; +const OSSymbol *gIOPMStatsResponsePrompt; const OSSymbol *gIOPMStatsDriverPSChangeSlow; #define kBadPMFeatureID 0 @@ -560,53 +579,137 @@ static void IOPMRootDomainWillShutdown(void) } } -extern "C" +extern "C" IONotifier * registerSleepWakeInterest(IOServiceInterestHandler handler, void * self, void * ref) { - IONotifier * registerSleepWakeInterest(IOServiceInterestHandler handler, void * self, void * ref) - { - return gRootDomain->registerInterest( gIOGeneralInterest, handler, self, ref ); - } + return gRootDomain->registerInterest( gIOGeneralInterest, handler, self, ref ); +} - IONotifier * registerPrioritySleepWakeInterest(IOServiceInterestHandler handler, void * self, void * ref) - { - return gRootDomain->registerInterest( gIOPriorityPowerStateInterest, handler, self, ref ); - } +extern "C" IONotifier * registerPrioritySleepWakeInterest(IOServiceInterestHandler handler, void * self, void * ref) +{ + return gRootDomain->registerInterest( gIOPriorityPowerStateInterest, handler, self, ref ); +} - IOReturn acknowledgeSleepWakeNotification(void * PMrefcon) - { - return gRootDomain->allowPowerChange ( (unsigned long)PMrefcon ); - } +extern "C" IOReturn acknowledgeSleepWakeNotification(void * PMrefcon) +{ + return gRootDomain->allowPowerChange ( (unsigned long)PMrefcon ); +} - IOReturn vetoSleepWakeNotification(void * PMrefcon) - { - return gRootDomain->cancelPowerChange ( (unsigned long)PMrefcon ); +extern "C" IOReturn vetoSleepWakeNotification(void * PMrefcon) +{ + return gRootDomain->cancelPowerChange ( (unsigned long)PMrefcon ); +} + +extern "C" IOReturn rootDomainRestart ( void ) +{ + return gRootDomain->restartSystem(); +} + +extern "C" IOReturn rootDomainShutdown ( void ) +{ + return gRootDomain->shutdownSystem(); +} + +static void halt_log_putc(char c) +{ + if (gHaltLogPos >= (kHaltLogSize - 2)) return; + gHaltLog[gHaltLogPos++] = c; +} + +extern "C" void +_doprnt_log(const char *fmt, + va_list *argp, + void (*putc)(char), + int radix); + +static int +halt_log(const char *fmt, ...) +{ + va_list listp; + + va_start(listp, fmt); + _doprnt_log(fmt, &listp, &halt_log_putc, 16); + va_end(listp); + + return (0); +} + +extern "C" void +halt_log_enter(const char * what, const void * pc, uint64_t time) +{ + uint64_t nano, millis; + + if (!gHaltLog) return; + absolutetime_to_nanoseconds(time, &nano); + millis = nano / NSEC_PER_MSEC; + if (millis < 100) return; + + IOLockLock(gHaltLogLock); + if (pc) { + halt_log("%s: %qd ms @ 0x%lx, ", what, millis, VM_KERNEL_UNSLIDE(pc)); + OSKext::printKextsInBacktrace((vm_offset_t *) &pc, 1, &halt_log, + OSKext::kPrintKextsLock | OSKext::kPrintKextsUnslide | OSKext::kPrintKextsTerse); + } + else { + halt_log("%s: %qd ms\n", what, millis); } - IOReturn rootDomainRestart ( void ) + gHaltLog[gHaltLogPos] = 0; + IOLockUnlock(gHaltLogLock); +} + +extern uint32_t gFSState; + +extern "C" void IOSystemShutdownNotification(int stage) +{ + uint64_t startTime; + + if (kIOSystemShutdownNotificationStageRootUnmount == stage) { - return gRootDomain->restartSystem(); +#if !CONFIG_EMBEDDED + uint64_t nano, millis; + startTime = mach_absolute_time(); + IOService::getPlatform()->waitQuiet(30 * NSEC_PER_SEC); + absolutetime_to_nanoseconds(mach_absolute_time() - startTime, &nano); + millis = nano / NSEC_PER_MSEC; + if (gHaltTimeMaxLog && (millis >= gHaltTimeMaxLog)) + { + printf("waitQuiet() for unmount %qd ms\n", millis); + } +#endif + return; } - IOReturn rootDomainShutdown ( void ) + assert(kIOSystemShutdownNotificationStageProcessExit == stage); + + IOLockLock(gHaltLogLock); + if (!gHaltLog) { - return gRootDomain->shutdownSystem(); + gHaltLog = IONew(char, kHaltLogSize); + gHaltStartTime = mach_absolute_time(); + if (gHaltLog) halt_log_putc('\n'); } + IOLockUnlock(gHaltLogLock); - void IOSystemShutdownNotification(void) - { - IOPMRootDomainWillShutdown(); + startTime = mach_absolute_time(); + IOPMRootDomainWillShutdown(); + halt_log_enter("IOPMRootDomainWillShutdown", 0, mach_absolute_time() - startTime); #if HIBERNATION - IOHibernateSystemPostWake(); + startTime = mach_absolute_time(); + IOHibernateSystemPostWake(true); + gRootDomain->swdDebugTeardown(); + halt_log_enter("IOHibernateSystemPostWake", 0, mach_absolute_time() - startTime); +#endif + if (OSCompareAndSwap(0, 1, &gPagingOff)) + { +#if !CONFIG_EMBEDDED + gRootDomain->handlePlatformHaltRestart(kPEPagingOff); #endif - if (OSCompareAndSwap(0, 1, &gPagingOff)) - { - gRootDomain->handlePlatformHaltRestart(kPEPagingOff); - } } - - int sync_internal(void); } + +extern "C" int sync_internal(void); + /* A device is always in the highest power state which satisfies its driver, its policy-maker, and any power children it has, but within the constraint @@ -701,13 +804,15 @@ static void swdDebugSetupCallout( thread_call_param_t p0, thread_call_param_t p1 void IOPMrootDomain::swdDebugSetup( ) { #if HIBERNATION - static int32_t mem_only = -1; - if ((mem_only == -1) && - (PE_parse_boot_argn("swd_mem_only", &mem_only, sizeof(mem_only)) == false)) { - mem_only = 0; + static int32_t noDebugFile = -1; + if (noDebugFile == -1) { + if (PEGetCoprocessorVersion() >= kCoprocessorVersion2) + noDebugFile = 1; + else if (PE_parse_boot_argn("swd_mem_only", &noDebugFile, sizeof(noDebugFile)) == false) + noDebugFile = 0; } - if ((mem_only == 1) || (gRootDomain->sleepWakeDebugIsWdogEnabled() == false)) { + if ((noDebugFile == 1) || (gRootDomain->sleepWakeDebugIsWdogEnabled() == false)) { return; } DLOG("swdDebugSetup state:%d\n", swd_DebugImageSetup); @@ -715,7 +820,8 @@ void IOPMrootDomain::swdDebugSetup( ) swd_DebugImageSetup = TRUE; if (CAP_GAIN(kIOPMSystemCapabilityGraphics) || (CAP_LOSS(kIOPMSystemCapabilityGraphics))) { - IOHibernateSystemPostWakeTrim((void*)1, NULL); + IOHibernateSystemPostWake(true); + IOCloseDebugDataFile(); } IOOpenDebugDataFile(kSleepWakeStackBinFilename, SWD_BUF_SIZE); } @@ -763,13 +869,18 @@ static void disk_sync_callout( thread_call_param_t p0, thread_call_param_t p1 ) if (ON_STATE == powerState) { sync_internal(); + +#if HIBERNATION + // Block sleep until trim issued on previous wake path is completed. + IOHibernateSystemPostWake(true); +#endif swdDebugSetupCallout(p0, NULL); } #if HIBERNATION else { swdDebugTeardownCallout(p0, NULL); - IOHibernateSystemPostWake(); + IOHibernateSystemPostWake(false); if (gRootDomain) gRootDomain->sleepWakeDebugSaveSpinDumpFile(); @@ -781,19 +892,21 @@ static void disk_sync_callout( thread_call_param_t p0, thread_call_param_t p1 ) } //****************************************************************************** -static UInt32 computeDeltaTimeMS( const AbsoluteTime * startTime ) +static UInt32 computeDeltaTimeMS( const AbsoluteTime * startTime, AbsoluteTime * elapsedTime ) { AbsoluteTime endTime; UInt64 nano = 0; clock_get_uptime(&endTime); - if (CMP_ABSOLUTETIME(&endTime, startTime) > 0) + if (CMP_ABSOLUTETIME(&endTime, startTime) <= 0) *elapsedTime = 0; + else { SUB_ABSOLUTETIME(&endTime, startTime); absolutetime_to_nanoseconds(endTime, &nano); + *elapsedTime = endTime; } - return (UInt32)(nano / 1000000ULL); + return (UInt32)(nano / NSEC_PER_MSEC); } //****************************************************************************** @@ -807,12 +920,12 @@ sysctl_sleepwaketime SYSCTL_HANDLER_ARGS if (p == kernproc) { return sysctl_io_opaque(req, swt, sizeof(*swt), NULL); } else if(proc_is64bit(p)) { - struct user64_timeval t; + struct user64_timeval t = {}; t.tv_sec = swt->tv_sec; t.tv_usec = swt->tv_usec; return sysctl_io_opaque(req, &t, sizeof(t), NULL); } else { - struct user32_timeval t; + struct user32_timeval t = {}; t.tv_sec = swt->tv_sec; t.tv_usec = swt->tv_usec; return sysctl_io_opaque(req, &t, sizeof(t), NULL); @@ -850,7 +963,9 @@ static SYSCTL_PROC(_kern, OID_AUTO, willshutdown, 0, 0, sysctl_willshutdown, "I", ""); extern struct sysctl_oid sysctl__kern_iokittest; +extern struct sysctl_oid sysctl__debug_iokit; +#if !CONFIG_EMBEDDED static int sysctl_progressmeterenable @@ -888,6 +1003,7 @@ static SYSCTL_PROC(_kern, OID_AUTO, progressmeter, CTLTYPE_INT | CTLFLAG_RW | CTLFLAG_NOAUTO | CTLFLAG_KERN | CTLFLAG_LOCKED, 0, 0, sysctl_progressmeter, "I", ""); +#endif /* !CONFIG_EMBEDDED */ @@ -1002,10 +1118,10 @@ bool IOPMrootDomain::start( IOService * nub ) gIOPMUserTriggeredFullWakeKey = OSSymbol::withCStringNoCopy(kIOPMUserTriggeredFullWakeKey); gIOPMUserIsActiveKey = OSSymbol::withCStringNoCopy(kIOPMUserIsActiveKey); - gIOPMStatsApplicationResponseTimedOut = OSSymbol::withCString(kIOPMStatsResponseTimedOut); - gIOPMStatsApplicationResponseCancel = OSSymbol::withCString(kIOPMStatsResponseCancel); - gIOPMStatsApplicationResponseSlow = OSSymbol::withCString(kIOPMStatsResponseSlow); - gIOPMStatsApplicationResponsePrompt = OSSymbol::withCString(kIOPMStatsResponsePrompt); + gIOPMStatsResponseTimedOut = OSSymbol::withCString(kIOPMStatsResponseTimedOut); + gIOPMStatsResponseCancel = OSSymbol::withCString(kIOPMStatsResponseCancel); + gIOPMStatsResponseSlow = OSSymbol::withCString(kIOPMStatsResponseSlow); + gIOPMStatsResponsePrompt = OSSymbol::withCString(kIOPMStatsResponsePrompt); gIOPMStatsDriverPSChangeSlow = OSSymbol::withCString(kIOPMStatsDriverPSChangeSlow); sleepSupportedPEFunction = OSSymbol::withCString("IOPMSetSleepSupported"); @@ -1034,6 +1150,8 @@ bool IOPMrootDomain::start( IOService * nub ) PE_parse_boot_argn("darkwake", &gDarkWakeFlags, sizeof(gDarkWakeFlags)); PE_parse_boot_argn("noidle", &gNoIdleFlag, sizeof(gNoIdleFlag)); + PE_parse_boot_argn("haltmspanic", &gHaltTimeMaxPanic, sizeof(gHaltTimeMaxPanic)); + PE_parse_boot_argn("haltmslog", &gHaltTimeMaxLog, sizeof(gHaltTimeMaxLog)); queue_init(&aggressivesQueue); aggressivesThreadCall = thread_call_allocate(handleAggressivesFunction, this); @@ -1043,6 +1161,7 @@ bool IOPMrootDomain::start( IOService * nub ) featuresDictLock = IOLockAlloc(); settingsCtrlLock = IOLockAlloc(); wakeEventLock = IOLockAlloc(); + gHaltLogLock = IOLockAlloc(); setPMRootDomain(this); extraSleepTimer = thread_call_allocate( @@ -1228,11 +1347,14 @@ bool IOPMrootDomain::start( IOService * nub ) sysctl_register_oid(&sysctl__kern_waketime); sysctl_register_oid(&sysctl__kern_willshutdown); sysctl_register_oid(&sysctl__kern_iokittest); + sysctl_register_oid(&sysctl__debug_iokit); sysctl_register_oid(&sysctl__hw_targettype); +#if !CONFIG_EMBEDDED sysctl_register_oid(&sysctl__kern_progressmeterenable); sysctl_register_oid(&sysctl__kern_progressmeter); sysctl_register_oid(&sysctl__kern_wakereason); +#endif /* !CONFIG_EMBEDDED */ sysctl_register_oid(&sysctl__kern_consoleoptions); sysctl_register_oid(&sysctl__kern_progressoptions); @@ -1386,6 +1508,7 @@ IOReturn IOPMrootDomain::setProperties( OSObject * props_obj ) setProperty(key, b); } else if (key->isEqualTo(kIOPMDeepSleepDelayKey) || + key->isEqualTo(kIOPMDeepSleepTimerKey) || key->isEqualTo(kIOPMAutoPowerOffDelayKey) || key->isEqualTo(kIOPMAutoPowerOffTimerKey)) { @@ -2191,6 +2314,9 @@ IOReturn IOPMrootDomain::privateSleepSystem( uint32_t sleepReason ) void IOPMrootDomain::powerChangeDone( unsigned long previousPowerState ) { +#if !__i386__ && !__x86_64__ + uint64_t timeSinceReset = 0; +#endif uint64_t now; ASSERT_GATED(); DLOG("PowerChangeDone: %u->%u\n", @@ -2251,6 +2377,21 @@ void IOPMrootDomain::powerChangeDone( unsigned long previousPowerState ) ((IOService *)this)->stop_watchdog_timer(); //14456299 lowBatteryCondition = false; +#if DEVELOPMENT || DEBUG + extern int g_should_log_clock_adjustments; + if (g_should_log_clock_adjustments) { + clock_sec_t secs = 0; + clock_usec_t microsecs = 0; + uint64_t now_b = mach_absolute_time(); + + PEGetUTCTimeOfDay(&secs, µsecs); + + uint64_t now_a = mach_absolute_time(); + os_log(OS_LOG_DEFAULT, "%s PMU before going to sleep %lu s %d u %llu abs_b_PEG %llu abs_a_PEG \n", + __func__, (unsigned long)secs, microsecs, now_b, now_a); + } +#endif + getPlatform()->sleepKernel(); // The CPU(s) are off at this point, @@ -2273,7 +2414,7 @@ void IOPMrootDomain::powerChangeDone( unsigned long previousPowerState ) clock_sec_t wakeSecs; clock_usec_t wakeMicrosecs; - clock_initialize_calendar(); + clock_wakeup_calendar(); clock_get_calendar_microtime(&wakeSecs, &wakeMicrosecs); gIOLastWakeTime.tv_sec = wakeSecs; @@ -2438,7 +2579,9 @@ void IOPMrootDomain::powerChangeDone( unsigned long previousPowerState ) } } #else /* !__i386__ && !__x86_64__ */ - kdebugTrace(kPMLogSystemWake, 0, ml_get_wake_timebase() >> 32, ml_get_wake_timebase()); + timeSinceReset = ml_get_time_since_reset(); + + kdebugTrace(kPMLogSystemWake, 0, timeSinceReset >> 32, timeSinceReset); // stay awake for at least 30 seconds wranglerTickled = true; fullWakeReason = kFullWakeReasonLocalUser; @@ -2547,16 +2690,23 @@ bool IOPMrootDomain::updatePreventIdleSleepList( #if defined(__i386__) || defined(__x86_64__) if (addNotRemove && (service == wrangler) && !checkSystemCanSustainFullWake()) { + DLOG("Cannot cancel idle sleep\n"); return false; // do not idle-cancel } #endif - MSG("prevent idle sleep list: %s%c (%u)\n", - service->getName(), - (addNotRemove) ? '+' : '-', newCount); return true; } +//****************************************************************************** +// startSpinDump +//****************************************************************************** + +void IOPMrootDomain::startSpinDump(uint32_t spindumpKind) +{ + messageClients(kIOPMMessageLaunchBootSpinDump, (void *)(uintptr_t)spindumpKind); +} + //****************************************************************************** // preventSystemSleepListUpdate // @@ -2681,21 +2831,23 @@ bool IOPMrootDomain::tellChangeDown( unsigned long stateNum ) tracePoint( kIOPMTracePointSleepPriorityClients ); } - if ((SLEEP_STATE == stateNum) && !ignoreTellChangeDown) - { + if (!ignoreTellChangeDown) { userActivityAtSleep = userActivityCount; - hibernateAborted = false; DLOG("tellChangeDown::userActivityAtSleep %d\n", userActivityAtSleep); - // Direct callout into OSKext so it can disable kext unloads - // during sleep/wake to prevent deadlocks. - OSKextSystemSleepOrWake( kIOMessageSystemWillSleep ); + if (SLEEP_STATE == stateNum) { + hibernateAborted = false; - IOService::updateConsoleUsers(NULL, kIOMessageSystemWillSleep); + // Direct callout into OSKext so it can disable kext unloads + // during sleep/wake to prevent deadlocks. + OSKextSystemSleepOrWake( kIOMessageSystemWillSleep ); - // Two change downs are sent by IOServicePM. Ignore the 2nd. - // But tellClientsWithResponse() must be called for both. - ignoreTellChangeDown = true; + IOService::updateConsoleUsers(NULL, kIOMessageSystemWillSleep); + + // Two change downs are sent by IOServicePM. Ignore the 2nd. + // But tellClientsWithResponse() must be called for both. + ignoreTellChangeDown = true; + } } return super::tellClientsWithResponse( kIOMessageSystemWillSleep ); @@ -2961,9 +3113,6 @@ IOReturn IOPMrootDomain::sysPowerDownHandler( // We will ack within 20 seconds params->maxWaitForReply = 20 * 1000 * 1000; - // Remove EFI/BootRom's previous wake's failure data - PERemoveNVRAMProperty(kIOEFIBootRomFailureKey); - #if HIBERNATION gRootDomain->evaluateSystemSleepPolicyEarly(); @@ -3126,6 +3275,40 @@ void IOPMrootDomain::handlePublishSleepWakeUUID( bool shouldPublish ) } } +//****************************************************************************** +// IOPMGetSleepWakeUUIDKey +// +// Return the truth value of gSleepWakeUUIDIsSet and optionally copy the key. +// To get the full key -- a C string -- the buffer must large enough for +// the end-of-string character. +// The key is expected to be an UUID string +//****************************************************************************** + +extern "C" bool +IOPMCopySleepWakeUUIDKey(char *buffer, size_t buf_len) +{ + if (!gSleepWakeUUIDIsSet) { + return (false); + } + + if (buffer != NULL) { + OSString *string; + + string = (OSString *) + gRootDomain->copyProperty(kIOPMSleepWakeUUIDKey); + + if (string == NULL) { + *buffer = '\0'; + } else { + strlcpy(buffer, string->getCStringNoCopy(), buf_len); + + string->release(); + } + } + + return (true); +} + //****************************************************************************** // initializeBootSessionUUID // @@ -3224,7 +3407,9 @@ void IOPMrootDomain::willNotifyPowerChildren( IOPMPowerStateIndex newPowerState tasks_system_suspend(tasksSuspended); clock_interval_to_deadline(10, kSecondScale, &deadline); +#if !CONFIG_EMBEDDED vm_pageout_wait(AbsoluteTime_to_scalar(&deadline)); +#endif /* !CONFIG_EMBEDDED */ } #if HIBERNATION @@ -4012,6 +4197,7 @@ bool IOPMrootDomain::evaluateSystemSleepPolicy( uint32_t standbyDelay = 0; uint32_t powerOffDelay = 0; uint32_t powerOffTimer = 0; + uint32_t standbyTimer = 0; uint32_t mismatch; bool standbyEnabled; bool powerOffEnabled; @@ -4031,9 +4217,11 @@ bool IOPMrootDomain::evaluateSystemSleepPolicy( && (getProperty(kIOPMAutoPowerOffEnabledKey) == kOSBooleanTrue)); if (!getSleepOption(kIOPMAutoPowerOffTimerKey, &powerOffTimer)) powerOffTimer = powerOffDelay; + if (!getSleepOption(kIOPMDeepSleepTimerKey, &standbyTimer)) + standbyTimer = standbyDelay; - DLOG("phase %d, standby %d delay %u, poweroff %d delay %u timer %u, hibernate 0x%x\n", - sleepPhase, standbyEnabled, standbyDelay, + DLOG("phase %d, standby %d delay %u timer %u, poweroff %d delay %u timer %u, hibernate 0x%x\n", + sleepPhase, standbyEnabled, standbyDelay, standbyTimer, powerOffEnabled, powerOffDelay, powerOffTimer, *hibMode); // pmset level overrides @@ -4069,7 +4257,7 @@ bool IOPMrootDomain::evaluateSystemSleepPolicy( currentFactors |= kIOPMSleepFactorACPower; if (lowBatteryCondition) currentFactors |= kIOPMSleepFactorBatteryLow; - if (!standbyDelay) + if (!standbyDelay || !standbyTimer) currentFactors |= kIOPMSleepFactorStandbyNoDelay; if (standbyNixed || !standbyEnabled) currentFactors |= kIOPMSleepFactorStandbyDisabled; @@ -4134,6 +4322,7 @@ bool IOPMrootDomain::evaluateSystemSleepPolicy( gSleepPolicyVars->sleepReason = lastSleepReason; gSleepPolicyVars->sleepPhase = sleepPhase; gSleepPolicyVars->standbyDelay = standbyDelay; + gSleepPolicyVars->standbyTimer = standbyTimer; gSleepPolicyVars->poweroffDelay = powerOffDelay; gSleepPolicyVars->scheduledAlarms = _scheduledAlarms | _userScheduledAlarm; gSleepPolicyVars->poweroffTimer = powerOffTimer; @@ -4332,7 +4521,7 @@ void IOPMrootDomain::evaluateSystemSleepPolicyFinal( void ) if (evaluateSystemSleepPolicy(¶ms, kIOPMSleepPhase2, &hibernateMode)) { if ((kIOPMSleepTypeStandby == params.sleepType) - && gIOHibernateStandbyDisabled + && gIOHibernateStandbyDisabled && gSleepPolicyVars && (!(kIOPMSleepFactorStandbyForced & gSleepPolicyVars->sleepFactors))) { standbyNixed = true; @@ -4446,11 +4635,11 @@ bool IOPMrootDomain::getSleepOption( const char * key, uint32_t * option ) if (optionsProp) optionsProp->release(); - return true; + return ok; } #endif /* HIBERNATION */ -IOReturn IOPMrootDomain::getSystemSleepType( uint32_t * sleepType ) +IOReturn IOPMrootDomain::getSystemSleepType( uint32_t * sleepType, uint32_t * standbyTimer ) { #if HIBERNATION IOPMSystemSleepParameters params; @@ -4463,7 +4652,7 @@ IOReturn IOPMrootDomain::getSystemSleepType( uint32_t * sleepType ) OSMemberFunctionCast(IOWorkLoop::Action, this, &IOPMrootDomain::getSystemSleepType), (OSObject *) this, - (void *) sleepType); + (void *) sleepType, (void *) standbyTimer); return ret; } @@ -4474,6 +4663,11 @@ IOReturn IOPMrootDomain::getSystemSleepType( uint32_t * sleepType ) if (ok) { *sleepType = params.sleepType; + if (!getSleepOption(kIOPMDeepSleepTimerKey, standbyTimer) && + !getSleepOption(kIOPMDeepSleepDelayKey, standbyTimer)) { + DLOG("Standby delay is not set\n"); + *standbyTimer = 0; + } return kIOReturnSuccess; } #endif @@ -4489,6 +4683,16 @@ IOReturn IOPMrootDomain::getSystemSleepType( uint32_t * sleepType ) // //****************************************************************************** +// Phases while performing shutdown/restart +typedef enum { + kNotifyDone = 0x00, + kNotifyPriorityClients = 0x10, + kNotifyPowerPlaneDrivers = 0x20, + kNotifyHaltRestartAction = 0x30, + kQuiescePM = 0x40, +} shutdownPhase_t; + + struct HaltRestartApplierContext { IOPMrootDomain * RootDomain; unsigned long PowerState; @@ -4496,44 +4700,64 @@ struct HaltRestartApplierContext { UInt32 MessageType; UInt32 Counter; const char * LogString; -}; + shutdownPhase_t phase; + + IOServiceInterestHandler handler; +} gHaltRestartCtx; + +const char *shutdownPhase2String(shutdownPhase_t phase) +{ + switch(phase) { + case kNotifyDone: + return "Notifications completed"; + case kNotifyPriorityClients: + return "Notifying priority clients"; + case kNotifyPowerPlaneDrivers: + return "Notifying power plane drivers"; + case kNotifyHaltRestartAction: + return "Notifying HaltRestart action handlers"; + case kQuiescePM: + return "Quiescing PM"; + default: + return "Unknown"; + } + +} static void platformHaltRestartApplier( OSObject * object, void * context ) { IOPowerStateChangeNotification notify; HaltRestartApplierContext * ctx; - AbsoluteTime startTime; + AbsoluteTime startTime, elapsedTime; uint32_t deltaTime; ctx = (HaltRestartApplierContext *) context; + _IOServiceInterestNotifier * notifier; + notifier = OSDynamicCast(_IOServiceInterestNotifier, object); memset(¬ify, 0, sizeof(notify)); notify.powerRef = (void *)(uintptr_t)ctx->Counter; notify.returnValue = 0; notify.stateNumber = ctx->PowerState; notify.stateFlags = ctx->PowerFlags; + if (notifier) { + ctx->handler = notifier->handler; + } + clock_get_uptime(&startTime); ctx->RootDomain->messageClient( ctx->MessageType, object, (void *)¬ify ); - deltaTime = computeDeltaTimeMS(&startTime); + deltaTime = computeDeltaTimeMS(&startTime, &elapsedTime); - if ((deltaTime > kPMHaltTimeoutMS) || - (gIOKitDebug & kIOLogPMRootDomain)) - { - _IOServiceInterestNotifier * notifier; - notifier = OSDynamicCast(_IOServiceInterestNotifier, object); - - // IOService children of IOPMrootDomain are not instrumented. - // Only IORootParent currently falls under that group. + if ((deltaTime > kPMHaltTimeoutMS) && notifier) { - if (notifier) - { - LOG("%s handler %p took %u ms\n", + LOG("%s handler %p took %u ms\n", ctx->LogString, OBFUSCATE(notifier->handler), deltaTime); - } + halt_log_enter("PowerOff/Restart message to priority client", (const void *) notifier->handler, elapsedTime); } + ctx->handler = 0; ctx->Counter++; } @@ -4547,33 +4771,32 @@ static void quiescePowerTreeCallback( void * target, void * param ) void IOPMrootDomain::handlePlatformHaltRestart( UInt32 pe_type ) { - HaltRestartApplierContext ctx; - AbsoluteTime startTime; + AbsoluteTime startTime, elapsedTime; uint32_t deltaTime; - memset(&ctx, 0, sizeof(ctx)); - ctx.RootDomain = this; + memset(&gHaltRestartCtx, 0, sizeof(gHaltRestartCtx)); + gHaltRestartCtx.RootDomain = this; clock_get_uptime(&startTime); switch (pe_type) { case kPEHaltCPU: case kPEUPSDelayHaltCPU: - ctx.PowerState = OFF_STATE; - ctx.MessageType = kIOMessageSystemWillPowerOff; - ctx.LogString = "PowerOff"; + gHaltRestartCtx.PowerState = OFF_STATE; + gHaltRestartCtx.MessageType = kIOMessageSystemWillPowerOff; + gHaltRestartCtx.LogString = "PowerOff"; break; case kPERestartCPU: - ctx.PowerState = RESTART_STATE; - ctx.MessageType = kIOMessageSystemWillRestart; - ctx.LogString = "Restart"; + gHaltRestartCtx.PowerState = RESTART_STATE; + gHaltRestartCtx.MessageType = kIOMessageSystemWillRestart; + gHaltRestartCtx.LogString = "Restart"; break; case kPEPagingOff: - ctx.PowerState = ON_STATE; - ctx.MessageType = kIOMessageSystemPagingOff; - ctx.LogString = "PagingOff"; + gHaltRestartCtx.PowerState = ON_STATE; + gHaltRestartCtx.MessageType = kIOMessageSystemPagingOff; + gHaltRestartCtx.LogString = "PagingOff"; IOService::updateConsoleUsers(NULL, kIOMessageSystemPagingOff); #if HIBERNATION IOHibernateSystemRestart(); @@ -4584,8 +4807,9 @@ void IOPMrootDomain::handlePlatformHaltRestart( UInt32 pe_type ) return; } + gHaltRestartCtx.phase = kNotifyPriorityClients; // Notify legacy clients - applyToInterested(gIOPriorityPowerStateInterest, platformHaltRestartApplier, &ctx); + applyToInterested(gIOPriorityPowerStateInterest, platformHaltRestartApplier, &gHaltRestartCtx); // For normal shutdown, turn off File Server Mode. if (kPEHaltCPU == pe_type) @@ -4600,17 +4824,21 @@ void IOPMrootDomain::handlePlatformHaltRestart( UInt32 pe_type ) } } + if (kPEPagingOff != pe_type) { + gHaltRestartCtx.phase = kNotifyPowerPlaneDrivers; // Notify in power tree order - notifySystemShutdown(this, ctx.MessageType); + notifySystemShutdown(this, gHaltRestartCtx.MessageType); } + gHaltRestartCtx.phase = kNotifyHaltRestartAction; IOCPURunPlatformHaltRestartActions(pe_type); // Wait for PM to quiesce if ((kPEPagingOff != pe_type) && gPMHaltLock) { + gHaltRestartCtx.phase = kQuiescePM; AbsoluteTime quiesceTime = mach_absolute_time(); IOLockLock(gPMHaltLock); @@ -4624,13 +4852,52 @@ void IOPMrootDomain::handlePlatformHaltRestart( UInt32 pe_type ) } } IOLockUnlock(gPMHaltLock); - - deltaTime = computeDeltaTimeMS(&quiesceTime); + deltaTime = computeDeltaTimeMS(&quiesceTime, &elapsedTime); DLOG("PM quiesce took %u ms\n", deltaTime); + halt_log_enter("Quiesce", NULL, elapsedTime); } + gHaltRestartCtx.phase = kNotifyDone; + + deltaTime = computeDeltaTimeMS(&startTime, &elapsedTime); + LOG("%s all drivers took %u ms\n", gHaltRestartCtx.LogString, deltaTime); - deltaTime = computeDeltaTimeMS(&startTime); - LOG("%s all drivers took %u ms\n", ctx.LogString, deltaTime); + halt_log_enter(gHaltRestartCtx.LogString, NULL, elapsedTime); + + deltaTime = computeDeltaTimeMS(&gHaltStartTime, &elapsedTime); + LOG("%s total %u ms\n", gHaltRestartCtx.LogString, deltaTime); + + if (gHaltLog && gHaltTimeMaxLog && (deltaTime >= gHaltTimeMaxLog)) + { + printf("%s total %d ms:%s\n", gHaltRestartCtx.LogString, deltaTime, gHaltLog); + } + + checkShutdownTimeout(); +} + +bool IOPMrootDomain::checkShutdownTimeout() +{ + AbsoluteTime elapsedTime; + uint32_t deltaTime = computeDeltaTimeMS(&gHaltStartTime, &elapsedTime); + + if (gHaltTimeMaxPanic && (deltaTime >= gHaltTimeMaxPanic)) { + return true; + } + return false; +} + +void IOPMrootDomain::panicWithShutdownLog(uint32_t timeoutInMs) +{ + if (gHaltLog) { + if ((gHaltRestartCtx.phase == kNotifyPriorityClients) && gHaltRestartCtx.handler) { + halt_log_enter("Blocked on priority client", (void *)gHaltRestartCtx.handler, mach_absolute_time() - gHaltStartTime); + } + panic("%s timed out in phase '%s'. Total %d ms:%s", + gHaltRestartCtx.LogString, shutdownPhase2String(gHaltRestartCtx.phase), timeoutInMs, gHaltLog); + } + else { + panic("%s timed out in phase \'%s\'. Total %d ms", + gHaltRestartCtx.LogString, shutdownPhase2String(gHaltRestartCtx.phase), timeoutInMs); + } } //****************************************************************************** @@ -5132,10 +5399,20 @@ void IOPMrootDomain::handleOurPowerChangeDone( if (!CAP_CURRENT(kIOPMSystemCapabilityGraphics) && CAP_CURRENT(kIOPMSystemCapabilityCPU)) { +#if !CONFIG_EMBEDDED pmPowerStateQueue->submitPowerEvent( kPowerEventPolicyStimulus, (void *) kStimulusDarkWakeReentry, _systemStateGeneration ); +#else + // On embedded, there are no factors that can prolong a + // "darkWake" when a power down is vetoed. We need to + // promote to "fullWake" at least once so that factors + // that prevent idle sleep can assert themselves if required + pmPowerStateQueue->submitPowerEvent( + kPowerEventPolicyStimulus, + (void *) kStimulusDarkWakeActivityTickle); +#endif } // Revert device desire to max. @@ -5419,7 +5696,7 @@ void IOPMrootDomain::overridePowerChangeForUIService( absolutetime_to_nanoseconds(now, &nsec); if (kIOLogPMRootDomain & gIOKitDebug) MSG("Graphics suppressed %u ms\n", - ((int)((nsec) / 1000000ULL))); + ((int)((nsec) / NSEC_PER_MSEC))); } graphicsSuppressed = true; } @@ -5604,6 +5881,9 @@ protected: uint32_t ackTimeoutCnt; uint32_t msgType; // Message pending ack + uint64_t uuid0; + uint64_t uuid1; + const OSSymbol *identifier; }; OSDefineMetaClassAndStructors(IOPMServiceInterestNotifier, _IOServiceInterestNotifier) @@ -5633,7 +5913,7 @@ IONotifier * IOPMrootDomain::registerInterest( if (!notifier) return NULL; if (notifier->init()) { - rc = super::registerInterestForNotifer(notifier, typeOfInterest, handler, target, ref); + rc = super::registerInterestForNotifier(notifier, typeOfInterest, handler, target, ref); } if (rc != kIOReturnSuccess) { notifier->release(); @@ -5661,6 +5941,28 @@ IONotifier * IOPMrootDomain::registerInterest( } } + OSData *data = NULL; + uint8_t *uuid = NULL; + OSKext *kext = OSKext::lookupKextWithAddress((vm_address_t)handler); + if (kext) { + data = kext->copyUUID(); + } + if (data && (data->getLength() == sizeof(uuid_t))) { + uuid = (uint8_t *)(data->getBytesNoCopy()); + + notifier->uuid0 = ((uint64_t)(uuid[0]) << 56) | ((uint64_t)(uuid[1]) << 48) | ((uint64_t)(uuid[2]) << 40)| + ((uint64_t)(uuid[3]) << 32) | ((uint64_t)(uuid[4]) << 24) | ((uint64_t)(uuid[5]) << 16) | + ((uint64_t)(uuid[6]) << 8) | (uuid[7]); + notifier->uuid1 = ((uint64_t)(uuid[8]) << 56) | ((uint64_t)(uuid[9]) << 48) | ((uint64_t)(uuid[10]) << 40)| + ((uint64_t)(uuid[11]) << 32) | ((uint64_t)(uuid[12]) << 24) | ((uint64_t)(uuid[13]) << 16) | + ((uint64_t)(uuid[14]) << 8) | (uuid[15]); + + notifier->identifier = kext->getIdentifier(); + + } + if (kext) kext->release(); + if (data) data->release(); + return notifier; } @@ -5737,9 +6039,6 @@ bool IOPMrootDomain::systemMessageFilter( // app has not replied yet, wait for it *((OSObject **) arg3) = kOSBooleanFalse; - if (notifier) { - notifier->msgType = context->messageType; - } } allow = true; @@ -5757,9 +6056,6 @@ bool IOPMrootDomain::systemMessageFilter( if (object == (OSObject *) systemCapabilityNotifier) { allow = true; - if (notifier) { - notifier->msgType = context->messageType; - } break; } @@ -5775,9 +6071,6 @@ bool IOPMrootDomain::systemMessageFilter( if ((object == (OSObject *) systemCapabilityNotifier) && CAP_HIGHEST(kIOPMSystemCapabilityGraphics) && (fullToDarkReason == kIOPMSleepReasonIdle)) { - if (notifier) { - notifier->msgType = context->messageType; - } allow = true; } break; @@ -5805,8 +6098,6 @@ bool IOPMrootDomain::systemMessageFilter( else *((OSObject **) arg3) = kOSBooleanTrue; } - - notifier->msgType = context->messageType; } } else if ((context->notifyType == kNotifyPriority) && @@ -5828,6 +6119,9 @@ bool IOPMrootDomain::systemMessageFilter( _joinedCapabilityClients = 0; } } + if (notifier) { + notifier->msgType = context->messageType; + } return allow; } @@ -5948,7 +6242,9 @@ bool IOPMrootDomain::displayWranglerMatchPublished( IONotifier * notifier __unused) { #if !NO_KERNEL_HID - // found the display wrangler, now install a handler + // found the display wrangler, check for any display assertions already created + gRootDomain->evaluateWranglerAssertions(); + // install a handler if( !newService->registerInterest( gIOGeneralInterest, &displayWranglerNotification, target, 0) ) { @@ -6245,6 +6541,19 @@ bool IOPMrootDomain::checkSystemCanSustainFullWake( void ) return true; } +//****************************************************************************** +// mustHibernate +//****************************************************************************** + +#if HIBERNATION + +bool IOPMrootDomain::mustHibernate( void ) +{ + return (lowBatteryCondition || thermalWarningState); +} + +#endif /* HIBERNATION */ + //****************************************************************************** // adjustPowerState // @@ -6316,20 +6625,22 @@ void IOPMrootDomain::handleDisplayPowerOn( ) void IOPMrootDomain::dispatchPowerEvent( uint32_t event, void * arg0, uint64_t arg1 ) { - DLOG("power event %u args %p 0x%llx\n", event, OBFUSCATE(arg0), arg1); ASSERT_GATED(); switch (event) { case kPowerEventFeatureChanged: + DMSG("power event %u args %p 0x%llx\n", event, OBFUSCATE(arg0), arg1); messageClients(kIOPMMessageFeatureChange, this); break; case kPowerEventReceivedPowerNotification: + DMSG("power event %u args %p 0x%llx\n", event, OBFUSCATE(arg0), arg1); handlePowerNotification( (UInt32)(uintptr_t) arg0 ); break; case kPowerEventSystemBootCompleted: + DLOG("power event %u args %p 0x%llx\n", event, OBFUSCATE(arg0), arg1); if (systemBooting) { systemBooting = false; @@ -6369,6 +6680,7 @@ void IOPMrootDomain::dispatchPowerEvent( break; case kPowerEventSystemShutdown: + DLOG("power event %u args %p 0x%llx\n", event, OBFUSCATE(arg0), arg1); if (kOSBooleanTrue == (OSBoolean *) arg0) { /* We set systemShutdown = true during shutdown @@ -6383,18 +6695,20 @@ void IOPMrootDomain::dispatchPowerEvent( systemShutdown = true; } else { /* - A shutdown was initiated, but then the shutdown - was cancelled, clearing systemShutdown to false here. - */ + A shutdown was initiated, but then the shutdown + was cancelled, clearing systemShutdown to false here. + */ systemShutdown = false; } break; case kPowerEventUserDisabledSleep: + DLOG("power event %u args %p 0x%llx\n", event, OBFUSCATE(arg0), arg1); userDisabledAllSleep = (kOSBooleanTrue == (OSBoolean *) arg0); break; case kPowerEventRegisterSystemCapabilityClient: + DLOG("power event %u args %p 0x%llx\n", event, OBFUSCATE(arg0), arg1); if (systemCapabilityNotifier) { systemCapabilityNotifier->release(); @@ -6409,6 +6723,7 @@ void IOPMrootDomain::dispatchPowerEvent( [[clang::fallthrough]]; case kPowerEventRegisterKernelCapabilityClient: + DLOG("power event %u args %p 0x%llx\n", event, OBFUSCATE(arg0), arg1); if (!_joinedCapabilityClients) _joinedCapabilityClients = OSSet::withCapacity(8); if (arg0) @@ -6424,6 +6739,7 @@ void IOPMrootDomain::dispatchPowerEvent( break; case kPowerEventPolicyStimulus: + DMSG("power event %u args %p 0x%llx\n", event, OBFUSCATE(arg0), arg1); if (arg0) { int stimulus = (uintptr_t) arg0; @@ -6432,6 +6748,7 @@ void IOPMrootDomain::dispatchPowerEvent( break; case kPowerEventAssertionCreate: + DMSG("power event %u args %p 0x%llx\n", event, OBFUSCATE(arg0), arg1); if (pmAssertions) { pmAssertions->handleCreateAssertion((OSData *)arg0); } @@ -6439,25 +6756,30 @@ void IOPMrootDomain::dispatchPowerEvent( case kPowerEventAssertionRelease: + DMSG("power event %u args %p 0x%llx\n", event, OBFUSCATE(arg0), arg1); if (pmAssertions) { pmAssertions->handleReleaseAssertion(arg1); } break; case kPowerEventAssertionSetLevel: + DMSG("power event %u args %p 0x%llx\n", event, OBFUSCATE(arg0), arg1); if (pmAssertions) { pmAssertions->handleSetAssertionLevel(arg1, (IOPMDriverAssertionLevel)(uintptr_t)arg0); } break; case kPowerEventQueueSleepWakeUUID: + DLOG("power event %u args %p 0x%llx\n", event, OBFUSCATE(arg0), arg1); handleQueueSleepWakeUUID((OSObject *)arg0); break; case kPowerEventPublishSleepWakeUUID: + DLOG("power event %u args %p 0x%llx\n", event, OBFUSCATE(arg0), arg1); handlePublishSleepWakeUUID((bool)arg0); break; case kPowerEventSetDisplayPowerOn: + DLOG("power event %u args %p 0x%llx\n", event, OBFUSCATE(arg0), arg1); if (!wrangler) break; if (arg1 != 0) { @@ -6642,6 +6964,7 @@ void IOPMrootDomain::handlePowerNotification( UInt32 msg ) */ if (msg & kIOPMClamshellOpened) { + DLOG("Clamshell opened\n"); // Received clamshel open message from clamshell controlling driver // Update our internal state and tell general interest clients clamshellClosed = false; @@ -6673,6 +6996,7 @@ void IOPMrootDomain::handlePowerNotification( UInt32 msg ) */ if (msg & kIOPMClamshellClosed) { + DLOG("Clamshell closed\n"); // Received clamshel open message from clamshell controlling driver // Update our internal state and tell general interest clients clamshellClosed = true; @@ -6695,6 +7019,7 @@ void IOPMrootDomain::handlePowerNotification( UInt32 msg ) */ if (msg & kIOPMSetDesktopMode) { + DLOG("Desktop mode\n"); desktopMode = (0 != (msg & kIOPMSetValue)); msg &= ~(kIOPMSetDesktopMode | kIOPMSetValue); @@ -6748,6 +7073,7 @@ void IOPMrootDomain::handlePowerNotification( UInt32 msg ) */ if (msg & kIOPMEnableClamshell) { + DLOG("Clamshell enabled\n"); // Re-evaluate the lid state // System should sleep on external display disappearance // in lid closed operation. @@ -6767,6 +7093,7 @@ void IOPMrootDomain::handlePowerNotification( UInt32 msg ) */ if (msg & kIOPMDisableClamshell) { + DLOG("Clamshell disabled\n"); clamshellDisabled = true; sendClientClamshellNotification(); } @@ -6787,6 +7114,7 @@ void IOPMrootDomain::handlePowerNotification( UInt32 msg ) */ if (msg & kIOPMPowerButton) { + DLOG("Powerbutton press\n"); if (!wranglerAsleep) { OSString *pbs = OSString::withCString("DisablePowerButtonSleep"); @@ -6822,7 +7150,6 @@ void IOPMrootDomain::evaluatePolicy( int stimulus, uint32_t arg ) uint32_t u32; } flags; - DLOG("evaluatePolicy( %d, 0x%x )\n", stimulus, arg); ASSERT_GATED(); flags.u32 = 0; @@ -6830,6 +7157,7 @@ void IOPMrootDomain::evaluatePolicy( int stimulus, uint32_t arg ) switch (stimulus) { case kStimulusDisplayWranglerSleep: + DLOG("evaluatePolicy( %d, 0x%x )\n", stimulus, arg); if (!wranglerAsleep) { // first transition to wrangler sleep or lower @@ -6838,11 +7166,13 @@ void IOPMrootDomain::evaluatePolicy( int stimulus, uint32_t arg ) break; case kStimulusDisplayWranglerWake: + DLOG("evaluatePolicy( %d, 0x%x )\n", stimulus, arg); displayIdleForDemandSleep = false; wranglerAsleep = false; break; case kStimulusEnterUserActiveState: + DLOG("evaluatePolicy( %d, 0x%x )\n", stimulus, arg); if (_preventUserActive) { DLOG("user active dropped\n"); @@ -6868,6 +7198,7 @@ void IOPMrootDomain::evaluatePolicy( int stimulus, uint32_t arg ) break; case kStimulusLeaveUserActiveState: + DLOG("evaluatePolicy( %d, 0x%x )\n", stimulus, arg); if (userIsActive) { userIsActive = false; @@ -6882,6 +7213,7 @@ void IOPMrootDomain::evaluatePolicy( int stimulus, uint32_t arg ) case kStimulusAggressivenessChanged: { + DMSG("evaluatePolicy( %d, 0x%x )\n", stimulus, arg); unsigned long minutesToIdleSleep = 0; unsigned long minutesToDisplayDim = 0; unsigned long minutesDelta = 0; @@ -6934,6 +7266,7 @@ void IOPMrootDomain::evaluatePolicy( int stimulus, uint32_t arg ) } break; case kStimulusDemandSystemSleep: + DLOG("evaluatePolicy( %d, 0x%x )\n", stimulus, arg); displayIdleForDemandSleep = true; if (wrangler && wranglerIdleSettings) { @@ -6950,10 +7283,12 @@ void IOPMrootDomain::evaluatePolicy( int stimulus, uint32_t arg ) break; case kStimulusAllowSystemSleepChanged: + DLOG("evaluatePolicy( %d, 0x%x )\n", stimulus, arg); flags.bit.adjustPowerState = true; break; case kStimulusDarkWakeActivityTickle: + DLOG("evaluatePolicy( %d, 0x%x )\n", stimulus, arg); // arg == true implies real and not self generated wrangler tickle. // Update wake type on PM work loop instead of the tickle thread to // eliminate the possibility of an early tickle clobbering the wake @@ -6977,6 +7312,7 @@ void IOPMrootDomain::evaluatePolicy( int stimulus, uint32_t arg ) case kStimulusDarkWakeEntry: case kStimulusDarkWakeReentry: + DLOG("evaluatePolicy( %d, 0x%x )\n", stimulus, arg); // Any system transitions since the last dark wake transition // will invalid the stimulus. @@ -6993,6 +7329,10 @@ void IOPMrootDomain::evaluatePolicy( int stimulus, uint32_t arg ) { clock_get_uptime(&userBecameInactiveTime); flags.bit.evaluateDarkWake = true; + if (activitySinceSleep()) { + DLOG("User activity recorded while going to darkwake\n"); + reportUserInput(); + } } // Always accelerate disk spindown while in dark wake, @@ -7004,6 +7344,7 @@ void IOPMrootDomain::evaluatePolicy( int stimulus, uint32_t arg ) break; case kStimulusDarkWakeEvaluate: + DMSG("evaluatePolicy( %d, 0x%x )\n", stimulus, arg); if (systemDarkWake) { flags.bit.evaluateDarkWake = true; @@ -7011,6 +7352,7 @@ void IOPMrootDomain::evaluatePolicy( int stimulus, uint32_t arg ) break; case kStimulusNoIdleSleepPreventers: + DMSG("evaluatePolicy( %d, 0x%x )\n", stimulus, arg); flags.bit.adjustPowerState = true; break; @@ -7238,7 +7580,7 @@ void IOPMrootDomain::requestFullWake( FullWakeReason reason ) absolutetime_to_nanoseconds(now, &nsec); MSG("full wake %s (reason %u) %u ms\n", promotion ? "promotion" : "request", - fullWakeReason, ((int)((nsec) / 1000000ULL))); + fullWakeReason, ((int)((nsec) / NSEC_PER_MSEC))); } } @@ -7348,6 +7690,22 @@ void IOPMrootDomain::evaluateAssertions(IOPMDriverAssertionType newAssertions, I } } +void IOPMrootDomain::evaluateWranglerAssertions() +{ + if (gIOPMWorkLoop->inGate() == false) { + gIOPMWorkLoop->runAction( + OSMemberFunctionCast(IOWorkLoop::Action, this, &IOPMrootDomain::evaluateWranglerAssertions), + (OSObject *)this); + + return; + } + + if (pmAssertions->getActivatedAssertions() & kIOPMDriverAssertionPreventDisplaySleepBit) { + DLOG("wrangler setIgnoreIdleTimer\(1) on matching\n"); + wrangler->setIgnoreIdleTimer( true ); + } +} + // MARK: - // MARK: Statistics @@ -7379,7 +7737,7 @@ void IOPMrootDomain::pmStatsRecordEvent( if (stopping) { delta = gPMStats.hibWrite.stop - gPMStats.hibWrite.start; - IOLog("PMStats: Hibernate write took %qd ms\n", delta/1000000ULL); + IOLog("PMStats: Hibernate write took %qd ms\n", delta/NSEC_PER_MSEC); } break; case kIOPMStatsHibernateImageRead: @@ -7390,7 +7748,7 @@ void IOPMrootDomain::pmStatsRecordEvent( if (stopping) { delta = gPMStats.hibRead.stop - gPMStats.hibRead.start; - IOLog("PMStats: Hibernate read took %qd ms\n", delta/1000000ULL); + IOLog("PMStats: Hibernate read took %qd ms\n", delta/NSEC_PER_MSEC); publishPMStats = OSData::withBytes(&gPMStats, sizeof(gPMStats)); setProperty(kIOPMSleepStatisticsKey, publishPMStats); @@ -7425,23 +7783,29 @@ void IOPMrootDomain::pmStatsRecordApplicationResponse( if (object && (notify = OSDynamicCast(IOPMServiceInterestNotifier, object))) { - if (response->isEqualTo(gIOPMStatsApplicationResponseTimedOut)) + if (response->isEqualTo(gIOPMStatsResponseTimedOut)) notify->ackTimeoutCnt++; else notify->ackTimeoutCnt = 0; } - if (response->isEqualTo(gIOPMStatsApplicationResponsePrompt) || + if (response->isEqualTo(gIOPMStatsResponsePrompt) || (_systemTransitionType == kSystemTransitionNone) || (_systemTransitionType == kSystemTransitionNewCapClient)) return; if (response->isEqualTo(gIOPMStatsDriverPSChangeSlow)) { - kdebugTrace(kPMLogDrvResponseDelay, id, messageType, delay_ms); + kdebugTrace(kPMLogDrvPSChangeDelay, id, messageType, delay_ms); } else if (notify) { - kdebugTrace(kPMLogAppResponseDelay, id, notify->msgType, delay_ms); + // User space app or kernel capability client + if (id) { + kdebugTrace(kPMLogAppResponseDelay, id, notify->msgType, delay_ms); + } + else { + kdebugTrace(kPMLogDrvResponseDelay, notify->uuid0, messageType, delay_ms); + } notify->msgType = 0; } @@ -7458,6 +7822,10 @@ void IOPMrootDomain::pmStatsRecordApplicationResponse( msgNum->release(); } + if (!name && notify && notify->identifier) { + name = notify->identifier->getCStringNoCopy(); + } + if (name && (strlen(name) > 0)) { appname = OSSymbol::withCString(name); @@ -7467,8 +7835,11 @@ void IOPMrootDomain::pmStatsRecordApplicationResponse( } } + if (!id && notify) { + id = notify->uuid0; + } if (id != 0) { - pidNum = OSNumber::withNumber(id, 32); + pidNum = OSNumber::withNumber(id, 64); if (pidNum) { responseDescription->setObject(_statsPIDKey, pidNum); pidNum->release(); @@ -7548,7 +7919,6 @@ IOReturn IOPMrootDomain::callPlatformFunction( void * param3, void * param4 ) { uint32_t bootFailureCode = 0xffffffff; - unsigned int len = sizeof(bootFailureCode); if (pmTracer && functionName && functionName->isEqualTo(kIOPMRegisterNVRAMTracePointHandlerKey) && !pmTracer->tracePointHandler && !pmTracer->tracePointTarget) @@ -7561,11 +7931,17 @@ IOReturn IOPMrootDomain::callPlatformFunction( tracePointPCI = (uint32_t)(uintptr_t) param3; tracePointPhases = (uint32_t)(uintptr_t) param4; if ((tracePointPhases & 0xff) == kIOPMTracePointSystemSleep) { - if (!PEReadNVRAMProperty(kIOEFIBootRomFailureKey, &bootFailureCode, &len)) { - MSG("Failed to read failure code from NVRam\n"); - } - // Failure code from EFI/BootRom is a four byte structure - tracePointPCI = OSSwapBigToHostInt32(bootFailureCode); + + IORegistryEntry *node = IORegistryEntry::fromPath( "/chosen", gIODTPlane ); + if ( node ) { + OSData *data = OSDynamicCast( OSData, node->getProperty(kIOEFIBootRomFailureKey) ); + if ( data && data->getLength() == sizeof(bootFailureCode) ) { + memcpy(&bootFailureCode, data->getBytesNoCopy(), sizeof(bootFailureCode)); + } + node->release(); + } + // Failure code from EFI/BootRom is a four byte structure + tracePointPCI = OSSwapBigToHostInt32(bootFailureCode); } statusCode = (((uint64_t)tracePointPCI) << 32) | tracePointPhases; if ((tracePointPhases & 0xff) != kIOPMTracePointSystemUp) { @@ -7619,14 +7995,57 @@ void IOPMrootDomain::tracePoint( uint8_t point ) pmTracer->tracePoint(point); } -void IOPMrootDomain::traceDetail(uint32_t msgType, uint32_t msgIndex, uintptr_t handler) +void IOPMrootDomain::traceDetail(OSObject *object) +{ + IOPMServiceInterestNotifier *notifier = OSDynamicCast(IOPMServiceInterestNotifier, object); + if (!notifier) { + DLOG("Unknown notifier\n"); + return; + } + + if (!systemBooting) { + pmTracer->traceDetail( notifier->uuid0 >> 32 ); + kdebugTrace(kPMLogSleepWakeMessage, pmTracer->getTracePhase(), notifier->msgType, notifier->uuid0, notifier->uuid1); + if (notifier->identifier) { + DLOG("trace point 0x%02x msg 0x%x to %s\n", pmTracer->getTracePhase(), notifier->msgType, + notifier->identifier->getCStringNoCopy()); + } + else { + DLOG("trace point 0x%02x msg 0x%x\n", pmTracer->getTracePhase(), notifier->msgType); + } + } + +} + + +void IOPMrootDomain::traceAckDelay(OSObject *object, uint32_t response, uint32_t delay_ms) +{ + IOPMServiceInterestNotifier *notifier = OSDynamicCast(IOPMServiceInterestNotifier, object); + if (!notifier) { + DLOG("Unknown notifier\n"); + return; + } + + if (!systemBooting) { + kdebugTrace(kPMLogDrvResponseDelay, notifier->uuid0, notifier->uuid1, response, delay_ms); + if (notifier->identifier) { + DLOG("Response from %s took %d ms(response:%d)\n", + notifier->identifier->getCStringNoCopy(), delay_ms, response); + } + else { + DLOG("Response from kext UUID %llx-%llx took %d ms(response:%d)\n", + notifier->uuid0, notifier->uuid1, delay_ms, response); + } + } +} + +void IOPMrootDomain::traceDetail(uint32_t msgType, uint32_t msgIndex, uint32_t delay) { if (!systemBooting) { - uint32_t detail = ((msgIndex & 0xff) << 24) | - ((msgType & 0xfff) << 12) | - (handler & 0xfff); + uint32_t detail = ((msgType & 0xffff) << 16) | (delay & 0xffff); pmTracer->traceDetail( detail ); - kdebugTrace(kPMLogSleepWakeTracePoint, 0, pmTracer->getTracePhase(), msgType, handler & 0xfff); + kdebugTrace(kPMLogSleepWakeTracePoint, pmTracer->getTracePhase(), msgType, delay); + DLOG("trace point 0x%02x msgType 0x%x detail 0x%08x\n", pmTracer->getTracePhase(), msgType, delay); } } @@ -7927,10 +8346,10 @@ void PMTraceWorker::tracePoint(uint8_t phase) void PMTraceWorker::traceDetail(uint32_t detail) { - + if (detail == traceData32) { + return; + } traceData32 = detail; - DLOG("trace point 0x%02x detail 0x%08x\n", tracePhase, traceData32); - RTC_TRACE(); } @@ -8108,7 +8527,7 @@ void PMHaltWorker::work( PMHaltWorker * me ) { IOService * service; OSSet * inner; - AbsoluteTime startTime; + AbsoluteTime startTime, elapsedTime; UInt32 deltaTime; bool timeout; @@ -8157,15 +8576,17 @@ void PMHaltWorker::work( PMHaltWorker * me ) IOLockUnlock(me->lock); } - deltaTime = computeDeltaTimeMS(&startTime); - if ((deltaTime > kPMHaltTimeoutMS) || timeout || - (gIOKitDebug & kIOLogPMRootDomain)) + deltaTime = computeDeltaTimeMS(&startTime, &elapsedTime); + if ((deltaTime > kPMHaltTimeoutMS) || timeout) { LOG("%s driver %s (0x%llx) took %u ms\n", (gPMHaltMessageType == kIOMessageSystemWillPowerOff) ? "PowerOff" : "Restart", service->getName(), service->getRegistryEntryID(), (uint32_t) deltaTime ); + halt_log_enter("PowerOff/Restart handler completed", + OSMemberFunctionCast(const void *, service, &IOService::systemWillShutdown), + elapsedTime); } service->release(); @@ -8194,9 +8615,12 @@ void PMHaltWorker::checkTimeout( PMHaltWorker * me, AbsoluteTime * now ) if (nano > 3000000000ULL) { me->timeout = true; + + halt_log_enter("PowerOff/Restart still waiting on handler", + OSMemberFunctionCast(const void *, me->service, &IOService::systemWillShutdown), + endTime); MSG("%s still waiting on %s\n", - (gPMHaltMessageType == kIOMessageSystemWillPowerOff) ? - "PowerOff" : "Restart", + (gPMHaltMessageType == kIOMessageSystemWillPowerOff) ? "PowerOff" : "Restart", me->service->getName()); } } @@ -8638,6 +9062,29 @@ void IOPMrootDomain::acceptSystemWakeEvents( bool accept ) else { _acceptSystemWakeEvents = false; +#if CONFIG_EMBEDDED + logWakeReason = gWakeReasonSysctlRegistered; +#if DEVELOPMENT + static int panic_allowed = -1; + + if ((panic_allowed == -1) && + (PE_parse_boot_argn("swd_wakereason_panic", &panic_allowed, sizeof(panic_allowed)) == false)) { + panic_allowed = 1; + } + + if (panic_allowed) { + size_t i = 0; + // Panic if wake reason is null or empty + for (i = 0; (i < strlen(gWakeReasonString)); i++) { + if ((gWakeReasonString[i] != ' ') && (gWakeReasonString[i] != '\t')) + break; + } + if (i >= strlen(gWakeReasonString)) { + panic("Wake reason is empty\n"); + } + } +#endif +#endif } WAKEEVENT_UNLOCK(); @@ -8693,6 +9140,9 @@ void IOPMrootDomain::claimSystemWakeEvent( // Lazy registration until the platform driver stops registering // the same name. gWakeReasonSysctlRegistered = true; +#if CONFIG_EMBEDDED + sysctl_register_oid(&sysctl__kern_wakereason); +#endif } if (_acceptSystemWakeEvents) { @@ -9342,6 +9792,7 @@ void IOPMrootDomain::takeStackshot(bool wdogTrigger, bool isOSXWatchdog, bool is swd_hdr * hdr = NULL; addr64_t data[3]; int wdog_panic = -1; + int stress_rack = -1; int cnt = 0; pid_t pid = 0; kern_return_t kr = KERN_SUCCESS; @@ -9372,9 +9823,10 @@ void IOPMrootDomain::takeStackshot(bool wdogTrigger, bool isOSXWatchdog, bool is if (wdogTrigger) { PE_parse_boot_argn("swd_panic", &wdog_panic, sizeof(wdog_panic)); - if (wdog_panic == 1) { + PE_parse_boot_argn("stress-rack", &stress_rack, sizeof(stress_rack)); + if ((wdog_panic == 1) || (stress_rack == 1) || (PEGetCoprocessorVersion() >= kCoprocessorVersion2)) { // If boot-arg specifies to panic then panic. - panic("Sleep/Wake hang detected\n"); + panic("Sleep/Wake hang detected"); return; } else if (swd_flags & SWD_BOOT_BY_SW_WDOG) { @@ -9382,6 +9834,10 @@ void IOPMrootDomain::takeStackshot(bool wdogTrigger, bool isOSXWatchdog, bool is // then don't trigger again until at least 1 successful sleep & wake. if (!(sleepCnt && (displayWakeCnt || darkWakeCnt))) { IOLog("Shutting down due to repeated Sleep/Wake failures\n"); + if (!tasksSuspended) { + tasksSuspended = TRUE; + tasks_system_suspend(true); + } PEHaltRestart(kPEHaltCPU); return; } @@ -9524,8 +9980,13 @@ exit: gRootDomain->swd_lock = 0; if (wdogTrigger) { - IOLog("Restarting to collect Sleep wake debug logs\n"); - PEHaltRestart(kPERestartCPU); + IOLog("Restarting to collect Sleep wake debug logs\n"); + if (!tasksSuspended) { + tasksSuspended = TRUE; + tasks_system_suspend(true); + } + + PEHaltRestart(kPERestartCPU); } else { logBufMap = sleepWakeDebugRetrieve(); @@ -9549,6 +10010,9 @@ void IOPMrootDomain::sleepWakeDebugMemAlloc( ) if ( kIOSleepWakeWdogOff & gIOKitDebug ) return; + if (PEGetCoprocessorVersion() >= kCoprocessorVersion2) + return; + if (!OSCompareAndSwap(0, 1, &gRootDomain->swd_lock)) return; @@ -9833,8 +10297,8 @@ uint32_t IOPMrootDomain::checkForValidDebugData(const char *fname, vfs_context_t vfs_context_ucred(*ctx), (int *) 0, vfs_context_proc(*ctx)); if (rc != 0) { - IOLog("sleepWakeDebugDumpFromFile: Failed to read header size %lu(rc=%d) from %s\n", - round_page(sizeof(IOHibernateImageHeader)), rc, fname); + IOLog("sleepWakeDebugDumpFromFile: Failed to read header size %llu(rc=%d) from %s\n", + mach_vm_round_page(sizeof(IOHibernateImageHeader)), rc, fname); error = SWD_FILEOP_ERROR; goto err; } @@ -9938,15 +10402,15 @@ void IOPMrootDomain::sleepWakeDebugDumpFromFile( ) hdrOffset = ((IOHibernateImageHeader *)tmpBuf)->deviceBlockSize; - DLOG("Reading swd_hdr len 0x%lx offset 0x%lx\n", round_page(sizeof(swd_hdr)), trunc_page(hdrOffset)); + DLOG("Reading swd_hdr len 0x%llx offset 0x%lx\n", mach_vm_round_page(sizeof(swd_hdr)), trunc_page(hdrOffset)); /* Read the sleep/wake debug header(swd_hdr) */ rc = vn_rdwr(UIO_READ, vp, (char *)tmpBuf, round_page(sizeof(swd_hdr)), trunc_page(hdrOffset), UIO_SYSSPACE, IO_SKIP_ENCRYPTION|IO_SYNC|IO_NODELOCKED|IO_UNIT|IO_NOCACHE, vfs_context_ucred(ctx), (int *) 0, vfs_context_proc(ctx)); if (rc != 0) { - DMSG("sleepWakeDebugDumpFromFile: Failed to debug read header size %lu. rc=%d\n", - round_page(sizeof(swd_hdr)), rc); + DMSG("sleepWakeDebugDumpFromFile: Failed to debug read header size %llu. rc=%d\n", + mach_vm_round_page(sizeof(swd_hdr)), rc); swd_flags |= SWD_FILEOP_ERROR; goto exit; } @@ -10223,7 +10687,7 @@ void IOPMrootDomain::sleepWakeDebugTrig(bool restart) (wdog_panic == 0)) { return; } - panic("Sleep/Wake hang detected\n"); + panic("Sleep/Wake hang detected"); return; } }