Android/frameworks_base
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

PackageManagerService snapshot: statistics

Browse Source 
Bug: 177425470

Collect periodic snapshot statistics.  The statistics are:
 1. Number of snapshots built
 2. Number of times a snapshot was reused
 3. Number of "big" snapshot build times
 4. Number of "quick" snapshot rebuilds
 4. Maximum time spent building a single snapshot
 5. Cumulative time spent building snapshots
All statistics are reset after being logged.

Collect event snapshot statistics.  The statistics are:
 1. The time taken for a big snapshot build
At most 5 events are logged in any periodic poll interval.

The periodic log interval is 10 minutes.  This will be lengthened
after we have some dogfood exprience.

A long snapshot build time is currently defined as anything over 5ms.

A quick snapshot rebuild is one that happens within 100ms of the
previous snapshot.

This change is designed to monitor the health of the snapshot feature.
A future improvement will allow statistics to be dumped on demand and
to report statistics via WestWorld.

Also:
 1. A places that still used the word "cache" are changed to use the
    word "snapshot".
 2. The unused DEBUG_CACHE flag is removed

Test: atest
 * FrameworksServicesTests:UserSystemPackageInstallerTest
 * FrameworksServicesTests:PackageManagerSettingsTests
 * FrameworksServicesTests:PackageManagerServiceTest
 * FrameworksServicesTests:AppsFilterTest
 * FrameworksServicesTests:PackageInstallerSessionTest
 * FrameworksServicesTests:ScanTests

Change-Id: Id964f7d9fc16cf49e064044643b3c65862183a7d
This commit is contained in:
Lee Shombert
2021-01-27 10:37:14 -08:00
parent 3f08df9fe9
commit 9e1206ce51
2 changed files with 136 additions and 31 deletions
Download Patch File Download Diff File Expand all files Collapse all files

6
services/core/java/com/android/server/EventLogTags.logtags
View File

@@ -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

161
services/core/java/com/android/server/pm/PackageManagerService.java
View File

@@ -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;
// 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.
// 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);
// 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;
}