diff --git a/services/core/java/com/android/server/EventLogTags.logtags b/services/core/java/com/android/server/EventLogTags.logtags index 9f91dd6b982b6..483250ad22577 100644 --- a/services/core/java/com/android/server/EventLogTags.logtags +++ b/services/core/java/com/android/server/EventLogTags.logtags @@ -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 diff --git a/services/core/java/com/android/server/pm/DumpState.java b/services/core/java/com/android/server/pm/DumpState.java index 6875b8a5abeb4..ec79483e0f34b 100644 --- a/services/core/java/com/android/server/pm/DumpState.java +++ b/services/core/java/com/android/server/pm/DumpState.java @@ -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; diff --git a/services/core/java/com/android/server/pm/PackageManagerService.java b/services/core/java/com/android/server/pm/PackageManagerService.java index 85c5a5ea84b8b..59039baf2764a 100644 --- a/services/core/java/com/android/server/pm/PackageManagerService.java +++ b/services/core/java/com/android/server/pm/PackageManagerService.java @@ -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 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 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(" : 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); + } + } } /** diff --git a/services/core/java/com/android/server/pm/SnapshotStatistics.java b/services/core/java/com/android/server/pm/SnapshotStatistics.java new file mode 100644 index 0000000000000..c425bad50ae87 --- /dev/null +++ b/services/core/java/com/android/server/pm/SnapshotStatistics.java @@ -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: + *
    + *
  • The time to create a snapshot - this is the performance cost of a snapshot + *
  • The lifetime of the snapshot - creation time over lifetime is the amortized cost + *
  • The number of times a snapshot is reused - this is the number of times lock + * contention was avoided. + *
+ + * 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. + *
    + *
  • Roll the quick statistics immediately. + *
  • Roll the long statistics every SNAPSHOT_LONG_TICKER ticks. The long + * statistics hold a week's worth of data. + *
  • Roll the logging statistics every SNAPSHOT_LOGGING_TICKER ticks. The logging + * statistics hold 10 minutes worth of data. + *
+ */ + 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"); + } +}