Merge "PackageManagerService snapshot: statistics" into sc-dev

2 files changed, 136 insertions, 31 deletions

diff --git a/services/core/java/com/android/server/EventLogTags.logtags b/services/core/java/com/android/server/EventLogTags.logtags
index b595eb15ee15..9f91dd6b982b 100644
--- a/services/core/java/com/android/server/EventLogTags.logtags
+++ b/services/core/java/com/android/server/EventLogTags.logtags
@@ -1,4 +1,4 @@
-# See system/core/logcat/event.logtags for a description of the format of this file.
+# See system/logging/logcat/event.logtags for a description of the format of this file.
 
 option java_package com.android.server
 
@@ -173,6 +173,10 @@ option java_package com.android.server
 3120 pm_critical_info (msg|3)
 # Disk usage stats for verifying quota correctness
 3121 pm_package_stats (manual_time|2|3),(quota_time|2|3),(manual_data|2|2),(quota_data|2|2),(manual_cache|2|2),(quota_cache|2|2)
+# Snapshot statistics
+3130 pm_snapshot_stats (build_count|1|1),(reuse_count|1|1),(big_builds|1|1),(quick_rebuilds|1|1),(max_build_time|1|3),(cumm_build_time|1|3)
+# Snapshot rebuild instance
+3131 pm_snapshot_rebuild (build_time|1|3),(elapsed|1|3)
 
 # ---------------------------
 # InputMethodManagerService.java
diff --git a/services/core/java/com/android/server/pm/PackageManagerService.java b/services/core/java/com/android/server/pm/PackageManagerService.java
index 50aacd677fdc..c27e670c4c99 100644
--- a/services/core/java/com/android/server/pm/PackageManagerService.java
+++ b/services/core/java/com/android/server/pm/PackageManagerService.java
@@ -518,8 +518,7 @@ public class PackageManagerService extends IPackageManager.Stub
     public static final boolean DEBUG_PERMISSIONS = false;
     private static final boolean DEBUG_SHARED_LIBRARIES = false;
     public static final boolean DEBUG_COMPRESSION = Build.IS_DEBUGGABLE;
-    public static final boolean DEBUG_CACHES = false;
-    public static final boolean TRACE_CACHES = false;
+    public static final boolean TRACE_SNAPSHOTS = false;
     private static final boolean DEBUG_PER_UID_READ_TIMEOUTS = false;
 
     // Debug output for dexopting. This is shared between PackageManagerService, OtaDexoptService
@@ -2015,7 +2014,7 @@ public class PackageManagerService extends IPackageManager.Stub
     }
 
     /**
-     * A computer provides the functional interface to the cache
+     * A computer provides the functional interface to the snapshot.
      */
     private interface Computer {
 
@@ -2181,13 +2180,11 @@ public class PackageManagerService extends IPackageManager.Stub
         private final ResolveInfo mInstantAppInstallerInfo;
         private final InstantAppRegistry mInstantAppRegistry;
         private final ApplicationInfo mLocalAndroidApplication;
+        private final AppsFilter mAppsFilter;
 
         // Immutable service attribute
         private final String mAppPredictionServicePackage;
 
-        // TODO: create cache copies of the following attributes
-        private final AppsFilter mAppsFilter;
-
         // The following are not cloned since changes to these have never
         // been guarded by the PMS lock.
         private final Context mContext;
@@ -4738,11 +4735,11 @@ public class PackageManagerService extends IPackageManager.Stub
     private final Computer mLiveComputer;
     // A lock-free cache for frequently called functions.
     private volatile Computer mSnapshotComputer;
-    // If true, the cached computer object is invalid (the cache is stale).
-    // The attribute is static since it may be set from outside classes.
+    // If true, the snapshot is invalid (stale).  The attribute is static since it may be
+    // set from outside classes.
     private static volatile boolean sSnapshotInvalid = true;
-    // If true, the cache is corked.  Do not create a new cache but continue to use the
-    // existing one.  This throttles cache creation during periods of churn in Package
+    // If true, the snapshot is corked.  Do not create a new snapshot but use the live
+    // computer.  This throttles snapshot creation during periods of churn in Package
     // Manager.
     private static volatile boolean sSnapshotCorked = false;
 
@@ -4754,13 +4751,121 @@ public class PackageManagerService extends IPackageManager.Stub
      */
     private final Object mSnapshotLock = new Object();
 
-    // A counter of all queries that hit the cache.
-    private AtomicInteger mSnapshotHits = new AtomicInteger(0);
+    // A counter of all queries that hit the current snapshot.
+    @GuardedBy("mSnapshotLock")
+    private int mSnapshotHits = 0;
+
+    // A class to record snapshot statistics.
+    private static class SnapshotStatistics {
+        // A build time is "big" if it takes longer than 5ms.
+        private static final long SNAPSHOT_BIG_BUILD_TIME_NS = TimeUnit.MILLISECONDS.toNanos(5);
+
+        // A snapshot is in quick succession to the previous snapshot if it less than
+        // 100ms since the previous snapshot.
+        private static final long SNAPSHOT_QUICK_REBUILD_INTERVAL_NS =
+                TimeUnit.MILLISECONDS.toNanos(100);
+
+        // The interval between snapshot statistics logging, in ns.
+        private static final long SNAPSHOT_LOG_INTERVAL_NS = TimeUnit.MINUTES.toNanos(10);
+
+        // The throttle parameters for big build reporting.  Do not report more than this
+        // many events in a single log interval.
+        private static final int SNAPSHOT_BUILD_REPORT_LIMIT = 10;
+
+        // The time the snapshot statistics were last logged.
+        private long mStatisticsSent = 0;
+
+        // The number of build events logged since the last periodic log.
+        private int mLoggedBuilds = 0;
+
+        // The time of the last build.
+        private long mLastBuildTime = 0;
+
+        // The number of times the snapshot has been rebuilt since the statistics were
+        // last logged.
+        private int mRebuilds = 0;
+
+        // The number of times the snapshot has been used since it was rebuilt.
+        private int mReused = 0;
+
+        // The number of "big" build times since the last log.  "Big" is defined by
+        // SNAPSHOT_BIG_BUILD_TIME.
+        private int mBigBuilds = 0;
+
+        // The number of quick rebuilds.  "Quick" is defined by
+        // SNAPSHOT_QUICK_REBUILD_INTERVAL_NS.
+        private int mQuickRebuilds = 0;
+
+        // The time take to build a snapshot.  This is cumulative over the rebuilds recorded
+        // in mRebuilds, so the average time to build a snapshot is given by
+        // mBuildTimeNs/mRebuilds.
+        private int mBuildTimeNs = 0;
+
+        // The maximum build time since the last log.
+        private long mMaxBuildTimeNs = 0;
+
+        // The constant that converts ns to ms.  This is the divisor.
+        private final long NS_TO_MS = TimeUnit.MILLISECONDS.toNanos(1);
 
-    // The number of queries at the last miss.  This is updated when the cache is rebuilt
-    // (guarded by mLock) and is used to report the hit run-length.
+        // Convert ns to an int ms.  The maximum range of this method is about 24 days.
+        // There is no expectation that an event will take longer than that.
+        private int nsToMs(long ns) {
+            return (int) (ns / NS_TO_MS);
+        }
+
+        // The single method records a rebuild.  The "now" parameter is passed in because
+        // the caller needed it to computer the duration, so pass it in to avoid
+        // recomputing it.
+        private void rebuild(long now, long done, int hits) {
+            if (mStatisticsSent == 0) {
+                mStatisticsSent = now;
+            }
+            final long elapsed = now - mLastBuildTime;
+            final long duration = done - now;
+            mLastBuildTime = now;
+
+            if (mMaxBuildTimeNs < duration) {
+                mMaxBuildTimeNs = duration;
+            }
+            mRebuilds++;
+            mReused += hits;
+            mBuildTimeNs += duration;
+
+            boolean log_build = false;
+            if (duration > SNAPSHOT_BIG_BUILD_TIME_NS) {
+                log_build = true;
+                mBigBuilds++;
+            }
+            if (elapsed < SNAPSHOT_QUICK_REBUILD_INTERVAL_NS) {
+                log_build = true;
+                mQuickRebuilds++;
+            }
+            if (log_build && mLoggedBuilds < SNAPSHOT_BUILD_REPORT_LIMIT) {
+                EventLogTags.writePmSnapshotRebuild(nsToMs(duration), nsToMs(elapsed));
+                mLoggedBuilds++;
+            }
+
+            final long log_interval = now - mStatisticsSent;
+            if (log_interval >= SNAPSHOT_LOG_INTERVAL_NS) {
+                EventLogTags.writePmSnapshotStats(mRebuilds, mReused,
+                                                  mBigBuilds, mQuickRebuilds,
+                                                  nsToMs(mMaxBuildTimeNs),
+                                                  nsToMs(mBuildTimeNs));
+                mStatisticsSent = now;
+                mRebuilds = 0;
+                mReused = 0;
+                mBuildTimeNs = 0;
+                mMaxBuildTimeNs = 0;
+                mBigBuilds = 0;
+                mQuickRebuilds = 0;
+                mLoggedBuilds = 0;
+            }
+        }
+    }
+
+    // Snapshot statistics.
     @GuardedBy("mLock")
-    private int mSnapshotRebuilt = 0;
+    private final SnapshotStatistics mSnapshotStatistics = new SnapshotStatistics();
 
     // The snapshot disable/enable switch.  An image with the flag set true uses snapshots
     // and an image with the flag set false does not use snapshots.
@@ -4786,23 +4891,21 @@ public class PackageManagerService extends IPackageManager.Stub
             // yet invalidated the snapshot.  Always give the thread the live computer.
             return mLiveComputer;
         }
-        int hits = 0;
-        if (TRACE_CACHES) {
-            hits = mSnapshotHits.incrementAndGet();
-        }
         synchronized (mSnapshotLock) {
             Computer c = mSnapshotComputer;
             if (sSnapshotCorked && (c != null)) {
                 // Snapshots are corked, which means new ones should not be built right now.
                 return c;
             }
+            // Deliberately capture the value pre-increment
+            final int hits = mSnapshotHits++;
             if (sSnapshotInvalid || (c == null)) {
                 // The snapshot is invalid if it is marked as invalid or if it is null.  If it
                 // is null, then it is currently being rebuilt by rebuildSnapshot().
                 synchronized (mLock) {
                     // Rebuild the snapshot if it is invalid.  Note that the snapshot might be
                     // invalidated as it is rebuilt.  However, the snapshot is still
-                    // self-consistent (the lock is being held)and is current as of the time
+                    // self-consistent (the lock is being held) and is current as of the time
                     // this function is entered.
                     if (sSnapshotInvalid) {
                         rebuildSnapshot(hits);
@@ -4820,22 +4923,20 @@ public class PackageManagerService extends IPackageManager.Stub
     }
 
     /**
-     * Rebuild the cached computer.  mSnapshotComputer is temporarily set to null to block
-     * other threads from using the invalid computer until it is rebuilt.
+     * Rebuild the cached computer.  mSnapshotComputer is temporarily set to null to block other
+     * threads from using the invalid computer until it is rebuilt.
      */
     @GuardedBy("mLock")
     private void rebuildSnapshot(int hits) {
+        final long now = System.nanoTime();
         mSnapshotComputer = null;
         sSnapshotInvalid = false;
         final Snapshot args = new Snapshot(Snapshot.SNAPPED);
         mSnapshotComputer = new ComputerEngine(args);
+        final long done = System.nanoTime();
 
-        // Still guarded by mLock
-        final int run = hits - mSnapshotRebuilt;
-        mSnapshotRebuilt = hits;
-        if (TRACE_CACHES) {
-            Log.w(TAG, "computer: rebuild after " + run + " hits");
-        }
+        mSnapshotStatistics.rebuild(now, done, hits);
+        mSnapshotHits = 0;
     }
 
     /**
@@ -4852,8 +4953,8 @@ public class PackageManagerService extends IPackageManager.Stub
      * @hide
      */
     public static void onChange(@Nullable Watchable what) {
-        if (TRACE_CACHES) {
-            Log.e(TAG, "computer: onChange(" + what + ")");
+        if (TRACE_SNAPSHOTS) {
+            Log.e(TAG, "snapshot: onChange(" + what + ")");
         }
         sSnapshotInvalid = true;
     }