diff options
| -rw-r--r-- | services/core/java/com/android/server/EventLogTags.logtags | 6 | ||||
| -rw-r--r-- | services/core/java/com/android/server/pm/PackageManagerService.java | 161 |
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; } |