Use timeout for *dexopt* wake lock

There are reports of *dexopt* lock being held for 10+ minutes, which shouldn't
normally happen on threads that are monitored by the Watchdog. Added
logging to help detecting that.

The lock is now held with a timeout of WAKELOCK_TIMEOUT_MS. It is set to a
higher value than PM's watchdog timeout for easier reading from a timing
histogram.

Test: Manual, device boots without errors
Bug: 37756892
Change-Id: Iac569474d1c95447e08fe5e9870e4518b8d22c65
diff --git a/services/core/java/com/android/server/pm/PackageDexOptimizer.java b/services/core/java/com/android/server/pm/PackageDexOptimizer.java
index 254bc2a..7e60189 100644
--- a/services/core/java/com/android/server/pm/PackageDexOptimizer.java
+++ b/services/core/java/com/android/server/pm/PackageDexOptimizer.java
@@ -24,6 +24,7 @@
 import android.os.Environment;
 import android.os.FileUtils;
 import android.os.PowerManager;
+import android.os.SystemClock;
 import android.os.UserHandle;
 import android.os.WorkSource;
 import android.util.Log;
@@ -54,6 +55,7 @@
 import static com.android.server.pm.InstructionSets.getAppDexInstructionSets;
 import static com.android.server.pm.InstructionSets.getDexCodeInstructionSets;
 
+import static com.android.server.pm.PackageManagerService.WATCHDOG_TIMEOUT;
 import static com.android.server.pm.PackageManagerServiceCompilerMapping.getNonProfileGuidedCompilerFilter;
 import static dalvik.system.DexFile.isProfileGuidedCompilerFilter;
 
@@ -67,13 +69,17 @@
     public static final int DEX_OPT_SKIPPED = 0;
     public static final int DEX_OPT_PERFORMED = 1;
     public static final int DEX_OPT_FAILED = -1;
+    // One minute over PM WATCHDOG_TIMEOUT
+    private static final long WAKELOCK_TIMEOUT_MS = WATCHDOG_TIMEOUT + 1000 * 60;
 
     /** Special library name that skips shared libraries check during compilation. */
     public static final String SKIP_SHARED_LIBRARY_CHECK = "&";
 
+    @GuardedBy("mInstallLock")
     private final Installer mInstaller;
     private final Object mInstallLock;
 
+    @GuardedBy("mInstallLock")
     private final PowerManager.WakeLock mDexoptWakeLock;
     private volatile boolean mSystemReady;
 
@@ -111,21 +117,12 @@
             return DEX_OPT_SKIPPED;
         }
         synchronized (mInstallLock) {
-            // During boot the system doesn't need to instantiate and obtain a wake lock.
-            // PowerManager might not be ready, but that doesn't mean that we can't proceed with
-            // dexopt.
-            final boolean useLock = mSystemReady;
-            if (useLock) {
-                mDexoptWakeLock.setWorkSource(new WorkSource(pkg.applicationInfo.uid));
-                mDexoptWakeLock.acquire();
-            }
+            final long acquireTime = acquireWakeLockLI(pkg.applicationInfo.uid);
             try {
                 return performDexOptLI(pkg, sharedLibraries, instructionSets, checkProfiles,
                         targetCompilationFilter, packageStats, isUsedByOtherApps);
             } finally {
-                if (useLock) {
-                    mDexoptWakeLock.release();
-                }
+                releaseWakeLockLI(acquireTime);
             }
         }
     }
@@ -250,26 +247,50 @@
     public int dexOptSecondaryDexPath(ApplicationInfo info, String path, Set<String> isas,
             String compilerFilter, boolean isUsedByOtherApps) {
         synchronized (mInstallLock) {
-            // During boot the system doesn't need to instantiate and obtain a wake lock.
-            // PowerManager might not be ready, but that doesn't mean that we can't proceed with
-            // dexopt.
-            final boolean useLock = mSystemReady;
-            if (useLock) {
-                mDexoptWakeLock.setWorkSource(new WorkSource(info.uid));
-                mDexoptWakeLock.acquire();
-            }
+            final long acquireTime = acquireWakeLockLI(info.uid);
             try {
                 return dexOptSecondaryDexPathLI(info, path, isas, compilerFilter,
                         isUsedByOtherApps);
             } finally {
-                if (useLock) {
-                    mDexoptWakeLock.release();
-                }
+                releaseWakeLockLI(acquireTime);
             }
         }
     }
 
     @GuardedBy("mInstallLock")
+    private long acquireWakeLockLI(final int uid) {
+        // During boot the system doesn't need to instantiate and obtain a wake lock.
+        // PowerManager might not be ready, but that doesn't mean that we can't proceed with
+        // dexopt.
+        if (!mSystemReady) {
+            return -1;
+        }
+        mDexoptWakeLock.setWorkSource(new WorkSource(uid));
+        mDexoptWakeLock.acquire(WAKELOCK_TIMEOUT_MS);
+        return SystemClock.elapsedRealtime();
+    }
+
+    @GuardedBy("mInstallLock")
+    private void releaseWakeLockLI(final long acquireTime) {
+        if (acquireTime < 0) {
+            return;
+        }
+        try {
+            if (mDexoptWakeLock.isHeld()) {
+                mDexoptWakeLock.release();
+            }
+            final long duration = SystemClock.elapsedRealtime() - acquireTime;
+            if (duration >= WAKELOCK_TIMEOUT_MS) {
+                Slog.wtf(TAG, "WakeLock " + mDexoptWakeLock.getTag()
+                        + " time out. Operation took " + duration + " ms. Thread: "
+                        + Thread.currentThread().getName());
+            }
+        } catch (Exception e) {
+            Slog.wtf(TAG, "Error while releasing " + mDexoptWakeLock.getTag() + " lock", e);
+        }
+    }
+
+    @GuardedBy("mInstallLock")
     private int dexOptSecondaryDexPathLI(ApplicationInfo info, String path, Set<String> isas,
             String compilerFilter, boolean isUsedByOtherApps) {
         compilerFilter = getRealCompilerFilter(info, compilerFilter, isUsedByOtherApps);