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

Merge "Improve PackageManager snapshot statistics" into sc-dev

Browse Source
This commit is contained in:
TreeHugger Robot
2021-04-15 17:48:29 +00:00
committed by Android (Google) Code Review
parent 14af8e97dd 6e67ca77fb
commit e6c98e887c
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");
}
}