#define ns_per_us 1000
#define k30Seconds (30*us_per_s)
#define k5Seconds ( 5*us_per_s)
+#if CONFIG_EMBEDDED
+#define kCanSleepMaxTimeReq k5Seconds
+#else
#define kCanSleepMaxTimeReq k30Seconds
+#endif
#define kMaxTimeRequested k30Seconds
#define kMinAckTimeoutTicks (10*1000000)
#define kIOPMTardyAckSPSKey "IOPMTardyAckSetPowerState"
// use message tracer to log messages longer than (ns):
#define LOG_APP_RESPONSE_MSG_TRACER (3 * 1000ULL * 1000ULL * 1000ULL)
+// log kext responses longer than (ns):
+#define LOG_KEXT_RESPONSE_TIMES (100ULL * 1000ULL * 1000ULL)
+
enum {
kReserveDomainPower = 1
};
PM_ERROR("%s::setPowerState(%p, %lu -> %lu) timed out after %d ms\n",
fName, OBFUSCATE(this), fCurrentPowerState, fHeadNotePowerState, NS_TO_MS(nsec));
+#if DEBUG && CONFIG_EMBEDDED
+ panic("%s::setPowerState(%p, %lu -> %lu) timed out after %d ms",
+ fName, this, fCurrentPowerState, fHeadNotePowerState, NS_TO_MS(nsec));
+#else
if (gIOKitDebug & kIOLogDebugPower)
{
panic("%s::setPowerState(%p, %lu -> %lu) timed out after %d ms",
// Unblock state machine and pretend driver has acked.
done = true;
}
+#endif
} else {
// still waiting, set timer again
start_ack_timer();
// TODO: record message type if possible
IOService::getPMRootDomain()->pmStatsRecordApplicationResponse(
- gIOPMStatsApplicationResponseTimedOut,
+ gIOPMStatsResponseTimedOut,
name, 0, (30*1000), pid, object);
}
applyToInterested( gIOGeneralInterest,
pmTellClientWithResponse, (void *) &context );
- fNotifyClientArray = context.notifyClients;
break;
case kNotifyPriority:
case kNotifyCapabilityChangeApps:
applyToInterested( gIOAppPowerStateInterest,
pmTellCapabilityAppWithResponse, (void *) &context );
- fNotifyClientArray = context.notifyClients;
if(context.messageType == kIOMessageCanSystemSleep)
{
maxTimeOut = kCanSleepMaxTimeReq;
pmTellCapabilityClientWithResponse, (void *) &context );
break;
}
+ fNotifyClientArray = context.notifyClients;
// do we have to wait for somebody?
if ( !checkForDone() )
_IOServiceInterestNotifier * notifier;
uint32_t msgIndex, msgRef, msgType;
IOReturn retCode;
+ AbsoluteTime start, end;
+ uint64_t nsec;
if (context->messageFilter &&
!context->messageFilter(context->us, object, context, 0, 0))
OBFUSCATE(object), OBFUSCATE(notifier->handler));
}
+ if (0 == context->notifyClients)
+ context->notifyClients = OSArray::withCapacity( 32 );
+
notify.powerRef = (void *)(uintptr_t) msgRef;
notify.returnValue = 0;
notify.stateNumber = context->stateNumber;
if (context->enableTracing && (notifier != 0))
{
- getPMRootDomain()->traceDetail(msgType, msgIndex, (uintptr_t) notifier->handler);
+ getPMRootDomain()->traceDetail(notifier);
}
+ clock_get_uptime(&start);
retCode = context->us->messageClient(msgType, object, (void *) ¬ify, sizeof(notify));
+ clock_get_uptime(&end);
if (kIOReturnSuccess == retCode)
{
if (0 == notify.returnValue) {
OUR_PMLog(kPMLogClientAcknowledge, msgRef, (uintptr_t) object);
+ context->responseArray->setObject(msgIndex, replied);
} else {
replied = kOSBooleanFalse;
if ( notify.returnValue > context->maxTimeRequested )
else
context->maxTimeRequested = notify.returnValue;
}
+ //
+ // Track time taken to ack, by storing the timestamp of
+ // callback completion
+ OSNumber * num;
+ num = OSNumber::withNumber(AbsoluteTime_to_scalar(&end), sizeof(uint64_t) * 8);
+ if (num) {
+ context->responseArray->setObject(msgIndex, num);
+ num->release();
+ }
+ else {
+ context->responseArray->setObject(msgIndex, replied);
+ }
}
- } else {
+
+ if (context->enableTracing) {
+ SUB_ABSOLUTETIME(&end, &start);
+ absolutetime_to_nanoseconds(end, &nsec);
+
+ if ((nsec > LOG_KEXT_RESPONSE_TIMES) || (notify.returnValue != 0)) {
+ getPMRootDomain()->traceAckDelay(notifier, notify.returnValue/1000, NS_TO_MS(nsec));
+ }
+ }
+ }
+ else {
// not a client of ours
// so we won't be waiting for response
OUR_PMLog(kPMLogClientAcknowledge, msgRef, 0);
+ context->responseArray->setObject(msgIndex, replied);
+ }
+ if (context->notifyClients) {
+ context->notifyClients->setObject(msgIndex, object);
}
- context->responseArray->setObject(msgIndex, replied);
}
//*********************************************************************************
_IOServiceInterestNotifier * notifier;
uint32_t msgIndex, msgRef, msgType;
IOReturn retCode;
+ AbsoluteTime start, end;
+ uint64_t nsec;
memset(&msgArg, 0, sizeof(msgArg));
if (context->messageFilter &&
return;
}
+ if (0 == context->notifyClients) {
+ context->notifyClients = OSArray::withCapacity( 32 );
+ }
notifier = OSDynamicCast(_IOServiceInterestNotifier, object);
msgType = context->messageType;
msgIndex = context->responseArray->getCount();
if (context->enableTracing && (notifier != 0))
{
- getPMRootDomain()->traceDetail(msgType, msgIndex, (uintptr_t) notifier->handler);
+ getPMRootDomain()->traceDetail(notifier);
}
+ clock_get_uptime(&start);
retCode = context->us->messageClient(
msgType, object, (void *) &msgArg, sizeof(msgArg));
+ clock_get_uptime(&end);
if ( kIOReturnSuccess == retCode )
{
{
// client doesn't want time to respond
OUR_PMLog(kPMLogClientAcknowledge, msgRef, (uintptr_t) object);
+ context->responseArray->setObject(msgIndex, replied);
}
else
{
{
context->maxTimeRequested = kCapabilityClientMaxWait;
PM_ERROR("%s: client %p returned %u for %s\n",
- context->us->getName(),
- notifier ? (void *) OBFUSCATE(notifier->handler) : OBFUSCATE(object),
- msgArg.maxWaitForReply,
- getIOMessageString(msgType));
+ context->us->getName(),
+ notifier ? (void *) OBFUSCATE(notifier->handler) : OBFUSCATE(object),
+ msgArg.maxWaitForReply,
+ getIOMessageString(msgType));
}
else
context->maxTimeRequested = msgArg.maxWaitForReply;
}
+
+ // Track time taken to ack, by storing the timestamp of
+ // callback completion
+ OSNumber * num;
+ num = OSNumber::withNumber(AbsoluteTime_to_scalar(&end), sizeof(uint64_t) * 8);
+ if (num) {
+ context->responseArray->setObject(msgIndex, num);
+ num->release();
+ }
+ else {
+ context->responseArray->setObject(msgIndex, replied);
+ }
+ }
+
+ if (context->enableTracing) {
+ SUB_ABSOLUTETIME(&end, &start);
+ absolutetime_to_nanoseconds(end, &nsec);
+
+ if ((nsec > LOG_KEXT_RESPONSE_TIMES) || (msgArg.maxWaitForReply != 0)) {
+ getPMRootDomain()->traceAckDelay(notifier, msgArg.maxWaitForReply/1000, NS_TO_MS(nsec));
+ }
}
}
else
// not a client of ours
// so we won't be waiting for response
OUR_PMLog(kPMLogClientAcknowledge, msgRef, 0);
+ context->responseArray->setObject(msgIndex, replied);
+ }
+ if (context->notifyClients) {
+ context->notifyClients->setObject(msgIndex, object);
}
- context->responseArray->setObject(msgIndex, replied);
}
//*********************************************************************************
uint64_t nsec;
char name[128];
- name[0] = '\0';
- proc_name(pid, name, sizeof(name));
clock_get_uptime(&now);
AbsoluteTime_to_scalar(&start) = num->unsigned64BitValue();
SUB_ABSOLUTETIME(&now, &start);
absolutetime_to_nanoseconds(now, &nsec);
+ if (pid != 0) {
+ name[0] = '\0';
+ proc_name(pid, name, sizeof(name));
+
+ if (nsec > LOG_APP_RESPONSE_TIMES)
+ {
+ IOLog("PM response took %d ms (%d, %s)\n", NS_TO_MS(nsec),
+ pid, name);
+ }
+
+
+ if (nsec > LOG_APP_RESPONSE_MSG_TRACER)
+ {
+ // TODO: populate the messageType argument
+ getPMRootDomain()->pmStatsRecordApplicationResponse(
+ gIOPMStatsResponseSlow,
+ name, 0, NS_TO_MS(nsec), pid, object);
+ }
+ else
+ {
+ getPMRootDomain()->pmStatsRecordApplicationResponse(
+ gIOPMStatsResponsePrompt,
+ name, 0, NS_TO_MS(nsec), pid, object);
+ }
+ }
+ else {
+ getPMRootDomain()->traceAckDelay(object, 0, NS_TO_MS(nsec));
+ }
+
if (kIOLogDebugPower & gIOKitDebug)
{
PM_LOG("Ack(%u) %u ms\n",
(uint32_t) ordinalComponent,
NS_TO_MS(nsec));
}
-
- // > 100 ms
- if (nsec > LOG_APP_RESPONSE_TIMES)
- {
- IOLog("PM response took %d ms (%d, %s)\n", NS_TO_MS(nsec),
- pid, name);
- }
-
- if (nsec > LOG_APP_RESPONSE_MSG_TRACER)
- {
- // TODO: populate the messageType argument
- getPMRootDomain()->pmStatsRecordApplicationResponse(
- gIOPMStatsApplicationResponseSlow,
- name, 0, NS_TO_MS(nsec), pid, object);
- }
- else
- {
- getPMRootDomain()->pmStatsRecordApplicationResponse(
- gIOPMStatsApplicationResponsePrompt,
- name, 0, NS_TO_MS(nsec), pid, object);
- }
-
-
theFlag = kOSBooleanFalse;
}
else if (object) {
getPMRootDomain()->pmStatsRecordApplicationResponse(
- gIOPMStatsApplicationResponsePrompt,
+ gIOPMStatsResponsePrompt,
0, 0, 0, pid, object);
}
OSString * name = (OSString *) request->fArg2;
getPMRootDomain()->pmStatsRecordApplicationResponse(
- gIOPMStatsApplicationResponseCancel,
+ gIOPMStatsResponseCancel,
name ? name->getCStringNoCopy() : "", 0,
0, (int)(uintptr_t) request->fArg1, 0);
}
MSG_ENTRY( kIOMessageSystemWillRestart ),
MSG_ENTRY( kIOMessageSystemWillPowerOn ),
MSG_ENTRY( kIOMessageSystemCapabilityChange ),
- MSG_ENTRY( kIOPMMessageLastCallBeforeSleep )
+ MSG_ENTRY( kIOPMMessageLastCallBeforeSleep ),
+ MSG_ENTRY( kIOMessageSystemPagingOff ),
+ { 0, NULL }
};
return IOFindNameForValue(msg, msgNames);
projects / apple / xnu.git / blobdiff