diff --git a/core/java/android/os/PowerManager.java b/core/java/android/os/PowerManager.java index f381fdfc4c629..75f8279c6c12c 100644 --- a/core/java/android/os/PowerManager.java +++ b/core/java/android/os/PowerManager.java @@ -773,6 +773,7 @@ public final class PowerManager { private boolean mHeld; private WorkSource mWorkSource; private String mHistoryTag; + private final String mTraceName; private final Runnable mReleaser = new Runnable() { public void run() { @@ -785,6 +786,7 @@ public final class PowerManager { mTag = tag; mPackageName = packageName; mToken = new Binder(); + mTraceName = "WakeLock (" + mTag + ")"; } @Override @@ -792,6 +794,7 @@ public final class PowerManager { synchronized (mToken) { if (mHeld) { Log.wtf(TAG, "WakeLock finalized while still held: " + mTag); + Trace.asyncTraceEnd(Trace.TRACE_TAG_POWER, mTraceName, 0); try { mService.releaseWakeLock(mToken, 0); } catch (RemoteException e) { @@ -858,6 +861,7 @@ public final class PowerManager { // should immediately acquire the wake lock once again despite never having // been explicitly released by the keyguard. mHandler.removeCallbacks(mReleaser); + Trace.asyncTraceBegin(Trace.TRACE_TAG_POWER, mTraceName, 0); try { mService.acquireWakeLock(mToken, mFlags, mTag, mPackageName, mWorkSource, mHistoryTag); @@ -897,6 +901,7 @@ public final class PowerManager { if (!mRefCounted || --mCount == 0) { mHandler.removeCallbacks(mReleaser); if (mHeld) { + Trace.asyncTraceEnd(Trace.TRACE_TAG_POWER, mTraceName, 0); try { mService.releaseWakeLock(mToken, flags); } catch (RemoteException e) { diff --git a/core/java/android/os/Trace.java b/core/java/android/os/Trace.java index 474192fd0c906..31b58490ba240 100644 --- a/core/java/android/os/Trace.java +++ b/core/java/android/os/Trace.java @@ -36,6 +36,7 @@ public final class Trace { private static final String TAG = "Trace"; // These tags must be kept in sync with system/core/include/cutils/trace.h. + // They should also be added to frameworks/native/cmds/atrace/atrace.cpp. /** @hide */ public static final long TRACE_TAG_NEVER = 0; /** @hide */ @@ -72,6 +73,8 @@ public final class Trace { public static final long TRACE_TAG_RS = 1L << 15; /** @hide */ public static final long TRACE_TAG_BIONIC = 1L << 16; + /** @hide */ + public static final long TRACE_TAG_POWER = 1L << 17; private static final long TRACE_TAG_NOT_READY = 1L << 63; private static final int MAX_SECTION_NAME_LEN = 127; diff --git a/services/core/java/com/android/server/display/DisplayPowerController.java b/services/core/java/com/android/server/display/DisplayPowerController.java index 9a6732126ebd1..46cb6c398d99b 100644 --- a/services/core/java/com/android/server/display/DisplayPowerController.java +++ b/services/core/java/com/android/server/display/DisplayPowerController.java @@ -37,7 +37,7 @@ import android.os.Message; import android.os.PowerManager; import android.os.RemoteException; import android.os.SystemClock; -import android.text.format.DateUtils; +import android.os.Trace; import android.util.MathUtils; import android.util.Slog; import android.util.Spline; @@ -74,6 +74,8 @@ final class DisplayPowerController implements AutomaticBrightnessController.Call private static boolean DEBUG = false; private static final boolean DEBUG_PRETEND_PROXIMITY_SENSOR_ABSENT = false; + private static final String SCREEN_ON_BLOCKED_TRACE_NAME = "Screen on blocked"; + // If true, uses the electron beam on animation. // We might want to turn this off if we cannot get a guarantee that the screen // actually turns on and starts showing new content after the call to set the @@ -714,11 +716,10 @@ final class DisplayPowerController implements AutomaticBrightnessController.Call private void blockScreenOn() { if (!mScreenOnWasBlocked) { + Trace.asyncTraceBegin(Trace.TRACE_TAG_POWER, SCREEN_ON_BLOCKED_TRACE_NAME, 0); mScreenOnWasBlocked = true; mScreenOnBlockStartRealTime = SystemClock.elapsedRealtime(); - if (DEBUG) { - Slog.d(TAG, "Blocked screen on."); - } + Slog.i(TAG, "Blocking screen on until initial contents have been drawn."); } } @@ -726,9 +727,8 @@ final class DisplayPowerController implements AutomaticBrightnessController.Call if (mScreenOnWasBlocked) { mScreenOnWasBlocked = false; long delay = SystemClock.elapsedRealtime() - mScreenOnBlockStartRealTime; - if (delay > 1000 || DEBUG) { - Slog.d(TAG, "Unblocked screen on after " + delay + " ms"); - } + Slog.i(TAG, "Unblocked screen on after " + delay + " ms"); + Trace.asyncTraceEnd(Trace.TRACE_TAG_POWER, SCREEN_ON_BLOCKED_TRACE_NAME, 0); } } diff --git a/services/core/java/com/android/server/display/DisplayPowerState.java b/services/core/java/com/android/server/display/DisplayPowerState.java index 6522b89e2d422..a7651e42107ed 100644 --- a/services/core/java/com/android/server/display/DisplayPowerState.java +++ b/services/core/java/com/android/server/display/DisplayPowerState.java @@ -23,6 +23,7 @@ import android.os.AsyncTask; import android.os.Handler; import android.os.Looper; import android.os.PowerManager; +import android.os.Trace; import android.util.FloatProperty; import android.util.IntProperty; import android.util.Slog; @@ -405,19 +406,38 @@ final class DisplayPowerState { } boolean suspending = Display.isSuspendedState(state); if (stateChanged && !suspending) { - mBlanker.requestDisplayState(state); + requestDisplayState(state); } if (backlightChanged) { - mBacklight.setBrightness(backlight); + setBrightness(backlight); } if (stateChanged && suspending) { - mBlanker.requestDisplayState(state); + requestDisplayState(state); } } // Let the outer class know that all changes have been applied. postScreenUpdateThreadSafe(); } + + private void requestDisplayState(int state) { + Trace.traceBegin(Trace.TRACE_TAG_POWER, "requestDisplayState(" + + Display.stateToString(state) + ")"); + try { + mBlanker.requestDisplayState(state); + } finally { + Trace.traceEnd(Trace.TRACE_TAG_POWER); + } + } + + private void setBrightness(int backlight) { + Trace.traceBegin(Trace.TRACE_TAG_POWER, "setBrightness(" + backlight + ")"); + try { + mBacklight.setBrightness(backlight); + } finally { + Trace.traceEnd(Trace.TRACE_TAG_POWER); + } + } }; } } diff --git a/services/core/java/com/android/server/display/LocalDisplayAdapter.java b/services/core/java/com/android/server/display/LocalDisplayAdapter.java index 4fd006d7e70ac..9c91ab505f2f8 100644 --- a/services/core/java/com/android/server/display/LocalDisplayAdapter.java +++ b/services/core/java/com/android/server/display/LocalDisplayAdapter.java @@ -21,7 +21,7 @@ import android.os.Handler; import android.os.IBinder; import android.os.Looper; import android.os.SystemProperties; -import android.util.Pair; +import android.os.Trace; import android.util.Slog; import android.util.SparseArray; import android.view.Display; @@ -224,8 +224,14 @@ final class LocalDisplayAdapter extends DisplayAdapter { @Override public void requestDisplayStateLocked(int state) { if (mState != state) { - SurfaceControl.setDisplayPowerMode(getDisplayTokenLocked(), - getPowerModeForState(state)); + final int mode = getPowerModeForState(state); + Trace.traceBegin(Trace.TRACE_TAG_POWER, "requestDisplayState(" + + Display.stateToString(state) + ", id=" + mBuiltInDisplayId + ")"); + try { + SurfaceControl.setDisplayPowerMode(getDisplayTokenLocked(), mode); + } finally { + Trace.traceEnd(Trace.TRACE_TAG_POWER); + } mState = state; updateDeviceInfoLocked(); } diff --git a/services/core/java/com/android/server/dreams/DreamController.java b/services/core/java/com/android/server/dreams/DreamController.java index 334f0aca497dd..768ccf228513b 100644 --- a/services/core/java/com/android/server/dreams/DreamController.java +++ b/services/core/java/com/android/server/dreams/DreamController.java @@ -25,6 +25,7 @@ import android.os.Handler; import android.os.IBinder; import android.os.RemoteException; import android.os.IBinder.DeathRecipient; +import android.os.Trace; import android.os.UserHandle; import android.service.dreams.DreamService; import android.service.dreams.IDreamService; @@ -111,41 +112,46 @@ final class DreamController { boolean isTest, boolean canDoze, int userId) { stopDream(true /*immediate*/); - // Close the notification shade. Don't need to send to all, but better to be explicit. - mContext.sendBroadcastAsUser(mCloseNotificationShadeIntent, UserHandle.ALL); - - Slog.i(TAG, "Starting dream: name=" + name - + ", isTest=" + isTest + ", canDoze=" + canDoze - + ", userId=" + userId); - - mCurrentDream = new DreamRecord(token, name, isTest, canDoze, userId); - + Trace.traceBegin(Trace.TRACE_TAG_POWER, "startDream"); try { - mIWindowManager.addWindowToken(token, WindowManager.LayoutParams.TYPE_DREAM); - } catch (RemoteException ex) { - Slog.e(TAG, "Unable to add window token for dream.", ex); - stopDream(true /*immediate*/); - return; - } + // Close the notification shade. Don't need to send to all, but better to be explicit. + mContext.sendBroadcastAsUser(mCloseNotificationShadeIntent, UserHandle.ALL); - Intent intent = new Intent(DreamService.SERVICE_INTERFACE); - intent.setComponent(name); - intent.addFlags(Intent.FLAG_ACTIVITY_EXCLUDE_FROM_RECENTS); - try { - if (!mContext.bindServiceAsUser(intent, mCurrentDream, - Context.BIND_AUTO_CREATE, new UserHandle(userId))) { - Slog.e(TAG, "Unable to bind dream service: " + intent); + Slog.i(TAG, "Starting dream: name=" + name + + ", isTest=" + isTest + ", canDoze=" + canDoze + + ", userId=" + userId); + + mCurrentDream = new DreamRecord(token, name, isTest, canDoze, userId); + + try { + mIWindowManager.addWindowToken(token, WindowManager.LayoutParams.TYPE_DREAM); + } catch (RemoteException ex) { + Slog.e(TAG, "Unable to add window token for dream.", ex); stopDream(true /*immediate*/); return; } - } catch (SecurityException ex) { - Slog.e(TAG, "Unable to bind dream service: " + intent, ex); - stopDream(true /*immediate*/); - return; - } - mCurrentDream.mBound = true; - mHandler.postDelayed(mStopUnconnectedDreamRunnable, DREAM_CONNECTION_TIMEOUT); + Intent intent = new Intent(DreamService.SERVICE_INTERFACE); + intent.setComponent(name); + intent.addFlags(Intent.FLAG_ACTIVITY_EXCLUDE_FROM_RECENTS); + try { + if (!mContext.bindServiceAsUser(intent, mCurrentDream, + Context.BIND_AUTO_CREATE, new UserHandle(userId))) { + Slog.e(TAG, "Unable to bind dream service: " + intent); + stopDream(true /*immediate*/); + return; + } + } catch (SecurityException ex) { + Slog.e(TAG, "Unable to bind dream service: " + intent, ex); + stopDream(true /*immediate*/); + return; + } + + mCurrentDream.mBound = true; + mHandler.postDelayed(mStopUnconnectedDreamRunnable, DREAM_CONNECTION_TIMEOUT); + } finally { + Trace.traceEnd(Trace.TRACE_TAG_POWER); + } } public void stopDream(boolean immediate) { @@ -153,71 +159,76 @@ final class DreamController { return; } - if (!immediate) { - if (mCurrentDream.mWakingGently) { - return; // already waking gently - } + Trace.traceBegin(Trace.TRACE_TAG_POWER, "stopDream"); + try { + if (!immediate) { + if (mCurrentDream.mWakingGently) { + return; // already waking gently + } - if (mCurrentDream.mService != null) { - // Give the dream a moment to wake up and finish itself gently. - mCurrentDream.mWakingGently = true; - try { - mCurrentDream.mService.wakeUp(); - mHandler.postDelayed(mStopStubbornDreamRunnable, DREAM_FINISH_TIMEOUT); - return; - } catch (RemoteException ex) { - // oh well, we tried, finish immediately instead + if (mCurrentDream.mService != null) { + // Give the dream a moment to wake up and finish itself gently. + mCurrentDream.mWakingGently = true; + try { + mCurrentDream.mService.wakeUp(); + mHandler.postDelayed(mStopStubbornDreamRunnable, DREAM_FINISH_TIMEOUT); + return; + } catch (RemoteException ex) { + // oh well, we tried, finish immediately instead + } } } - } - final DreamRecord oldDream = mCurrentDream; - mCurrentDream = null; - Slog.i(TAG, "Stopping dream: name=" + oldDream.mName - + ", isTest=" + oldDream.mIsTest + ", canDoze=" + oldDream.mCanDoze - + ", userId=" + oldDream.mUserId); + final DreamRecord oldDream = mCurrentDream; + mCurrentDream = null; + Slog.i(TAG, "Stopping dream: name=" + oldDream.mName + + ", isTest=" + oldDream.mIsTest + ", canDoze=" + oldDream.mCanDoze + + ", userId=" + oldDream.mUserId); - mHandler.removeCallbacks(mStopUnconnectedDreamRunnable); - mHandler.removeCallbacks(mStopStubbornDreamRunnable); + mHandler.removeCallbacks(mStopUnconnectedDreamRunnable); + mHandler.removeCallbacks(mStopStubbornDreamRunnable); - if (oldDream.mSentStartBroadcast) { - mContext.sendBroadcastAsUser(mDreamingStoppedIntent, UserHandle.ALL); - } + if (oldDream.mSentStartBroadcast) { + mContext.sendBroadcastAsUser(mDreamingStoppedIntent, UserHandle.ALL); + } + + if (oldDream.mService != null) { + // Tell the dream that it's being stopped so that + // it can shut down nicely before we yank its window token out from + // under it. + try { + oldDream.mService.detach(); + } catch (RemoteException ex) { + // we don't care; this thing is on the way out + } + + try { + oldDream.mService.asBinder().unlinkToDeath(oldDream, 0); + } catch (NoSuchElementException ex) { + // don't care + } + oldDream.mService = null; + } + + if (oldDream.mBound) { + mContext.unbindService(oldDream); + } - if (oldDream.mService != null) { - // Tell the dream that it's being stopped so that - // it can shut down nicely before we yank its window token out from - // under it. try { - oldDream.mService.detach(); + mIWindowManager.removeWindowToken(oldDream.mToken); } catch (RemoteException ex) { - // we don't care; this thing is on the way out + Slog.w(TAG, "Error removing window token for dream.", ex); } - try { - oldDream.mService.asBinder().unlinkToDeath(oldDream, 0); - } catch (NoSuchElementException ex) { - // don't care - } - oldDream.mService = null; + mHandler.post(new Runnable() { + @Override + public void run() { + mListener.onDreamStopped(oldDream.mToken); + } + }); + } finally { + Trace.traceEnd(Trace.TRACE_TAG_POWER); } - - if (oldDream.mBound) { - mContext.unbindService(oldDream); - } - - try { - mIWindowManager.removeWindowToken(oldDream.mToken); - } catch (RemoteException ex) { - Slog.w(TAG, "Error removing window token for dream.", ex); - } - - mHandler.post(new Runnable() { - @Override - public void run() { - mListener.onDreamStopped(oldDream.mToken); - } - }); } private void attach(IDreamService service) { diff --git a/services/core/java/com/android/server/lights/LightsService.java b/services/core/java/com/android/server/lights/LightsService.java index 94cf6689e9218..9dcc5294b36fe 100644 --- a/services/core/java/com/android/server/lights/LightsService.java +++ b/services/core/java/com/android/server/lights/LightsService.java @@ -23,6 +23,7 @@ import android.content.pm.PackageManager; import android.os.Handler; import android.os.IHardwareService; import android.os.Message; +import android.os.Trace; import android.util.Slog; import java.io.FileInputStream; @@ -105,7 +106,12 @@ public class LightsService extends SystemService { mMode = mode; mOnMS = onMS; mOffMS = offMS; - setLight_native(mNativePointer, mId, color, mode, onMS, offMS, brightnessMode); + Trace.traceBegin(Trace.TRACE_TAG_POWER, "setLight(" + mId + ", " + color + ")"); + try { + setLight_native(mNativePointer, mId, color, mode, onMS, offMS, brightnessMode); + } finally { + Trace.traceEnd(Trace.TRACE_TAG_POWER); + } } } diff --git a/services/core/java/com/android/server/power/Notifier.java b/services/core/java/com/android/server/power/Notifier.java index 2b4a24a768a1c..464972428409c 100644 --- a/services/core/java/com/android/server/power/Notifier.java +++ b/services/core/java/com/android/server/power/Notifier.java @@ -406,7 +406,6 @@ final class Notifier { private void sendNextBroadcast() { final int powerState; - final int goToSleepReason; synchronized (mLock) { if (mBroadcastedPowerState == POWER_STATE_UNKNOWN) { // Broadcasted power state is unknown. Send wake up. diff --git a/services/core/java/com/android/server/power/PowerManagerService.java b/services/core/java/com/android/server/power/PowerManagerService.java index db19285b290fe..41db2c39b0c42 100644 --- a/services/core/java/com/android/server/power/PowerManagerService.java +++ b/services/core/java/com/android/server/power/PowerManagerService.java @@ -56,6 +56,7 @@ import android.os.RemoteException; import android.os.SystemClock; import android.os.SystemProperties; import android.os.SystemService; +import android.os.Trace; import android.os.UserHandle; import android.os.WorkSource; import android.provider.Settings; @@ -817,17 +818,12 @@ public final class PowerManagerService extends com.android.server.SystemService + " [" + wakeLock.mTag + "], flags=0x" + Integer.toHexString(flags)); } - mWakeLocks.remove(index); - notifyWakeLockReleasedLocked(wakeLock); - wakeLock.mLock.unlinkToDeath(wakeLock, 0); - if ((flags & PowerManager.WAIT_FOR_PROXIMITY_NEGATIVE) != 0) { mRequestWaitForNegativeProximity = true; } - applyWakeLockFlagsOnReleaseLocked(wakeLock); - mDirty |= DIRTY_WAKE_LOCKS; - updatePowerStateLocked(); + wakeLock.mLock.unlinkToDeath(wakeLock, 0); + removeWakeLockLocked(wakeLock, index); } } @@ -843,15 +839,19 @@ public final class PowerManagerService extends com.android.server.SystemService return; } - mWakeLocks.remove(index); - notifyWakeLockReleasedLocked(wakeLock); - - applyWakeLockFlagsOnReleaseLocked(wakeLock); - mDirty |= DIRTY_WAKE_LOCKS; - updatePowerStateLocked(); + removeWakeLockLocked(wakeLock, index); } } + private void removeWakeLockLocked(WakeLock wakeLock, int index) { + mWakeLocks.remove(index); + notifyWakeLockReleasedLocked(wakeLock); + + applyWakeLockFlagsOnReleaseLocked(wakeLock); + mDirty |= DIRTY_WAKE_LOCKS; + updatePowerStateLocked(); + } + private void applyWakeLockFlagsOnReleaseLocked(WakeLock wakeLock) { if ((wakeLock.mFlags & PowerManager.ON_AFTER_RELEASE) != 0 && isScreenLock(wakeLock)) { @@ -972,21 +972,26 @@ public final class PowerManagerService extends com.android.server.SystemService return false; } - mNotifier.onUserActivity(event, uid); + Trace.traceBegin(Trace.TRACE_TAG_POWER, "userActivity"); + try { + mNotifier.onUserActivity(event, uid); - if ((flags & PowerManager.USER_ACTIVITY_FLAG_NO_CHANGE_LIGHTS) != 0) { - if (eventTime > mLastUserActivityTimeNoChangeLights - && eventTime > mLastUserActivityTime) { - mLastUserActivityTimeNoChangeLights = eventTime; - mDirty |= DIRTY_USER_ACTIVITY; - return true; - } - } else { - if (eventTime > mLastUserActivityTime) { - mLastUserActivityTime = eventTime; - mDirty |= DIRTY_USER_ACTIVITY; - return true; + if ((flags & PowerManager.USER_ACTIVITY_FLAG_NO_CHANGE_LIGHTS) != 0) { + if (eventTime > mLastUserActivityTimeNoChangeLights + && eventTime > mLastUserActivityTime) { + mLastUserActivityTimeNoChangeLights = eventTime; + mDirty |= DIRTY_USER_ACTIVITY; + return true; + } + } else { + if (eventTime > mLastUserActivityTime) { + mLastUserActivityTime = eventTime; + mDirty |= DIRTY_USER_ACTIVITY; + return true; + } } + } finally { + Trace.traceEnd(Trace.TRACE_TAG_POWER); } return false; } @@ -1009,25 +1014,30 @@ public final class PowerManagerService extends com.android.server.SystemService return false; } - switch (mWakefulness) { - case WAKEFULNESS_ASLEEP: - Slog.i(TAG, "Waking up from sleep (uid " + uid +")..."); - break; - case WAKEFULNESS_DREAMING: - Slog.i(TAG, "Waking up from dream (uid " + uid +")..."); - break; - case WAKEFULNESS_DOZING: - Slog.i(TAG, "Waking up from dozing (uid " + uid +")..."); - break; + Trace.traceBegin(Trace.TRACE_TAG_POWER, "wakeUp"); + try { + switch (mWakefulness) { + case WAKEFULNESS_ASLEEP: + Slog.i(TAG, "Waking up from sleep (uid " + uid +")..."); + break; + case WAKEFULNESS_DREAMING: + Slog.i(TAG, "Waking up from dream (uid " + uid +")..."); + break; + case WAKEFULNESS_DOZING: + Slog.i(TAG, "Waking up from dozing (uid " + uid +")..."); + break; + } + + mLastWakeTime = eventTime; + mDirty |= DIRTY_WAKEFULNESS; + mWakefulness = WAKEFULNESS_AWAKE; + setInteractiveStateLocked(true, 0); + + userActivityNoUpdateLocked( + eventTime, PowerManager.USER_ACTIVITY_EVENT_OTHER, 0, uid); + } finally { + Trace.traceEnd(Trace.TRACE_TAG_POWER); } - - mLastWakeTime = eventTime; - mDirty |= DIRTY_WAKEFULNESS; - mWakefulness = WAKEFULNESS_AWAKE; - setInteractiveStateLocked(true, 0); - - userActivityNoUpdateLocked( - eventTime, PowerManager.USER_ACTIVITY_EVENT_OTHER, 0, uid); return true; } @@ -1055,53 +1065,58 @@ public final class PowerManagerService extends com.android.server.SystemService return false; } - switch (reason) { - case PowerManager.GO_TO_SLEEP_REASON_DEVICE_ADMIN: - Slog.i(TAG, "Going to sleep due to device administration policy " - + "(uid " + uid +")..."); - break; - case PowerManager.GO_TO_SLEEP_REASON_TIMEOUT: - Slog.i(TAG, "Going to sleep due to screen timeout (uid " + uid +")..."); - break; - case PowerManager.GO_TO_SLEEP_REASON_LID_SWITCH: - Slog.i(TAG, "Going to sleep due to lid switch (uid " + uid +")..."); - break; - case PowerManager.GO_TO_SLEEP_REASON_POWER_BUTTON: - Slog.i(TAG, "Going to sleep due to power button (uid " + uid +")..."); - break; - case PowerManager.GO_TO_SLEEP_REASON_HDMI: - Slog.i(TAG, "Going to sleep due to HDMI standby (uid " + uid +")..."); - break; - default: - Slog.i(TAG, "Going to sleep by application request (uid " + uid +")..."); - reason = PowerManager.GO_TO_SLEEP_REASON_APPLICATION; - break; - } - - mLastSleepTime = eventTime; - mDirty |= DIRTY_WAKEFULNESS; - mWakefulness = WAKEFULNESS_DOZING; - mSandmanSummoned = true; - setInteractiveStateLocked(false, reason); - - // Report the number of wake locks that will be cleared by going to sleep. - int numWakeLocksCleared = 0; - final int numWakeLocks = mWakeLocks.size(); - for (int i = 0; i < numWakeLocks; i++) { - final WakeLock wakeLock = mWakeLocks.get(i); - switch (wakeLock.mFlags & PowerManager.WAKE_LOCK_LEVEL_MASK) { - case PowerManager.FULL_WAKE_LOCK: - case PowerManager.SCREEN_BRIGHT_WAKE_LOCK: - case PowerManager.SCREEN_DIM_WAKE_LOCK: - numWakeLocksCleared += 1; + Trace.traceBegin(Trace.TRACE_TAG_POWER, "goToSleep"); + try { + switch (reason) { + case PowerManager.GO_TO_SLEEP_REASON_DEVICE_ADMIN: + Slog.i(TAG, "Going to sleep due to device administration policy " + + "(uid " + uid +")..."); + break; + case PowerManager.GO_TO_SLEEP_REASON_TIMEOUT: + Slog.i(TAG, "Going to sleep due to screen timeout (uid " + uid +")..."); + break; + case PowerManager.GO_TO_SLEEP_REASON_LID_SWITCH: + Slog.i(TAG, "Going to sleep due to lid switch (uid " + uid +")..."); + break; + case PowerManager.GO_TO_SLEEP_REASON_POWER_BUTTON: + Slog.i(TAG, "Going to sleep due to power button (uid " + uid +")..."); + break; + case PowerManager.GO_TO_SLEEP_REASON_HDMI: + Slog.i(TAG, "Going to sleep due to HDMI standby (uid " + uid +")..."); + break; + default: + Slog.i(TAG, "Going to sleep by application request (uid " + uid +")..."); + reason = PowerManager.GO_TO_SLEEP_REASON_APPLICATION; break; } - } - EventLog.writeEvent(EventLogTags.POWER_SLEEP_REQUESTED, numWakeLocksCleared); - // Skip dozing if requested. - if ((flags & PowerManager.GO_TO_SLEEP_FLAG_NO_DOZE) != 0) { - reallyGoToSleepNoUpdateLocked(eventTime, uid); + mLastSleepTime = eventTime; + mDirty |= DIRTY_WAKEFULNESS; + mWakefulness = WAKEFULNESS_DOZING; + mSandmanSummoned = true; + setInteractiveStateLocked(false, reason); + + // Report the number of wake locks that will be cleared by going to sleep. + int numWakeLocksCleared = 0; + final int numWakeLocks = mWakeLocks.size(); + for (int i = 0; i < numWakeLocks; i++) { + final WakeLock wakeLock = mWakeLocks.get(i); + switch (wakeLock.mFlags & PowerManager.WAKE_LOCK_LEVEL_MASK) { + case PowerManager.FULL_WAKE_LOCK: + case PowerManager.SCREEN_BRIGHT_WAKE_LOCK: + case PowerManager.SCREEN_DIM_WAKE_LOCK: + numWakeLocksCleared += 1; + break; + } + } + EventLog.writeEvent(EventLogTags.POWER_SLEEP_REQUESTED, numWakeLocksCleared); + + // Skip dozing if requested. + if ((flags & PowerManager.GO_TO_SLEEP_FLAG_NO_DOZE) != 0) { + reallyGoToSleepNoUpdateLocked(eventTime, uid); + } + } finally { + Trace.traceEnd(Trace.TRACE_TAG_POWER); } return true; } @@ -1124,12 +1139,17 @@ public final class PowerManagerService extends com.android.server.SystemService return false; } - Slog.i(TAG, "Nap time (uid " + uid +")..."); + Trace.traceBegin(Trace.TRACE_TAG_POWER, "nap"); + try { + Slog.i(TAG, "Nap time (uid " + uid +")..."); - mDirty |= DIRTY_WAKEFULNESS; - mWakefulness = WAKEFULNESS_DREAMING; - mSandmanSummoned = true; - setInteractiveStateLocked(true, 0); + mDirty |= DIRTY_WAKEFULNESS; + mWakefulness = WAKEFULNESS_DREAMING; + mSandmanSummoned = true; + setInteractiveStateLocked(true, 0); + } finally { + Trace.traceEnd(Trace.TRACE_TAG_POWER); + } return true; } @@ -1145,11 +1165,16 @@ public final class PowerManagerService extends com.android.server.SystemService return false; } - Slog.i(TAG, "Sleeping (uid " + uid +")..."); + Trace.traceBegin(Trace.TRACE_TAG_POWER, "reallyGoToSleep"); + try { + Slog.i(TAG, "Sleeping (uid " + uid +")..."); - mDirty |= DIRTY_WAKEFULNESS; - mWakefulness = WAKEFULNESS_ASLEEP; - setInteractiveStateLocked(false, PowerManager.GO_TO_SLEEP_REASON_TIMEOUT); + mDirty |= DIRTY_WAKEFULNESS; + mWakefulness = WAKEFULNESS_ASLEEP; + setInteractiveStateLocked(false, PowerManager.GO_TO_SLEEP_REASON_TIMEOUT); + } finally { + Trace.traceEnd(Trace.TRACE_TAG_POWER); + } return true; } @@ -1186,40 +1211,45 @@ public final class PowerManagerService extends com.android.server.SystemService Slog.wtf(TAG, "Power manager lock was not held when calling updatePowerStateLocked"); } - // Phase 0: Basic state updates. - updateIsPoweredLocked(mDirty); - updateStayOnLocked(mDirty); + Trace.traceBegin(Trace.TRACE_TAG_POWER, "updatePowerState"); + try { + // Phase 0: Basic state updates. + updateIsPoweredLocked(mDirty); + updateStayOnLocked(mDirty); - // Phase 1: Update wakefulness. - // Loop because the wake lock and user activity computations are influenced - // by changes in wakefulness. - final long now = SystemClock.uptimeMillis(); - int dirtyPhase2 = 0; - for (;;) { - int dirtyPhase1 = mDirty; - dirtyPhase2 |= dirtyPhase1; - mDirty = 0; + // Phase 1: Update wakefulness. + // Loop because the wake lock and user activity computations are influenced + // by changes in wakefulness. + final long now = SystemClock.uptimeMillis(); + int dirtyPhase2 = 0; + for (;;) { + int dirtyPhase1 = mDirty; + dirtyPhase2 |= dirtyPhase1; + mDirty = 0; - updateWakeLockSummaryLocked(dirtyPhase1); - updateUserActivitySummaryLocked(now, dirtyPhase1); - if (!updateWakefulnessLocked(dirtyPhase1)) { - break; + updateWakeLockSummaryLocked(dirtyPhase1); + updateUserActivitySummaryLocked(now, dirtyPhase1); + if (!updateWakefulnessLocked(dirtyPhase1)) { + break; + } } + + // Phase 2: Update dreams and display power state. + updateDreamLocked(dirtyPhase2); + updateDisplayPowerStateLocked(dirtyPhase2); + + // Phase 3: Send notifications, if needed. + if (mDisplayReady) { + finishInteractiveStateChangeLocked(); + } + + // Phase 4: Update suspend blocker. + // Because we might release the last suspend blocker here, we need to make sure + // we finished everything else first! + updateSuspendBlockerLocked(); + } finally { + Trace.traceEnd(Trace.TRACE_TAG_POWER); } - - // Phase 2: Update dreams and display power state. - updateDreamLocked(dirtyPhase2); - updateDisplayPowerStateLocked(dirtyPhase2); - - // Phase 3: Send notifications, if needed. - if (mDisplayReady) { - finishInteractiveStateChangeLocked(); - } - - // Phase 4: Update suspend blocker. - // Because we might release the last suspend blocker here, we need to make sure - // we finished everything else first! - updateSuspendBlockerLocked(); } /** @@ -1990,7 +2020,12 @@ public final class PowerManagerService extends com.android.server.SystemService Slog.d(TAG, "Setting HAL auto-suspend mode to " + enable); } mHalAutoSuspendModeEnabled = enable; - nativeSetAutoSuspend(enable); + Trace.traceBegin(Trace.TRACE_TAG_POWER, "setHalAutoSuspend(" + enable + ")"); + try { + nativeSetAutoSuspend(enable); + } finally { + Trace.traceEnd(Trace.TRACE_TAG_POWER); + } } } @@ -2000,7 +2035,12 @@ public final class PowerManagerService extends com.android.server.SystemService Slog.d(TAG, "Setting HAL interactive mode to " + enable); } mHalInteractiveModeEnabled = enable; - nativeSetInteractive(enable); + Trace.traceBegin(Trace.TRACE_TAG_POWER, "setHalInteractive(" + enable + ")"); + try { + nativeSetInteractive(enable); + } finally { + Trace.traceEnd(Trace.TRACE_TAG_POWER); + } } } @@ -2587,20 +2627,23 @@ public final class PowerManagerService extends com.android.server.SystemService private final class SuspendBlockerImpl implements SuspendBlocker { private final String mName; + private final String mTraceName; private int mReferenceCount; public SuspendBlockerImpl(String name) { mName = name; + mTraceName = "SuspendBlocker (" + name + ")"; } @Override protected void finalize() throws Throwable { try { if (mReferenceCount != 0) { - Log.wtf(TAG, "Suspend blocker \"" + mName + Slog.wtf(TAG, "Suspend blocker \"" + mName + "\" was finalized without being released!"); mReferenceCount = 0; nativeReleaseSuspendBlocker(mName); + Trace.asyncTraceEnd(Trace.TRACE_TAG_POWER, mTraceName, 0); } } finally { super.finalize(); @@ -2615,6 +2658,7 @@ public final class PowerManagerService extends com.android.server.SystemService if (DEBUG_SPEW) { Slog.d(TAG, "Acquiring suspend blocker \"" + mName + "\"."); } + Trace.asyncTraceBegin(Trace.TRACE_TAG_POWER, mTraceName, 0); nativeAcquireSuspendBlocker(mName); } } @@ -2629,8 +2673,9 @@ public final class PowerManagerService extends com.android.server.SystemService Slog.d(TAG, "Releasing suspend blocker \"" + mName + "\"."); } nativeReleaseSuspendBlocker(mName); + Trace.asyncTraceEnd(Trace.TRACE_TAG_POWER, mTraceName, 0); } else if (mReferenceCount < 0) { - Log.wtf(TAG, "Suspend blocker \"" + mName + Slog.wtf(TAG, "Suspend blocker \"" + mName + "\" was released without being acquired!", new Throwable()); mReferenceCount = 0; } @@ -2646,6 +2691,8 @@ public final class PowerManagerService extends com.android.server.SystemService } private final class ScreenOnBlockerImpl implements ScreenOnBlocker { + private static final String TRACE_NAME = "ScreenOnBlocker"; + private int mNestCount; public boolean isHeld() { @@ -2658,9 +2705,12 @@ public final class PowerManagerService extends com.android.server.SystemService public void acquire() { synchronized (this) { mNestCount += 1; - if (DEBUG) { + if (DEBUG || true) { Slog.d(TAG, "Screen on blocked: mNestCount=" + mNestCount); } + if (mNestCount == 1) { + Trace.asyncTraceBegin(Trace.TRACE_TAG_POWER, TRACE_NAME, 0); + } } } @@ -2668,17 +2718,17 @@ public final class PowerManagerService extends com.android.server.SystemService public void release() { synchronized (this) { mNestCount -= 1; - if (mNestCount < 0) { - Log.wtf(TAG, "Screen on blocker was released without being acquired!", + if (mNestCount == 0) { + if (DEBUG || true) { + Slog.d(TAG, "Screen on unblocked: mNestCount=" + mNestCount); + } + mHandler.sendEmptyMessage(MSG_SCREEN_ON_BLOCKER_RELEASED); + Trace.asyncTraceEnd(Trace.TRACE_TAG_POWER, TRACE_NAME, 0); + } else if (mNestCount < 0) { + Slog.wtf(TAG, "Screen on blocker was released without being acquired!", new Throwable()); mNestCount = 0; } - if (mNestCount == 0) { - mHandler.sendEmptyMessage(MSG_SCREEN_ON_BLOCKER_RELEASED); - } - if (DEBUG) { - Slog.d(TAG, "Screen on unblocked: mNestCount=" + mNestCount); - } } }