diff options
6 files changed, 155 insertions, 13 deletions
diff --git a/apex/appsearch/framework/java/android/app/appsearch/SearchResults.java b/apex/appsearch/framework/java/android/app/appsearch/SearchResults.java index 43686724936a..0106b0f3c1b6 100644 --- a/apex/appsearch/framework/java/android/app/appsearch/SearchResults.java +++ b/apex/appsearch/framework/java/android/app/appsearch/SearchResults.java @@ -25,6 +25,7 @@ import android.app.appsearch.aidl.IAppSearchManager; import android.app.appsearch.aidl.IAppSearchResultCallback; import android.os.Bundle; import android.os.RemoteException; +import android.os.SystemClock; import android.util.Log; import com.android.internal.util.Preconditions; @@ -109,14 +110,19 @@ public class SearchResults implements Closeable { try { if (mIsFirstLoad) { mIsFirstLoad = false; + long binderCallStartTimeMillis = SystemClock.elapsedRealtime(); if (mDatabaseName == null) { // Global query, there's no one package-database combination to check. mService.globalQuery(mPackageName, mQueryExpression, - mSearchSpec.getBundle(), mUserId, wrapCallback(executor, callback)); + mSearchSpec.getBundle(), mUserId, + binderCallStartTimeMillis, + wrapCallback(executor, callback)); } else { // Normal local query, pass in specified database. mService.query(mPackageName, mDatabaseName, mQueryExpression, - mSearchSpec.getBundle(), mUserId, wrapCallback(executor, callback)); + mSearchSpec.getBundle(), mUserId, + binderCallStartTimeMillis, + wrapCallback(executor, callback)); } } else { mService.getNextPage(mNextPageToken, mUserId, wrapCallback(executor, callback)); 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 6f7e82e8126c..8846889b8687 100644 --- a/apex/appsearch/framework/java/android/app/appsearch/aidl/IAppSearchManager.aidl +++ b/apex/appsearch/framework/java/android/app/appsearch/aidl/IAppSearchManager.aidl @@ -139,6 +139,7 @@ interface IAppSearchManager { * @param queryExpression String to search for * @param searchSpecBundle SearchSpec bundle * @param userId Id of the calling user + * @param binderCallStartTimeMillis start timestamp of binder call in Millis * @param callback {@link AppSearchResult}<{@link Bundle}> of performing this * operation. */ @@ -148,6 +149,7 @@ interface IAppSearchManager { in String queryExpression, in Bundle searchSpecBundle, in int userId, + in long binderCallStartTimeMillis, in IAppSearchResultCallback callback); /** @@ -158,6 +160,7 @@ interface IAppSearchManager { * @param queryExpression String to search for * @param searchSpecBundle SearchSpec bundle * @param userId Id of the calling user + * @param binderCallStartTimeMillis start timestamp of binder call in Millis * @param callback {@link AppSearchResult}<{@link Bundle}> of performing this * operation. */ @@ -166,6 +169,7 @@ interface IAppSearchManager { in String queryExpression, in Bundle searchSpecBundle, 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 777f9fe00bca..7bb590738e68 100644 --- a/apex/appsearch/service/java/com/android/server/appsearch/AppSearchManagerService.java +++ b/apex/appsearch/service/java/com/android/server/appsearch/AppSearchManagerService.java @@ -384,10 +384,10 @@ public class AppSearchManagerService extends SystemService { Objects.requireNonNull(databaseName); Objects.requireNonNull(documentBundles); Objects.requireNonNull(callback); + long totalLatencyStartTimeMillis = SystemClock.elapsedRealtime(); int callingUid = Binder.getCallingUid(); int callingUserId = handleIncomingUser(userId, callingUid); EXECUTOR.execute(() -> { - long totalLatencyStartTimeMillis = SystemClock.elapsedRealtime(); @AppSearchResult.ResultCode int statusCode = AppSearchResult.RESULT_OK; PlatformLogger logger = null; int operationSuccessCount = 0; @@ -498,32 +498,62 @@ public class AppSearchManagerService extends SystemService { @NonNull String queryExpression, @NonNull Bundle searchSpecBundle, @UserIdInt int userId, + @ElapsedRealtimeLong long binderCallStartTimeMillis, @NonNull IAppSearchResultCallback callback) { Objects.requireNonNull(packageName); Objects.requireNonNull(databaseName); Objects.requireNonNull(queryExpression); Objects.requireNonNull(searchSpecBundle); 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); verifyCallingPackage(callingUid, packageName); AppSearchImpl impl = mImplInstanceManager.getAppSearchImpl(callingUserId); + logger = mLoggerInstanceManager.getPlatformLogger(callingUserId); SearchResultPage searchResultPage = impl.query( packageName, databaseName, queryExpression, new SearchSpec(searchSpecBundle), - /*logger=*/ null); + logger); + ++operationSuccessCount; invokeCallbackOnResult( callback, AppSearchResult.newSuccessfulResult(searchResultPage.getBundle())); } 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); + CallStats.Builder cBuilder = new CallStats.Builder(packageName, + databaseName) + .setCallType(CallStats.CALL_TYPE_SEARCH) + // 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()); + } } }); } @@ -534,17 +564,24 @@ public class AppSearchManagerService extends SystemService { @NonNull String queryExpression, @NonNull Bundle searchSpecBundle, @UserIdInt int userId, + @ElapsedRealtimeLong long binderCallStartTimeMillis, @NonNull IAppSearchResultCallback callback) { Objects.requireNonNull(packageName); Objects.requireNonNull(queryExpression); Objects.requireNonNull(searchSpecBundle); 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); verifyCallingPackage(callingUid, packageName); + logger = mLoggerInstanceManager.getPlatformLogger(callingUserId); AppSearchImpl impl = mImplInstanceManager.getAppSearchImpl(callingUserId); SearchResultPage searchResultPage = @@ -553,12 +590,36 @@ public class AppSearchManagerService extends SystemService { new SearchSpec(searchSpecBundle), packageName, callingUid, - /*logger=*/ null); + logger); + ++operationSuccessCount; invokeCallbackOnResult( callback, AppSearchResult.newSuccessfulResult(searchResultPage.getBundle())); - } catch (Throwable t) { + } 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) database would be nulluable once we remove generalStats + CallStats.Builder cBuilder = new CallStats.Builder(packageName, + /*database=*/ "") + .setCallType(CallStats.CALL_TYPE_GLOBAL_SEARCH) + // 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()); + } } }); } 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 88f238e91e45..3f9466bb114b 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; @@ -198,7 +199,12 @@ public final class PlatformLogger implements AppSearchLogger { @Override public void logStats(@NonNull SearchStats stats) throws AppSearchException { - // TODO(b/173532925): Implement + Objects.requireNonNull(stats); + synchronized (mLock) { + if (shouldLogForTypeLocked(CallStats.CALL_TYPE_SEARCH)) { + logStatsImplLocked(stats); + } + } } /** @@ -242,7 +248,9 @@ public final class PlatformLogger implements AppSearchLogger { // // Something is wrong while calculating the hash code for database // this shouldn't happen since we always use "MD5" and "UTF-8" - Log.e(TAG, "Error calculating hash code for database " + database, e); + if (database != null) { + Log.e(TAG, "Error calculating hash code for database " + database, e); + } } } @@ -277,7 +285,55 @@ public final class PlatformLogger implements AppSearchLogger { // // Something is wrong while calculating the hash code for database // this shouldn't happen since we always use "MD5" and "UTF-8" - Log.e(TAG, "Error calculating hash code for database " + database, e); + if (database != null) { + Log.e(TAG, "Error calculating hash code for database " + database, e); + } + } + } + + @GuardedBy("mLock") + private void logStatsImplLocked(@NonNull SearchStats stats) { + mLastPushTimeMillisLocked = SystemClock.elapsedRealtime(); + ExtraStats extraStats = createExtraStatsLocked(stats.getPackageName(), + CallStats.CALL_TYPE_SEARCH); + String database = stats.getDatabase(); + try { + int hashCodeForDatabase = calculateHashCodeMd5(database); + FrameworkStatsLog.write(FrameworkStatsLog.APP_SEARCH_QUERY_STATS_REPORTED, + extraStats.mSamplingRatio, + extraStats.mSkippedSampleCount, + extraStats.mPackageUid, + hashCodeForDatabase, + stats.getStatusCode(), + stats.getTotalLatencyMillis(), + stats.getRewriteSearchSpecLatencyMillis(), + stats.getRewriteSearchResultLatencyMillis(), + stats.getVisibilityScope(), + stats.getNativeLatencyMillis(), + stats.getTermCount(), + stats.getQueryLength(), + stats.getFilteredNamespaceCount(), + stats.getFilteredSchemaTypeCount(), + stats.getRequestedPageSize(), + stats.getCurrentPageReturnedResultCount(), + stats.isFirstPage(), + stats.getParseQueryLatencyMillis(), + stats.getRankingStrategy(), + stats.getScoredDocumentCount(), + stats.getScoringLatencyMillis(), + stats.getRankingLatencyMillis(), + stats.getDocumentRetrievingLatencyMillis(), + stats.getResultWithSnippetsCount()); + } catch (NoSuchAlgorithmException | UnsupportedEncodingException e) { + // TODO(b/184204720) report hashing error to Westworld + // We need to set a special value(e.g. 0xFFFFFFFF) for the hashing of the database, + // so in the dashboard we know there is some error for hashing. + // + // Something is wrong while calculating the hash code for database + // this shouldn't happen since we always use "MD5" and "UTF-8" + if (database != null) { + Log.e(TAG, "Error calculating hash code for database " + database, e); + } } } @@ -285,13 +341,20 @@ public final class PlatformLogger implements AppSearchLogger { * Calculate the hash code as an integer by returning the last four bytes of its MD5. * * @param str a string - * @return hash code as an integer + * @return hash code as an integer. returns -1 if str is null. * @throws AppSearchException if either algorithm or encoding does not exist. */ @VisibleForTesting @NonNull - static int calculateHashCodeMd5(@NonNull String str) throws + static int calculateHashCodeMd5(@Nullable String str) throws NoSuchAlgorithmException, UnsupportedEncodingException { + if (str == null) { + // Just return -1 if caller doesn't have database name + // For some stats like globalQuery, databaseName can be null. + // Since in atom it is an integer, we have to return something here. + return -1; + } + MessageDigest md = MessageDigest.getInstance("MD5"); md.update(str.getBytes(/*charsetName=*/ "UTF-8")); byte[] digest = md.digest(); diff --git a/services/tests/servicestests/src/com/android/server/appsearch/stats/PlatformLoggerTest.java b/services/tests/servicestests/src/com/android/server/appsearch/stats/PlatformLoggerTest.java index 217430c37ccb..e5bdafd69374 100644 --- a/services/tests/servicestests/src/com/android/server/appsearch/stats/PlatformLoggerTest.java +++ b/services/tests/servicestests/src/com/android/server/appsearch/stats/PlatformLoggerTest.java @@ -196,6 +196,12 @@ public class PlatformLoggerTest { } @Test + public void testCalculateHashCode_MD5_strIsNull() throws + NoSuchAlgorithmException, UnsupportedEncodingException { + assertThat(PlatformLogger.calculateHashCodeMd5(/*str=*/ null)).isEqualTo(-1); + } + + @Test public void testShouldLogForTypeLocked_trueWhenSampleRatioIsOne() { final int samplingRatio = 1; final String testPackageName = "packageName"; 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 4a09cf8b6c26..27740d182012 100644 --- a/services/tests/servicestests/src/com/android/server/pm/BaseShortcutManagerTest.java +++ b/services/tests/servicestests/src/com/android/server/pm/BaseShortcutManagerTest.java @@ -746,7 +746,8 @@ public abstract class BaseShortcutManagerTest extends InstrumentationTestCase { @Override public void query(String packageName, String databaseName, String queryExpression, - Bundle searchSpecBundle, int userId, IAppSearchResultCallback callback) + Bundle searchSpecBundle, int userId, long binderCallStartTimeMillis, + IAppSearchResultCallback callback) throws RemoteException { final String key = getKey(userId, databaseName); if (!mDocumentMap.containsKey(key)) { @@ -776,7 +777,8 @@ public abstract class BaseShortcutManagerTest extends InstrumentationTestCase { @Override public void globalQuery(String packageName, String queryExpression, Bundle searchSpecBundle, - int userId, IAppSearchResultCallback callback) throws RemoteException { + int userId, long binderCallStartTimeMillis, IAppSearchResultCallback callback) + throws RemoteException { ignore(callback); } |