diff --git a/apex/appsearch/framework/java/android/app/appsearch/AppSearchSession.java b/apex/appsearch/framework/java/android/app/appsearch/AppSearchSession.java index f379739a3778c..486acb4a3d7e6 100644 --- a/apex/appsearch/framework/java/android/app/appsearch/AppSearchSession.java +++ b/apex/appsearch/framework/java/android/app/appsearch/AppSearchSession.java @@ -241,6 +241,7 @@ public final class AppSearchSession implements Closeable { documentBundles.add(documents.get(i).getBundle()); } try { + // TODO(b/173532925) a timestamp needs to be sent here to calculate binder latency mService.putDocuments(mPackageName, mDatabaseName, documentBundles, mUserId, new IAppSearchBatchResultCallback.Stub() { public void onResult(AppSearchBatchResult result) { 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 new file mode 100644 index 0000000000000..aeb66d90b5bec --- /dev/null +++ b/apex/appsearch/service/java/com/android/server/appsearch/stats/PlatformLogger.java @@ -0,0 +1,315 @@ +/* + * Copyright (C) 2021 The Android Open Source Project + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package com.android.server.appsearch.stats; + +import android.annotation.NonNull; +import android.annotation.Nullable; +import android.content.Context; +import android.content.pm.PackageManager; +import android.os.Process; +import android.os.SystemClock; +import android.util.ArrayMap; +import android.util.SparseIntArray; + +import com.android.internal.annotations.GuardedBy; +import com.android.internal.annotations.VisibleForTesting; +import com.android.internal.util.Preconditions; +import com.android.server.appsearch.external.localstorage.AppSearchLogger; +import com.android.server.appsearch.external.localstorage.stats.CallStats; +import com.android.server.appsearch.external.localstorage.stats.PutDocumentStats; + +import java.util.Map; +import java.util.Random; + +/** + * Logger Implementation using Westworld. + * + *

This class is thread-safe. + * + * @hide + */ +public final class PlatformLogger implements AppSearchLogger { + private static final String TAG = "AppSearchPlatformLogger"; + + // Context of the system service. + private final Context mContext; + + // User ID of the caller who we're logging for. + private final int mUserId; + + // Configuration for the logger + private final Config mConfig; + + private final Random mRng = new Random(); + private final Object mLock = new Object(); + + /** + * SparseArray to track how many stats we skipped due to + * {@link Config#mMinTimeIntervalBetweenSamplesMillis}. + * + *

We can have correct extrapolated number by adding those counts back when we log + * the same type of stats next time. E.g. the true count of an event could be estimated as: + * SUM(sampling_ratio * (num_skipped_sample + 1)) as est_count + * + *

The key to the SparseArray is {@link CallStats.CallType} + */ + @GuardedBy("mLock") + private final SparseIntArray mSkippedSampleCountLocked = + new SparseIntArray(); + + /** + * Map to cache the packageUid for each package. + * + *

It maps packageName to packageUid. + * + *

The entry will be removed whenever the app gets uninstalled + */ + @GuardedBy("mLock") + private final Map mPackageUidCacheLocked = + new ArrayMap<>(); + + /** + * Elapsed time for last stats logged from boot in millis + */ + @GuardedBy("mLock") + private long mLastPushTimeMillisLocked = 0; + + /** + * Class to configure the {@link PlatformLogger} + */ + public static final class Config { + // Minimum time interval (in millis) since last message logged to Westworld before + // logging again. + private final long mMinTimeIntervalBetweenSamplesMillis; + + // Default sampling ratio for all types of stats + private final int mDefaultSamplingRatio; + + /** + * Sampling ratios for different types of stats + * + *

This SparseArray is passed by client and is READ-ONLY. The key to that SparseArray is + * {@link CallStats.CallType} + * + *

If sampling ratio is missing for certain stats type, + * {@link Config#mDefaultSamplingRatio} will be used. + * + *

E.g. sampling ratio=10 means that one out of every 10 stats was logged. If sampling + * ratio is 1, we will log each sample and it acts as if the sampling is disabled. + */ + @NonNull + private final SparseIntArray mSamplingRatios; + + /** + * Configuration for {@link PlatformLogger} + * + * @param minTimeIntervalBetweenSamplesMillis minimum time interval apart in Milliseconds + * required for two consecutive stats logged + * @param defaultSamplingRatio default sampling ratio + * @param samplingRatios SparseArray to customize sampling ratio for + * different stat types + */ + public Config(long minTimeIntervalBetweenSamplesMillis, + int defaultSamplingRatio, + @Nullable SparseIntArray samplingRatios) { + mMinTimeIntervalBetweenSamplesMillis = minTimeIntervalBetweenSamplesMillis; + mDefaultSamplingRatio = defaultSamplingRatio; + if (samplingRatios != null) { + mSamplingRatios = samplingRatios; + } else { + mSamplingRatios = new SparseIntArray(); + } + } + } + + /** + * Helper class to hold platform specific stats for Westworld. + */ + static final class ExtraStats { + // UID for the calling package of the stats. + final int mPackageUid; + // sampling ratio for the call type of the stats. + final int mSamplingRatio; + // number of samplings skipped before the current one for the same call type. + final int mSkippedSampleCount; + + ExtraStats(int packageUid, int samplingRatio, int skippedSampleCount) { + mPackageUid = packageUid; + mSamplingRatio = samplingRatio; + mSkippedSampleCount = skippedSampleCount; + } + } + + /** + * Westworld constructor + */ + public PlatformLogger(@NonNull Context context, int userId, @NonNull Config config) { + mContext = Preconditions.checkNotNull(context); + mConfig = Preconditions.checkNotNull(config); + mUserId = userId; + } + + /** Logs {@link CallStats}. */ + @Override + public void logStats(@NonNull CallStats stats) { + Preconditions.checkNotNull(stats); + synchronized (mLock) { + if (shouldLogForTypeLocked(stats.getCallType())) { + logToWestworldLocked(stats); + } + } + } + + /** Logs {@link PutDocumentStats}. */ + @Override + public void logStats(@NonNull PutDocumentStats stats) { + Preconditions.checkNotNull(stats); + synchronized (mLock) { + if (shouldLogForTypeLocked(CallStats.CALL_TYPE_PUT_DOCUMENT)) { + logToWestworldLocked(stats); + } + } + } + + /** + * Removes cached UID for package. + * + * @return removed UID for the package, or {@code INVALID_UID} if package was not previously + * cached. + */ + public int removeCachedUidForPackage(@NonNull String packageName) { + // TODO(b/173532925) This needs to be called when we get PACKAGE_REMOVED intent + Preconditions.checkNotNull(packageName); + synchronized (mLock) { + Integer uid = mPackageUidCacheLocked.remove(packageName); + return uid != null ? uid : Process.INVALID_UID; + } + } + + @GuardedBy("mLock") + private void logToWestworldLocked(@NonNull CallStats stats) { + mLastPushTimeMillisLocked = SystemClock.elapsedRealtime(); + ExtraStats extraStats = createExtraStatsLocked(stats.getGeneralStats().getPackageName(), + stats.getCallType()); + /* TODO(b/173532925) Log the CallStats to Westworld + stats.log(..., samplingRatio, skippedSampleCount, ...) + */ + } + + @GuardedBy("mLock") + private void logToWestworldLocked(@NonNull PutDocumentStats stats) { + mLastPushTimeMillisLocked = SystemClock.elapsedRealtime(); + ExtraStats extraStats = createExtraStatsLocked(stats.getGeneralStats().getPackageName(), + CallStats.CALL_TYPE_PUT_DOCUMENT); + /* TODO(b/173532925) Log the PutDocumentStats to Westworld + stats.log(..., samplingRatio, skippedSampleCount, ...) + */ + } + + @VisibleForTesting + @GuardedBy("mLock") + @NonNull + ExtraStats createExtraStatsLocked(@NonNull String packageName, + @CallStats.CallType int callType) { + int packageUid = getPackageUidAsUserLocked(packageName); + int samplingRatio = mConfig.mSamplingRatios.get(callType, + mConfig.mDefaultSamplingRatio); + + int skippedSampleCount = mSkippedSampleCountLocked.get(callType, + /*valueOfKeyIfNotFound=*/ 0); + mSkippedSampleCountLocked.put(callType, 0); + + return new ExtraStats(packageUid, samplingRatio, skippedSampleCount); + } + + /** + * Checks if this stats should be logged. + * + *

It won't be logged if it is "sampled" out, or it is too close to the previous logged + * stats. + */ + @GuardedBy("mLock") + @VisibleForTesting + boolean shouldLogForTypeLocked(@CallStats.CallType int callType) { + int samplingRatio = mConfig.mSamplingRatios.get(callType, + mConfig.mDefaultSamplingRatio); + + // Sampling + if (!shouldSample(samplingRatio)) { + return false; + } + + // Rate limiting + // Check the timestamp to see if it is too close to last logged sample + long currentTimeMillis = SystemClock.elapsedRealtime(); + if (mLastPushTimeMillisLocked + > currentTimeMillis - mConfig.mMinTimeIntervalBetweenSamplesMillis) { + int count = mSkippedSampleCountLocked.get(callType, /*valueOfKeyIfNotFound=*/ 0); + ++count; + mSkippedSampleCountLocked.put(callType, count); + return false; + } + + return true; + } + + /** + * Checks if the stats should be "sampled" + * + * @param samplingRatio sampling ratio + * @return if the stats should be sampled + */ + private boolean shouldSample(int samplingRatio) { + if (samplingRatio <= 0) { + return false; + } + + return mRng.nextInt((int) samplingRatio) == 0; + } + + /** + * Finds the UID of the {@code packageName}. Returns {@link Process#INVALID_UID} if unable to + * find the UID. + */ + @GuardedBy("mLock") + private int getPackageUidAsUserLocked(@NonNull String packageName) { + Integer packageUid = mPackageUidCacheLocked.get(packageName); + if (packageUid != null) { + return packageUid; + } + + // TODO(b/173532925) since VisibilityStore has the same method, we can make this a + // utility function + try { + packageUid = mContext.getPackageManager().getPackageUidAsUser(packageName, mUserId); + mPackageUidCacheLocked.put(packageName, packageUid); + return packageUid; + } catch (PackageManager.NameNotFoundException e) { + // Package doesn't exist, continue + } + return Process.INVALID_UID; + } + + // + // Functions below are used for tests only + // + @VisibleForTesting + @GuardedBy("mLock") + void setLastPushTimeMillisLocked(long lastPushElapsedTimeMillis) { + mLastPushTimeMillisLocked = lastPushElapsedTimeMillis; + } +} 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 new file mode 100644 index 0000000000000..7afcbf7ead1cc --- /dev/null +++ b/services/tests/servicestests/src/com/android/server/appsearch/stats/PlatformLoggerTest.java @@ -0,0 +1,248 @@ +/* + * Copyright (C) 2021 The Android Open Source Project + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package com.android.server.appsearch.stats; + +import static com.google.common.truth.Truth.assertThat; + +import static org.mockito.Mockito.anyInt; +import static org.mockito.Mockito.eq; +import static org.mockito.Mockito.times; +import static org.mockito.Mockito.verify; + +import android.content.Context; +import android.content.ContextWrapper; +import android.content.pm.PackageManager; +import android.os.SystemClock; +import android.os.UserHandle; +import android.util.SparseIntArray; + +import androidx.test.core.app.ApplicationProvider; + +import com.android.server.appsearch.external.localstorage.MockPackageManager; +import com.android.server.appsearch.external.localstorage.stats.CallStats; + +import org.junit.Before; +import org.junit.Test; + +public class PlatformLoggerTest { + private static final int TEST_MIN_TIME_INTERVAL_BETWEEN_SAMPLES_MILLIS = 100; + private static final int TEST_DEFAULT_SAMPLING_RATIO = 10; + private static final String TEST_PACKAGE_NAME = "packageName"; + private MockPackageManager mMockPackageManager = new MockPackageManager(); + private Context mContext; + + @Before + public void setUp() throws Exception { + Context context = ApplicationProvider.getApplicationContext(); + mContext = + new ContextWrapper(context) { + @Override + public PackageManager getPackageManager() { + return mMockPackageManager.getMockPackageManager(); + } + }; + } + + @Test + public void testcreateExtraStatsLocked_nullSamplingRatioMap_returnsDefaultSamplingRatio() { + PlatformLogger logger = new PlatformLogger( + ApplicationProvider.getApplicationContext(), + UserHandle.USER_NULL, + new PlatformLogger.Config( + TEST_MIN_TIME_INTERVAL_BETWEEN_SAMPLES_MILLIS, + TEST_DEFAULT_SAMPLING_RATIO, + /*samplingRatioMap=*/ null)); + + // Make sure default sampling ratio is used if samplingMap is not provided. + assertThat(logger.createExtraStatsLocked(TEST_PACKAGE_NAME, + CallStats.CALL_TYPE_UNKNOWN).mSamplingRatio).isEqualTo( + TEST_DEFAULT_SAMPLING_RATIO); + assertThat(logger.createExtraStatsLocked(TEST_PACKAGE_NAME, + CallStats.CALL_TYPE_INITIALIZE).mSamplingRatio).isEqualTo( + TEST_DEFAULT_SAMPLING_RATIO); + assertThat(logger.createExtraStatsLocked(TEST_PACKAGE_NAME, + CallStats.CALL_TYPE_QUERY).mSamplingRatio).isEqualTo( + TEST_DEFAULT_SAMPLING_RATIO); + assertThat(logger.createExtraStatsLocked(TEST_PACKAGE_NAME, + CallStats.CALL_TYPE_FLUSH).mSamplingRatio).isEqualTo( + TEST_DEFAULT_SAMPLING_RATIO); + } + + + @Test + public void testcreateExtraStatsLocked_with_samplingRatioMap_returnsConfiguredSamplingRatio() { + int putDocumentSamplingRatio = 1; + int querySamplingRatio = 2; + final SparseIntArray samplingRatios = new SparseIntArray(); + samplingRatios.put(CallStats.CALL_TYPE_PUT_DOCUMENT, putDocumentSamplingRatio); + samplingRatios.put(CallStats.CALL_TYPE_QUERY, querySamplingRatio); + PlatformLogger logger = new PlatformLogger( + ApplicationProvider.getApplicationContext(), + UserHandle.USER_NULL, + new PlatformLogger.Config( + TEST_MIN_TIME_INTERVAL_BETWEEN_SAMPLES_MILLIS, + TEST_DEFAULT_SAMPLING_RATIO, + samplingRatios)); + + // The default sampling ratio should be used if no sampling ratio is + // provided for certain call type. + assertThat(logger.createExtraStatsLocked(TEST_PACKAGE_NAME, + CallStats.CALL_TYPE_INITIALIZE).mSamplingRatio).isEqualTo( + TEST_DEFAULT_SAMPLING_RATIO); + assertThat(logger.createExtraStatsLocked(TEST_PACKAGE_NAME, + CallStats.CALL_TYPE_FLUSH).mSamplingRatio).isEqualTo( + TEST_DEFAULT_SAMPLING_RATIO); + + // The configured sampling ratio is used if sampling ratio is available + // for certain call type. + assertThat(logger.createExtraStatsLocked(TEST_PACKAGE_NAME, + CallStats.CALL_TYPE_PUT_DOCUMENT).mSamplingRatio).isEqualTo( + putDocumentSamplingRatio); + assertThat(logger.createExtraStatsLocked(TEST_PACKAGE_NAME, + CallStats.CALL_TYPE_QUERY).mSamplingRatio).isEqualTo( + querySamplingRatio); + } + + @Test + public void testShouldLogForTypeLocked_trueWhenSampleRatioIsOne() { + final int samplingRatio = 1; + final String testPackageName = "packageName"; + PlatformLogger logger = new PlatformLogger( + ApplicationProvider.getApplicationContext(), + UserHandle.USER_NULL, + new PlatformLogger.Config( + TEST_MIN_TIME_INTERVAL_BETWEEN_SAMPLES_MILLIS, + samplingRatio, + /* samplingMap=*/ null)); + + // Sample should always be logged for the first time if sampling is disabled(value is one). + assertThat(logger.shouldLogForTypeLocked(CallStats.CALL_TYPE_PUT_DOCUMENT)).isTrue(); + assertThat(logger.createExtraStatsLocked(testPackageName, + CallStats.CALL_TYPE_PUT_DOCUMENT).mSkippedSampleCount).isEqualTo(0); + } + + @Test + public void testShouldLogForTypeLocked_falseWhenSampleRatioIsNegative() { + final int samplingRatio = -1; + final String testPackageName = "packageName"; + PlatformLogger logger = new PlatformLogger( + ApplicationProvider.getApplicationContext(), + UserHandle.USER_NULL, + new PlatformLogger.Config( + TEST_MIN_TIME_INTERVAL_BETWEEN_SAMPLES_MILLIS, + samplingRatio, + /* samplingMap=*/ null)); + + // Makes sure sample will be excluded due to sampling if sample ratio is negative. + assertThat(logger.shouldLogForTypeLocked(CallStats.CALL_TYPE_PUT_DOCUMENT)).isFalse(); + // Skipped count should be 0 since it doesn't pass the sampling. + assertThat(logger.createExtraStatsLocked(testPackageName, + CallStats.CALL_TYPE_PUT_DOCUMENT).mSkippedSampleCount).isEqualTo(0); + } + + @Test + public void testShouldLogForTypeLocked_falseWhenWithinCoolOffInterval() { + // Next sample won't be excluded due to sampling. + final int samplingRatio = 1; + // Next sample would guaranteed to be too close. + final int minTimeIntervalBetweenSamplesMillis = Integer.MAX_VALUE; + final String testPackageName = "packageName"; + PlatformLogger logger = new PlatformLogger( + ApplicationProvider.getApplicationContext(), + UserHandle.USER_NULL, + new PlatformLogger.Config( + minTimeIntervalBetweenSamplesMillis, + samplingRatio, + /* samplingMap=*/ null)); + logger.setLastPushTimeMillisLocked(SystemClock.elapsedRealtime()); + + // Makes sure sample will be excluded due to rate limiting if samples are too close. + assertThat(logger.shouldLogForTypeLocked(CallStats.CALL_TYPE_PUT_DOCUMENT)).isFalse(); + assertThat(logger.createExtraStatsLocked(testPackageName, + CallStats.CALL_TYPE_PUT_DOCUMENT).mSkippedSampleCount).isEqualTo(1); + } + + @Test + public void testShouldLogForTypeLocked_trueWhenOutsideOfCoolOffInterval() { + // Next sample won't be excluded due to sampling. + final int samplingRatio = 1; + // Next sample would guaranteed to be included. + final int minTimeIntervalBetweenSamplesMillis = 0; + final String testPackageName = "packageName"; + PlatformLogger logger = new PlatformLogger( + ApplicationProvider.getApplicationContext(), + UserHandle.USER_NULL, + new PlatformLogger.Config( + minTimeIntervalBetweenSamplesMillis, + samplingRatio, + /* samplingMap=*/ null)); + logger.setLastPushTimeMillisLocked(SystemClock.elapsedRealtime()); + + // Makes sure sample will be logged if it is not too close to previous sample. + assertThat(logger.shouldLogForTypeLocked(CallStats.CALL_TYPE_PUT_DOCUMENT)).isTrue(); + assertThat(logger.createExtraStatsLocked(testPackageName, + CallStats.CALL_TYPE_PUT_DOCUMENT).mSkippedSampleCount).isEqualTo(0); + } + + /** Makes sure the caching works while getting the UID for calling package. */ + @Test + public void testGetPackageUidAsUser() throws Exception { + final String testPackageName = "packageName"; + final int testUid = 1234; + PlatformLogger logger = new PlatformLogger( + mContext, + mContext.getUserId(), + new PlatformLogger.Config( + TEST_MIN_TIME_INTERVAL_BETWEEN_SAMPLES_MILLIS, + TEST_DEFAULT_SAMPLING_RATIO, + /* samplingMap=*/ null)); + mMockPackageManager.mockGetPackageUidAsUser(testPackageName, mContext.getUserId(), testUid); + + // + // First time, no cache + // + PlatformLogger.ExtraStats extraStats = logger.createExtraStatsLocked(testPackageName, + CallStats.CALL_TYPE_PUT_DOCUMENT); + + verify(mMockPackageManager.getMockPackageManager(), times(1)).getPackageUidAsUser( + eq(testPackageName), /*userId=*/ anyInt()); + assertThat(extraStats.mPackageUid).isEqualTo(testUid); + + // + // Second time, we have cache + // + extraStats = logger.createExtraStatsLocked(testPackageName, + CallStats.CALL_TYPE_PUT_DOCUMENT); + + // Count is still one since we will use the cache + verify(mMockPackageManager.getMockPackageManager(), times(1)).getPackageUidAsUser( + eq(testPackageName), /*userId=*/ anyInt()); + assertThat(extraStats.mPackageUid).isEqualTo(testUid); + + // + // Remove the cache and try again + // + assertThat(logger.removeCachedUidForPackage(testPackageName)).isEqualTo(testUid); + extraStats = logger.createExtraStatsLocked(testPackageName, + CallStats.CALL_TYPE_PUT_DOCUMENT); + + // count increased by 1 since cache is cleared + verify(mMockPackageManager.getMockPackageManager(), times(2)).getPackageUidAsUser( + eq(testPackageName), /*userId=*/ anyInt()); + assertThat(extraStats.mPackageUid).isEqualTo(testUid); + } +}