Merge "Logging for DisplayPowerController SuspendBlockers" into tm-dev am: aedd857b68

Original change: https://googleplex-android-review.googlesource.com/c/platform/frameworks/base/+/18375396

Change-Id: I89b9a9dac8af66e8b0f3bd9a6845ed293f7ec052
Signed-off-by: Automerger Merge Worker <android-build-automerger-merge-worker@system.gserviceaccount.com>

core/java/android/hardware/display/DisplayManagerInternal.java

@@ -569,8 +569,19 @@ public abstract class DisplayManagerInternal {
         void onProximityNegative();
         void onDisplayStateChange(boolean allInactive, boolean allOff);
 
-        void acquireSuspendBlocker();
+        /**
-        void releaseSuspendBlocker();
+         * Acquires a suspend blocker with a specified label.
+         *
+         * @param id A logging label for the acquisition.
+         */
+        void acquireSuspendBlocker(String id);
+
+        /**
+         * Releases a suspend blocker with a specified label.
+         *
+         * @param id A logging label for the release.
+         */
+        void releaseSuspendBlocker(String id);
     }
 
     /**

services/core/java/com/android/server/display/DisplayPowerController.java

@@ -472,6 +472,13 @@ final class DisplayPowerController implements AutomaticBrightnessController.Call
 
     private DisplayDeviceConfig mDisplayDeviceConfig;
 
+    // Identifiers for suspend blocker acuisition requests
+    private final String mSuspendBlockerIdUnfinishedBusiness;
+    private final String mSuspendBlockerIdOnStateChanged;
+    private final String mSuspendBlockerIdProxPositive;
+    private final String mSuspendBlockerIdProxNegative;
+    private final String mSuspendBlockerIdProxDebounce;
+
     /**
      * Creates the display power controller.
      */
@@ -482,7 +489,14 @@ final class DisplayPowerController implements AutomaticBrightnessController.Call
             Runnable onBrightnessChangeRunnable) {
         mLogicalDisplay = logicalDisplay;
         mDisplayId = mLogicalDisplay.getDisplayIdLocked();
-        TAG = "DisplayPowerController[" + mDisplayId + "]";
+        final String displayIdStr = "[" + mDisplayId + "]";
+        TAG = "DisplayPowerController" + displayIdStr;
+        mSuspendBlockerIdUnfinishedBusiness = displayIdStr + "unfinished business";
+        mSuspendBlockerIdOnStateChanged = displayIdStr + "on state changed";
+        mSuspendBlockerIdProxPositive = displayIdStr + "prox positive";
+        mSuspendBlockerIdProxNegative = displayIdStr + "prox negative";
+        mSuspendBlockerIdProxDebounce = displayIdStr + "prox debounce";
+
         mDisplayDevice = mLogicalDisplay.getPrimaryDisplayDeviceLocked();
         mUniqueDisplayId = logicalDisplay.getPrimaryDisplayDeviceLocked().getUniqueId();
         mDisplayStatsId = mUniqueDisplayId.hashCode();
@@ -1084,7 +1098,7 @@ final class DisplayPowerController implements AutomaticBrightnessController.Call
         mBrightnessThrottler.stop();
         mHandler.removeCallbacksAndMessages(null);
         if (mUnfinishedBusiness) {
-            mCallbacks.releaseSuspendBlocker();
+            mCallbacks.releaseSuspendBlocker(mSuspendBlockerIdUnfinishedBusiness);
             mUnfinishedBusiness = false;
         }
 
@@ -1650,7 +1664,7 @@ final class DisplayPowerController implements AutomaticBrightnessController.Call
             if (DEBUG) {
                 Slog.d(TAG, "Unfinished business...");
             }
-            mCallbacks.acquireSuspendBlocker();
+            mCallbacks.acquireSuspendBlocker(mSuspendBlockerIdUnfinishedBusiness);
             mUnfinishedBusiness = true;
         }
 
@@ -1675,7 +1689,7 @@ final class DisplayPowerController implements AutomaticBrightnessController.Call
                 Slog.d(TAG, "Finished business...");
             }
             mUnfinishedBusiness = false;
-            mCallbacks.releaseSuspendBlocker();
+            mCallbacks.releaseSuspendBlocker(mSuspendBlockerIdUnfinishedBusiness);
         }
 
         // Record if dozing for future comparison.
@@ -2228,19 +2242,19 @@ final class DisplayPowerController implements AutomaticBrightnessController.Call
     private void clearPendingProximityDebounceTime() {
         if (mPendingProximityDebounceTime >= 0) {
             mPendingProximityDebounceTime = -1;
-            mCallbacks.releaseSuspendBlocker(); // release wake lock
+            mCallbacks.releaseSuspendBlocker(mSuspendBlockerIdProxDebounce);
         }
     }
 
     private void setPendingProximityDebounceTime(long debounceTime) {
         if (mPendingProximityDebounceTime < 0) {
-            mCallbacks.acquireSuspendBlocker(); // acquire wake lock
+            mCallbacks.acquireSuspendBlocker(mSuspendBlockerIdProxDebounce);
         }
         mPendingProximityDebounceTime = debounceTime;
     }
 
     private void sendOnStateChangedWithWakelock() {
-        mCallbacks.acquireSuspendBlocker();
+        mCallbacks.acquireSuspendBlocker(mSuspendBlockerIdOnStateChanged);
         mHandler.post(mOnStateChangedRunnable);
     }
 
@@ -2401,12 +2415,12 @@ final class DisplayPowerController implements AutomaticBrightnessController.Call
         @Override
         public void run() {
             mCallbacks.onStateChanged();
-            mCallbacks.releaseSuspendBlocker();
+            mCallbacks.releaseSuspendBlocker(mSuspendBlockerIdOnStateChanged);
         }
     };
 
     private void sendOnProximityPositiveWithWakelock() {
-        mCallbacks.acquireSuspendBlocker();
+        mCallbacks.acquireSuspendBlocker(mSuspendBlockerIdProxPositive);
         mHandler.post(mOnProximityPositiveRunnable);
     }
 
@@ -2414,12 +2428,12 @@ final class DisplayPowerController implements AutomaticBrightnessController.Call
         @Override
         public void run() {
             mCallbacks.onProximityPositive();
-            mCallbacks.releaseSuspendBlocker();
+            mCallbacks.releaseSuspendBlocker(mSuspendBlockerIdProxPositive);
         }
     };
 
     private void sendOnProximityNegativeWithWakelock() {
-        mCallbacks.acquireSuspendBlocker();
+        mCallbacks.acquireSuspendBlocker(mSuspendBlockerIdProxNegative);
         mHandler.post(mOnProximityNegativeRunnable);
     }
 
@@ -2427,7 +2441,7 @@ final class DisplayPowerController implements AutomaticBrightnessController.Call
         @Override
         public void run() {
             mCallbacks.onProximityNegative();
-            mCallbacks.releaseSuspendBlocker();
+            mCallbacks.releaseSuspendBlocker(mSuspendBlockerIdProxNegative);
         }
     };
 

services/core/java/com/android/server/power/PowerManagerService.java

@@ -94,7 +94,9 @@ import android.service.dreams.DreamManagerInternal;
 import android.service.vr.IVrManager;
 import android.service.vr.IVrStateCallbacks;
 import android.sysprop.InitProperties;
+import android.util.ArrayMap;
 import android.util.KeyValueListParser;
+import android.util.LongArray;
 import android.util.PrintWriterPrinter;
 import android.util.Slog;
 import android.util.SparseArray;
@@ -135,8 +137,10 @@ import java.io.FileDescriptor;
 import java.io.PrintWriter;
 import java.lang.annotation.Retention;
 import java.lang.annotation.RetentionPolicy;
+import java.text.SimpleDateFormat;
 import java.util.ArrayList;
 import java.util.Arrays;
+import java.util.Date;
 import java.util.List;
 import java.util.NoSuchElementException;
 import java.util.Objects;
@@ -274,6 +278,11 @@ public final class PowerManagerService extends SystemService
      */
     private static final long ENHANCED_DISCHARGE_PREDICTION_BROADCAST_MIN_DELAY_MS = 60 * 1000L;
 
+    /** Reason ID for holding display suspend blocker. */
+    private static final String HOLDING_DISPLAY_SUSPEND_BLOCKER = "holding display";
+
+    private static final SimpleDateFormat DATE_FORMAT = new SimpleDateFormat("MM-dd HH:mm:ss.SSS");
+
     private final Context mContext;
     private final ServiceThread mHandlerThread;
     private final Handler mHandler;
@@ -1134,7 +1143,7 @@ public final class PowerManagerService extends SystemService
                 mHoldingBootingSuspendBlocker = true;
             }
             if (mDisplaySuspendBlocker != null) {
-                mDisplaySuspendBlocker.acquire();
+                mDisplaySuspendBlocker.acquire(HOLDING_DISPLAY_SUSPEND_BLOCKER);
                 mHoldingDisplaySuspendBlocker = true;
             }
             mHalAutoSuspendModeEnabled = false;
@@ -3529,13 +3538,13 @@ public final class PowerManagerService extends SystemService
         }
 
         @Override
-        public void acquireSuspendBlocker() {
+        public void acquireSuspendBlocker(String name) {
-            mDisplaySuspendBlocker.acquire();
+            mDisplaySuspendBlocker.acquire(name);
         }
 
         @Override
-        public void releaseSuspendBlocker() {
+        public void releaseSuspendBlocker(String name) {
-            mDisplaySuspendBlocker.release();
+            mDisplaySuspendBlocker.release(name);
         }
     };
 
@@ -3579,7 +3588,7 @@ public final class PowerManagerService extends SystemService
             mHoldingWakeLockSuspendBlocker = true;
         }
         if (needDisplaySuspendBlocker && !mHoldingDisplaySuspendBlocker) {
-            mDisplaySuspendBlocker.acquire();
+            mDisplaySuspendBlocker.acquire(HOLDING_DISPLAY_SUSPEND_BLOCKER);
             mHoldingDisplaySuspendBlocker = true;
         }
 
@@ -3609,7 +3618,7 @@ public final class PowerManagerService extends SystemService
             mHoldingWakeLockSuspendBlocker = false;
         }
         if (!needDisplaySuspendBlocker && mHoldingDisplaySuspendBlocker) {
-            mDisplaySuspendBlocker.release();
+            mDisplaySuspendBlocker.release(HOLDING_DISPLAY_SUSPEND_BLOCKER);
             mHoldingDisplaySuspendBlocker = false;
         }
 
@@ -5234,10 +5243,15 @@ public final class PowerManagerService extends SystemService
     }
 
     private final class SuspendBlockerImpl implements SuspendBlocker {
+        private static final String UNKNOWN_ID = "unknown";
         private final String mName;
         private final String mTraceName;
         private int mReferenceCount;
 
+        // Maps suspend blocker IDs to a list (LongArray) of open acquisitions for the suspend
+        // blocker. Each value is a timestamp of when the acquisition was made.
+        private final ArrayMap<String, LongArray> mOpenReferenceTimes = new ArrayMap<>();
+
         public SuspendBlockerImpl(String name) {
             mName = name;
             mTraceName = "SuspendBlocker (" + name + ")";
@@ -5260,7 +5274,13 @@ public final class PowerManagerService extends SystemService
 
         @Override
         public void acquire() {
+            acquire(UNKNOWN_ID);
+        }
+
+        @Override
+        public void acquire(String id) {
             synchronized (this) {
+                recordReferenceLocked(id);
                 mReferenceCount += 1;
                 if (mReferenceCount == 1) {
                     if (DEBUG_SPEW) {
@@ -5274,7 +5294,13 @@ public final class PowerManagerService extends SystemService
 
         @Override
         public void release() {
+            release(UNKNOWN_ID);
+        }
+
+        @Override
+        public void release(String id) {
             synchronized (this) {
+                removeReferenceLocked(id);
                 mReferenceCount -= 1;
                 if (mReferenceCount == 0) {
                     if (DEBUG_SPEW) {
@@ -5293,7 +5319,32 @@ public final class PowerManagerService extends SystemService
         @Override
         public String toString() {
             synchronized (this) {
-                return mName + ": ref count=" + mReferenceCount;
+                StringBuilder builder = new StringBuilder();
+                builder.append(mName);
+                builder.append(": ref count=").append(mReferenceCount);
+                builder.append(" [");
+                int size = mOpenReferenceTimes.size();
+                for (int i = 0; i < size; i++) {
+                    String id = mOpenReferenceTimes.keyAt(i);
+                    LongArray times = mOpenReferenceTimes.valueAt(i);
+                    if (times == null || times.size() == 0) {
+                        continue;
+                    }
+
+                    if (i > 0) {
+                        builder.append(", ");
+                    }
+                    builder.append(id).append(": (");
+                    for (int j = 0; j < times.size(); j++) {
+                        if (j > 0) {
+                            builder.append(", ");
+                        }
+                        builder.append(DATE_FORMAT.format(new Date(times.get(j))));
+                    }
+                    builder.append(")");
+                }
+                builder.append("]");
+                return builder.toString();
             }
         }
 
@@ -5305,6 +5356,22 @@ public final class PowerManagerService extends SystemService
             }
             proto.end(sbToken);
         }
+
+        private void recordReferenceLocked(String id) {
+            LongArray times = mOpenReferenceTimes.get(id);
+            if (times == null) {
+                times = new LongArray();
+                mOpenReferenceTimes.put(id, times);
+            }
+            times.add(System.currentTimeMillis());
+        }
+
+        private void removeReferenceLocked(String id) {
+            LongArray times = mOpenReferenceTimes.get(id);
+            if (times != null && times.size() > 0) {
+                times.remove(times.size() - 1);
+            }
+        }
     }
 
     static final class UidState {

services/core/java/com/android/server/power/SuspendBlocker.java

@@ -34,6 +34,17 @@ interface SuspendBlocker {
      */
     void acquire();
 
+    /**
+     * Acquires the suspend blocker.
+     * Prevents the CPU from going to sleep.
+     *
+     * Calls to acquire() nest and must be matched by the same number
+     * of calls to release().
+     *
+     * @param id Identifier for this particular acquire. Used for tracking/logging.
+     */
+    void acquire(String id);
+
     /**
      * Releases the suspend blocker.
      * Allows the CPU to go to sleep if no other suspend blockers are held.
@@ -43,5 +54,16 @@ interface SuspendBlocker {
      */
     void release();
 
+    /**
+     * Releases the suspend blocker.
+     * Allows the CPU to go to sleep if no other suspend blockers are held.
+     *
+     * It is an error to call release() if the suspend blocker has not been acquired.
+     * The system may crash.
+     *
+     * @param id Identifier for this particular release. Used for tracking/logging.
+     */
+    void release(String id);
+
     void dumpDebug(ProtoOutputStream proto, long fieldId);
 }