only start latency measurement on successful phrase triggers

Bug: 265850090
Test: atest SoundTriggerMiddlewareLoggingTest
Change-Id: Ifaba86daea8ab92551ed75a251cd3a6ca55ffaed
This commit is contained in:
Nicholas Ambur
2023-02-13 18:32:30 +00:00
parent 71f29f316b
commit 91701dd240
3 changed files with 224 additions and 24 deletions

View File

@@ -29,6 +29,7 @@ android_test {
srcs: [
"src/**/*.java",
":FrameworksCoreTestDoubles-sources",
],
static_libs: [

View File

@@ -0,0 +1,181 @@
/*
* 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.server.soundtrigger_middleware;
import static com.android.internal.util.LatencyTracker.ACTION_SHOW_VOICE_INTERACTION;
import static com.google.common.truth.Truth.assertThat;
import static org.mockito.ArgumentMatchers.anyInt;
import static org.mockito.Mockito.verify;
import android.Manifest;
import android.app.ActivityThread;
import android.media.permission.Identity;
import android.media.permission.IdentityContext;
import android.media.soundtrigger.PhraseRecognitionEvent;
import android.media.soundtrigger.PhraseRecognitionExtra;
import android.media.soundtrigger.RecognitionEvent;
import android.media.soundtrigger.RecognitionStatus;
import android.media.soundtrigger_middleware.ISoundTriggerCallback;
import android.media.soundtrigger_middleware.ISoundTriggerModule;
import android.os.BatteryStatsInternal;
import android.os.Process;
import android.os.RemoteException;
import androidx.test.platform.app.InstrumentationRegistry;
import com.android.internal.util.FakeLatencyTracker;
import org.junit.After;
import org.junit.Before;
import org.junit.Test;
import org.junit.runner.RunWith;
import org.junit.runners.JUnit4;
import org.mockito.ArgumentCaptor;
import org.mockito.Mock;
import org.mockito.MockitoAnnotations;
import java.util.Optional;
@RunWith(JUnit4.class)
public class SoundTriggerMiddlewareLoggingTest {
private FakeLatencyTracker mLatencyTracker;
@Mock
private BatteryStatsInternal mBatteryStatsInternal;
@Mock
private ISoundTriggerMiddlewareInternal mDelegateMiddleware;
@Mock
private ISoundTriggerCallback mISoundTriggerCallback;
@Mock
private ISoundTriggerModule mSoundTriggerModule;
private SoundTriggerMiddlewareLogging mSoundTriggerMiddlewareLogging;
@Before
public void setUp() throws Exception {
MockitoAnnotations.initMocks(this);
InstrumentationRegistry.getInstrumentation().getUiAutomation()
.adoptShellPermissionIdentity(Manifest.permission.WRITE_DEVICE_CONFIG,
Manifest.permission.READ_DEVICE_CONFIG);
Identity identity = new Identity();
identity.uid = Process.myUid();
identity.pid = Process.myPid();
identity.packageName = ActivityThread.currentOpPackageName();
IdentityContext.create(identity);
mLatencyTracker = FakeLatencyTracker.create();
mLatencyTracker.forceEnabled(ACTION_SHOW_VOICE_INTERACTION, -1);
mSoundTriggerMiddlewareLogging = new SoundTriggerMiddlewareLogging(mLatencyTracker,
() -> mBatteryStatsInternal,
mDelegateMiddleware);
}
@After
public void tearDown() {
InstrumentationRegistry.getInstrumentation().getUiAutomation()
.dropShellPermissionIdentity();
}
@Test
public void testSetUpAndTearDown() {
}
@Test
public void testOnPhraseRecognitionStartsLatencyTrackerWithSuccessfulPhraseIdTrigger()
throws RemoteException {
ArgumentCaptor<ISoundTriggerCallback> soundTriggerCallbackCaptor = ArgumentCaptor.forClass(
ISoundTriggerCallback.class);
mSoundTriggerMiddlewareLogging.attach(0, mISoundTriggerCallback);
verify(mDelegateMiddleware).attach(anyInt(), soundTriggerCallbackCaptor.capture());
triggerPhraseRecognitionEvent(soundTriggerCallbackCaptor.getValue(),
RecognitionStatus.SUCCESS, Optional.of(100) /* keyphraseId */);
assertThat(mLatencyTracker.getActiveActionStartTime(
ACTION_SHOW_VOICE_INTERACTION)).isGreaterThan(-1);
}
@Test
public void testOnPhraseRecognitionRestartsActiveSession() throws RemoteException {
ArgumentCaptor<ISoundTriggerCallback> soundTriggerCallbackCaptor = ArgumentCaptor.forClass(
ISoundTriggerCallback.class);
mSoundTriggerMiddlewareLogging.attach(0, mISoundTriggerCallback);
verify(mDelegateMiddleware).attach(anyInt(), soundTriggerCallbackCaptor.capture());
triggerPhraseRecognitionEvent(soundTriggerCallbackCaptor.getValue(),
RecognitionStatus.SUCCESS, Optional.of(100) /* keyphraseId */);
long firstTriggerSessionStartTime = mLatencyTracker.getActiveActionStartTime(
ACTION_SHOW_VOICE_INTERACTION);
triggerPhraseRecognitionEvent(soundTriggerCallbackCaptor.getValue(),
RecognitionStatus.SUCCESS, Optional.of(100) /* keyphraseId */);
assertThat(mLatencyTracker.getActiveActionStartTime(
ACTION_SHOW_VOICE_INTERACTION)).isGreaterThan(-1);
assertThat(mLatencyTracker.getActiveActionStartTime(
ACTION_SHOW_VOICE_INTERACTION)).isNotEqualTo(firstTriggerSessionStartTime);
}
@Test
public void testOnPhraseRecognitionNeverStartsLatencyTrackerWithNonSuccessEvent()
throws RemoteException {
ArgumentCaptor<ISoundTriggerCallback> soundTriggerCallbackCaptor = ArgumentCaptor.forClass(
ISoundTriggerCallback.class);
mSoundTriggerMiddlewareLogging.attach(0, mISoundTriggerCallback);
verify(mDelegateMiddleware).attach(anyInt(), soundTriggerCallbackCaptor.capture());
triggerPhraseRecognitionEvent(soundTriggerCallbackCaptor.getValue(),
RecognitionStatus.ABORTED, Optional.of(100) /* keyphraseId */);
assertThat(
mLatencyTracker.getActiveActionStartTime(ACTION_SHOW_VOICE_INTERACTION)).isEqualTo(
-1);
}
@Test
public void testOnPhraseRecognitionNeverStartsLatencyTrackerWithNoKeyphraseId()
throws RemoteException {
ArgumentCaptor<ISoundTriggerCallback> soundTriggerCallbackCaptor = ArgumentCaptor.forClass(
ISoundTriggerCallback.class);
mSoundTriggerMiddlewareLogging.attach(0, mISoundTriggerCallback);
verify(mDelegateMiddleware).attach(anyInt(), soundTriggerCallbackCaptor.capture());
triggerPhraseRecognitionEvent(soundTriggerCallbackCaptor.getValue(),
RecognitionStatus.SUCCESS, Optional.empty() /* keyphraseId */);
assertThat(
mLatencyTracker.getActiveActionStartTime(ACTION_SHOW_VOICE_INTERACTION)).isEqualTo(
-1);
}
private void triggerPhraseRecognitionEvent(ISoundTriggerCallback callback,
@RecognitionStatus int triggerEventStatus, Optional<Integer> optionalKeyphraseId)
throws RemoteException {
// trigger a phrase recognition to start a latency tracker session
PhraseRecognitionEvent successEventWithKeyphraseId = new PhraseRecognitionEvent();
successEventWithKeyphraseId.common = new RecognitionEvent();
successEventWithKeyphraseId.common.status = triggerEventStatus;
if (optionalKeyphraseId.isPresent()) {
PhraseRecognitionExtra recognitionExtra = new PhraseRecognitionExtra();
recognitionExtra.id = optionalKeyphraseId.get();
successEventWithKeyphraseId.phraseExtras =
new PhraseRecognitionExtra[]{recognitionExtra};
}
callback.onPhraseRecognition(0 /* modelHandle */, successEventWithKeyphraseId,
0 /* captureSession */);
}
}

View File

@@ -26,6 +26,7 @@ import android.media.soundtrigger.PhraseRecognitionEvent;
import android.media.soundtrigger.PhraseSoundModel;
import android.media.soundtrigger.RecognitionConfig;
import android.media.soundtrigger.RecognitionEvent;
import android.media.soundtrigger.RecognitionStatus;
import android.media.soundtrigger.SoundModel;
import android.media.soundtrigger_middleware.ISoundTriggerCallback;
import android.media.soundtrigger_middleware.ISoundTriggerModule;
@@ -36,6 +37,8 @@ import android.os.RemoteException;
import android.os.SystemClock;
import android.util.Log;
import com.android.internal.annotations.VisibleForTesting;
import com.android.internal.util.ArrayUtils;
import com.android.internal.util.LatencyTracker;
import com.android.server.LocalServices;
@@ -44,6 +47,7 @@ import java.text.SimpleDateFormat;
import java.util.Date;
import java.util.LinkedList;
import java.util.Objects;
import java.util.function.Supplier;
/**
* An ISoundTriggerMiddlewareService decorator, which adds logging of all API calls (and
@@ -71,12 +75,23 @@ import java.util.Objects;
public class SoundTriggerMiddlewareLogging implements ISoundTriggerMiddlewareInternal, Dumpable {
private static final String TAG = "SoundTriggerMiddlewareLogging";
private final @NonNull ISoundTriggerMiddlewareInternal mDelegate;
private final @NonNull Context mContext;
private final @NonNull LatencyTracker mLatencyTracker;
private final @NonNull Supplier<BatteryStatsInternal> mBatteryStatsInternalSupplier;
public SoundTriggerMiddlewareLogging(@NonNull Context context,
@NonNull ISoundTriggerMiddlewareInternal delegate) {
this(LatencyTracker.getInstance(context),
() -> BatteryStatsHolder.INSTANCE,
delegate);
}
@VisibleForTesting
public SoundTriggerMiddlewareLogging(@NonNull LatencyTracker latencyTracker,
@NonNull Supplier<BatteryStatsInternal> batteryStatsInternalSupplier,
@NonNull ISoundTriggerMiddlewareInternal delegate) {
mDelegate = delegate;
mContext = context;
mLatencyTracker = latencyTracker;
mBatteryStatsInternalSupplier = batteryStatsInternalSupplier;
}
@Override
@@ -294,7 +309,7 @@ public class SoundTriggerMiddlewareLogging implements ISoundTriggerMiddlewareInt
public void onRecognition(int modelHandle, RecognitionEvent event, int captureSession)
throws RemoteException {
try {
BatteryStatsHolder.INSTANCE.noteWakingSoundTrigger(
mBatteryStatsInternalSupplier.get().noteWakingSoundTrigger(
SystemClock.elapsedRealtime(), mOriginatorIdentity.uid);
mCallbackDelegate.onRecognition(modelHandle, event, captureSession);
logVoidReturn("onRecognition", modelHandle, event);
@@ -309,7 +324,7 @@ public class SoundTriggerMiddlewareLogging implements ISoundTriggerMiddlewareInt
int captureSession)
throws RemoteException {
try {
BatteryStatsHolder.INSTANCE.noteWakingSoundTrigger(
mBatteryStatsInternalSupplier.get().noteWakingSoundTrigger(
SystemClock.elapsedRealtime(), mOriginatorIdentity.uid);
startKeyphraseEventLatencyTracking(event);
mCallbackDelegate.onPhraseRecognition(modelHandle, event, captureSession);
@@ -361,26 +376,6 @@ public class SoundTriggerMiddlewareLogging implements ISoundTriggerMiddlewareInt
logVoidReturnWithObject(this, mOriginatorIdentity, methodName, args);
}
/**
* Starts the latency tracking log for keyphrase hotword invocation.
* The measurement covers from when the SoundTrigger HAL emits an event to when the
* {@link android.service.voice.VoiceInteractionSession} system UI view is shown.
*/
private void startKeyphraseEventLatencyTracking(PhraseRecognitionEvent event) {
String latencyTrackerTag = null;
if (event.phraseExtras.length > 0) {
latencyTrackerTag = "KeyphraseId=" + event.phraseExtras[0].id;
}
LatencyTracker latencyTracker = LatencyTracker.getInstance(mContext);
// To avoid adding cancel to all of the different failure modes between here and
// showing the system UI, we defensively cancel once.
// Either we hit the LatencyTracker timeout of 15 seconds or we defensively cancel
// here if any error occurs.
latencyTracker.onActionCancel(LatencyTracker.ACTION_SHOW_VOICE_INTERACTION);
latencyTracker.onActionStart(LatencyTracker.ACTION_SHOW_VOICE_INTERACTION,
latencyTrackerTag);
}
@Override
public IBinder asBinder() {
return mCallbackDelegate.asBinder();
@@ -399,6 +394,29 @@ public class SoundTriggerMiddlewareLogging implements ISoundTriggerMiddlewareInt
LocalServices.getService(BatteryStatsInternal.class);
}
/**
* Starts the latency tracking log for keyphrase hotword invocation.
* The measurement covers from when the SoundTrigger HAL emits an event to when the
* {@link android.service.voice.VoiceInteractionSession} system UI view is shown.
*
* <p>The session is only started if the {@link PhraseRecognitionEvent} has a status of
* {@link RecognitionStatus#SUCCESS}
*/
private void startKeyphraseEventLatencyTracking(PhraseRecognitionEvent event) {
if (event.common.status != RecognitionStatus.SUCCESS
|| ArrayUtils.isEmpty(event.phraseExtras)) {
return;
}
String latencyTrackerTag = "KeyphraseId=" + event.phraseExtras[0].id;
// To avoid adding cancel to all the different failure modes between here and
// showing the system UI, we defensively cancel once.
// Either we hit the LatencyTracker timeout of 15 seconds or we defensively cancel
// here if any error occurs.
mLatencyTracker.onActionCancel(LatencyTracker.ACTION_SHOW_VOICE_INTERACTION);
mLatencyTracker.onActionStart(LatencyTracker.ACTION_SHOW_VOICE_INTERACTION,
latencyTrackerTag);
}
////////////////////////////////////////////////////////////////////////////////////////////////
// Actual logging logic below.