Log SearchStats in the platform (d6d22f0e) · Commits · e / os / android_frameworks_base

apex/appsearch/framework/java/android/app/appsearch/SearchResults.java

+8 −2

Original line number	Diff line number	Diff line
		@@ -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));

apex/appsearch/framework/java/android/app/appsearch/aidl/IAppSearchManager.aidl

+4 −0

Original line number	Diff line number	Diff line
		@@ -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);

		/**

apex/appsearch/service/java/com/android/server/appsearch/AppSearchManagerService.java

+65 −4

Original line number	Diff line number	Diff line
		@@ -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) {
		++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());
		}
		}
		});
		}

apex/appsearch/service/java/com/android/server/appsearch/stats/PlatformLogger.java

+68 −5

Original line number	Diff line number	Diff line
		@@ -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,9 +248,11 @@ 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"
		if (database != null) {
		Log.e(TAG, "Error calculating hash code for database " + database, e);
		}
		}
		}

		@GuardedBy("mLock")
		private void logStatsImplLocked(@NonNull PutDocumentStats stats) {
		@@ -277,21 +285,76 @@ 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"
		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);
		}
		}
		}

		/**
		* 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();

services/tests/servicestests/src/com/android/server/appsearch/stats/PlatformLoggerTest.java

+6 −0

Original line number	Diff line number	Diff line
		@@ -195,6 +195,12 @@ public class PlatformLoggerTest {
		assertThat(longHashCode).isEqualTo(calculateHashCodeMd5withBigInteger(longStr));
		}

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