diff --git a/core/java/com/android/internal/util/LatencyTracker.java b/core/java/com/android/internal/util/LatencyTracker.java index 43a9f5f62e65b..3c0675504e254 100644 --- a/core/java/com/android/internal/util/LatencyTracker.java +++ b/core/java/com/android/internal/util/LatencyTracker.java @@ -48,6 +48,7 @@ import static com.android.internal.util.LatencyTracker.ActionProperties.SAMPLE_I import static com.android.internal.util.LatencyTracker.ActionProperties.TRACE_THRESHOLD_SUFFIX; import android.Manifest; +import android.annotation.ElapsedRealtimeLong; import android.annotation.IntDef; import android.annotation.NonNull; import android.annotation.Nullable; @@ -55,7 +56,6 @@ import android.annotation.RequiresPermission; import android.app.ActivityThread; import android.content.Context; import android.os.Build; -import android.os.ConditionVariable; import android.os.SystemClock; import android.os.Trace; import android.provider.DeviceConfig; @@ -79,7 +79,7 @@ import java.util.concurrent.TimeUnit; * Class to track various latencies in SystemUI. It then writes the latency to statsd and also * outputs it to logcat so these latencies can be captured by tests and then used for dashboards. *

- * This is currently only in Keyguard so it can be shared between SystemUI and Keyguard, but + * This is currently only in Keyguard. It can be shared between SystemUI and Keyguard, but * eventually we'd want to merge these two packages together so Keyguard can use common classes * that are shared with SystemUI. */ @@ -285,8 +285,6 @@ public class LatencyTracker { UIACTION_LATENCY_REPORTED__ACTION__ACTION_REQUEST_IME_HIDDEN, }; - private static LatencyTracker sLatencyTracker; - private final Object mLock = new Object(); @GuardedBy("mLock") private final SparseArray mSessions = new SparseArray<>(); @@ -294,20 +292,21 @@ public class LatencyTracker { private final SparseArray mActionPropertiesMap = new SparseArray<>(); @GuardedBy("mLock") private boolean mEnabled; - @VisibleForTesting - public final ConditionVariable mDeviceConfigPropertiesUpdated = new ConditionVariable(); - public static LatencyTracker getInstance(Context context) { - if (sLatencyTracker == null) { - synchronized (LatencyTracker.class) { - if (sLatencyTracker == null) { - sLatencyTracker = new LatencyTracker(); - } - } - } - return sLatencyTracker; + // Wrapping this in a holder class achieves lazy loading behavior + private static final class SLatencyTrackerHolder { + private static final LatencyTracker sLatencyTracker = new LatencyTracker(); } + public static LatencyTracker getInstance(Context context) { + return SLatencyTrackerHolder.sLatencyTracker; + } + + /** + * Constructor for LatencyTracker + * + *

This constructor is only visible for test classes to inject their own consumer callbacks + */ @RequiresPermission(Manifest.permission.READ_DEVICE_CONFIG) @VisibleForTesting public LatencyTracker() { @@ -349,11 +348,8 @@ public class LatencyTracker { properties.getInt(actionName + TRACE_THRESHOLD_SUFFIX, legacyActionTraceThreshold))); } - if (DEBUG) { - Log.d(TAG, "updated action properties: " + mActionPropertiesMap); - } + onDeviceConfigPropertiesUpdated(mActionPropertiesMap); } - mDeviceConfigPropertiesUpdated.open(); } /** @@ -477,7 +473,7 @@ public class LatencyTracker { */ public void onActionStart(@Action int action, String tag) { synchronized (mLock) { - if (!isEnabled()) { + if (!isEnabled(action)) { return; } // skip if the action is already instrumenting. @@ -501,7 +497,7 @@ public class LatencyTracker { */ public void onActionEnd(@Action int action) { synchronized (mLock) { - if (!isEnabled()) { + if (!isEnabled(action)) { return; } Session session = mSessions.get(action); @@ -539,6 +535,24 @@ public class LatencyTracker { } } + /** + * Testing API to get the time when a given action was started. + * + * @param action Action which to retrieve start time from + * @return Elapsed realtime timestamp when the action started. -1 if the action is not active. + * @hide + */ + @VisibleForTesting + @ElapsedRealtimeLong + public long getActiveActionStartTime(@Action int action) { + synchronized (mLock) { + if (mSessions.contains(action)) { + return mSessions.get(action).mStartRtc; + } + return -1; + } + } + /** * Logs an action that has started and ended. This needs to be called from the main thread. * @@ -549,6 +563,9 @@ public class LatencyTracker { boolean shouldSample; int traceThreshold; synchronized (mLock) { + if (!isEnabled(action)) { + return; + } ActionProperties actionProperties = mActionPropertiesMap.get(action); if (actionProperties == null) { return; @@ -559,28 +576,24 @@ public class LatencyTracker { traceThreshold = actionProperties.getTraceThreshold(); } - if (traceThreshold > 0 && duration >= traceThreshold) { - PerfettoTrigger.trigger(getTraceTriggerNameForAction(action)); + boolean shouldTriggerPerfettoTrace = traceThreshold > 0 && duration >= traceThreshold; + + if (DEBUG) { + Log.i(TAG, "logAction: " + getNameOfAction(STATSD_ACTION[action]) + + " duration=" + duration + + " shouldSample=" + shouldSample + + " shouldTriggerPerfettoTrace=" + shouldTriggerPerfettoTrace); } - logActionDeprecated(action, duration, shouldSample); - } - - /** - * Logs an action that has started and ended. This needs to be called from the main thread. - * - * @param action The action to end. One of the ACTION_* values. - * @param duration The duration of the action in ms. - * @param writeToStatsLog Whether to write the measured latency to FrameworkStatsLog. - */ - public static void logActionDeprecated( - @Action int action, int duration, boolean writeToStatsLog) { - Log.i(TAG, getNameOfAction(STATSD_ACTION[action]) + " latency=" + duration); EventLog.writeEvent(EventLogTags.SYSUI_LATENCY, action, duration); - - if (writeToStatsLog) { - FrameworkStatsLog.write( - FrameworkStatsLog.UI_ACTION_LATENCY_REPORTED, STATSD_ACTION[action], duration); + if (shouldTriggerPerfettoTrace) { + onTriggerPerfetto(getTraceTriggerNameForAction(action)); + } + if (shouldSample) { + onLogToFrameworkStats( + new FrameworkStatsLogEvent(action, FrameworkStatsLog.UI_ACTION_LATENCY_REPORTED, + STATSD_ACTION[action], duration) + ); } } @@ -642,10 +655,10 @@ public class LatencyTracker { } @VisibleForTesting - static class ActionProperties { + public static class ActionProperties { static final String ENABLE_SUFFIX = "_enable"; static final String SAMPLE_INTERVAL_SUFFIX = "_sample_interval"; - // TODO: migrate all usages of the legacy trace theshold property + // TODO: migrate all usages of the legacy trace threshold property static final String LEGACY_TRACE_THRESHOLD_SUFFIX = ""; static final String TRACE_THRESHOLD_SUFFIX = "_trace_threshold"; @@ -655,7 +668,8 @@ public class LatencyTracker { private final int mSamplingInterval; private final int mTraceThreshold; - ActionProperties( + @VisibleForTesting + public ActionProperties( @Action int action, boolean enabled, int samplingInterval, @@ -668,20 +682,24 @@ public class LatencyTracker { this.mTraceThreshold = traceThreshold; } + @VisibleForTesting @Action - int getAction() { + public int getAction() { return mAction; } - boolean isEnabled() { + @VisibleForTesting + public boolean isEnabled() { return mEnabled; } - int getSamplingInterval() { + @VisibleForTesting + public int getSamplingInterval() { return mSamplingInterval; } - int getTraceThreshold() { + @VisibleForTesting + public int getTraceThreshold() { return mTraceThreshold; } @@ -694,5 +712,103 @@ public class LatencyTracker { + ", mTraceThreshold=" + mTraceThreshold + "}"; } + + @Override + public boolean equals(@Nullable Object o) { + if (this == o) { + return true; + } + if (o == null) { + return false; + } + if (!(o instanceof ActionProperties)) { + return false; + } + ActionProperties that = (ActionProperties) o; + return mAction == that.mAction + && mEnabled == that.mEnabled + && mSamplingInterval == that.mSamplingInterval + && mTraceThreshold == that.mTraceThreshold; + } + + @Override + public int hashCode() { + int _hash = 1; + _hash = 31 * _hash + mAction; + _hash = 31 * _hash + Boolean.hashCode(mEnabled); + _hash = 31 * _hash + mSamplingInterval; + _hash = 31 * _hash + mTraceThreshold; + return _hash; + } + } + + /** + * Testing method intended to be overridden to determine when the LatencyTracker's device + * properties are updated. + */ + @VisibleForTesting + public void onDeviceConfigPropertiesUpdated(SparseArray actionProperties) { + if (DEBUG) { + Log.d(TAG, "onDeviceConfigPropertiesUpdated: " + actionProperties); + } + } + + /** + * Testing class intended to be overridden to determine when LatencyTracker triggers perfetto. + */ + @VisibleForTesting + public void onTriggerPerfetto(String triggerName) { + if (DEBUG) { + Log.i(TAG, "onTriggerPerfetto: triggerName=" + triggerName); + } + PerfettoTrigger.trigger(triggerName); + } + + /** + * Testing method intended to be overridden to determine when LatencyTracker writes to + * FrameworkStatsLog. + */ + @VisibleForTesting + public void onLogToFrameworkStats(FrameworkStatsLogEvent event) { + if (DEBUG) { + Log.i(TAG, "onLogToFrameworkStats: event=" + event); + } + FrameworkStatsLog.write(event.logCode, event.statsdAction, event.durationMillis); + } + + /** + * Testing class intended to reject what should be written to the {@link FrameworkStatsLog} + * + *

This class is used in {@link #onLogToFrameworkStats(FrameworkStatsLogEvent)} for test code + * to observer when and what information is being logged by {@link LatencyTracker} + */ + @VisibleForTesting + public static class FrameworkStatsLogEvent { + + @VisibleForTesting + public final int action; + @VisibleForTesting + public final int logCode; + @VisibleForTesting + public final int statsdAction; + @VisibleForTesting + public final int durationMillis; + + private FrameworkStatsLogEvent(int action, int logCode, int statsdAction, + int durationMillis) { + this.action = action; + this.logCode = logCode; + this.statsdAction = statsdAction; + this.durationMillis = durationMillis; + } + + @Override + public String toString() { + return "FrameworkStatsLogEvent{" + + " logCode=" + logCode + + ", statsdAction=" + statsdAction + + ", durationMillis=" + durationMillis + + "}"; + } } } diff --git a/core/tests/coretests/Android.bp b/core/tests/coretests/Android.bp index e811bb67fb990..3ea15924e96d3 100644 --- a/core/tests/coretests/Android.bp +++ b/core/tests/coretests/Android.bp @@ -20,6 +20,7 @@ android_test { "BinderProxyCountingTestService/src/**/*.java", "BinderDeathRecipientHelperApp/src/**/*.java", "aidl/**/I*.aidl", + ":FrameworksCoreTestDoubles-sources", ], aidl: { diff --git a/core/tests/coretests/src/com/android/internal/util/FakeLatencyTrackerTest.java b/core/tests/coretests/src/com/android/internal/util/FakeLatencyTrackerTest.java new file mode 100644 index 0000000000000..e6f10adacee33 --- /dev/null +++ b/core/tests/coretests/src/com/android/internal/util/FakeLatencyTrackerTest.java @@ -0,0 +1,67 @@ +/* + * Copyright (C) 2023 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.internal.util; + +import static com.android.internal.util.FrameworkStatsLog.UIACTION_LATENCY_REPORTED__ACTION__ACTION_SHOW_VOICE_INTERACTION; +import static com.android.internal.util.FrameworkStatsLog.UI_ACTION_LATENCY_REPORTED; +import static com.android.internal.util.LatencyTracker.ACTION_SHOW_VOICE_INTERACTION; + +import static com.google.common.truth.Truth.assertThat; + +import androidx.test.ext.junit.runners.AndroidJUnit4; + +import org.junit.Before; +import org.junit.Test; +import org.junit.runner.RunWith; + +import java.util.List; + +/** + * This test class verifies the additional methods which {@link FakeLatencyTracker} exposes. + * + *

The typical {@link LatencyTracker} behavior test coverage is present in + * {@link LatencyTrackerTest} + */ +@RunWith(AndroidJUnit4.class) +public class FakeLatencyTrackerTest { + + private FakeLatencyTracker mFakeLatencyTracker; + + @Before + public void setUp() throws Exception { + mFakeLatencyTracker = FakeLatencyTracker.create(); + } + + @Test + public void testForceEnabled() throws Exception { + mFakeLatencyTracker.logAction(ACTION_SHOW_VOICE_INTERACTION, 1234); + + assertThat(mFakeLatencyTracker.getEventsWrittenToFrameworkStats( + ACTION_SHOW_VOICE_INTERACTION)).isEmpty(); + + mFakeLatencyTracker.forceEnabled(ACTION_SHOW_VOICE_INTERACTION, 1000); + mFakeLatencyTracker.logAction(ACTION_SHOW_VOICE_INTERACTION, 1234); + List events = + mFakeLatencyTracker.getEventsWrittenToFrameworkStats( + ACTION_SHOW_VOICE_INTERACTION); + assertThat(events).hasSize(1); + assertThat(events.get(0).logCode).isEqualTo(UI_ACTION_LATENCY_REPORTED); + assertThat(events.get(0).statsdAction).isEqualTo( + UIACTION_LATENCY_REPORTED__ACTION__ACTION_SHOW_VOICE_INTERACTION); + assertThat(events.get(0).durationMillis).isEqualTo(1234); + } +} diff --git a/core/tests/coretests/src/com/android/internal/util/LatencyTrackerTest.java b/core/tests/coretests/src/com/android/internal/util/LatencyTrackerTest.java index d1f0b5e1dd304..645324d57ea9d 100644 --- a/core/tests/coretests/src/com/android/internal/util/LatencyTrackerTest.java +++ b/core/tests/coretests/src/com/android/internal/util/LatencyTrackerTest.java @@ -16,19 +16,22 @@ package com.android.internal.util; +import static android.provider.DeviceConfig.NAMESPACE_LATENCY_TRACKER; import static android.text.TextUtils.formatSimple; +import static com.android.internal.util.FrameworkStatsLog.UI_ACTION_LATENCY_REPORTED; import static com.android.internal.util.LatencyTracker.STATSD_ACTION; import static com.google.common.truth.Truth.assertThat; import static com.google.common.truth.Truth.assertWithMessage; import android.provider.DeviceConfig; -import android.util.Log; import androidx.test.ext.junit.runners.AndroidJUnit4; import androidx.test.filters.SmallTest; +import com.android.internal.util.LatencyTracker.ActionProperties; + import com.google.common.truth.Expect; import org.junit.Before; @@ -38,7 +41,6 @@ import org.junit.runner.RunWith; import java.lang.reflect.Field; import java.lang.reflect.Modifier; -import java.time.Duration; import java.util.Arrays; import java.util.HashMap; import java.util.HashSet; @@ -49,27 +51,23 @@ import java.util.stream.Collectors; @SmallTest @RunWith(AndroidJUnit4.class) public class LatencyTrackerTest { - private static final String TAG = LatencyTrackerTest.class.getSimpleName(); private static final String ENUM_NAME_PREFIX = "UIACTION_LATENCY_REPORTED__ACTION__"; - private static final String ACTION_ENABLE_SUFFIX = "_enable"; - private static final Duration TEST_TIMEOUT = Duration.ofMillis(500); @Rule public final Expect mExpect = Expect.create(); + // Fake is used because it tests the real logic of LatencyTracker, and it only fakes the + // outcomes (PerfettoTrigger and FrameworkStatsLog). + private FakeLatencyTracker mLatencyTracker; + @Before - public void setUp() { - DeviceConfig.deleteProperty(DeviceConfig.NAMESPACE_LATENCY_TRACKER, - LatencyTracker.SETTINGS_ENABLED_KEY); - getAllActions().forEach(action -> { - DeviceConfig.deleteProperty(DeviceConfig.NAMESPACE_LATENCY_TRACKER, - action.getName().toLowerCase() + ACTION_ENABLE_SUFFIX); - }); + public void setUp() throws Exception { + mLatencyTracker = FakeLatencyTracker.create(); } @Test public void testCujsMapToEnumsCorrectly() { - List actions = getAllActions(); + List actions = getAllActionFields(); Map enumsMap = Arrays.stream(FrameworkStatsLog.class.getDeclaredFields()) .filter(f -> f.getName().startsWith(ENUM_NAME_PREFIX) && Modifier.isStatic(f.getModifiers()) @@ -101,7 +99,7 @@ public class LatencyTrackerTest { @Test public void testCujTypeEnumCorrectlyDefined() throws Exception { - List cujEnumFields = getAllActions(); + List cujEnumFields = getAllActionFields(); HashSet allValues = new HashSet<>(); for (Field field : cujEnumFields) { int fieldValue = field.getInt(null); @@ -118,92 +116,242 @@ public class LatencyTrackerTest { } @Test - public void testIsEnabled_globalEnabled() { - DeviceConfig.setProperty(DeviceConfig.NAMESPACE_LATENCY_TRACKER, + public void testIsEnabled_trueWhenGlobalEnabled() throws Exception { + DeviceConfig.setProperty(NAMESPACE_LATENCY_TRACKER, LatencyTracker.SETTINGS_ENABLED_KEY, "true", false); - LatencyTracker latencyTracker = new LatencyTracker(); - waitForLatencyTrackerToUpdateProperties(latencyTracker); - assertThat(latencyTracker.isEnabled()).isTrue(); + mLatencyTracker.waitForGlobalEnabledState(true); + mLatencyTracker.waitForAllPropertiesEnableState(true); + + //noinspection deprecation + assertThat(mLatencyTracker.isEnabled()).isTrue(); } @Test - public void testIsEnabled_globalDisabled() { - DeviceConfig.setProperty(DeviceConfig.NAMESPACE_LATENCY_TRACKER, + public void testIsEnabled_falseWhenGlobalDisabled() throws Exception { + DeviceConfig.setProperty(NAMESPACE_LATENCY_TRACKER, LatencyTracker.SETTINGS_ENABLED_KEY, "false", false); - LatencyTracker latencyTracker = new LatencyTracker(); - waitForLatencyTrackerToUpdateProperties(latencyTracker); - assertThat(latencyTracker.isEnabled()).isFalse(); + mLatencyTracker.waitForGlobalEnabledState(false); + mLatencyTracker.waitForAllPropertiesEnableState(false); + + //noinspection deprecation + assertThat(mLatencyTracker.isEnabled()).isFalse(); } @Test - public void testIsEnabledAction_useGlobalValueWhenActionEnableIsNotSet() { - LatencyTracker latencyTracker = new LatencyTracker(); + public void testIsEnabledAction_useGlobalValueWhenActionEnableIsNotSet() + throws Exception { // using a single test action, but this applies to all actions int action = LatencyTracker.ACTION_SHOW_VOICE_INTERACTION; - Log.i(TAG, "setting property=" + LatencyTracker.SETTINGS_ENABLED_KEY + ", value=true"); - latencyTracker.mDeviceConfigPropertiesUpdated.close(); - DeviceConfig.setProperty(DeviceConfig.NAMESPACE_LATENCY_TRACKER, + DeviceConfig.deleteProperty(NAMESPACE_LATENCY_TRACKER, + "action_show_voice_interaction_enable"); + mLatencyTracker.waitForAllPropertiesEnableState(false); + DeviceConfig.setProperty(NAMESPACE_LATENCY_TRACKER, LatencyTracker.SETTINGS_ENABLED_KEY, "true", false); - waitForLatencyTrackerToUpdateProperties(latencyTracker); - assertThat( - latencyTracker.isEnabled(action)).isTrue(); + mLatencyTracker.waitForGlobalEnabledState(true); + mLatencyTracker.waitForAllPropertiesEnableState(true); - Log.i(TAG, "setting property=" + LatencyTracker.SETTINGS_ENABLED_KEY - + ", value=false"); - latencyTracker.mDeviceConfigPropertiesUpdated.close(); - DeviceConfig.setProperty(DeviceConfig.NAMESPACE_LATENCY_TRACKER, - LatencyTracker.SETTINGS_ENABLED_KEY, "false", false); - waitForLatencyTrackerToUpdateProperties(latencyTracker); - assertThat(latencyTracker.isEnabled(action)).isFalse(); + assertThat(mLatencyTracker.isEnabled(action)).isTrue(); } @Test public void testIsEnabledAction_actionPropertyOverridesGlobalProperty() - throws DeviceConfig.BadConfigException { - LatencyTracker latencyTracker = new LatencyTracker(); + throws Exception { // using a single test action, but this applies to all actions int action = LatencyTracker.ACTION_SHOW_VOICE_INTERACTION; - String actionEnableProperty = "action_show_voice_interaction" + ACTION_ENABLE_SUFFIX; - Log.i(TAG, "setting property=" + actionEnableProperty + ", value=true"); + DeviceConfig.setProperty(NAMESPACE_LATENCY_TRACKER, + LatencyTracker.SETTINGS_ENABLED_KEY, "false", false); + mLatencyTracker.waitForGlobalEnabledState(false); - latencyTracker.mDeviceConfigPropertiesUpdated.close(); - Map properties = new HashMap() {{ - put(LatencyTracker.SETTINGS_ENABLED_KEY, "false"); - put(actionEnableProperty, "true"); - }}; + Map deviceConfigProperties = new HashMap<>(); + deviceConfigProperties.put("action_show_voice_interaction_enable", "true"); + deviceConfigProperties.put("action_show_voice_interaction_sample_interval", "1"); + deviceConfigProperties.put("action_show_voice_interaction_trace_threshold", "-1"); DeviceConfig.setProperties( - new DeviceConfig.Properties(DeviceConfig.NAMESPACE_LATENCY_TRACKER, - properties)); - waitForLatencyTrackerToUpdateProperties(latencyTracker); - assertThat(latencyTracker.isEnabled(action)).isTrue(); + new DeviceConfig.Properties(NAMESPACE_LATENCY_TRACKER, + deviceConfigProperties)); - latencyTracker.mDeviceConfigPropertiesUpdated.close(); - Log.i(TAG, "setting property=" + actionEnableProperty + ", value=false"); - properties.put(LatencyTracker.SETTINGS_ENABLED_KEY, "true"); - properties.put(actionEnableProperty, "false"); - DeviceConfig.setProperties( - new DeviceConfig.Properties(DeviceConfig.NAMESPACE_LATENCY_TRACKER, - properties)); - waitForLatencyTrackerToUpdateProperties(latencyTracker); - assertThat(latencyTracker.isEnabled(action)).isFalse(); + mLatencyTracker.waitForMatchingActionProperties( + new ActionProperties(action, true /* enabled */, 1 /* samplingInterval */, + -1 /* traceThreshold */)); + + assertThat(mLatencyTracker.isEnabled(action)).isTrue(); } - private void waitForLatencyTrackerToUpdateProperties(LatencyTracker latencyTracker) { - try { - Thread.sleep(TEST_TIMEOUT.toMillis()); - } catch (InterruptedException e) { - e.printStackTrace(); - } - assertThat(latencyTracker.mDeviceConfigPropertiesUpdated.block( - TEST_TIMEOUT.toMillis())).isTrue(); + @Test + public void testLogsWhenEnabled() throws Exception { + // using a single test action, but this applies to all actions + int action = LatencyTracker.ACTION_SHOW_VOICE_INTERACTION; + Map deviceConfigProperties = new HashMap<>(); + deviceConfigProperties.put("action_show_voice_interaction_enable", "true"); + deviceConfigProperties.put("action_show_voice_interaction_sample_interval", "1"); + deviceConfigProperties.put("action_show_voice_interaction_trace_threshold", "-1"); + DeviceConfig.setProperties( + new DeviceConfig.Properties(NAMESPACE_LATENCY_TRACKER, + deviceConfigProperties)); + mLatencyTracker.waitForMatchingActionProperties( + new ActionProperties(action, true /* enabled */, 1 /* samplingInterval */, + -1 /* traceThreshold */)); + + mLatencyTracker.logAction(action, 1234); + assertThat(mLatencyTracker.getEventsWrittenToFrameworkStats(action)).hasSize(1); + LatencyTracker.FrameworkStatsLogEvent frameworkStatsLog = + mLatencyTracker.getEventsWrittenToFrameworkStats(action).get(0); + assertThat(frameworkStatsLog.logCode).isEqualTo(UI_ACTION_LATENCY_REPORTED); + assertThat(frameworkStatsLog.statsdAction).isEqualTo(STATSD_ACTION[action]); + assertThat(frameworkStatsLog.durationMillis).isEqualTo(1234); + + mLatencyTracker.clearEvents(); + + mLatencyTracker.onActionStart(action); + mLatencyTracker.onActionEnd(action); + // assert that action was logged, but we cannot confirm duration logged + assertThat(mLatencyTracker.getEventsWrittenToFrameworkStats(action)).hasSize(1); + frameworkStatsLog = mLatencyTracker.getEventsWrittenToFrameworkStats(action).get(0); + assertThat(frameworkStatsLog.logCode).isEqualTo(UI_ACTION_LATENCY_REPORTED); + assertThat(frameworkStatsLog.statsdAction).isEqualTo(STATSD_ACTION[action]); } - private List getAllActions() { - return Arrays.stream(LatencyTracker.class.getDeclaredFields()) - .filter(field -> field.getName().startsWith("ACTION_") - && Modifier.isStatic(field.getModifiers()) - && field.getType() == int.class) - .collect(Collectors.toList()); + @Test + public void testDoesNotLogWhenDisabled() throws Exception { + // using a single test action, but this applies to all actions + int action = LatencyTracker.ACTION_SHOW_VOICE_INTERACTION; + DeviceConfig.setProperty(NAMESPACE_LATENCY_TRACKER, "action_show_voice_interaction_enable", + "false", false); + mLatencyTracker.waitForActionEnabledState(action, false); + assertThat(mLatencyTracker.isEnabled(action)).isFalse(); + + mLatencyTracker.logAction(action, 1234); + assertThat(mLatencyTracker.getEventsWrittenToFrameworkStats(action)).isEmpty(); + + mLatencyTracker.onActionStart(action); + mLatencyTracker.onActionEnd(action); + assertThat(mLatencyTracker.getEventsWrittenToFrameworkStats(action)).isEmpty(); + } + + @Test + public void testOnActionEndDoesNotLogWithoutOnActionStart() + throws Exception { + // using a single test action, but this applies to all actions + int action = LatencyTracker.ACTION_SHOW_VOICE_INTERACTION; + DeviceConfig.setProperty(NAMESPACE_LATENCY_TRACKER, "action_show_voice_interaction_enable", + "true", false); + mLatencyTracker.waitForActionEnabledState(action, true); + assertThat(mLatencyTracker.isEnabled(action)).isTrue(); + + mLatencyTracker.onActionEnd(action); + assertThat(mLatencyTracker.getEventsWrittenToFrameworkStats(action)).isEmpty(); + } + + @Test + public void testOnActionEndDoesNotLogWhenCanceled() + throws Exception { + // using a single test action, but this applies to all actions + int action = LatencyTracker.ACTION_SHOW_VOICE_INTERACTION; + DeviceConfig.setProperty(NAMESPACE_LATENCY_TRACKER, "action_show_voice_interaction_enable", + "true", false); + mLatencyTracker.waitForActionEnabledState(action, true); + assertThat(mLatencyTracker.isEnabled(action)).isTrue(); + + mLatencyTracker.onActionStart(action); + mLatencyTracker.onActionCancel(action); + mLatencyTracker.onActionEnd(action); + assertThat(mLatencyTracker.getEventsWrittenToFrameworkStats(action)).isEmpty(); + } + + @Test + public void testNeverTriggersPerfettoWhenThresholdNegative() + throws Exception { + // using a single test action, but this applies to all actions + int action = LatencyTracker.ACTION_SHOW_VOICE_INTERACTION; + Map deviceConfigProperties = new HashMap<>(); + deviceConfigProperties.put("action_show_voice_interaction_enable", "true"); + deviceConfigProperties.put("action_show_voice_interaction_sample_interval", "1"); + deviceConfigProperties.put("action_show_voice_interaction_trace_threshold", "-1"); + DeviceConfig.setProperties( + new DeviceConfig.Properties(NAMESPACE_LATENCY_TRACKER, + deviceConfigProperties)); + mLatencyTracker.waitForMatchingActionProperties( + new ActionProperties(action, true /* enabled */, 1 /* samplingInterval */, + -1 /* traceThreshold */)); + + mLatencyTracker.onActionStart(action); + mLatencyTracker.onActionEnd(action); + assertThat(mLatencyTracker.getTriggeredPerfettoTraceNames()).isEmpty(); + } + + @Test + public void testNeverTriggersPerfettoWhenDisabled() + throws Exception { + // using a single test action, but this applies to all actions + int action = LatencyTracker.ACTION_SHOW_VOICE_INTERACTION; + Map deviceConfigProperties = new HashMap<>(); + deviceConfigProperties.put("action_show_voice_interaction_enable", "false"); + deviceConfigProperties.put("action_show_voice_interaction_sample_interval", "1"); + deviceConfigProperties.put("action_show_voice_interaction_trace_threshold", "1"); + DeviceConfig.setProperties( + new DeviceConfig.Properties(NAMESPACE_LATENCY_TRACKER, + deviceConfigProperties)); + mLatencyTracker.waitForMatchingActionProperties( + new ActionProperties(action, false /* enabled */, 1 /* samplingInterval */, + 1 /* traceThreshold */)); + + mLatencyTracker.onActionStart(action); + mLatencyTracker.onActionEnd(action); + assertThat(mLatencyTracker.getTriggeredPerfettoTraceNames()).isEmpty(); + } + + @Test + public void testTriggersPerfettoWhenAboveThreshold() + throws Exception { + // using a single test action, but this applies to all actions + int action = LatencyTracker.ACTION_SHOW_VOICE_INTERACTION; + Map deviceConfigProperties = new HashMap<>(); + deviceConfigProperties.put("action_show_voice_interaction_enable", "true"); + deviceConfigProperties.put("action_show_voice_interaction_sample_interval", "1"); + deviceConfigProperties.put("action_show_voice_interaction_trace_threshold", "1"); + DeviceConfig.setProperties( + new DeviceConfig.Properties(NAMESPACE_LATENCY_TRACKER, + deviceConfigProperties)); + mLatencyTracker.waitForMatchingActionProperties( + new ActionProperties(action, true /* enabled */, 1 /* samplingInterval */, + 1 /* traceThreshold */)); + + mLatencyTracker.onActionStart(action); + // We need to sleep here to ensure that the end call is past the set trace threshold (1ms) + Thread.sleep(5 /* millis */); + mLatencyTracker.onActionEnd(action); + assertThat(mLatencyTracker.getTriggeredPerfettoTraceNames()).hasSize(1); + assertThat(mLatencyTracker.getTriggeredPerfettoTraceNames().get(0)).isEqualTo( + "com.android.telemetry.latency-tracker-ACTION_SHOW_VOICE_INTERACTION"); + } + + @Test + public void testNeverTriggersPerfettoWhenBelowThreshold() + throws Exception { + // using a single test action, but this applies to all actions + int action = LatencyTracker.ACTION_SHOW_VOICE_INTERACTION; + Map deviceConfigProperties = new HashMap<>(); + deviceConfigProperties.put("action_show_voice_interaction_enable", "true"); + deviceConfigProperties.put("action_show_voice_interaction_sample_interval", "1"); + deviceConfigProperties.put("action_show_voice_interaction_trace_threshold", "1000"); + DeviceConfig.setProperties( + new DeviceConfig.Properties(NAMESPACE_LATENCY_TRACKER, + deviceConfigProperties)); + mLatencyTracker.waitForMatchingActionProperties( + new ActionProperties(action, true /* enabled */, 1 /* samplingInterval */, + 1000 /* traceThreshold */)); + + mLatencyTracker.onActionStart(action); + // No sleep here to ensure that end call comes before 1000ms threshold + mLatencyTracker.onActionEnd(action); + assertThat(mLatencyTracker.getTriggeredPerfettoTraceNames()).isEmpty(); + } + + private List getAllActionFields() { + return Arrays.stream(LatencyTracker.class.getDeclaredFields()).filter( + field -> field.getName().startsWith("ACTION_") && Modifier.isStatic( + field.getModifiers()) && field.getType() == int.class).collect( + Collectors.toList()); } private int getIntFieldChecked(Field field) { diff --git a/core/tests/coretests/testdoubles/Android.bp b/core/tests/coretests/testdoubles/Android.bp new file mode 100644 index 0000000000000..35f6911ce4815 --- /dev/null +++ b/core/tests/coretests/testdoubles/Android.bp @@ -0,0 +1,19 @@ +package { + // See: http://go/android-license-faq + // A large-scale-change added 'default_applicable_licenses' to import + // all of the 'license_kinds' from "frameworks_base_license" + // to get the below license kinds: + // SPDX-license-identifier-Apache-2.0 + // SPDX-license-identifier-BSD + // legacy_unencumbered + default_applicable_licenses: ["frameworks_base_license"], +} + +filegroup { + name: "FrameworksCoreTestDoubles-sources", + srcs: ["src/**/*.java"], + visibility: [ + "//frameworks/base/core/tests/coretests", + "//frameworks/base/services/tests/voiceinteractiontests", + ], +} diff --git a/core/tests/coretests/testdoubles/OWNERS b/core/tests/coretests/testdoubles/OWNERS new file mode 100644 index 0000000000000..baf92ec067c3e --- /dev/null +++ b/core/tests/coretests/testdoubles/OWNERS @@ -0,0 +1 @@ +per-file *LatencyTracker* = file:/core/java/com/android/internal/util/LATENCY_TRACKER_OWNERS diff --git a/core/tests/coretests/testdoubles/src/com/android/internal/util/FakeLatencyTracker.java b/core/tests/coretests/testdoubles/src/com/android/internal/util/FakeLatencyTracker.java new file mode 100644 index 0000000000000..306ecdee9167a --- /dev/null +++ b/core/tests/coretests/testdoubles/src/com/android/internal/util/FakeLatencyTracker.java @@ -0,0 +1,285 @@ +/* + * Copyright (C) 2023 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.internal.util; + +import static com.android.internal.util.LatencyTracker.ActionProperties.ENABLE_SUFFIX; +import static com.android.internal.util.LatencyTracker.ActionProperties.SAMPLE_INTERVAL_SUFFIX; +import static com.android.internal.util.LatencyTracker.ActionProperties.TRACE_THRESHOLD_SUFFIX; + +import static com.google.common.truth.Truth.assertThat; + +import android.os.ConditionVariable; +import android.provider.DeviceConfig; +import android.util.Log; +import android.util.SparseArray; + +import androidx.annotation.Nullable; + +import com.android.internal.annotations.GuardedBy; + +import com.google.common.collect.ImmutableMap; + +import java.time.Duration; +import java.util.ArrayList; +import java.util.Collections; +import java.util.HashMap; +import java.util.List; +import java.util.Locale; +import java.util.Map; +import java.util.concurrent.Callable; +import java.util.concurrent.atomic.AtomicReference; + +public final class FakeLatencyTracker extends LatencyTracker { + + private static final String TAG = "FakeLatencyTracker"; + private static final Duration FORCE_UPDATE_TIMEOUT = Duration.ofSeconds(1); + + private final Object mLock = new Object(); + @GuardedBy("mLock") + private final Map> mLatenciesLogged; + @GuardedBy("mLock") + private final List mPerfettoTraceNamesTriggered; + private final AtomicReference> mLastPropertiesUpdate = + new AtomicReference<>(); + @Nullable + @GuardedBy("mLock") + private Callable mShouldClosePropertiesUpdatedCallable = null; + private final ConditionVariable mDeviceConfigPropertiesUpdated = new ConditionVariable(); + + public static FakeLatencyTracker create() throws Exception { + Log.i(TAG, "create"); + disableForAllActions(); + FakeLatencyTracker fakeLatencyTracker = new FakeLatencyTracker(); + // always return the fake in the disabled state and let the client control the desired state + fakeLatencyTracker.waitForGlobalEnabledState(false); + fakeLatencyTracker.waitForAllPropertiesEnableState(false); + return fakeLatencyTracker; + } + + FakeLatencyTracker() { + super(); + mLatenciesLogged = new HashMap<>(); + mPerfettoTraceNamesTriggered = new ArrayList<>(); + } + + private static void disableForAllActions() throws DeviceConfig.BadConfigException { + Map properties = new HashMap<>(); + properties.put(LatencyTracker.SETTINGS_ENABLED_KEY, "false"); + for (int action : STATSD_ACTION) { + Log.d(TAG, "disabling action=" + action + ", property=" + getNameOfAction( + action).toLowerCase(Locale.ROOT) + ENABLE_SUFFIX); + properties.put(getNameOfAction(action).toLowerCase(Locale.ROOT) + ENABLE_SUFFIX, + "false"); + } + + DeviceConfig.setProperties( + new DeviceConfig.Properties(DeviceConfig.NAMESPACE_LATENCY_TRACKER, properties)); + } + + public void forceEnabled(int action, int traceThresholdMillis) + throws Exception { + String actionName = getNameOfAction(STATSD_ACTION[action]).toLowerCase(Locale.ROOT); + String actionEnableProperty = actionName + ENABLE_SUFFIX; + String actionSampleProperty = actionName + SAMPLE_INTERVAL_SUFFIX; + String actionTraceProperty = actionName + TRACE_THRESHOLD_SUFFIX; + Log.i(TAG, "setting property=" + actionTraceProperty + ", value=" + traceThresholdMillis); + Log.i(TAG, "setting property=" + actionEnableProperty + ", value=true"); + + Map properties = new HashMap<>(ImmutableMap.of( + actionEnableProperty, "true", + // Fake forces to sample every event + actionSampleProperty, String.valueOf(1), + actionTraceProperty, String.valueOf(traceThresholdMillis) + )); + DeviceConfig.setProperties( + new DeviceConfig.Properties(DeviceConfig.NAMESPACE_LATENCY_TRACKER, properties)); + waitForMatchingActionProperties( + new ActionProperties(action, true /* enabled */, 1 /* samplingInterval */, + traceThresholdMillis)); + } + + public List getEventsWrittenToFrameworkStats(@Action int action) { + synchronized (mLock) { + Log.i(TAG, "getEventsWrittenToFrameworkStats: mLatenciesLogged=" + mLatenciesLogged); + return mLatenciesLogged.getOrDefault(action, Collections.emptyList()); + } + } + + public List getTriggeredPerfettoTraceNames() { + synchronized (mLock) { + return mPerfettoTraceNamesTriggered; + } + } + + public void clearEvents() { + synchronized (mLock) { + mLatenciesLogged.clear(); + mPerfettoTraceNamesTriggered.clear(); + } + } + + @Override + public void onDeviceConfigPropertiesUpdated(SparseArray actionProperties) { + Log.d(TAG, "onDeviceConfigPropertiesUpdated: " + actionProperties); + mLastPropertiesUpdate.set(actionProperties); + synchronized (mLock) { + if (mShouldClosePropertiesUpdatedCallable != null) { + try { + boolean shouldClosePropertiesUpdated = + mShouldClosePropertiesUpdatedCallable.call(); + Log.i(TAG, "shouldClosePropertiesUpdatedCallable callable result=" + + shouldClosePropertiesUpdated); + if (shouldClosePropertiesUpdated) { + Log.i(TAG, "shouldClosePropertiesUpdatedCallable=true, opening condition"); + mShouldClosePropertiesUpdatedCallable = null; + mDeviceConfigPropertiesUpdated.open(); + } + } catch (Exception e) { + Log.e(TAG, "exception when calling callable", e); + throw new RuntimeException(e); + } + } else { + Log.i(TAG, "no conditional callable set, opening condition"); + mDeviceConfigPropertiesUpdated.open(); + } + } + } + + @Override + public void onTriggerPerfetto(String triggerName) { + synchronized (mLock) { + mPerfettoTraceNamesTriggered.add(triggerName); + } + } + + @Override + public void onLogToFrameworkStats(FrameworkStatsLogEvent event) { + synchronized (mLock) { + Log.i(TAG, "onLogToFrameworkStats: event=" + event); + List eventList = mLatenciesLogged.getOrDefault(event.action, + new ArrayList<>()); + eventList.add(event); + mLatenciesLogged.put(event.action, eventList); + } + } + + public void waitForAllPropertiesEnableState(boolean enabledState) throws Exception { + Log.i(TAG, "waitForAllPropertiesEnableState: enabledState=" + enabledState); + synchronized (mLock) { + Log.i(TAG, "closing condition"); + mDeviceConfigPropertiesUpdated.close(); + // Update the callable to only close the properties updated condition when all the + // desired properties have been updated. The DeviceConfig callbacks may happen multiple + // times so testing the resulting updates is required. + mShouldClosePropertiesUpdatedCallable = () -> { + Log.i(TAG, "verifying if last properties update has all properties enable=" + + enabledState); + SparseArray newProperties = mLastPropertiesUpdate.get(); + if (newProperties != null) { + for (int i = 0; i < newProperties.size(); i++) { + if (newProperties.get(i).isEnabled() != enabledState) { + return false; + } + } + } + return true; + }; + if (mShouldClosePropertiesUpdatedCallable.call()) { + return; + } + } + Log.i(TAG, "waiting for condition"); + assertThat(mDeviceConfigPropertiesUpdated.block(FORCE_UPDATE_TIMEOUT.toMillis())).isTrue(); + } + + public void waitForMatchingActionProperties(ActionProperties actionProperties) + throws Exception { + Log.i(TAG, "waitForMatchingActionProperties: actionProperties=" + actionProperties); + synchronized (mLock) { + Log.i(TAG, "closing condition"); + mDeviceConfigPropertiesUpdated.close(); + // Update the callable to only close the properties updated condition when all the + // desired properties have been updated. The DeviceConfig callbacks may happen multiple + // times so testing the resulting updates is required. + mShouldClosePropertiesUpdatedCallable = () -> { + Log.i(TAG, "verifying if last properties update contains matching property =" + + actionProperties); + SparseArray newProperties = mLastPropertiesUpdate.get(); + if (newProperties != null) { + if (newProperties.size() > 0) { + return newProperties.get(actionProperties.getAction()).equals( + actionProperties); + } + } + return false; + }; + if (mShouldClosePropertiesUpdatedCallable.call()) { + return; + } + } + Log.i(TAG, "waiting for condition"); + assertThat(mDeviceConfigPropertiesUpdated.block(FORCE_UPDATE_TIMEOUT.toMillis())).isTrue(); + } + + public void waitForActionEnabledState(int action, boolean enabledState) throws Exception { + Log.i(TAG, "waitForActionEnabledState:" + + " action=" + action + ", enabledState=" + enabledState); + synchronized (mLock) { + Log.i(TAG, "closing condition"); + mDeviceConfigPropertiesUpdated.close(); + // Update the callable to only close the properties updated condition when all the + // desired properties have been updated. The DeviceConfig callbacks may happen multiple + // times so testing the resulting updates is required. + mShouldClosePropertiesUpdatedCallable = () -> { + Log.i(TAG, "verifying if last properties update contains action=" + action + + ", enabledState=" + enabledState); + SparseArray newProperties = mLastPropertiesUpdate.get(); + if (newProperties != null) { + if (newProperties.size() > 0) { + return newProperties.get(action).isEnabled() == enabledState; + } + } + return false; + }; + if (mShouldClosePropertiesUpdatedCallable.call()) { + return; + } + } + Log.i(TAG, "waiting for condition"); + assertThat(mDeviceConfigPropertiesUpdated.block(FORCE_UPDATE_TIMEOUT.toMillis())).isTrue(); + } + + public void waitForGlobalEnabledState(boolean enabledState) throws Exception { + Log.i(TAG, "waitForGlobalEnabledState: enabledState=" + enabledState); + synchronized (mLock) { + Log.i(TAG, "closing condition"); + mDeviceConfigPropertiesUpdated.close(); + // Update the callable to only close the properties updated condition when all the + // desired properties have been updated. The DeviceConfig callbacks may happen multiple + // times so testing the resulting updates is required. + mShouldClosePropertiesUpdatedCallable = () -> { + //noinspection deprecation + return isEnabled() == enabledState; + }; + if (mShouldClosePropertiesUpdatedCallable.call()) { + return; + } + } + Log.i(TAG, "waiting for condition"); + assertThat(mDeviceConfigPropertiesUpdated.block(FORCE_UPDATE_TIMEOUT.toMillis())).isTrue(); + } +}