From d0db6f00435b83c88f041ccf0cfcb9986ae8e6ef Mon Sep 17 00:00:00 2001
From: Dianne Hackborn <hackbod@google.com>
Date: Mon, 18 Jul 2016 14:14:20 -0700
Subject: [PATCH] Add reporting of long wake locks.

These appear as a new event in the battery stats history,
"longwake" in the long version and "Elw" in the checkin.

The power manager keeps track of which wake locks are held
for a long time and reports them to battery stats.  Long
is currently considered 1 minute or more.  Once it is long,
the start event will appear, and once if is released the
event will end.

In the case of a wake lock changing (typically its work
source changing), for purposes of this accounting this is
considering a pure release of the old state and start of
the new state...  so the timer will reset back to one
minute until the wake lock is considered long.  This is done
to prevent things that make lots of changes to wake lock
work sources from spamming the log.

Bug: 28753137

Change-Id: I33b6168c57a7ea6ea558273dec731704123124a5
---
 core/java/android/os/BatteryStats.java        |  12 +-
 .../android/internal/app/IBatteryStats.aidl   |   2 +
 .../android/internal/os/BatteryStatsImpl.java |  30 ++++
 .../server/am/BatteryStatsService.java        |  14 ++
 .../com/android/server/power/Notifier.java    |  42 +++++
 .../server/power/PowerManagerService.java     | 154 +++++++++++++++++-
 6 files changed, 246 insertions(+), 8 deletions(-)

diff --git a/core/java/android/os/BatteryStats.java b/core/java/android/os/BatteryStats.java
index 1b9e2aa3896af..af9c99f20ae3f 100644
--- a/core/java/android/os/BatteryStats.java
+++ b/core/java/android/os/BatteryStats.java
@@ -1302,9 +1302,11 @@ public abstract class BatteryStats implements Parcelable {
         // Event for the UID that woke up the application processor.
         // Used for wakeups coming from WiFi, modem, etc.
         public static final int EVENT_WAKEUP_AP = 0x0013;
+        // Event for reporting that a specific partial wake lock has been held for a long duration.
+        public static final int EVENT_LONG_WAKE_LOCK = 0x0014;
 
         // Number of event types.
-        public static final int EVENT_COUNT = 0x0014;
+        public static final int EVENT_COUNT = 0x0015;
         // Mask to extract out only the type part of the event.
         public static final int EVENT_TYPE_MASK = ~(EVENT_FLAG_START|EVENT_FLAG_FINISH);
 
@@ -1332,6 +1334,10 @@ public abstract class BatteryStats implements Parcelable {
                 EVENT_TEMP_WHITELIST | EVENT_FLAG_START;
         public static final int EVENT_TEMP_WHITELIST_FINISH =
                 EVENT_TEMP_WHITELIST | EVENT_FLAG_FINISH;
+        public static final int EVENT_LONG_WAKE_LOCK_START =
+                EVENT_LONG_WAKE_LOCK | EVENT_FLAG_START;
+        public static final int EVENT_LONG_WAKE_LOCK_FINISH =
+                EVENT_LONG_WAKE_LOCK | EVENT_FLAG_FINISH;
 
         // For CMD_EVENT.
         public int eventCode;
@@ -1996,13 +2002,13 @@ public abstract class BatteryStats implements Parcelable {
     public static final String[] HISTORY_EVENT_NAMES = new String[] {
             "null", "proc", "fg", "top", "sync", "wake_lock_in", "job", "user", "userfg", "conn",
             "active", "pkginst", "pkgunin", "alarm", "stats", "inactive", "active", "tmpwhitelist",
-            "screenwake", "wakeupap"
+            "screenwake", "wakeupap", "longwake"
     };
 
     public static final String[] HISTORY_EVENT_CHECKIN_NAMES = new String[] {
             "Enl", "Epr", "Efg", "Etp", "Esy", "Ewl", "Ejb", "Eur", "Euf", "Ecn",
             "Eac", "Epi", "Epu", "Eal", "Est", "Eai", "Eaa", "Etw",
-            "Esw", "Ewa"
+            "Esw", "Ewa", "Elw"
     };
 
     /**
diff --git a/core/java/com/android/internal/app/IBatteryStats.aidl b/core/java/com/android/internal/app/IBatteryStats.aidl
index ca69746784dd8..5623a2cb430c1 100644
--- a/core/java/com/android/internal/app/IBatteryStats.aidl
+++ b/core/java/com/android/internal/app/IBatteryStats.aidl
@@ -79,6 +79,8 @@ interface IBatteryStats {
             String newHistoryName, int newType, boolean newUnimportantForLogging);
     void noteStopWakelockFromSource(in WorkSource ws, int pid, String name, String historyName,
             int type);
+    void noteLongPartialWakelockStart(String name, String historyName, int uid);
+    void noteLongPartialWakelockFinish(String name, String historyName, int uid);
 
     void noteVibratorOn(int uid, long durationMillis);
     void noteVibratorOff(int uid);
diff --git a/core/java/com/android/internal/os/BatteryStatsImpl.java b/core/java/com/android/internal/os/BatteryStatsImpl.java
index 11c1de19bb961..b174e33251682 100644
--- a/core/java/com/android/internal/os/BatteryStatsImpl.java
+++ b/core/java/com/android/internal/os/BatteryStatsImpl.java
@@ -3285,6 +3285,36 @@ public class BatteryStatsImpl extends BatteryStats {
         }
     }
 
+    public void noteLongPartialWakelockStart(String name, String historyName, int uid) {
+        uid = mapUid(uid);
+        final long elapsedRealtime = mClocks.elapsedRealtime();
+        final long uptime = mClocks.uptimeMillis();
+        if (historyName == null) {
+            historyName = name;
+        }
+        if (!mActiveEvents.updateState(HistoryItem.EVENT_LONG_WAKE_LOCK_START, historyName, uid,
+                0)) {
+            return;
+        }
+        addHistoryEventLocked(elapsedRealtime, uptime, HistoryItem.EVENT_LONG_WAKE_LOCK_START,
+                historyName, uid);
+    }
+
+    public void noteLongPartialWakelockFinish(String name, String historyName, int uid) {
+        uid = mapUid(uid);
+        final long elapsedRealtime = mClocks.elapsedRealtime();
+        final long uptime = mClocks.uptimeMillis();
+        if (historyName == null) {
+            historyName = name;
+        }
+        if (!mActiveEvents.updateState(HistoryItem.EVENT_LONG_WAKE_LOCK_FINISH, historyName, uid,
+                0)) {
+            return;
+        }
+        addHistoryEventLocked(elapsedRealtime, uptime, HistoryItem.EVENT_LONG_WAKE_LOCK_FINISH,
+                historyName, uid);
+    }
+
     void aggregateLastWakeupUptimeLocked(long uptimeMs) {
         if (mLastWakeupReason != null) {
             long deltaUptime = uptimeMs - mLastWakeupUptimeMs;
diff --git a/services/core/java/com/android/server/am/BatteryStatsService.java b/services/core/java/com/android/server/am/BatteryStatsService.java
index 7fe29b086556e..ff13125a84173 100644
--- a/services/core/java/com/android/server/am/BatteryStatsService.java
+++ b/services/core/java/com/android/server/am/BatteryStatsService.java
@@ -484,6 +484,20 @@ public final class BatteryStatsService extends IBatteryStats.Stub
         }
     }
 
+    public void noteLongPartialWakelockStart(String name, String historyName, int uid) {
+        enforceCallingPermission();
+        synchronized (mStats) {
+            mStats.noteLongPartialWakelockStart(name, historyName, uid);
+        }
+    }
+
+    public void noteLongPartialWakelockFinish(String name, String historyName, int uid) {
+        enforceCallingPermission();
+        synchronized (mStats) {
+            mStats.noteLongPartialWakelockFinish(name, historyName, uid);
+        }
+    }
+
     public void noteStartSensor(int uid, int sensor) {
         enforceCallingPermission();
         synchronized (mStats) {
diff --git a/services/core/java/com/android/server/power/Notifier.java b/services/core/java/com/android/server/power/Notifier.java
index 9ccfd67980f53..4e9f5a2b2b52a 100644
--- a/services/core/java/com/android/server/power/Notifier.java
+++ b/services/core/java/com/android/server/power/Notifier.java
@@ -194,6 +194,48 @@ final class Notifier {
         }
     }
 
+    public void onLongPartialWakeLockStart(String tag, int ownerUid, WorkSource workSource,
+            String historyTag) {
+        if (DEBUG) {
+            Slog.d(TAG, "onLongPartialWakeLockStart: ownerUid=" + ownerUid
+                    + ", workSource=" + workSource);
+        }
+
+        try {
+            if (workSource != null) {
+                final int N = workSource.size();
+                for (int i=0; i<N; i++) {
+                    mBatteryStats.noteLongPartialWakelockStart(tag, historyTag, workSource.get(i));
+                }
+            } else {
+                mBatteryStats.noteLongPartialWakelockStart(tag, historyTag, ownerUid);
+            }
+        } catch (RemoteException ex) {
+            // Ignore
+        }
+    }
+
+    public void onLongPartialWakeLockFinish(String tag, int ownerUid, WorkSource workSource,
+            String historyTag) {
+        if (DEBUG) {
+            Slog.d(TAG, "onLongPartialWakeLockFinish: ownerUid=" + ownerUid
+                    + ", workSource=" + workSource);
+        }
+
+        try {
+            if (workSource != null) {
+                final int N = workSource.size();
+                for (int i=0; i<N; i++) {
+                    mBatteryStats.noteLongPartialWakelockFinish(tag, historyTag, workSource.get(i));
+                }
+            } else {
+                mBatteryStats.noteLongPartialWakelockFinish(tag, historyTag, ownerUid);
+            }
+        } catch (RemoteException ex) {
+            // Ignore
+        }
+    }
+
     /**
      * Called when a wake lock is changing.
      */
diff --git a/services/core/java/com/android/server/power/PowerManagerService.java b/services/core/java/com/android/server/power/PowerManagerService.java
index 12a2d2ef924ad..2215cbb904809 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.service.dreams.DreamManagerInternal;
 import android.service.vr.IVrManager;
 import android.service.vr.IVrStateCallbacks;
 import android.util.EventLog;
+import android.util.PrintWriterPrinter;
 import android.util.Slog;
 import android.util.SparseIntArray;
 import android.util.TimeUtils;
@@ -73,9 +74,7 @@ import com.android.server.Watchdog;
 import com.android.server.am.BatteryStatsService;
 import com.android.server.lights.Light;
 import com.android.server.lights.LightsManager;
-import com.android.server.vr.VrManagerInternal;
 import com.android.server.vr.VrManagerService;
-import com.android.server.vr.VrStateListener;
 import libcore.util.Objects;
 
 import java.io.FileDescriptor;
@@ -108,6 +107,8 @@ public final class PowerManagerService extends SystemService
     private static final int MSG_SANDMAN = 2;
     // Message: Sent when the screen brightness boost expires.
     private static final int MSG_SCREEN_BRIGHTNESS_BOOST_TIMEOUT = 3;
+    // Message: Polling to look for long held wake locks.
+    private static final int MSG_CHECK_FOR_LONG_WAKELOCKS = 4;
 
     // Dirty bit: mWakeLocks changed
     private static final int DIRTY_WAKE_LOCKS = 1 << 0;
@@ -159,6 +160,9 @@ public final class PowerManagerService extends SystemService
     // This should perhaps be a setting.
     private static final int SCREEN_BRIGHTNESS_BOOST_TIMEOUT = 5 * 1000;
 
+    // How long a partial wake lock must be held until we consider it a long wake lock.
+    static final long MIN_LONG_WAKE_CHECK_INTERVAL = 60*1000;
+
     // Power hints defined in hardware/libhardware/include/hardware/power.h.
     private static final int POWER_HINT_LOW_POWER = 5;
     private static final int POWER_HINT_VR_MODE = 7;
@@ -221,6 +225,15 @@ public final class PowerManagerService extends SystemService
     // A bitfield that summarizes the state of all active wakelocks.
     private int mWakeLockSummary;
 
+    // Have we scheduled a message to check for long wake locks?  This is when we will check.
+    private long mNotifyLongScheduled;
+
+    // Last time we checked for long wake locks.
+    private long mNotifyLongDispatched;
+
+    // The time we decided to do next long check.
+    private long mNotifyLongNextCheck;
+
     // If true, instructs the display controller to wait for the proximity sensor to
     // go negative before turning the screen on.
     private boolean mRequestWaitForNegativeProximity;
@@ -1025,6 +1038,38 @@ public final class PowerManagerService extends SystemService
             mNotifier.onWakeLockAcquired(wakeLock.mFlags, wakeLock.mTag, wakeLock.mPackageName,
                     wakeLock.mOwnerUid, wakeLock.mOwnerPid, wakeLock.mWorkSource,
                     wakeLock.mHistoryTag);
+            restartNofifyLongTimerLocked(wakeLock);
+        }
+    }
+
+    private void enqueueNotifyLongMsgLocked(long time) {
+        mNotifyLongScheduled = time;
+        Message msg = mHandler.obtainMessage(MSG_CHECK_FOR_LONG_WAKELOCKS);
+        msg.setAsynchronous(true);
+        mHandler.sendMessageAtTime(msg, time);
+    }
+
+    private void restartNofifyLongTimerLocked(WakeLock wakeLock) {
+        wakeLock.mAcquireTime = SystemClock.uptimeMillis();
+        if ((wakeLock.mFlags & PowerManager.WAKE_LOCK_LEVEL_MASK)
+                == PowerManager.PARTIAL_WAKE_LOCK && mNotifyLongScheduled == 0) {
+            enqueueNotifyLongMsgLocked(wakeLock.mAcquireTime + MIN_LONG_WAKE_CHECK_INTERVAL);
+        }
+    }
+
+    private void notifyWakeLockLongStartedLocked(WakeLock wakeLock) {
+        if (mSystemReady && !wakeLock.mDisabled) {
+            wakeLock.mNotifiedLong = true;
+            mNotifier.onLongPartialWakeLockStart(wakeLock.mTag, wakeLock.mOwnerUid,
+                    wakeLock.mWorkSource, wakeLock.mHistoryTag);
+        }
+    }
+
+    private void notifyWakeLockLongFinishedLocked(WakeLock wakeLock) {
+        if (wakeLock.mNotifiedLong) {
+            wakeLock.mNotifiedLong = false;
+            mNotifier.onLongPartialWakeLockFinish(wakeLock.mTag, wakeLock.mOwnerUid,
+                    wakeLock.mWorkSource, wakeLock.mHistoryTag);
         }
     }
 
@@ -1034,15 +1079,23 @@ public final class PowerManagerService extends SystemService
             mNotifier.onWakeLockChanging(wakeLock.mFlags, wakeLock.mTag, wakeLock.mPackageName,
                     wakeLock.mOwnerUid, wakeLock.mOwnerPid, wakeLock.mWorkSource,
                     wakeLock.mHistoryTag, flags, tag, packageName, uid, pid, ws, historyTag);
+            notifyWakeLockLongFinishedLocked(wakeLock);
+            // Changing the wake lock will count as releasing the old wake lock(s) and
+            // acquiring the new ones...  we do this because otherwise once a wakelock
+            // becomes long, if we just continued to treat it as long we can get in to
+            // situations where we spam battery stats with every following change to it.
+            restartNofifyLongTimerLocked(wakeLock);
         }
     }
 
     private void notifyWakeLockReleasedLocked(WakeLock wakeLock) {
         if (mSystemReady && wakeLock.mNotifiedAcquired) {
             wakeLock.mNotifiedAcquired = false;
+            wakeLock.mAcquireTime = 0;
             mNotifier.onWakeLockReleased(wakeLock.mFlags, wakeLock.mTag,
                     wakeLock.mPackageName, wakeLock.mOwnerUid, wakeLock.mOwnerPid,
                     wakeLock.mWorkSource, wakeLock.mHistoryTag);
+            notifyWakeLockLongFinishedLocked(wakeLock);
         }
     }
 
@@ -1599,6 +1652,42 @@ public final class PowerManagerService extends SystemService
         }
     }
 
+    void checkForLongWakeLocks() {
+        synchronized (mLock) {
+            final long now = SystemClock.uptimeMillis();
+            mNotifyLongDispatched = now;
+            final long when = now - MIN_LONG_WAKE_CHECK_INTERVAL;
+            long nextCheckTime = Long.MAX_VALUE;
+            final int numWakeLocks = mWakeLocks.size();
+            for (int i = 0; i < numWakeLocks; i++) {
+                final WakeLock wakeLock = mWakeLocks.get(i);
+                if ((wakeLock.mFlags & PowerManager.WAKE_LOCK_LEVEL_MASK)
+                        == PowerManager.PARTIAL_WAKE_LOCK) {
+                    if (wakeLock.mNotifiedAcquired && !wakeLock.mNotifiedLong) {
+                        if (wakeLock.mAcquireTime < when) {
+                            // This wake lock has exceeded the long acquire time, report!
+                            notifyWakeLockLongStartedLocked(wakeLock);
+                        } else {
+                            // This wake lock could still become a long one, at this time.
+                            long checkTime = wakeLock.mAcquireTime + MIN_LONG_WAKE_CHECK_INTERVAL;
+                            if (checkTime < nextCheckTime) {
+                                nextCheckTime = checkTime;
+                            }
+                        }
+                    }
+                }
+            }
+            mNotifyLongScheduled = 0;
+            mHandler.removeMessages(MSG_CHECK_FOR_LONG_WAKELOCKS);
+            if (nextCheckTime != Long.MAX_VALUE) {
+                mNotifyLongNextCheck = nextCheckTime;
+                enqueueNotifyLongMsgLocked(nextCheckTime);
+            } else {
+                mNotifyLongNextCheck = 0;
+            }
+        }
+    }
+
     /**
      * Updates the value of mUserActivitySummary to summarize the user requested
      * state of the system such as whether the screen should be bright or dim.
@@ -2748,6 +2837,27 @@ public final class PowerManagerService extends SystemService
             pw.println("  mHalAutoSuspendModeEnabled=" + mHalAutoSuspendModeEnabled);
             pw.println("  mHalInteractiveModeEnabled=" + mHalInteractiveModeEnabled);
             pw.println("  mWakeLockSummary=0x" + Integer.toHexString(mWakeLockSummary));
+            pw.print("  mNotifyLongScheduled=");
+            if (mNotifyLongScheduled == 0) {
+                pw.print("(none)");
+            } else {
+                TimeUtils.formatDuration(mNotifyLongScheduled, SystemClock.uptimeMillis(), pw);
+            }
+            pw.println();
+            pw.print("  mNotifyLongDispatched=");
+            if (mNotifyLongDispatched == 0) {
+                pw.print("(none)");
+            } else {
+                TimeUtils.formatDuration(mNotifyLongDispatched, SystemClock.uptimeMillis(), pw);
+            }
+            pw.println();
+            pw.print("  mNotifyLongNextCheck=");
+            if (mNotifyLongNextCheck == 0) {
+                pw.print("(none)");
+            } else {
+                TimeUtils.formatDuration(mNotifyLongNextCheck, SystemClock.uptimeMillis(), pw);
+            }
+            pw.println();
             pw.println("  mUserActivitySummary=0x" + Integer.toHexString(mUserActivitySummary));
             pw.println("  mRequestWaitForNegativeProximity=" + mRequestWaitForNegativeProximity);
             pw.println("  mSandmanScheduled=" + mSandmanScheduled);
@@ -2855,6 +2965,10 @@ public final class PowerManagerService extends SystemService
                 pw.print(": "); pw.println(mUidState.valueAt(i));
             }
 
+            pw.println();
+            pw.println("Looper state:");
+            mHandler.getLooper().dump(new PrintWriterPrinter(pw), "  ");
+
             pw.println();
             pw.println("Wake Locks: size=" + mWakeLocks.size());
             for (WakeLock wl : mWakeLocks) {
@@ -2984,6 +3098,9 @@ public final class PowerManagerService extends SystemService
                 case MSG_SCREEN_BRIGHTNESS_BOOST_TIMEOUT:
                     handleScreenBrightnessBoostTimeout();
                     break;
+                case MSG_CHECK_FOR_LONG_WAKELOCKS:
+                    checkForLongWakeLocks();
+                    break;
             }
         }
     }
@@ -3000,7 +3117,9 @@ public final class PowerManagerService extends SystemService
         public String mHistoryTag;
         public final int mOwnerUid;
         public final int mOwnerPid;
+        public long mAcquireTime;
         public boolean mNotifiedAcquired;
+        public boolean mNotifiedLong;
         public boolean mDisabled;
 
         public WakeLock(IBinder lock, int flags, String tag, String packageName,
@@ -3059,9 +3178,34 @@ public final class PowerManagerService extends SystemService
 
         @Override
         public String toString() {
-            return getLockLevelString()
-                    + " '" + mTag + "'" + getLockFlagsString() + (mDisabled ? " DISABLED" : "")
-                    + " (uid=" + mOwnerUid + ", pid=" + mOwnerPid + ", ws=" + mWorkSource + ")";
+            StringBuilder sb = new StringBuilder();
+            sb.append(getLockLevelString());
+            sb.append(" '");
+            sb.append(mTag);
+            sb.append("'");
+            sb.append(getLockFlagsString());
+            if (mDisabled) {
+                sb.append(" DISABLED");
+            }
+            if (mNotifiedAcquired) {
+                sb.append(" ACQ=");
+                TimeUtils.formatDuration(mAcquireTime-SystemClock.uptimeMillis(), sb);
+            }
+            if (mNotifiedLong) {
+                sb.append(" LONG");
+            }
+            sb.append(" (uid=");
+            sb.append(mOwnerUid);
+            if (mOwnerPid != 0) {
+                sb.append(" pid=");
+                sb.append(mOwnerPid);
+            }
+            if (mWorkSource != null) {
+                sb.append(" ws=");
+                sb.append(mWorkSource);
+            }
+            sb.append(")");
+            return sb.toString();
         }
 
         @SuppressWarnings("deprecation")