Donate to e Foundation | Murena handsets with /e/OS | Own a part of Murena! Learn more

Commit e2fbc3b8 authored by Lee Shombert's avatar Lee Shombert
Browse files

Enhance PropertyInvalidatedCache debug 

Bug: 159039903

A set of small changes to the class to allow for addition debugging.
1. Distinguish a cache that is disabled because the nonce has not
   set from a cache that is disabled because it is corked.
2. Count the times the cache was bypassed because it was corked, unset,
   or disabled.  This does not count the times the cache was bypassed
   because it was locally disabled.  Add these counts to dumpsys.
3. Count the number of times a cache is invalidated, corked, and
   recorked (corked while already corked).  Add these counts to dumpsys.
4. Log some additional information if cache inconsistency is detected.
5. Record cache overflows and cache high-water marks.

Test: Run the following tests with and without the changes.  Verify that
the changes do not affect behavior.
 * CtsContactsProviderTestCases
 * FrameworksServicesTests
 * FrameworksServicesTests:UserManagerServiceCreateProfileTest
 * PlatformScenarioTests
 * PtsChreTestCases
 * FrameworksServicesTests:UserManagerServiceUserInfoTest
 * FrameworksServicesTests:UserManagerServiceIdRecyclingTest
 * CtsProviderTestCases
 * FrameworksServicesTests:UserSystemPackageInstallerTest
 * FrameworksServicesTests:PackageManagerSettingsTests
 * FrameworksServicesTests:UserLifecycleTests
 * CtsCalendarProviderTestCases
 * BluetoothInstrumentationTests
Pull a bug report and verify that the new counters are included.

Change-Id: I38d5545947d6f09c7e62e094c7b2858aab4a8cf9
parent 97683bf1

core/java/android/app/PropertyInvalidatedCache.java

+99 −21
Original line number Diff line number Diff line
@@ -175,14 +175,33 @@ import java.util.concurrent.atomic.AtomicLong; 
 *

 * Caching can be disabled completely by initializing {@code sEnabled} to false and rebuilding.

 *

 * To test a binder cache, create one or more tests that exercise the binder method.  This

 * should be done twice: once with production code and once with a special image that sets

 * {@code DEBUG} and {@code VERIFY} true.  In the latter case, verify that no cache

 * inconsistencies are reported.  If a cache inconsistency is reported, however, it might be a

 * false positive.  This happens if the server side data can be read and written non-atomically

 * with respect to cache invalidation.

 *

 * @param <Query> The class used to index cache entries: must be hashable and comparable

 * @param <Result> The class holding cache entries; use a boxed primitive if possible

 *

 * {@hide}

 */

public abstract class PropertyInvalidatedCache<Query, Result> {

    private static final long NONCE_UNSET = 0;

    private static final long NONCE_DISABLED = -1;

    /**

     * Reserved nonce values.  The code is written assuming that these

     * values are contiguous.

     */

    private static final int NONCE_UNSET = 0;

    private static final int NONCE_DISABLED = 1;

    private static final int NONCE_CORKED = 2;

    private static final int NONCE_RESERVED = NONCE_CORKED + 1;



    /**

     * The names of the nonces

     */

    private static final String[] sNonceName =

            new String[]{ "unset", "disabled", "corked" };



    private static final String TAG = "PropertyInvalidatedCache";

    private static final boolean DEBUG = false;
@@ -195,10 +214,27 @@ public abstract class PropertyInvalidatedCache<Query, Result> { 
    @GuardedBy("mLock")

    private long mMisses = 0;



    @GuardedBy("mLock")

    private long mMissDisabled[] = new long[]{ 0, 0, 0 };



    @GuardedBy("mLock")

    private long mMissOverflow = 0;



    @GuardedBy("mLock")

    private long mHighWaterMark = 0;



    // Most invalidation is done in a static context, so the counters need to be accessible.

    @GuardedBy("sCorkLock")

    private static final HashMap<String, Long> sInvalidates = new HashMap<>();



    /**

     * Record the number of invalidate or cork calls that were nops because

     * the cache was already corked.  This is static because invalidation is

     * done in a static context.

     */

    @GuardedBy("sCorkLock")

    private static final HashMap<String, Long> sCorkedInvalidates = new HashMap<>();



    /**

     * If sEnabled is false then all cache operations are stubbed out.  Set

     * it to false inside test processes.
@@ -271,7 +307,15 @@ public abstract class PropertyInvalidatedCache<Query, Result> { 
            true /* LRU access order */) {

                @Override

                protected boolean removeEldestEntry(Map.Entry eldest) {

                    return size() > maxEntries;

                    final int size = size();

                    if (size > mHighWaterMark) {

                        mHighWaterMark = size;

                    }

                    if (size > maxEntries) {

                        mMissOverflow++;

                        return true;

                    }

                    return false;

                }

            };

        synchronized (sCorkLock) {
@@ -363,14 +407,21 @@ public abstract class PropertyInvalidatedCache<Query, Result> { 
        // Let access to mDisabled race: it's atomic anyway.

        long currentNonce = (!isDisabledLocal()) ? getCurrentNonce() : NONCE_DISABLED;

        for (;;) {

            if (currentNonce == NONCE_DISABLED || currentNonce == NONCE_UNSET) {

            if (currentNonce == NONCE_DISABLED || currentNonce == NONCE_UNSET ||

                currentNonce == NONCE_CORKED) {

                if (!mDisabled) {

                    // Do not bother collecting statistics if the cache is

                    // locally disabled.

                    synchronized (mLock) {

                        mMissDisabled[(int) currentNonce]++;

                    }

                }



                if (DEBUG) {

                    if (!mDisabled) {

                        Log.d(TAG, String.format(

                            "cache %s %s for %s",

                            cacheName(),

                            currentNonce == NONCE_DISABLED ? "disabled" : "unset",

                            queryToString(query)));

                            cacheName(), sNonceName[(int) currentNonce], queryToString(query)));

                    }

                }

                return recompute(query);
@@ -383,9 +434,9 @@ public abstract class PropertyInvalidatedCache<Query, Result> { 
                    if (cachedResult != null) mHits++;

                } else {

                    if (DEBUG) {

                        Log.d(TAG,

                                String.format("clearing cache %s because nonce changed [%s] -> [%s]",

                                        cacheName(),

                        Log.d(TAG, String.format(

                            "clearing cache %s of %d entries because nonce changed [%s] -> [%s]",

                            cacheName(), mCache.size(),

                            mLastSeenNonce, currentNonce));

                    }

                    mCache.clear();
@@ -517,6 +568,8 @@ public abstract class PropertyInvalidatedCache<Query, Result> { 
                if (DEBUG) {

                    Log.d(TAG, "ignoring invalidation due to cork: " + name);

                }

                final long count = sCorkedInvalidates.getOrDefault(name, (long) 0);

                sCorkedInvalidates.put(name, count + 1);

                return;

            }

            invalidateCacheLocked(name);
@@ -538,7 +591,7 @@ public abstract class PropertyInvalidatedCache<Query, Result> { 
        long newValue;

        do {

            newValue = NoPreloadHolder.next();

        } while (newValue == NONCE_UNSET || newValue == NONCE_DISABLED);

        } while (newValue >= 0 && newValue < NONCE_RESERVED);

        final String newValueString = Long.toString(newValue);

        if (DEBUG) {

            Log.d(TAG,
@@ -567,13 +620,21 @@ public abstract class PropertyInvalidatedCache<Query, Result> { 
     * @param name Name of the cache-key property to cork

     */

    public static void corkInvalidations(@NonNull String name) {

        if (!sEnabled) {

            if (DEBUG) {

                Log.w(TAG, String.format(

                    "cache cork %s suppressed", name));

            }

            return;

        }



        synchronized (sCorkLock) {

            int numberCorks = sCorks.getOrDefault(name, 0);

            if (DEBUG) {

                Log.d(TAG, String.format("corking %s: numberCorks=%s", name, numberCorks));

            }



            // If we're the first ones to cork this cache, set the cache to the unset state so

            // If we're the first ones to cork this cache, set the cache to the corked state so

            // existing caches talk directly to their services while we've corked updates.

            // Make sure we don't clobber a disabled cache value.
@@ -584,8 +645,11 @@ public abstract class PropertyInvalidatedCache<Query, Result> { 
            if (numberCorks == 0) {

                final long nonce = SystemProperties.getLong(name, NONCE_UNSET);

                if (nonce != NONCE_UNSET && nonce != NONCE_DISABLED) {

                    SystemProperties.set(name, Long.toString(NONCE_UNSET));

                    SystemProperties.set(name, Long.toString(NONCE_CORKED));

                }

            } else {

                final long count = sCorkedInvalidates.getOrDefault(name, (long) 0);

                sCorkedInvalidates.put(name, count + 1);

            }

            sCorks.put(name, numberCorks + 1);

            if (DEBUG) {
@@ -602,6 +666,14 @@ public abstract class PropertyInvalidatedCache<Query, Result> { 
     * @param name Name of the cache-key property to uncork

     */

    public static void uncorkInvalidations(@NonNull String name) {

        if (!sEnabled) {

            if (DEBUG) {

                Log.w(TAG, String.format(

                    "cache uncork %s suppressed", name));

            }

            return;

        }



        synchronized (sCorkLock) {

            int numberCorks = sCorks.getOrDefault(name, 0);

            if (DEBUG) {
@@ -729,8 +801,9 @@ public abstract class PropertyInvalidatedCache<Query, Result> { 
            boolean nonceChanged = (getCurrentNonce() != mLastSeenNonce);

            if (!nonceChanged && !debugCompareQueryResults(proposedResult, resultToCompare)) {

                Log.e(TAG, String.format(

                    "cache %s inconsistent for %s",

                    cacheName(), queryToString(query)));

                    "cache %s inconsistent for %s is %s should be %s",

                    cacheName(), queryToString(query),

                    proposedResult, resultToCompare));

            }

            // Always return the "true" result in verification mode.

            return resultToCompare;
@@ -784,18 +857,23 @@ public abstract class PropertyInvalidatedCache<Query, Result> { 


    private void dumpContents(PrintWriter pw, String[] args) {

        long invalidateCount;



        long corkedInvalidates;

        synchronized (sCorkLock) {

            invalidateCount = sInvalidates.getOrDefault(mPropertyName, (long) 0);

            corkedInvalidates = sCorkedInvalidates.getOrDefault(mPropertyName, (long) 0);

        }



        synchronized (mLock) {

            pw.println(String.format("  Cache Property Name: %s", cacheName()));

            pw.println(String.format("    Hits: %d, Misses: %d, Invalidates: %d",

                    mHits, mMisses, invalidateCount));

            pw.println(String.format("    Hits: %d, Misses: %d, Invalidates: %d, Overflows: %d",

                    mHits, mMisses, invalidateCount, mMissOverflow));

            pw.println(String.format("    Miss-corked: %d, Miss-unset: %d, Miss-other: %d," +

                    " CorkedInvalidates: %d",

                    mMissDisabled[NONCE_CORKED], mMissDisabled[NONCE_UNSET],

                    mMissDisabled[NONCE_DISABLED], corkedInvalidates));

            pw.println(String.format("    Last Observed Nonce: %d", mLastSeenNonce));

            pw.println(String.format("    Current Size: %d, Max Size: %d",

                    mCache.entrySet().size(), mMaxEntries));

            pw.println(String.format("    Current Size: %d, Max Size: %d, HW Mark: %d",

                    mCache.size(), mMaxEntries, mHighWaterMark));

            pw.println(String.format("    Enabled: %s", mDisabled ? "false" : "true"));



            Set<Map.Entry<Query, Result>> cacheEntries = mCache.entrySet();