Android/frameworks_base
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

rework LatencyTracker for testing

Browse Source 
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
Download Patch File Download Diff File Expand all files Collapse all files

210
core/java/com/android/internal/util/LatencyTracker.java
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 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.
* <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
* 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<Session> mSessions = new SparseArray<>();
@@ -294,20 +292,21 @@ public class LatencyTracker {
private final SparseArray<ActionProperties> 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
*
* <p>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> 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
+ "}";
}
}
}

1
core/tests/coretests/Android.bp
View File

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

67
core/tests/coretests/src/com/android/internal/util/FakeLatencyTrackerTest.java Normal file
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);
}
}

298
core/tests/coretests/src/com/android/internal/util/LatencyTrackerTest.java
View File

@@ -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<Field> actions = getAllActions();
List<Field> actions = getAllActionFields();
Map<Integer, String> 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<Field> cujEnumFields = getAllActions();
List<Field> cujEnumFields = getAllActionFields();
HashSet<Integer> 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<String, String> properties = new HashMap<String, String>() {{
put(LatencyTracker.SETTINGS_ENABLED_KEY, "false");
put(actionEnableProperty, "true");
}};
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(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<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.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() {
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<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) {

19
core/tests/coretests/testdoubles/Android.bp Normal file
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",
],
}

1
core/tests/coretests/testdoubles/OWNERS Normal file
View File

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

285
core/tests/coretests/testdoubles/src/com/android/internal/util/FakeLatencyTracker.java Normal file
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();
}
}