Merge "PackageManagerService snapshot: statistics" into sc-dev

# 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

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

    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

    }

    /**

     * A computer provides the functional interface to the cache

     * A computer provides the functional interface to the snapshot.

     */

    private interface Computer {

        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;

    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;

     */

    private final Object mSnapshotLock = new Object();

    // A counter of all queries that hit the cache.

    private AtomicInteger mSnapshotHits = new AtomicInteger(0);

    // A counter of all queries that hit the current snapshot.

    @GuardedBy("mSnapshotLock")

    private int mSnapshotHits = 0;

    // A class to record snapshot statistics.

    private static class SnapshotStatistics {

        // A build time is "big" if it takes longer than 5ms.

        private static final long SNAPSHOT_BIG_BUILD_TIME_NS = TimeUnit.MILLISECONDS.toNanos(5);

        // A snapshot is in quick succession to the previous snapshot if it less than

        // 100ms since the previous snapshot.

        private static final long SNAPSHOT_QUICK_REBUILD_INTERVAL_NS =

                TimeUnit.MILLISECONDS.toNanos(100);

        // The interval between snapshot statistics logging, in ns.

        private static final long SNAPSHOT_LOG_INTERVAL_NS = TimeUnit.MINUTES.toNanos(10);

        // The throttle parameters for big build reporting.  Do not report more than this

        // many events in a single log interval.

        private static final int SNAPSHOT_BUILD_REPORT_LIMIT = 10;

        // The time the snapshot statistics were last logged.

        private long mStatisticsSent = 0;

        // The number of build events logged since the last periodic log.

        private int mLoggedBuilds = 0;

        // The time of the last build.

        private long mLastBuildTime = 0;

        // The number of times the snapshot has been rebuilt since the statistics were

        // last logged.

        private int mRebuilds = 0;

        // The number of times the snapshot has been used since it was rebuilt.

        private int mReused = 0;

        // The number of "big" build times since the last log.  "Big" is defined by

        // SNAPSHOT_BIG_BUILD_TIME.

        private int mBigBuilds = 0;

        // The number of quick rebuilds.  "Quick" is defined by

        // SNAPSHOT_QUICK_REBUILD_INTERVAL_NS.

        private int mQuickRebuilds = 0;

        // The time take to build a snapshot.  This is cumulative over the rebuilds recorded

        // in mRebuilds, so the average time to build a snapshot is given by

        // mBuildTimeNs/mRebuilds.

        private int mBuildTimeNs = 0;

        // The maximum build time since the last log.

        private long mMaxBuildTimeNs = 0;

        // The constant that converts ns to ms.  This is the divisor.

        private final long NS_TO_MS = TimeUnit.MILLISECONDS.toNanos(1);

    // The number of queries at the last miss.  This is updated when the cache is rebuilt

    // (guarded by mLock) and is used to report the hit run-length.

        // Convert ns to an int ms.  The maximum range of this method is about 24 days.

        // There is no expectation that an event will take longer than that.

        private int nsToMs(long ns) {

            return (int) (ns / NS_TO_MS);

        }

        // The single method records a rebuild.  The "now" parameter is passed in because

        // the caller needed it to computer the duration, so pass it in to avoid

        // recomputing it.

        private void rebuild(long now, long done, int hits) {

            if (mStatisticsSent == 0) {

                mStatisticsSent = now;

            }

            final long elapsed = now - mLastBuildTime;

            final long duration = done - now;

            mLastBuildTime = now;

            if (mMaxBuildTimeNs < duration) {

                mMaxBuildTimeNs = duration;

            }

            mRebuilds++;

            mReused += hits;

            mBuildTimeNs += duration;

            boolean log_build = false;

            if (duration > SNAPSHOT_BIG_BUILD_TIME_NS) {

                log_build = true;

                mBigBuilds++;

            }

            if (elapsed < SNAPSHOT_QUICK_REBUILD_INTERVAL_NS) {

                log_build = true;

                mQuickRebuilds++;

            }

            if (log_build && mLoggedBuilds < SNAPSHOT_BUILD_REPORT_LIMIT) {

                EventLogTags.writePmSnapshotRebuild(nsToMs(duration), nsToMs(elapsed));

                mLoggedBuilds++;

            }

            final long log_interval = now - mStatisticsSent;

            if (log_interval >= SNAPSHOT_LOG_INTERVAL_NS) {

                EventLogTags.writePmSnapshotStats(mRebuilds, mReused,

                                                  mBigBuilds, mQuickRebuilds,

                                                  nsToMs(mMaxBuildTimeNs),

                                                  nsToMs(mBuildTimeNs));

                mStatisticsSent = now;

                mRebuilds = 0;

                mReused = 0;

                mBuildTimeNs = 0;

                mMaxBuildTimeNs = 0;

                mBigBuilds = 0;

                mQuickRebuilds = 0;

                mLoggedBuilds = 0;

            }

        }

    }

    // Snapshot statistics.

    @GuardedBy("mLock")

    private int mSnapshotRebuilt = 0;

    private final SnapshotStatistics mSnapshotStatistics = new SnapshotStatistics();

    // The snapshot disable/enable switch.  An image with the flag set true uses snapshots

    // and an image with the flag set false does not use snapshots.

            // 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().

    }

    /**

     * 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;

    }

    /**

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

    }