From 91701dd240f787f018f8de0ed150a1e6cf134d12 Mon Sep 17 00:00:00 2001 From: Nicholas Ambur Date: Mon, 13 Feb 2023 18:32:30 +0000 Subject: [PATCH] only start latency measurement on successful phrase triggers Bug: 265850090 Test: atest SoundTriggerMiddlewareLoggingTest Change-Id: Ifaba86daea8ab92551ed75a251cd3a6ca55ffaed --- .../tests/voiceinteractiontests/Android.bp | 1 + .../SoundTriggerMiddlewareLoggingTest.java | 181 ++++++++++++++++++ .../SoundTriggerMiddlewareLogging.java | 66 ++++--- 3 files changed, 224 insertions(+), 24 deletions(-) create mode 100644 services/tests/voiceinteractiontests/src/com/android/server/soundtrigger_middleware/SoundTriggerMiddlewareLoggingTest.java diff --git a/services/tests/voiceinteractiontests/Android.bp b/services/tests/voiceinteractiontests/Android.bp index 9ca287686758b..986fb71afa2d0 100644 --- a/services/tests/voiceinteractiontests/Android.bp +++ b/services/tests/voiceinteractiontests/Android.bp @@ -29,6 +29,7 @@ android_test { srcs: [ "src/**/*.java", + ":FrameworksCoreTestDoubles-sources", ], static_libs: [ diff --git a/services/tests/voiceinteractiontests/src/com/android/server/soundtrigger_middleware/SoundTriggerMiddlewareLoggingTest.java b/services/tests/voiceinteractiontests/src/com/android/server/soundtrigger_middleware/SoundTriggerMiddlewareLoggingTest.java new file mode 100644 index 0000000000000..8694094ce6ac2 --- /dev/null +++ b/services/tests/voiceinteractiontests/src/com/android/server/soundtrigger_middleware/SoundTriggerMiddlewareLoggingTest.java @@ -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 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 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 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 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 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 */); + } +} diff --git a/services/voiceinteraction/java/com/android/server/soundtrigger_middleware/SoundTriggerMiddlewareLogging.java b/services/voiceinteraction/java/com/android/server/soundtrigger_middleware/SoundTriggerMiddlewareLogging.java index 7d5750e499072..2f8d17d77e521 100644 --- a/services/voiceinteraction/java/com/android/server/soundtrigger_middleware/SoundTriggerMiddlewareLogging.java +++ b/services/voiceinteraction/java/com/android/server/soundtrigger_middleware/SoundTriggerMiddlewareLogging.java @@ -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 mBatteryStatsInternalSupplier; public SoundTriggerMiddlewareLogging(@NonNull Context context, @NonNull ISoundTriggerMiddlewareInternal delegate) { + this(LatencyTracker.getInstance(context), + () -> BatteryStatsHolder.INSTANCE, + delegate); + } + + @VisibleForTesting + public SoundTriggerMiddlewareLogging(@NonNull LatencyTracker latencyTracker, + @NonNull Supplier 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. + * + *

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.