rework LatencyTracker for testing

Modify the VisibleForTesting methods of the LatencyTracker class to
improve the testibility. The class is modified to support overriding
callbacks when actions/outcomes are taken by LatencyTracker based on
its inputs.

Test classes using LatencyTracker can now verify:
1. When PerfettoTrigger has been triggered
2. When FrameworkStatsLog is written to

This CL fixes a bug where only the global enable flag is
checked when calling onActionStart and onActionEnd. It also
adds a new enabled check for when the public logAction API is called.

Test: atest LatencyTrackerTest
Bug: 269254242
Change-Id: I4f8d21bca4a9e52fb3875e88387b8c8641f64c94
This commit is contained in:
Nicholas Ambur
2023-03-01 09:51:12 +00:00
parent 31302573d7
commit 5de4d65996
7 changed files with 759 additions and 122 deletions

View File

@@ -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 static com.android.internal.util.LatencyTracker.ActionProperties.TRACE_THRESHOLD_SUFFIX;
import android.Manifest; import android.Manifest;
import android.annotation.ElapsedRealtimeLong;
import android.annotation.IntDef; import android.annotation.IntDef;
import android.annotation.NonNull; import android.annotation.NonNull;
import android.annotation.Nullable; import android.annotation.Nullable;
@@ -55,7 +56,6 @@ import android.annotation.RequiresPermission;
import android.app.ActivityThread; import android.app.ActivityThread;
import android.content.Context; import android.content.Context;
import android.os.Build; import android.os.Build;
import android.os.ConditionVariable;
import android.os.SystemClock; import android.os.SystemClock;
import android.os.Trace; import android.os.Trace;
import android.provider.DeviceConfig; 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 * 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. * outputs it to logcat so these latencies can be captured by tests and then used for dashboards.
* <p> * <p>
* 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 * eventually we'd want to merge these two packages together so Keyguard can use common classes
* that are shared with SystemUI. * that are shared with SystemUI.
*/ */
@@ -285,8 +285,6 @@ public class LatencyTracker {
UIACTION_LATENCY_REPORTED__ACTION__ACTION_REQUEST_IME_HIDDEN, UIACTION_LATENCY_REPORTED__ACTION__ACTION_REQUEST_IME_HIDDEN,
}; };
private static LatencyTracker sLatencyTracker;
private final Object mLock = new Object(); private final Object mLock = new Object();
@GuardedBy("mLock") @GuardedBy("mLock")
private final SparseArray<Session> mSessions = new SparseArray<>(); private final SparseArray<Session> mSessions = new SparseArray<>();
@@ -294,20 +292,21 @@ public class LatencyTracker {
private final SparseArray<ActionProperties> mActionPropertiesMap = new SparseArray<>(); private final SparseArray<ActionProperties> mActionPropertiesMap = new SparseArray<>();
@GuardedBy("mLock") @GuardedBy("mLock")
private boolean mEnabled; private boolean mEnabled;
@VisibleForTesting
public final ConditionVariable mDeviceConfigPropertiesUpdated = new ConditionVariable();
public static LatencyTracker getInstance(Context context) { // Wrapping this in a holder class achieves lazy loading behavior
if (sLatencyTracker == null) { private static final class SLatencyTrackerHolder {
synchronized (LatencyTracker.class) { private static final LatencyTracker sLatencyTracker = new LatencyTracker();
if (sLatencyTracker == null) {
sLatencyTracker = new LatencyTracker();
}
}
}
return sLatencyTracker;
} }
public static LatencyTracker getInstance(Context context) {
return SLatencyTrackerHolder.sLatencyTracker;
}
/**
* Constructor for LatencyTracker
*
* <p>This constructor is only visible for test classes to inject their own consumer callbacks
*/
@RequiresPermission(Manifest.permission.READ_DEVICE_CONFIG) @RequiresPermission(Manifest.permission.READ_DEVICE_CONFIG)
@VisibleForTesting @VisibleForTesting
public LatencyTracker() { public LatencyTracker() {
@@ -349,11 +348,8 @@ public class LatencyTracker {
properties.getInt(actionName + TRACE_THRESHOLD_SUFFIX, properties.getInt(actionName + TRACE_THRESHOLD_SUFFIX,
legacyActionTraceThreshold))); legacyActionTraceThreshold)));
} }
if (DEBUG) { onDeviceConfigPropertiesUpdated(mActionPropertiesMap);
Log.d(TAG, "updated action properties: " + mActionPropertiesMap);
}
} }
mDeviceConfigPropertiesUpdated.open();
} }
/** /**
@@ -477,7 +473,7 @@ public class LatencyTracker {
*/ */
public void onActionStart(@Action int action, String tag) { public void onActionStart(@Action int action, String tag) {
synchronized (mLock) { synchronized (mLock) {
if (!isEnabled()) { if (!isEnabled(action)) {
return; return;
} }
// skip if the action is already instrumenting. // skip if the action is already instrumenting.
@@ -501,7 +497,7 @@ public class LatencyTracker {
*/ */
public void onActionEnd(@Action int action) { public void onActionEnd(@Action int action) {
synchronized (mLock) { synchronized (mLock) {
if (!isEnabled()) { if (!isEnabled(action)) {
return; return;
} }
Session session = mSessions.get(action); 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. * 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; boolean shouldSample;
int traceThreshold; int traceThreshold;
synchronized (mLock) { synchronized (mLock) {
if (!isEnabled(action)) {
return;
}
ActionProperties actionProperties = mActionPropertiesMap.get(action); ActionProperties actionProperties = mActionPropertiesMap.get(action);
if (actionProperties == null) { if (actionProperties == null) {
return; return;
@@ -559,28 +576,24 @@ public class LatencyTracker {
traceThreshold = actionProperties.getTraceThreshold(); traceThreshold = actionProperties.getTraceThreshold();
} }
if (traceThreshold > 0 && duration >= traceThreshold) { boolean shouldTriggerPerfettoTrace = traceThreshold > 0 && duration >= traceThreshold;
PerfettoTrigger.trigger(getTraceTriggerNameForAction(action));
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); EventLog.writeEvent(EventLogTags.SYSUI_LATENCY, action, duration);
if (shouldTriggerPerfettoTrace) {
if (writeToStatsLog) { onTriggerPerfetto(getTraceTriggerNameForAction(action));
FrameworkStatsLog.write( }
FrameworkStatsLog.UI_ACTION_LATENCY_REPORTED, STATSD_ACTION[action], duration); if (shouldSample) {
onLogToFrameworkStats(
new FrameworkStatsLogEvent(action, FrameworkStatsLog.UI_ACTION_LATENCY_REPORTED,
STATSD_ACTION[action], duration)
);
} }
} }
@@ -642,10 +655,10 @@ public class LatencyTracker {
} }
@VisibleForTesting @VisibleForTesting
static class ActionProperties { public static class ActionProperties {
static final String ENABLE_SUFFIX = "_enable"; static final String ENABLE_SUFFIX = "_enable";
static final String SAMPLE_INTERVAL_SUFFIX = "_sample_interval"; 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 LEGACY_TRACE_THRESHOLD_SUFFIX = "";
static final String TRACE_THRESHOLD_SUFFIX = "_trace_threshold"; static final String TRACE_THRESHOLD_SUFFIX = "_trace_threshold";
@@ -655,7 +668,8 @@ public class LatencyTracker {
private final int mSamplingInterval; private final int mSamplingInterval;
private final int mTraceThreshold; private final int mTraceThreshold;
ActionProperties( @VisibleForTesting
public ActionProperties(
@Action int action, @Action int action,
boolean enabled, boolean enabled,
int samplingInterval, int samplingInterval,
@@ -668,20 +682,24 @@ public class LatencyTracker {
this.mTraceThreshold = traceThreshold; this.mTraceThreshold = traceThreshold;
} }
@VisibleForTesting
@Action @Action
int getAction() { public int getAction() {
return mAction; return mAction;
} }
boolean isEnabled() { @VisibleForTesting
public boolean isEnabled() {
return mEnabled; return mEnabled;
} }
int getSamplingInterval() { @VisibleForTesting
public int getSamplingInterval() {
return mSamplingInterval; return mSamplingInterval;
} }
int getTraceThreshold() { @VisibleForTesting
public int getTraceThreshold() {
return mTraceThreshold; return mTraceThreshold;
} }
@@ -694,5 +712,103 @@ public class LatencyTracker {
+ ", mTraceThreshold=" + mTraceThreshold + ", 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> 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}
*
* <p>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
+ "}";
}
} }
} }

View File

@@ -20,6 +20,7 @@ android_test {
"BinderProxyCountingTestService/src/**/*.java", "BinderProxyCountingTestService/src/**/*.java",
"BinderDeathRecipientHelperApp/src/**/*.java", "BinderDeathRecipientHelperApp/src/**/*.java",
"aidl/**/I*.aidl", "aidl/**/I*.aidl",
":FrameworksCoreTestDoubles-sources",
], ],
aidl: { aidl: {

View File

@@ -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.
*
* <p>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<LatencyTracker.FrameworkStatsLogEvent> 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);
}
}

View File

@@ -16,19 +16,22 @@
package com.android.internal.util; package com.android.internal.util;
import static android.provider.DeviceConfig.NAMESPACE_LATENCY_TRACKER;
import static android.text.TextUtils.formatSimple; 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.android.internal.util.LatencyTracker.STATSD_ACTION;
import static com.google.common.truth.Truth.assertThat; import static com.google.common.truth.Truth.assertThat;
import static com.google.common.truth.Truth.assertWithMessage; import static com.google.common.truth.Truth.assertWithMessage;
import android.provider.DeviceConfig; import android.provider.DeviceConfig;
import android.util.Log;
import androidx.test.ext.junit.runners.AndroidJUnit4; import androidx.test.ext.junit.runners.AndroidJUnit4;
import androidx.test.filters.SmallTest; import androidx.test.filters.SmallTest;
import com.android.internal.util.LatencyTracker.ActionProperties;
import com.google.common.truth.Expect; import com.google.common.truth.Expect;
import org.junit.Before; import org.junit.Before;
@@ -38,7 +41,6 @@ import org.junit.runner.RunWith;
import java.lang.reflect.Field; import java.lang.reflect.Field;
import java.lang.reflect.Modifier; import java.lang.reflect.Modifier;
import java.time.Duration;
import java.util.Arrays; import java.util.Arrays;
import java.util.HashMap; import java.util.HashMap;
import java.util.HashSet; import java.util.HashSet;
@@ -49,27 +51,23 @@ import java.util.stream.Collectors;
@SmallTest @SmallTest
@RunWith(AndroidJUnit4.class) @RunWith(AndroidJUnit4.class)
public class LatencyTrackerTest { 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 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 @Rule
public final Expect mExpect = Expect.create(); 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 @Before
public void setUp() { public void setUp() throws Exception {
DeviceConfig.deleteProperty(DeviceConfig.NAMESPACE_LATENCY_TRACKER, mLatencyTracker = FakeLatencyTracker.create();
LatencyTracker.SETTINGS_ENABLED_KEY);
getAllActions().forEach(action -> {
DeviceConfig.deleteProperty(DeviceConfig.NAMESPACE_LATENCY_TRACKER,
action.getName().toLowerCase() + ACTION_ENABLE_SUFFIX);
});
} }
@Test @Test
public void testCujsMapToEnumsCorrectly() { public void testCujsMapToEnumsCorrectly() {
List<Field> actions = getAllActions(); List<Field> actions = getAllActionFields();
Map<Integer, String> enumsMap = Arrays.stream(FrameworkStatsLog.class.getDeclaredFields()) Map<Integer, String> enumsMap = Arrays.stream(FrameworkStatsLog.class.getDeclaredFields())
.filter(f -> f.getName().startsWith(ENUM_NAME_PREFIX) .filter(f -> f.getName().startsWith(ENUM_NAME_PREFIX)
&& Modifier.isStatic(f.getModifiers()) && Modifier.isStatic(f.getModifiers())
@@ -101,7 +99,7 @@ public class LatencyTrackerTest {
@Test @Test
public void testCujTypeEnumCorrectlyDefined() throws Exception { public void testCujTypeEnumCorrectlyDefined() throws Exception {
List<Field> cujEnumFields = getAllActions(); List<Field> cujEnumFields = getAllActionFields();
HashSet<Integer> allValues = new HashSet<>(); HashSet<Integer> allValues = new HashSet<>();
for (Field field : cujEnumFields) { for (Field field : cujEnumFields) {
int fieldValue = field.getInt(null); int fieldValue = field.getInt(null);
@@ -118,92 +116,242 @@ public class LatencyTrackerTest {
} }
@Test @Test
public void testIsEnabled_globalEnabled() { public void testIsEnabled_trueWhenGlobalEnabled() throws Exception {
DeviceConfig.setProperty(DeviceConfig.NAMESPACE_LATENCY_TRACKER, DeviceConfig.setProperty(NAMESPACE_LATENCY_TRACKER,
LatencyTracker.SETTINGS_ENABLED_KEY, "true", false); LatencyTracker.SETTINGS_ENABLED_KEY, "true", false);
LatencyTracker latencyTracker = new LatencyTracker(); mLatencyTracker.waitForGlobalEnabledState(true);
waitForLatencyTrackerToUpdateProperties(latencyTracker); mLatencyTracker.waitForAllPropertiesEnableState(true);
assertThat(latencyTracker.isEnabled()).isTrue();
//noinspection deprecation
assertThat(mLatencyTracker.isEnabled()).isTrue();
} }
@Test @Test
public void testIsEnabled_globalDisabled() { public void testIsEnabled_falseWhenGlobalDisabled() throws Exception {
DeviceConfig.setProperty(DeviceConfig.NAMESPACE_LATENCY_TRACKER, DeviceConfig.setProperty(NAMESPACE_LATENCY_TRACKER,
LatencyTracker.SETTINGS_ENABLED_KEY, "false", false); LatencyTracker.SETTINGS_ENABLED_KEY, "false", false);
LatencyTracker latencyTracker = new LatencyTracker(); mLatencyTracker.waitForGlobalEnabledState(false);
waitForLatencyTrackerToUpdateProperties(latencyTracker); mLatencyTracker.waitForAllPropertiesEnableState(false);
assertThat(latencyTracker.isEnabled()).isFalse();
//noinspection deprecation
assertThat(mLatencyTracker.isEnabled()).isFalse();
} }
@Test @Test
public void testIsEnabledAction_useGlobalValueWhenActionEnableIsNotSet() { public void testIsEnabledAction_useGlobalValueWhenActionEnableIsNotSet()
LatencyTracker latencyTracker = new LatencyTracker(); throws Exception {
// using a single test action, but this applies to all actions // using a single test action, but this applies to all actions
int action = LatencyTracker.ACTION_SHOW_VOICE_INTERACTION; int action = LatencyTracker.ACTION_SHOW_VOICE_INTERACTION;
Log.i(TAG, "setting property=" + LatencyTracker.SETTINGS_ENABLED_KEY + ", value=true"); DeviceConfig.deleteProperty(NAMESPACE_LATENCY_TRACKER,
latencyTracker.mDeviceConfigPropertiesUpdated.close(); "action_show_voice_interaction_enable");
DeviceConfig.setProperty(DeviceConfig.NAMESPACE_LATENCY_TRACKER, mLatencyTracker.waitForAllPropertiesEnableState(false);
DeviceConfig.setProperty(NAMESPACE_LATENCY_TRACKER,
LatencyTracker.SETTINGS_ENABLED_KEY, "true", false); LatencyTracker.SETTINGS_ENABLED_KEY, "true", false);
waitForLatencyTrackerToUpdateProperties(latencyTracker); mLatencyTracker.waitForGlobalEnabledState(true);
assertThat( mLatencyTracker.waitForAllPropertiesEnableState(true);
latencyTracker.isEnabled(action)).isTrue();
Log.i(TAG, "setting property=" + LatencyTracker.SETTINGS_ENABLED_KEY assertThat(mLatencyTracker.isEnabled(action)).isTrue();
+ ", value=false");
latencyTracker.mDeviceConfigPropertiesUpdated.close();
DeviceConfig.setProperty(DeviceConfig.NAMESPACE_LATENCY_TRACKER,
LatencyTracker.SETTINGS_ENABLED_KEY, "false", false);
waitForLatencyTrackerToUpdateProperties(latencyTracker);
assertThat(latencyTracker.isEnabled(action)).isFalse();
} }
@Test @Test
public void testIsEnabledAction_actionPropertyOverridesGlobalProperty() public void testIsEnabledAction_actionPropertyOverridesGlobalProperty()
throws DeviceConfig.BadConfigException { throws Exception {
LatencyTracker latencyTracker = new LatencyTracker();
// using a single test action, but this applies to all actions // using a single test action, but this applies to all actions
int action = LatencyTracker.ACTION_SHOW_VOICE_INTERACTION; int action = LatencyTracker.ACTION_SHOW_VOICE_INTERACTION;
String actionEnableProperty = "action_show_voice_interaction" + ACTION_ENABLE_SUFFIX; DeviceConfig.setProperty(NAMESPACE_LATENCY_TRACKER,
Log.i(TAG, "setting property=" + actionEnableProperty + ", value=true"); LatencyTracker.SETTINGS_ENABLED_KEY, "false", false);
mLatencyTracker.waitForGlobalEnabledState(false);
latencyTracker.mDeviceConfigPropertiesUpdated.close(); Map<String, String> deviceConfigProperties = new HashMap<>();
Map<String, String> properties = new HashMap<String, String>() {{ deviceConfigProperties.put("action_show_voice_interaction_enable", "true");
put(LatencyTracker.SETTINGS_ENABLED_KEY, "false"); deviceConfigProperties.put("action_show_voice_interaction_sample_interval", "1");
put(actionEnableProperty, "true"); deviceConfigProperties.put("action_show_voice_interaction_trace_threshold", "-1");
}};
DeviceConfig.setProperties( DeviceConfig.setProperties(
new DeviceConfig.Properties(DeviceConfig.NAMESPACE_LATENCY_TRACKER, new DeviceConfig.Properties(NAMESPACE_LATENCY_TRACKER,
properties)); deviceConfigProperties));
waitForLatencyTrackerToUpdateProperties(latencyTracker);
assertThat(latencyTracker.isEnabled(action)).isTrue();
latencyTracker.mDeviceConfigPropertiesUpdated.close(); mLatencyTracker.waitForMatchingActionProperties(
Log.i(TAG, "setting property=" + actionEnableProperty + ", value=false"); new ActionProperties(action, true /* enabled */, 1 /* samplingInterval */,
properties.put(LatencyTracker.SETTINGS_ENABLED_KEY, "true"); -1 /* traceThreshold */));
properties.put(actionEnableProperty, "false");
DeviceConfig.setProperties( assertThat(mLatencyTracker.isEnabled(action)).isTrue();
new DeviceConfig.Properties(DeviceConfig.NAMESPACE_LATENCY_TRACKER,
properties));
waitForLatencyTrackerToUpdateProperties(latencyTracker);
assertThat(latencyTracker.isEnabled(action)).isFalse();
} }
private void waitForLatencyTrackerToUpdateProperties(LatencyTracker latencyTracker) { @Test
try { public void testLogsWhenEnabled() throws Exception {
Thread.sleep(TEST_TIMEOUT.toMillis()); // using a single test action, but this applies to all actions
} catch (InterruptedException e) { int action = LatencyTracker.ACTION_SHOW_VOICE_INTERACTION;
e.printStackTrace(); Map<String, String> deviceConfigProperties = new HashMap<>();
} deviceConfigProperties.put("action_show_voice_interaction_enable", "true");
assertThat(latencyTracker.mDeviceConfigPropertiesUpdated.block( deviceConfigProperties.put("action_show_voice_interaction_sample_interval", "1");
TEST_TIMEOUT.toMillis())).isTrue(); 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<Field> getAllActions() { @Test
return Arrays.stream(LatencyTracker.class.getDeclaredFields()) public void testDoesNotLogWhenDisabled() throws Exception {
.filter(field -> field.getName().startsWith("ACTION_") // using a single test action, but this applies to all actions
&& Modifier.isStatic(field.getModifiers()) int action = LatencyTracker.ACTION_SHOW_VOICE_INTERACTION;
&& field.getType() == int.class) DeviceConfig.setProperty(NAMESPACE_LATENCY_TRACKER, "action_show_voice_interaction_enable",
.collect(Collectors.toList()); "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<String, String> 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<String, String> 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<String, String> 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<String, String> 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<Field> 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) { private int getIntFieldChecked(Field field) {

View File

@@ -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",
],
}

View File

@@ -0,0 +1 @@
per-file *LatencyTracker* = file:/core/java/com/android/internal/util/LATENCY_TRACKER_OWNERS

View File

@@ -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<Integer, List<FrameworkStatsLogEvent>> mLatenciesLogged;
@GuardedBy("mLock")
private final List<String> mPerfettoTraceNamesTriggered;
private final AtomicReference<SparseArray<ActionProperties>> mLastPropertiesUpdate =
new AtomicReference<>();
@Nullable
@GuardedBy("mLock")
private Callable<Boolean> 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<String, String> 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<String, String> 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<FrameworkStatsLogEvent> getEventsWrittenToFrameworkStats(@Action int action) {
synchronized (mLock) {
Log.i(TAG, "getEventsWrittenToFrameworkStats: mLatenciesLogged=" + mLatenciesLogged);
return mLatenciesLogged.getOrDefault(action, Collections.emptyList());
}
}
public List<String> getTriggeredPerfettoTraceNames() {
synchronized (mLock) {
return mPerfettoTraceNamesTriggered;
}
}
public void clearEvents() {
synchronized (mLock) {
mLatenciesLogged.clear();
mPerfettoTraceNamesTriggered.clear();
}
}
@Override
public void onDeviceConfigPropertiesUpdated(SparseArray<ActionProperties> 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<FrameworkStatsLogEvent> 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<ActionProperties> 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<ActionProperties> 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<ActionProperties> 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();
}
}