commit 657153bd28b36e0eaa223b489f1a80fc85e29be8
author Dianne Hackborn <hackbod@google.com> Fri Jul 29 14:54:14 2016 -0700
committer Dianne Hackborn <hackbod@google.com> Fri Jul 29 14:54:14 2016 -0700
tree fc80dc43aa759b46e9ebf2c3c5180c4b9881f4e0
parent 0da397ea71e67c22f75c41fa1c7a9a2fc9777ac3

Work on issue #30407061: OverflowArrayMap.stopObject unable to find object

Add more debug info when this happens to try to better
understand what is going on.

Change-Id: Id8c979d1c2d3769ce68156fb7e69d5ff9d5ded1c

core/java/com/android/internal/os/BatteryStatsImpl.java

diff --git a/core/java/com/android/internal/os/BatteryStatsImpl.java b/core/java/com/android/internal/os/BatteryStatsImpl.java
index b174e33..17635ae 100644
--- a/core/java/com/android/internal/os/BatteryStatsImpl.java
+++ b/core/java/com/android/internal/os/BatteryStatsImpl.java
@@ -1791,11 +1791,17 @@
     public abstract class OverflowArrayMap<T> {
         private static final String OVERFLOW_NAME = "*overflow*";
 
+        final int mUid;
         final ArrayMap<String, T> mMap = new ArrayMap<>();
         T mCurOverflow;
         ArrayMap<String, MutableInt> mActiveOverflow;
+        long mLastOverflowTime;
+        long mLastOverflowFinishTime;
+        long mLastClearTime;
+        long mLastCleanupTime;
 
-        public OverflowArrayMap() {
+        public OverflowArrayMap(int uid) {
+            mUid = uid;
         }
 
         public ArrayMap<String, T> getMap() {
@@ -1803,6 +1809,7 @@
         }
 
         public void clear() {
+            mLastClearTime = SystemClock.elapsedRealtime();
             mMap.clear();
             mCurOverflow = null;
             mActiveOverflow = null;
@@ -1819,6 +1826,7 @@
         }
 
         public void cleanup() {
+            mLastCleanupTime = SystemClock.elapsedRealtime();
             if (mActiveOverflow != null) {
                 if (mActiveOverflow.size() == 0) {
                     mActiveOverflow = null;
@@ -1885,6 +1893,7 @@
                     mActiveOverflow = new ArrayMap<>();
                 }
                 mActiveOverflow.put(name, new MutableInt(1));
+                mLastOverflowTime = SystemClock.elapsedRealtime();
                 return obj;
             }
 
@@ -1914,6 +1923,7 @@
                         over.value--;
                         if (over.value <= 0) {
                             mActiveOverflow.remove(name);
+                            mLastOverflowFinishTime = SystemClock.elapsedRealtime();
                         }
                         return obj;
                     }
@@ -1922,9 +1932,35 @@
 
             // Huh, they are stopping an active operation but we can't find one!
             // That's not good.
-            Slog.wtf(TAG, "Unable to find object for " + name + " mapsize="
-                    + mMap.size() + " activeoverflow=" + mActiveOverflow
-                    + " curoverflow=" + mCurOverflow);
+            StringBuilder sb = new StringBuilder();
+            sb.append("Unable to find object for ");
+            sb.append(name);
+            sb.append(" in uid ");
+            sb.append(mUid);
+            sb.append(" mapsize=");
+            sb.append(mMap.size());
+            sb.append(" activeoverflow=");
+            sb.append(mActiveOverflow);
+            sb.append(" curoverflow=");
+            sb.append(mCurOverflow);
+            long now = SystemClock.elapsedRealtime();
+            if (mLastOverflowTime != 0) {
+                sb.append(" lastOverflowTime=");
+                TimeUtils.formatDuration(mLastOverflowTime-now, sb);
+            }
+            if (mLastOverflowFinishTime != 0) {
+                sb.append(" lastOverflowFinishTime=");
+                TimeUtils.formatDuration(mLastOverflowFinishTime-now, sb);
+            }
+            if (mLastClearTime != 0) {
+                sb.append(" lastClearTime=");
+                TimeUtils.formatDuration(mLastClearTime-now, sb);
+            }
+            if (mLastCleanupTime != 0) {
+                sb.append(" lastCleanupTime=");
+                TimeUtils.formatDuration(mLastCleanupTime-now, sb);
+            }
+            Slog.wtf(TAG, sb.toString());
             return null;
         }
 
@@ -5084,18 +5120,18 @@
             mSystemCpuTime = new LongSamplingCounter(mBsi.mOnBatteryTimeBase);
             mCpuPower = new LongSamplingCounter(mBsi.mOnBatteryTimeBase);
 
-            mWakelockStats = mBsi.new OverflowArrayMap<Wakelock>() {
+            mWakelockStats = mBsi.new OverflowArrayMap<Wakelock>(uid) {
                 @Override public Wakelock instantiateObject() {
                     return new Wakelock(mBsi, Uid.this);
                 }
             };
-            mSyncStats = mBsi.new OverflowArrayMap<StopwatchTimer>() {
+            mSyncStats = mBsi.new OverflowArrayMap<StopwatchTimer>(uid) {
                 @Override public StopwatchTimer instantiateObject() {
                     return new StopwatchTimer(mBsi.mClocks, Uid.this, SYNC, null,
                             mBsi.mOnBatteryTimeBase);
                 }
             };
-            mJobStats = mBsi.new OverflowArrayMap<StopwatchTimer>() {
+            mJobStats = mBsi.new OverflowArrayMap<StopwatchTimer>(uid) {
                 @Override public StopwatchTimer instantiateObject() {
                     return new StopwatchTimer(mBsi.mClocks, Uid.this, JOB, null,
                             mBsi.mOnBatteryTimeBase);