From f168f2737eb555caa95f7a3727084c465e9fb5d9 Mon Sep 17 00:00:00 2001 From: Lee Shombert Date: Fri, 24 Jul 2020 15:53:07 -0700 Subject: [PATCH] Enhance PropertyInvalidatedCache debugging Bug: 162103383 Update 'dumpsys cacheinfo': add the number times a cache is cleared, rename misses due to cache disabled/unset/corked to "skips", and fix the logic counting cache invalidates. Make the cache name distinct from the property. There is no change to legacy caches (which continue to use the property as the name) but caches that share the cache_key.package_info property now have distinct names. Add the property name to auto-corker debug messages. Test: Boot and run 'dumpsys cacheinfo' to verify the output. Change-Id: I3e3e500dc9a1559fd7ccdc49fb00292ab5f712c1 --- .../android/app/PropertyInvalidatedCache.java | 65 ++++++++++++++----- .../android/content/pm/PackageManager.java | 6 +- .../android/permission/PermissionManager.java | 4 +- 3 files changed, 55 insertions(+), 20 deletions(-) diff --git a/core/java/android/app/PropertyInvalidatedCache.java b/core/java/android/app/PropertyInvalidatedCache.java index bca6f39e1dedd..54f3f10260501 100644 --- a/core/java/android/app/PropertyInvalidatedCache.java +++ b/core/java/android/app/PropertyInvalidatedCache.java @@ -215,7 +215,7 @@ public abstract class PropertyInvalidatedCache { private long mMisses = 0; @GuardedBy("mLock") - private long mMissDisabled[] = new long[]{ 0, 0, 0 }; + private long mSkips[] = new long[]{ 0, 0, 0 }; @GuardedBy("mLock") private long mMissOverflow = 0; @@ -223,6 +223,9 @@ public abstract class PropertyInvalidatedCache { @GuardedBy("mLock") private long mHighWaterMark = 0; + @GuardedBy("mLock") + private long mClears = 0; + // Most invalidation is done in a static context, so the counters need to be accessible. @GuardedBy("sCorkLock") private static final HashMap sInvalidates = new HashMap<>(); @@ -273,6 +276,13 @@ public abstract class PropertyInvalidatedCache { */ private volatile SystemProperties.Handle mPropertyHandle; + /** + * The name by which this cache is known. This should normally be the + * binder call that is being cached, but the constructors default it to + * the property name. + */ + private final String mCacheName; + @GuardedBy("mLock") private final LinkedHashMap mCache; @@ -297,9 +307,23 @@ public abstract class PropertyInvalidatedCache { * * @param maxEntries Maximum number of entries to cache; LRU discard * @param propertyName Name of the system property holding the cache invalidation nonce + * Defaults the cache name to the property name. */ public PropertyInvalidatedCache(int maxEntries, @NonNull String propertyName) { + this(maxEntries, propertyName, propertyName); + } + + /** + * Make a new property invalidated cache. + * + * @param maxEntries Maximum number of entries to cache; LRU discard + * @param propertyName Name of the system property holding the cache invalidation nonce + * @param cacheName Name of this cache in debug and dumpsys + */ + public PropertyInvalidatedCache(int maxEntries, @NonNull String propertyName, + @NonNull String cacheName) { mPropertyName = propertyName; + mCacheName = cacheName; mMaxEntries = maxEntries; mCache = new LinkedHashMap( 2 /* start small */, @@ -320,7 +344,6 @@ public abstract class PropertyInvalidatedCache { }; synchronized (sCorkLock) { sCaches.put(this, null); - sInvalidates.put(propertyName, (long) 0); } } @@ -333,6 +356,7 @@ public abstract class PropertyInvalidatedCache { Log.d(TAG, "clearing cache for " + mPropertyName); } mCache.clear(); + mClears++; } } @@ -413,7 +437,7 @@ public abstract class PropertyInvalidatedCache { // Do not bother collecting statistics if the cache is // locally disabled. synchronized (mLock) { - mMissDisabled[(int) currentNonce]++; + mSkips[(int) currentNonce]++; } } @@ -742,12 +766,16 @@ public abstract class PropertyInvalidatedCache { boolean alreadyQueued = mUncorkDeadlineMs >= 0; if (DEBUG) { Log.w(TAG, String.format( - "autoCork mUncorkDeadlineMs=%s", mUncorkDeadlineMs)); + "autoCork %s mUncorkDeadlineMs=%s", mPropertyName, + mUncorkDeadlineMs)); } mUncorkDeadlineMs = SystemClock.uptimeMillis() + mAutoCorkDelayMs; if (!alreadyQueued) { getHandlerLocked().sendEmptyMessageAtTime(0, mUncorkDeadlineMs); PropertyInvalidatedCache.corkInvalidations(mPropertyName); + } else { + final long count = sCorkedInvalidates.getOrDefault(mPropertyName, (long) 0); + sCorkedInvalidates.put(mPropertyName, count + 1); } } } @@ -756,7 +784,8 @@ public abstract class PropertyInvalidatedCache { synchronized (mLock) { if (DEBUG) { Log.w(TAG, String.format( - "handleMsesage mUncorkDeadlineMs=%s", mUncorkDeadlineMs)); + "handleMsesage %s mUncorkDeadlineMs=%s", + mPropertyName, mUncorkDeadlineMs)); } if (mUncorkDeadlineMs < 0) { @@ -816,7 +845,7 @@ public abstract class PropertyInvalidatedCache { * method is public so clients can use it. */ public String cacheName() { - return mPropertyName; + return mCacheName; } /** @@ -864,16 +893,20 @@ public abstract class PropertyInvalidatedCache { } synchronized (mLock) { - pw.println(String.format(" Cache Property Name: %s", cacheName())); - 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, HW Mark: %d", - mCache.size(), mMaxEntries, mHighWaterMark)); + pw.println(String.format(" Cache Name: %s", cacheName())); + pw.println(String.format(" Property: %s", mPropertyName)); + final long skips = mSkips[NONCE_CORKED] + mSkips[NONCE_UNSET] + mSkips[NONCE_DISABLED]; + pw.println(String.format(" Hits: %d, Misses: %d, Skips: %d, Clears: %d", + mHits, mMisses, skips, mClears)); + pw.println(String.format(" Skip-corked: %d, Skip-unset: %d, Skip-other: %d", + mSkips[NONCE_CORKED], mSkips[NONCE_UNSET], + mSkips[NONCE_DISABLED])); + pw.println(String.format( + " Nonce: 0x%016x, Invalidates: %d, CorkedInvalidates: %d", + mLastSeenNonce, invalidateCount, corkedInvalidates)); + pw.println(String.format( + " Current Size: %d, Max Size: %d, HW Mark: %d, Overflows: %d", + mCache.size(), mMaxEntries, mHighWaterMark, mMissOverflow)); pw.println(String.format(" Enabled: %s", mDisabled ? "false" : "true")); Set> cacheEntries = mCache.entrySet(); diff --git a/core/java/android/content/pm/PackageManager.java b/core/java/android/content/pm/PackageManager.java index 9c7dc9610522f..856642994734b 100644 --- a/core/java/android/content/pm/PackageManager.java +++ b/core/java/android/content/pm/PackageManager.java @@ -8078,7 +8078,8 @@ public abstract class PackageManager { private static final PropertyInvalidatedCache sApplicationInfoCache = new PropertyInvalidatedCache( - 16, PermissionManager.CACHE_KEY_PACKAGE_INFO) { + 16, PermissionManager.CACHE_KEY_PACKAGE_INFO, + "getApplicationInfo") { @Override protected ApplicationInfo recompute(ApplicationInfoQuery query) { return getApplicationInfoAsUserUncached( @@ -8179,7 +8180,8 @@ public abstract class PackageManager { private static final PropertyInvalidatedCache sPackageInfoCache = new PropertyInvalidatedCache( - 32, PermissionManager.CACHE_KEY_PACKAGE_INFO) { + 32, PermissionManager.CACHE_KEY_PACKAGE_INFO, + "getPackageInfo") { @Override protected PackageInfo recompute(PackageInfoQuery query) { return getPackageInfoAsUserUncached( diff --git a/core/java/android/permission/PermissionManager.java b/core/java/android/permission/PermissionManager.java index bf3d46fa4a449..0c190719af570 100644 --- a/core/java/android/permission/PermissionManager.java +++ b/core/java/android/permission/PermissionManager.java @@ -608,7 +608,7 @@ public final class PermissionManager { /** @hide */ private static final PropertyInvalidatedCache sPermissionCache = new PropertyInvalidatedCache( - 16, CACHE_KEY_PACKAGE_INFO) { + 16, CACHE_KEY_PACKAGE_INFO, "checkPermission") { @Override protected Integer recompute(PermissionQuery query) { return checkPermissionUncached(query.permission, query.pid, query.uid); @@ -689,7 +689,7 @@ public final class PermissionManager { private static PropertyInvalidatedCache sPackageNamePermissionCache = new PropertyInvalidatedCache( - 16, CACHE_KEY_PACKAGE_INFO) { + 16, CACHE_KEY_PACKAGE_INFO, "checkPackageNamePermission") { @Override protected Integer recompute(PackageNamePermissionQuery query) { return checkPackageNamePermissionUncached(