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

Improve PackageManager snapshot statistics

Browse Source 
Bug: 184751735

This makes some small improvements to the snapshot statistics.
The change emphasizes long rebuild times over short snapshot
lifetimes.

1. The pm_snapshot_rebuild "elapsed" field is renamed "lifetime".
   This is the number of times the previous snapshot (the snapshot
   that was replaced by this rebuild)  was used.

2. The pm_snapshot_stats cumulative build time is now a long.
   Wrap-around of the 32-bit int was seen during testing.  Also, the
   "quick_rebuilds" has been renamed to "short_lived".

3. pm_snapshot_rebuild events are only logged for long rebuild times.
   Short lifetimes are still counted but do not generate their own
   events.  Also, any rebuild time that is greater than the current
   maximum rebuild time is logged, even if the number of logged events
   is greater than the limit.

4. Snapshot statistics are included in the package manager dump.   Two
   sets of statistics are presented: there is a set of 10, rolling
   over every minute, and a set of two, rolling over every week.
   The snapshot statistics are part of the default "package" dumpsys
   output and can be selected individually with "package snapshot".

5. The SnapshotStatistics class is now in its own file.  At the
   momement, the class has code that is specific to
   PackageManagerService, but it should be possible to make the class
   more generic in the future, if desired.

See the bug for sample output.

Test: manual steps -
 * Create a bug report and verify that the new statistics are present.
 * Verify that pm_snapshot_rebuild events are generated for long
   rebuild times.

Change-Id: I3197d6b76e86ecfcdaff36f47e8a6b5d4a6e456d
This commit is contained in:
Lee Shombert
2021-04-15 08:52:49 -07:00
parent 41b21288eb
commit 6e67ca77fb
4 changed files with 700 additions and 135 deletions
Download Patch File Download Diff File Expand all files Collapse all files

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

@@ -174,9 +174,9 @@ option java_package com.android.server
# 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)
3130 pm_snapshot_stats (build_count|1|1),(reuse_count|1|1),(big_builds|1|1),(short_lived|1|1),(max_build_time|1|3),(cumm_build_time|2|3)
# Snapshot rebuild instance
3131 pm_snapshot_rebuild (build_time|1|3),(elapsed|1|3)
3131 pm_snapshot_rebuild (build_time|1|3),(lifetime|1|3)
# ---------------------------
# InputMethodManagerService.java

1
services/core/java/com/android/server/pm/DumpState.java
View File

@@ -45,6 +45,7 @@ public final class DumpState {
public static final int DUMP_QUERIES = 1 << 26;
public static final int DUMP_KNOWN_PACKAGES = 1 << 27;
public static final int DUMP_PER_UID_READ_TIMEOUTS = 1 << 28;
public static final int DUMP_SNAPSHOT_STATISTICS = 1 << 29;
public static final int OPTION_SHOW_FILTERS = 1 << 0;
public static final int OPTION_DUMP_ALL_COMPONENTS = 1 << 1;

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

@@ -1914,6 +1914,18 @@ public class PackageManagerService extends IPackageManager.Stub
*/
private interface Computer {
/**
* Administrative statistics: record that the snapshot has been used. Every call
* to use() increments the usage counter.
*/
void use();
/**
* Fetch the snapshot usage counter.
* @return The number of times this snapshot was used.
*/
int getUsed();
@NonNull List<ResolveInfo> queryIntentActivitiesInternal(Intent intent, String resolvedType,
int flags, @PrivateResolveFlags int privateResolveFlags, int filterCallingUid,
int userId, boolean resolveForStart, boolean allowDynamicSplits);
@@ -2065,6 +2077,9 @@ public class PackageManagerService extends IPackageManager.Stub
*/
private static class ComputerEngine implements Computer {
// The administrative use counter.
private int mUsed = 0;
// Cached attributes. The names in this class are the same as the
// names in PackageManagerService; see that class for documentation.
protected final Settings mSettings;
@@ -2157,6 +2172,20 @@ public class PackageManagerService extends IPackageManager.Stub
mService = args.service;
}
/**
* Record that the snapshot was used.
*/
public void use() {
mUsed++;
}
/**
* Return the usage counter.
*/
public int getUsed() {
return mUsed;
}
public @NonNull List<ResolveInfo> queryIntentActivitiesInternal(Intent intent,
String resolvedType, int flags, @PrivateResolveFlags int privateResolveFlags,
int filterCallingUid, int userId, boolean resolveForStart,
@@ -4885,121 +4914,11 @@ public class PackageManagerService extends IPackageManager.Stub
*/
private final Object mSnapshotLock = new Object();
// 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);
// 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 final SnapshotStatistics mSnapshotStatistics = new SnapshotStatistics();
/**
* The snapshot statistics. These are collected to track performance and to identify
* situations in which the snapshots are misbehaving.
*/
private final SnapshotStatistics mSnapshotStatistics;
// 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.
@@ -5033,10 +4952,9 @@ public class PackageManagerService extends IPackageManager.Stub
Computer c = mSnapshotComputer;
if (sSnapshotCorked && (c != null)) {
// Snapshots are corked, which means new ones should not be built right now.
c.use();
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().
@@ -5046,7 +4964,7 @@ public class PackageManagerService extends IPackageManager.Stub
// self-consistent (the lock is being held) and is current as of the time
// this function is entered.
if (sSnapshotInvalid) {
rebuildSnapshot(hits);
rebuildSnapshot();
}
// Guaranteed to be non-null. mSnapshotComputer is only be set to null
@@ -5056,6 +4974,7 @@ public class PackageManagerService extends IPackageManager.Stub
c = mSnapshotComputer;
}
}
c.use();
return c;
}
}
@@ -5065,16 +4984,16 @@ public class PackageManagerService extends IPackageManager.Stub
* threads from using the invalid computer until it is rebuilt.
*/
@GuardedBy("mLock")
private void rebuildSnapshot(int hits) {
final long now = System.nanoTime();
private void rebuildSnapshot() {
final long now = SystemClock.currentTimeMicro();
final int hits = mSnapshotComputer == null ? -1 : mSnapshotComputer.getUsed();
mSnapshotComputer = null;
sSnapshotInvalid = false;
final Snapshot args = new Snapshot(Snapshot.SNAPPED);
mSnapshotComputer = new ComputerEngine(args);
final long done = System.nanoTime();
final long done = SystemClock.currentTimeMicro();
mSnapshotStatistics.rebuild(now, done, hits);
mSnapshotHits = 0;
}
/**
@@ -6327,6 +6246,7 @@ public class PackageManagerService extends IPackageManager.Stub
mSnapshotEnabled = false;
mLiveComputer = createLiveComputer();
mSnapshotComputer = null;
mSnapshotStatistics = null;
mPackages.putAll(testParams.packages);
mEnableFreeCacheV2 = testParams.enableFreeCacheV2;
@@ -6479,17 +6399,20 @@ public class PackageManagerService extends IPackageManager.Stub
mDomainVerificationManager = injector.getDomainVerificationManagerInternal();
mDomainVerificationManager.setConnection(mDomainVerificationConnection);
// Create the computer as soon as the state objects have been installed. The
// cached computer is the same as the live computer until the end of the
// constructor, at which time the invalidation method updates it. The cache is
// corked initially to ensure a cached computer is not built until the end of the
// constructor.
mSnapshotEnabled = SNAPSHOT_ENABLED;
sSnapshotCorked = true;
sSnapshotInvalid = true;
mLiveComputer = createLiveComputer();
mSnapshotComputer = null;
registerObserver();
synchronized (mLock) {
// Create the computer as soon as the state objects have been installed. The
// cached computer is the same as the live computer until the end of the
// constructor, at which time the invalidation method updates it. The cache is
// corked initially to ensure a cached computer is not built until the end of the
// constructor.
mSnapshotEnabled = SNAPSHOT_ENABLED;
sSnapshotCorked = true;
sSnapshotInvalid = true;
mSnapshotStatistics = new SnapshotStatistics();
mLiveComputer = createLiveComputer();
mSnapshotComputer = null;
registerObserver();
}
// CHECKSTYLE:OFF IndentationCheck
synchronized (mInstallLock) {
@@ -23957,6 +23880,7 @@ public class PackageManagerService extends IPackageManager.Stub
pw.println(" dexopt: dump dexopt state");
pw.println(" compiler-stats: dump compiler statistics");
pw.println(" service-permissions: dump permissions required by services");
pw.println(" snapshot: dump snapshot statistics");
pw.println(" known-packages: dump known packages");
pw.println(" <package.name>: info about given package");
return;
@@ -24105,6 +24029,8 @@ public class PackageManagerService extends IPackageManager.Stub
dumpState.setDump(DumpState.DUMP_KNOWN_PACKAGES);
} else if ("t".equals(cmd) || "timeouts".equals(cmd)) {
dumpState.setDump(DumpState.DUMP_PER_UID_READ_TIMEOUTS);
} else if ("snapshot".equals(cmd)) {
dumpState.setDump(DumpState.DUMP_SNAPSHOT_STATISTICS);
} else if ("write".equals(cmd)) {
synchronized (mLock) {
writeSettingsLPrTEMP();
@@ -24433,6 +24359,22 @@ public class PackageManagerService extends IPackageManager.Stub
pw.println(")");
}
}
if (!checkin && dumpState.isDumping(DumpState.DUMP_SNAPSHOT_STATISTICS)) {
pw.println("Snapshot statistics");
if (!mSnapshotEnabled) {
pw.println(" Snapshots disabled");
} else {
int hits = 0;
synchronized (mSnapshotLock) {
if (mSnapshotComputer != null) {
hits = mSnapshotComputer.getUsed();
}
}
final long now = SystemClock.currentTimeMicro();
mSnapshotStatistics.dump(pw, " ", now, hits, true);
}
}
}
/**

622
services/core/java/com/android/server/pm/SnapshotStatistics.java Normal file
View File

@@ -0,0 +1,622 @@
/*
* Copyright (C) 2021 The Android Open Source Project
*
* Licensed under the Apache License, Version 2.0 (the "License");
* you may not use this file except in compliance with the License.
* You may obtain a copy of the License at
*
* http://www.apache.org/licenses/LICENSE-2.0
*
* Unless required by applicable law or agreed to in writing, software
* distributed under the License is distributed on an "AS IS" BASIS,
* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
* See the License for the specific language governing permissions and
* limitations under the License.
*/
package com.android.server.pm;
import android.annotation.Nullable;
import android.os.Handler;
import android.os.Looper;
import android.os.Message;
import android.os.SystemClock;
import android.text.TextUtils;
import com.android.server.EventLogTags;
import java.io.PrintWriter;
import java.util.Arrays;
import java.util.Locale;
/**
* This class records statistics about PackageManagerService snapshots. It maintains two sets of
* statistics: a periodic set which represents the last 10 minutes, and a cumulative set since
* process boot. The key metrics that are recorded are:
* <ul>
* <li> The time to create a snapshot - this is the performance cost of a snapshot
* <li> The lifetime of the snapshot - creation time over lifetime is the amortized cost
* <li> The number of times a snapshot is reused - this is the number of times lock
* contention was avoided.
* </ul>
* The time conversions in this class are designed to keep arithmetic using ints, rather
* than longs. Raw times are supplied as longs in units of us. These are left long.
* Rebuild durations however, are converted to ints. An int can express a duration of
* approximately 35 minutes. This is longer than any expected snapshot rebuild time, so
* an int is satisfactory. The exception is the cumulative rebuild time over the course
* of a monitoring cycle: this value is kept long since the cycle time is one week and in
* a badly behaved system, the rebuild time might exceed 35 minutes.
* @hide
*/
public class SnapshotStatistics {
/**
* The interval at which statistics should be ticked. It is 60s. The interval is in
* units of milliseconds because that is what's required by Handler.sendMessageDelayed().
*/
public static final int SNAPSHOT_TICK_INTERVAL_MS = 60 * 1000;
/**
* The number of ticks for long statistics. This is one week.
*/
public static final int SNAPSHOT_LONG_TICKS = 7 * 24 * 60;
/**
* The number snapshot event logs that can be generated in a single logging interval.
* A small number limits the logging generated by this class. A snapshot event log is
* generated for every big snapshot build time, up to the limit, or whenever the
* maximum build time is exceeded in the logging interval.
*/
public static final int SNAPSHOT_BUILD_REPORT_LIMIT = 10;
/**
* The number of microseconds in a millisecond.
*/
private static final int US_IN_MS = 1000;
/**
* A snapshot build time is "big" if it takes longer than 10ms.
*/
public static final int SNAPSHOT_BIG_BUILD_TIME_US = 10 * US_IN_MS;
/**
* A snapshot build time is reportable if it takes longer than 30ms. Testing shows
* that this is very rare.
*/
public static final int SNAPSHOT_REPORTABLE_BUILD_TIME_US = 30 * US_IN_MS;
/**
* A snapshot is short-lived it used fewer than 5 times.
*/
public static final int SNAPSHOT_SHORT_LIFETIME = 5;
/**
* The lock to control access to this object.
*/
private final Object mLock = new Object();
/**
* The bins for the build time histogram. Values are in us.
*/
private final BinMap mTimeBins;
/**
* The bins for the snapshot use histogram.
*/
private final BinMap mUseBins;
/**
* The number of events reported in the current tick.
*/
private int mEventsReported = 0;
/**
* The tick counter. At the default tick interval, this wraps every 4000 years or so.
*/
private int mTicks = 0;
/**
* The handler used for the periodic ticks.
*/
private Handler mHandler = null;
/**
* 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 usToMs(int us) {
return us / US_IN_MS;
}
/**
* This class exists to provide a fast bin lookup for histograms. An instance has an
* integer array that maps incoming values to bins. Values larger than the array are
* mapped to the top-most bin.
*/
private static class BinMap {
// The number of bins
private int mCount;
// The mapping of low integers to bins
private int[] mBinMap;
// The maximum mapped value. Values at or above this are mapped to the
// top bin.
private int mMaxBin;
// A copy of the original key
private int[] mUserKey;
/**
* Create a bin map. The input is an array of integers, which must be
* monotonically increasing (this is not checked). The result is an integer array
* as long as the largest value in the input.
*/
BinMap(int[] userKey) {
mUserKey = Arrays.copyOf(userKey, userKey.length);
// The number of bins is the length of the keys, plus 1 (for the max).
mCount = mUserKey.length + 1;
// The maximum value is one more than the last one in the map.
mMaxBin = mUserKey[mUserKey.length - 1] + 1;
mBinMap = new int[mMaxBin + 1];
int j = 0;
for (int i = 0; i < mUserKey.length; i++) {
while (j <= mUserKey[i]) {
mBinMap[j] = i;
j++;
}
}
mBinMap[mMaxBin] = mUserKey.length;
}
/**
* Map a value to a bin.
*/
public int getBin(int x) {
if (x >= 0 && x < mMaxBin) {
return mBinMap[x];
} else if (x >= mMaxBin) {
return mBinMap[mMaxBin];
} else {
// x is negative. The bin will not be used.
return 0;
}
}
/**
* The number of bins in this map
*/
public int count() {
return mCount;
}
/**
* For convenience, return the user key.
*/
public int[] userKeys() {
return mUserKey;
}
}
/**
* A complete set of statistics. These are public, making it simpler for a client to
* fetch the individual fields.
*/
public class Stats {
/**
* The start time for this set of statistics, in us.
*/
public long mStartTimeUs = 0;
/**
* The completion time for this set of statistics, in ns. A value of zero means
* the statistics are still active.
*/
public long mStopTimeUs = 0;
/**
* The build-time histogram. The total number of rebuilds is the sum over the
* histogram entries.
*/
public int[] mTimes;
/**
* The reuse histogram. The total number of snapshot uses is the sum over the
* histogram entries.
*/
public int[] mUsed;
/**
* The total number of rebuilds. This could be computed by summing over the use
* bins, but is maintained separately for convenience.
*/
public int mTotalBuilds = 0;
/**
* The total number of times any snapshot was used.
*/
public int mTotalUsed = 0;
/**
* The total number of builds that count as big, which means they took longer than
* SNAPSHOT_BIG_BUILD_TIME_NS.
*/
public int mBigBuilds = 0;
/**
* The total number of short-lived snapshots
*/
public int mShortLived = 0;
/**
* The time taken to build snapshots. This is cumulative over the rebuilds
* recorded in mRebuilds, so the average time to build a snapshot is given by
* mBuildTimeNs/mRebuilds. Note that this cannot be computed from the histogram.
*/
public long mTotalTimeUs = 0;
/**
* The maximum build time since the last log.
*/
public int mMaxBuildTimeUs = 0;
/**
* Record the rebuild. The parameters are the length of time it took to build the
* latest snapshot, and the number of times the _previous_ snapshot was used. A
* negative value for used signals an invalid value, which is the case the first
* time a snapshot is every built.
*/
private void rebuild(int duration, int used,
int buildBin, int useBin, boolean big, boolean quick) {
mTotalBuilds++;
mTimes[buildBin]++;
if (used >= 0) {
mTotalUsed += used;
mUsed[useBin]++;
}
mTotalTimeUs += duration;
boolean reportIt = false;
if (big) {
mBigBuilds++;
}
if (quick) {
mShortLived++;
}
if (mMaxBuildTimeUs < duration) {
mMaxBuildTimeUs = duration;
}
}
private Stats(long now) {
mStartTimeUs = now;
mTimes = new int[mTimeBins.count()];
mUsed = new int[mUseBins.count()];
}
/**
* Create a copy of the argument. The copy is made under lock but can then be
* used without holding the lock.
*/
private Stats(Stats orig) {
mStartTimeUs = orig.mStartTimeUs;
mStopTimeUs = orig.mStopTimeUs;
mTimes = Arrays.copyOf(orig.mTimes, orig.mTimes.length);
mUsed = Arrays.copyOf(orig.mUsed, orig.mUsed.length);
mTotalBuilds = orig.mTotalBuilds;
mTotalUsed = orig.mTotalUsed;
mBigBuilds = orig.mBigBuilds;
mShortLived = orig.mShortLived;
mTotalTimeUs = orig.mTotalTimeUs;
mMaxBuildTimeUs = orig.mMaxBuildTimeUs;
}
/**
* Set the end time for the statistics. The end time is used only for reporting
* in the dump() method.
*/
private void complete(long stop) {
mStopTimeUs = stop;
}
/**
* Format a time span into ddd:HH:MM:SS. The input is in us.
*/
private String durationToString(long us) {
// s has a range of several years
int s = (int) (us / (1000 * 1000));
int m = s / 60;
s %= 60;
int h = m / 60;
m %= 60;
int d = h / 24;
h %= 24;
if (d != 0) {
return TextUtils.formatSimple("%2d:%02d:%02d:%02d", d, h, m, s);
} else if (h != 0) {
return TextUtils.formatSimple("%2s %02d:%02d:%02d", "", h, m, s);
} else {
return TextUtils.formatSimple("%2s %2s %2d:%02d", "", "", m, s);
}
}
/**
* Print the prefix for dumping. This does not generate a line to the output.
*/
private void dumpPrefix(PrintWriter pw, String indent, long now, boolean header,
String title) {
pw.print(indent + " ");
if (header) {
pw.format(Locale.US, "%-23s", title);
} else {
pw.format(Locale.US, "%11s", durationToString(now - mStartTimeUs));
if (mStopTimeUs != 0) {
pw.format(Locale.US, " %11s", durationToString(now - mStopTimeUs));
} else {
pw.format(Locale.US, " %11s", "now");
}
}
}
/**
* Dump the summary statistics record. Choose the header or the data.
* number of builds
* number of uses
* number of big builds
* number of short lifetimes
* cumulative build time, in seconds
* maximum build time, in ms
*/
private void dumpStats(PrintWriter pw, String indent, long now, boolean header) {
dumpPrefix(pw, indent, now, header, "Summary stats");
if (header) {
pw.format(Locale.US, " %10s %10s %10s %10s %10s %10s",
"TotBlds", "TotUsed", "BigBlds", "ShortLvd",
"TotTime", "MaxTime");
} else {
pw.format(Locale.US,
" %10d %10d %10d %10d %10d %10d",
mTotalBuilds, mTotalUsed, mBigBuilds, mShortLived,
mTotalTimeUs / 1000, mMaxBuildTimeUs / 1000);
}
pw.println();
}
/**
* Dump the build time histogram. Choose the header or the data.
*/
private void dumpTimes(PrintWriter pw, String indent, long now, boolean header) {
dumpPrefix(pw, indent, now, header, "Build times");
if (header) {
int[] keys = mTimeBins.userKeys();
for (int i = 0; i < keys.length; i++) {
pw.format(Locale.US, " %10s",
TextUtils.formatSimple("<= %dms", keys[i]));
}
pw.format(Locale.US, " %10s",
TextUtils.formatSimple("> %dms", keys[keys.length - 1]));
} else {
for (int i = 0; i < mTimes.length; i++) {
pw.format(Locale.US, " %10d", mTimes[i]);
}
}
pw.println();
}
/**
* Dump the usage histogram. Choose the header or the data.
*/
private void dumpUsage(PrintWriter pw, String indent, long now, boolean header) {
dumpPrefix(pw, indent, now, header, "Use counters");
if (header) {
int[] keys = mUseBins.userKeys();
for (int i = 0; i < keys.length; i++) {
pw.format(Locale.US, " %10s", TextUtils.formatSimple("<= %d", keys[i]));
}
pw.format(Locale.US, " %10s",
TextUtils.formatSimple("> %d", keys[keys.length - 1]));
} else {
for (int i = 0; i < mUsed.length; i++) {
pw.format(Locale.US, " %10d", mUsed[i]);
}
}
pw.println();
}
/**
* Dump something, based on the "what" parameter.
*/
private void dump(PrintWriter pw, String indent, long now, boolean header, String what) {
if (what.equals("stats")) {
dumpStats(pw, indent, now, header);
} else if (what.equals("times")) {
dumpTimes(pw, indent, now, header);
} else if (what.equals("usage")) {
dumpUsage(pw, indent, now, header);
} else {
throw new IllegalArgumentException("unrecognized choice: " + what);
}
}
/**
* Report the object via an event. Presumably the record indicates an anomalous
* incident.
*/
private void report() {
EventLogTags.writePmSnapshotStats(
mTotalBuilds, mTotalUsed, mBigBuilds, mShortLived,
mMaxBuildTimeUs / US_IN_MS, mTotalTimeUs / US_IN_MS);
}
}
/**
* Long statistics. These roll over approximately every week.
*/
private Stats[] mLong;
/**
* Short statistics. These roll over approximately every minute;
*/
private Stats[] mShort;
/**
* The time of the last build. This can be used to compute the length of time a
* snapshot existed before being replaced.
*/
private long mLastBuildTime = 0;
/**
* Create a snapshot object. Initialize the bin levels. The last bin catches
* everything that is not caught earlier, so its value is not really important.
*/
public SnapshotStatistics() {
// Create the bin thresholds. The time bins are in units of us.
mTimeBins = new BinMap(new int[] { 1, 2, 5, 10, 20, 50, 100 });
mUseBins = new BinMap(new int[] { 1, 2, 5, 10, 20, 50, 100 });
// Create the raw statistics
final long now = SystemClock.currentTimeMicro();
mLong = new Stats[2];
mLong[0] = new Stats(now);
mShort = new Stats[10];
mShort[0] = new Stats(now);
// Create the message handler for ticks and start the ticker.
mHandler = new Handler(Looper.getMainLooper()) {
@Override
public void handleMessage(Message msg) {
SnapshotStatistics.this.handleMessage(msg);
}
};
scheduleTick();
}
/**
* Handle a message. The only messages are ticks, so the message parameter is ignored.
*/
private void handleMessage(@Nullable Message msg) {
tick();
scheduleTick();
}
/**
* Schedule one tick, a tick interval in the future.
*/
private void scheduleTick() {
mHandler.sendEmptyMessageDelayed(0, SNAPSHOT_TICK_INTERVAL_MS);
}
/**
* Record a rebuild. Cumulative and current statistics are updated. Events may be
* generated.
* @param now The time at which the snapshot rebuild began, in ns.
* @param done The time at which the snapshot rebuild completed, in ns.
* @param hits The number of times the previous snapshot was used.
*/
public void rebuild(long now, long done, int hits) {
// The duration has a span of about 2000s
final int duration = (int) (done - now);
boolean reportEvent = false;
synchronized (mLock) {
mLastBuildTime = now;
final int timeBin = mTimeBins.getBin(duration / 1000);
final int useBin = mUseBins.getBin(hits);
final boolean big = duration >= SNAPSHOT_BIG_BUILD_TIME_US;
final boolean quick = hits <= SNAPSHOT_SHORT_LIFETIME;
mShort[0].rebuild(duration, hits, timeBin, useBin, big, quick);
mLong[0].rebuild(duration, hits, timeBin, useBin, big, quick);
if (duration >= SNAPSHOT_REPORTABLE_BUILD_TIME_US) {
if (mEventsReported++ < SNAPSHOT_BUILD_REPORT_LIMIT) {
reportEvent = true;
}
}
}
// The IO to the logger is done outside the lock.
if (reportEvent) {
// Report the first N big builds, and every new maximum after that.
EventLogTags.writePmSnapshotRebuild(duration / US_IN_MS, hits);
}
}
/**
* Roll a stats array. Shift the elements up an index and create a new element at
* index zero. The old element zero is completed with the specified time.
*/
private void shift(Stats[] s, long now) {
s[0].complete(now);
for (int i = s.length - 1; i > 0; i--) {
s[i] = s[i - 1];
}
s[0] = new Stats(now);
}
/**
* Roll the statistics.
* <ul>
* <li> Roll the quick statistics immediately.
* <li> Roll the long statistics every SNAPSHOT_LONG_TICKER ticks. The long
* statistics hold a week's worth of data.
* <li> Roll the logging statistics every SNAPSHOT_LOGGING_TICKER ticks. The logging
* statistics hold 10 minutes worth of data.
* </ul>
*/
private void tick() {
synchronized (mLock) {
long now = SystemClock.currentTimeMicro();
mTicks++;
if (mTicks % SNAPSHOT_LONG_TICKS == 0) {
shift(mLong, now);
}
shift(mShort, now);
mEventsReported = 0;
}
}
/**
* Dump the statistics. The header is dumped from l[0], so that must not be null.
*/
private void dump(PrintWriter pw, String indent, long now, Stats[] l, Stats[] s, String what) {
l[0].dump(pw, indent, now, true, what);
for (int i = 0; i < s.length; i++) {
if (s[i] != null) {
s[i].dump(pw, indent, now, false, what);
}
}
for (int i = 0; i < l.length; i++) {
if (l[i] != null) {
l[i].dump(pw, indent, now, false, what);
}
}
}
/**
* Dump the statistics. The format is compatible with the PackageManager dumpsys
* output.
*/
public void dump(PrintWriter pw, String indent, long now, int unrecorded, boolean full) {
// Grab the raw statistics under lock, but print them outside of the lock.
Stats[] l;
Stats[] s;
synchronized (mLock) {
l = Arrays.copyOf(mLong, mLong.length);
l[0] = new Stats(l[0]);
s = Arrays.copyOf(mShort, mShort.length);
s[0] = new Stats(s[0]);
}
pw.format(Locale.US, "%s Unrecorded hits %d", indent, unrecorded);
pw.println();
dump(pw, indent, now, l, s, "stats");
if (!full) {
return;
}
pw.println();
dump(pw, indent, now, l, s, "times");
pw.println();
dump(pw, indent, now, l, s, "usage");
}
}