From 3a95c180c7fdf89251023d8e580d30e7a5daccbc Mon Sep 17 00:00:00 2001 From: Xiaoyu Jin Date: Sun, 9 May 2021 14:15:50 -0700 Subject: [PATCH] Log InitializeStats in the platform Bug: b/173532925 Test: atest CtsAppSearchTestCases FrameworksCoreTests:android.app.appsearch FrameworksServicesTests:AppSearchImplTest FrameworksServicesTests:com.android.server.appsearch.stats.PlatformLoggerTest Change-Id: Ib2f1b13addbd8ec2fe95db38313b870672370910 --- .../app/appsearch/AppSearchSession.java | 25 ++++--- .../app/appsearch/GlobalSearchSession.java | 26 ++++--- .../app/appsearch/aidl/IAppSearchManager.aidl | 6 +- .../appsearch/AppSearchManagerService.java | 68 +++++++++++++++---- .../server/appsearch/ImplInstanceManager.java | 22 +++--- .../appsearch/stats/PlatformLogger.java | 48 ++++++++++++- .../server/pm/BaseShortcutManagerTest.java | 3 +- 7 files changed, 149 insertions(+), 49 deletions(-) diff --git a/apex/appsearch/framework/java/android/app/appsearch/AppSearchSession.java b/apex/appsearch/framework/java/android/app/appsearch/AppSearchSession.java index 5910130e6069e..a7fcbfab1dc26 100644 --- a/apex/appsearch/framework/java/android/app/appsearch/AppSearchSession.java +++ b/apex/appsearch/framework/java/android/app/appsearch/AppSearchSession.java @@ -90,17 +90,20 @@ public final class AppSearchSession implements Closeable { @NonNull @CallbackExecutor Executor executor, @NonNull Consumer> callback) { try { - mService.initialize(mUserId, new IAppSearchResultCallback.Stub() { - @Override - public void onResult(AppSearchResultParcel resultParcel) { - executor.execute(() -> { - AppSearchResult result = resultParcel.getResult(); - if (result.isSuccess()) { - callback.accept( - AppSearchResult.newSuccessfulResult(AppSearchSession.this)); - } else { - callback.accept(AppSearchResult.newFailedResult(result)); - } + mService.initialize(mUserId, + /*binderCallStartTimeMillis=*/ SystemClock.elapsedRealtime(), + new IAppSearchResultCallback.Stub() { + @Override + public void onResult(AppSearchResultParcel resultParcel) { + executor.execute(() -> { + AppSearchResult result = resultParcel.getResult(); + if (result.isSuccess()) { + callback.accept( + AppSearchResult.newSuccessfulResult( + AppSearchSession.this)); + } else { + callback.accept(AppSearchResult.newFailedResult(result)); + } }); } }); diff --git a/apex/appsearch/framework/java/android/app/appsearch/GlobalSearchSession.java b/apex/appsearch/framework/java/android/app/appsearch/GlobalSearchSession.java index 7d246c20251be..7cbdcbdbe0f2d 100644 --- a/apex/appsearch/framework/java/android/app/appsearch/GlobalSearchSession.java +++ b/apex/appsearch/framework/java/android/app/appsearch/GlobalSearchSession.java @@ -23,6 +23,7 @@ import android.app.appsearch.aidl.AppSearchResultParcel; import android.app.appsearch.aidl.IAppSearchManager; import android.app.appsearch.aidl.IAppSearchResultCallback; import android.os.RemoteException; +import android.os.SystemClock; import android.util.Log; import com.android.internal.util.Preconditions; @@ -72,17 +73,20 @@ public class GlobalSearchSession implements Closeable { @NonNull @CallbackExecutor Executor executor, @NonNull Consumer> callback) { try { - mService.initialize(mUserId, new IAppSearchResultCallback.Stub() { - @Override - public void onResult(AppSearchResultParcel resultParcel) { - executor.execute(() -> { - AppSearchResult result = resultParcel.getResult(); - if (result.isSuccess()) { - callback.accept( - AppSearchResult.newSuccessfulResult(GlobalSearchSession.this)); - } else { - callback.accept(AppSearchResult.newFailedResult(result)); - } + mService.initialize(mUserId, + /*binderCallStartTimeMillis=*/ SystemClock.elapsedRealtime(), + new IAppSearchResultCallback.Stub() { + @Override + public void onResult(AppSearchResultParcel resultParcel) { + executor.execute(() -> { + AppSearchResult result = resultParcel.getResult(); + if (result.isSuccess()) { + callback.accept( + AppSearchResult.newSuccessfulResult( + GlobalSearchSession.this)); + } else { + callback.accept(AppSearchResult.newFailedResult(result)); + } }); } }); diff --git a/apex/appsearch/framework/java/android/app/appsearch/aidl/IAppSearchManager.aidl b/apex/appsearch/framework/java/android/app/appsearch/aidl/IAppSearchManager.aidl index 6f7e82e8126c9..c54bf86b72324 100644 --- a/apex/appsearch/framework/java/android/app/appsearch/aidl/IAppSearchManager.aidl +++ b/apex/appsearch/framework/java/android/app/appsearch/aidl/IAppSearchManager.aidl @@ -331,8 +331,12 @@ interface IAppSearchManager { * Creates and initializes AppSearchImpl for the calling app. * * @param userId Id of the calling user + * @param binderCallStartTimeMillis start timestamp of binder call in Millis * @param callback {@link IAppSearchResultCallback#onResult} will be called with an * {@link AppSearchResult}<{@link Void}>. */ - void initialize(in int userId, in IAppSearchResultCallback callback); + void initialize( + in int userId, + in long binderCallStartTimeMillis, + in IAppSearchResultCallback callback); } diff --git a/apex/appsearch/service/java/com/android/server/appsearch/AppSearchManagerService.java b/apex/appsearch/service/java/com/android/server/appsearch/AppSearchManagerService.java index 777f9fe00bcad..c80c775aed0ed 100644 --- a/apex/appsearch/service/java/com/android/server/appsearch/AppSearchManagerService.java +++ b/apex/appsearch/service/java/com/android/server/appsearch/AppSearchManagerService.java @@ -217,10 +217,13 @@ public class AppSearchManagerService extends SystemService { } if (ImplInstanceManager.getAppSearchDir(userId).exists()) { // Only clear the package's data if AppSearch exists for this user. - AppSearchImpl impl = mImplInstanceManager.getOrCreateAppSearchImpl(mContext, + PlatformLogger logger = mLoggerInstanceManager.getOrCreatePlatformLogger(mContext, userId); + AppSearchImpl impl = mImplInstanceManager.getOrCreateAppSearchImpl(mContext, + userId, logger); //TODO(b/145759910) clear visibility setting for package. impl.clearPackageData(packageName); + logger.removeCachedUidForPackage(packageName); } } catch (Throwable t) { Log.e(TAG, "Unable to remove data for package: " + packageName, t); @@ -423,22 +426,22 @@ public class AppSearchManagerService extends SystemService { invokeCallbackOnError(callback, t); } finally { if (logger != null) { + int estimatedBinderLatencyMillis = + 2 * (int) (totalLatencyStartTimeMillis - binderCallStartTimeMillis); + int totalLatencyMillis = + (int) (SystemClock.elapsedRealtime() - totalLatencyStartTimeMillis); CallStats.Builder cBuilder = new CallStats.Builder(packageName, databaseName) .setCallType(CallStats.CALL_TYPE_PUT_DOCUMENTS) // TODO(b/173532925) check the existing binder call latency chart // is good enough for us: // http://dashboards/view/_72c98f9a_91d9_41d4_ab9a_bc14f79742b4 - .setEstimatedBinderLatencyMillis( - 2 * (int) (totalLatencyStartTimeMillis - - binderCallStartTimeMillis)) + .setEstimatedBinderLatencyMillis(estimatedBinderLatencyMillis) .setNumOperationsSucceeded(operationSuccessCount) .setNumOperationsFailed(operationFailureCount); cBuilder.getGeneralStatsBuilder() .setStatusCode(statusCode) - .setTotalLatencyMillis( - (int) (SystemClock.elapsedRealtime() - - totalLatencyStartTimeMillis)); + .setTotalLatencyMillis(totalLatencyMillis); logger.logStats(cBuilder.build()); } } @@ -852,18 +855,51 @@ public class AppSearchManagerService extends SystemService { } @Override - public void initialize(@UserIdInt int userId, @NonNull IAppSearchResultCallback callback) { + public void initialize(@UserIdInt int userId, + @ElapsedRealtimeLong long binderCallStartTimeMillis, + @NonNull IAppSearchResultCallback callback) { Objects.requireNonNull(callback); + long totalLatencyStartTimeMillis = SystemClock.elapsedRealtime(); int callingUid = Binder.getCallingUid(); int callingUserId = handleIncomingUser(userId, callingUid); EXECUTOR.execute(() -> { + @AppSearchResult.ResultCode int statusCode = AppSearchResult.RESULT_OK; + PlatformLogger logger = null; + int operationSuccessCount = 0; + int operationFailureCount = 0; try { verifyUserUnlocked(callingUserId); - mImplInstanceManager.getOrCreateAppSearchImpl(mContext, callingUserId); - mLoggerInstanceManager.getOrCreatePlatformLogger(getContext(), callingUserId); + logger = mLoggerInstanceManager.getOrCreatePlatformLogger(mContext, + callingUserId); + mImplInstanceManager.getOrCreateAppSearchImpl(mContext, callingUserId, logger); + ++operationSuccessCount; invokeCallbackOnResult(callback, AppSearchResult.newSuccessfulResult(null)); } catch (Throwable t) { + ++operationFailureCount; + statusCode = throwableToFailedResult(t).getResultCode(); invokeCallbackOnError(callback, t); + } finally { + if (logger != null) { + int estimatedBinderLatencyMillis = + 2 * (int) (totalLatencyStartTimeMillis - binderCallStartTimeMillis); + int totalLatencyMillis = + (int) (SystemClock.elapsedRealtime() - totalLatencyStartTimeMillis); + // TODO(b/173532925) make packageName and database nullable after + // removing generalStats + CallStats.Builder cBuilder = new CallStats.Builder(/*packageName=*/"", + /*database=*/ "") + .setCallType(CallStats.CALL_TYPE_INITIALIZE) + // TODO(b/173532925) check the existing binder call latency chart + // is good enough for us: + // http://dashboards/view/_72c98f9a_91d9_41d4_ab9a_bc14f79742b4 + .setEstimatedBinderLatencyMillis(estimatedBinderLatencyMillis) + .setNumOperationsSucceeded(operationSuccessCount) + .setNumOperationsFailed(operationFailureCount); + cBuilder.getGeneralStatsBuilder() + .setStatusCode(statusCode) + .setTotalLatencyMillis(totalLatencyMillis); + logger.logStats(cBuilder.build()); + } } }); } @@ -960,8 +996,10 @@ public class AppSearchManagerService extends SystemService { int userId = userHandle.getIdentifier(); try { verifyUserUnlocked(userId); - AppSearchImpl impl = mImplInstanceManager.getOrCreateAppSearchImpl(mContext, + PlatformLogger logger = mLoggerInstanceManager.getOrCreatePlatformLogger(mContext, userId); + AppSearchImpl impl = mImplInstanceManager.getOrCreateAppSearchImpl(mContext, + userId, logger); stats.dataSize += impl.getStorageInfoForPackage(packageName).getSizeBytes(); } catch (Throwable t) { Log.e( @@ -985,8 +1023,10 @@ public class AppSearchManagerService extends SystemService { if (packagesForUid == null) { return; } - AppSearchImpl impl = mImplInstanceManager.getOrCreateAppSearchImpl(mContext, + PlatformLogger logger = mLoggerInstanceManager.getOrCreatePlatformLogger(mContext, userId); + AppSearchImpl impl = mImplInstanceManager.getOrCreateAppSearchImpl(mContext, + userId, logger); for (int i = 0; i < packagesForUid.length; i++) { stats.dataSize += impl.getStorageInfoForPackage(packagesForUid[i]).getSizeBytes(); @@ -1012,8 +1052,10 @@ public class AppSearchManagerService extends SystemService { if (packagesForUser == null) { return; } + PlatformLogger logger = mLoggerInstanceManager.getOrCreatePlatformLogger(mContext, + userId); AppSearchImpl impl = - mImplInstanceManager.getOrCreateAppSearchImpl(mContext, userId); + mImplInstanceManager.getOrCreateAppSearchImpl(mContext, userId, logger); for (int i = 0; i < packagesForUser.size(); i++) { String packageName = packagesForUser.get(i).packageName; stats.dataSize += impl.getStorageInfoForPackage(packageName).getSizeBytes(); diff --git a/apex/appsearch/service/java/com/android/server/appsearch/ImplInstanceManager.java b/apex/appsearch/service/java/com/android/server/appsearch/ImplInstanceManager.java index b815de48569f8..f8bc473cd2a58 100644 --- a/apex/appsearch/service/java/com/android/server/appsearch/ImplInstanceManager.java +++ b/apex/appsearch/service/java/com/android/server/appsearch/ImplInstanceManager.java @@ -19,6 +19,7 @@ package com.android.server.appsearch; import static android.content.pm.PackageManager.MATCH_FACTORY_ONLY; import android.annotation.NonNull; +import android.annotation.Nullable; import android.annotation.UserIdInt; import android.app.appsearch.exceptions.AppSearchException; import android.content.Context; @@ -30,6 +31,7 @@ import android.util.SparseArray; import com.android.internal.R; import com.android.internal.annotations.GuardedBy; import com.android.server.appsearch.external.localstorage.AppSearchImpl; +import com.android.server.appsearch.external.localstorage.AppSearchLogger; import java.io.File; @@ -88,16 +90,17 @@ public final class ImplInstanceManager { * one will be created. * * @param context The context - * @param userId The multi-user userId of the device user calling AppSearch + * @param userId The multi-user userId of the device user calling AppSearch * @return An initialized {@link AppSearchImpl} for this user */ @NonNull public AppSearchImpl getOrCreateAppSearchImpl( - @NonNull Context context, @UserIdInt int userId) throws AppSearchException { + @NonNull Context context, @UserIdInt int userId, @Nullable AppSearchLogger logger) + throws AppSearchException { synchronized (mInstancesLocked) { AppSearchImpl instance = mInstancesLocked.get(userId); if (instance == null) { - instance = createImpl(context, userId); + instance = createImpl(context, userId, logger); mInstancesLocked.put(userId, instance); } return instance; @@ -164,11 +167,12 @@ public final class ImplInstanceManager { } } - private AppSearchImpl createImpl(@NonNull Context context, @UserIdInt int userId) + private AppSearchImpl createImpl(@NonNull Context context, @UserIdInt int userId, + @Nullable AppSearchLogger logger) throws AppSearchException { File appSearchDir = getAppSearchDir(userId); return AppSearchImpl.create( - appSearchDir, context, userId, mGlobalQuerierPackage, /*logger=*/ null); + appSearchDir, context, userId, mGlobalQuerierPackage, logger); } /** @@ -182,10 +186,10 @@ public final class ImplInstanceManager { context.getString(R.string.config_globalAppSearchDataQuerierPackage); try { if (context.getPackageManager() - .getPackageInfoAsUser( - globalAppSearchDataQuerierPackage, - MATCH_FACTORY_ONLY, - UserHandle.USER_SYSTEM) + .getPackageInfoAsUser( + globalAppSearchDataQuerierPackage, + MATCH_FACTORY_ONLY, + UserHandle.USER_SYSTEM) == null) { return ""; } diff --git a/apex/appsearch/service/java/com/android/server/appsearch/stats/PlatformLogger.java b/apex/appsearch/service/java/com/android/server/appsearch/stats/PlatformLogger.java index 88f238e91e45c..15b0a05b89c2e 100644 --- a/apex/appsearch/service/java/com/android/server/appsearch/stats/PlatformLogger.java +++ b/apex/appsearch/service/java/com/android/server/appsearch/stats/PlatformLogger.java @@ -17,6 +17,7 @@ package com.android.server.appsearch.stats; import android.annotation.NonNull; +import android.annotation.Nullable; import android.app.appsearch.exceptions.AppSearchException; import android.content.Context; import android.content.pm.PackageManager; @@ -193,7 +194,12 @@ public final class PlatformLogger implements AppSearchLogger { @Override public void logStats(@NonNull InitializeStats stats) throws AppSearchException { - // TODO(b/173532925): Implement + Objects.requireNonNull(stats); + synchronized (mLock) { + if (shouldLogForTypeLocked(CallStats.CALL_TYPE_INITIALIZE)) { + logStatsImplLocked(stats); + } + } } @Override @@ -281,6 +287,32 @@ public final class PlatformLogger implements AppSearchLogger { } } + @GuardedBy("mLock") + private void logStatsImplLocked(@NonNull InitializeStats stats) { + mLastPushTimeMillisLocked = SystemClock.elapsedRealtime(); + ExtraStats extraStats = createExtraStatsLocked(/*packageName=*/ null, + CallStats.CALL_TYPE_INITIALIZE); + FrameworkStatsLog.write(FrameworkStatsLog.APP_SEARCH_INITIALIZE_STATS_REPORTED, + extraStats.mSamplingRatio, + extraStats.mSkippedSampleCount, + extraStats.mPackageUid, + stats.getStatusCode(), + stats.getTotalLatencyMillis(), + stats.hasDeSync(), + stats.getPrepareSchemaAndNamespacesLatencyMillis(), + stats.getPrepareVisibilityStoreLatencyMillis(), + stats.getNativeLatencyMillis(), + stats.getDocumentStoreRecoveryCause(), + stats.getIndexRestorationCause(), + stats.getSchemaStoreRecoveryCause(), + stats.getDocumentStoreRecoveryLatencyMillis(), + stats.getIndexRestorationLatencyMillis(), + stats.getSchemaStoreRecoveryLatencyMillis(), + stats.getDocumentStoreDataStatus(), + stats.getDocumentCount(), + stats.getSchemaTypeCount()); + } + /** * Calculate the hash code as an integer by returning the last four bytes of its MD5. * @@ -314,12 +346,19 @@ public final class PlatformLogger implements AppSearchLogger { *

This method is called by most of logToWestworldLocked functions to reduce code * duplication. */ + // TODO(b/173532925) Once we add CTS test for logging atoms and can inspect the result, we can + // remove this @VisibleForTesting and directly use PlatformLogger.logStats to test sampling and + // rate limiting. @VisibleForTesting @GuardedBy("mLock") @NonNull - ExtraStats createExtraStatsLocked(@NonNull String packageName, + ExtraStats createExtraStatsLocked(@Nullable String packageName, @CallStats.CallType int callType) { - int packageUid = getPackageUidAsUserLocked(packageName); + int packageUid = Process.INVALID_UID; + if (packageName != null) { + packageUid = getPackageUidAsUserLocked(packageName); + } + int samplingRatio = mConfig.mSamplingRatios.get(callType, mConfig.mDefaultSamplingRatio); @@ -337,6 +376,9 @@ public final class PlatformLogger implements AppSearchLogger { * stats. */ @GuardedBy("mLock") + // TODO(b/173532925) Once we add CTS test for logging atoms and can inspect the result, we can + // remove this @VisibleForTesting and directly use PlatformLogger.logStats to test sampling and + // rate limiting. @VisibleForTesting boolean shouldLogForTypeLocked(@CallStats.CallType int callType) { int samplingRatio = mConfig.mSamplingRatios.get(callType, diff --git a/services/tests/servicestests/src/com/android/server/pm/BaseShortcutManagerTest.java b/services/tests/servicestests/src/com/android/server/pm/BaseShortcutManagerTest.java index 4a09cf8b6c268..76c9f667fd2db 100644 --- a/services/tests/servicestests/src/com/android/server/pm/BaseShortcutManagerTest.java +++ b/services/tests/servicestests/src/com/android/server/pm/BaseShortcutManagerTest.java @@ -872,7 +872,8 @@ public abstract class BaseShortcutManagerTest extends InstrumentationTestCase { } @Override - public void initialize(int userId, IAppSearchResultCallback callback) + public void initialize(int userId, long binderCallStartTimeMillis, + IAppSearchResultCallback callback) throws RemoteException { ignore(callback); }