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. diff --git a/services/voiceinteraction/java/com/android/server/voiceinteraction/HotwordMetricsLogger.java b/services/voiceinteraction/java/com/android/server/voiceinteraction/HotwordMetricsLogger.java index c35d90f4a495a..f7b66a26ff683 100644 --- a/services/voiceinteraction/java/com/android/server/voiceinteraction/HotwordMetricsLogger.java +++ b/services/voiceinteraction/java/com/android/server/voiceinteraction/HotwordMetricsLogger.java @@ -34,10 +34,13 @@ import static com.android.internal.util.FrameworkStatsLog.HOTWORD_DETECTOR_EVENT import static com.android.internal.util.FrameworkStatsLog.HOTWORD_DETECTOR_KEYPHRASE_TRIGGERED__DETECTOR_TYPE__NORMAL_DETECTOR; import static com.android.internal.util.FrameworkStatsLog.HOTWORD_DETECTOR_KEYPHRASE_TRIGGERED__DETECTOR_TYPE__TRUSTED_DETECTOR_DSP; import static com.android.internal.util.FrameworkStatsLog.HOTWORD_DETECTOR_KEYPHRASE_TRIGGERED__DETECTOR_TYPE__TRUSTED_DETECTOR_SOFTWARE; +import static com.android.internal.util.LatencyTracker.ACTION_SHOW_VOICE_INTERACTION; +import android.content.Context; import android.service.voice.HotwordDetector; import com.android.internal.util.FrameworkStatsLog; +import com.android.internal.util.LatencyTracker; /** * A utility class for logging hotword statistics event. @@ -116,6 +119,46 @@ public final class HotwordMetricsLogger { metricsDetectorType, event, uid, streamSizeBytes, bundleSizeBytes, streamCount); } + /** + * Starts a {@link LatencyTracker} log for the time it takes to show the + * {@link android.service.voice.VoiceInteractionSession} system UI after a voice trigger. + * + * @see LatencyTracker + * + * @param tag Extra tag to separate different sessions from each other. + */ + public static void startHotwordTriggerToUiLatencySession(Context context, String tag) { + LatencyTracker.getInstance(context).onActionStart(ACTION_SHOW_VOICE_INTERACTION, tag); + } + + /** + * Completes a {@link LatencyTracker} log for the time it takes to show the + * {@link android.service.voice.VoiceInteractionSession} system UI after a voice trigger. + * + *

Completing this session will result in logging metric data.

+ * + * @see LatencyTracker + */ + public static void stopHotwordTriggerToUiLatencySession(Context context) { + LatencyTracker.getInstance(context).onActionEnd(ACTION_SHOW_VOICE_INTERACTION); + } + + /** + * Cancels a {@link LatencyTracker} log for the time it takes to show the + * {@link android.service.voice.VoiceInteractionSession} system UI after a voice trigger. + * + *

Cancels typically occur when the VoiceInteraction session UI is shown for reasons outside + * of a {@link android.hardware.soundtrigger.SoundTrigger.RecognitionEvent} such as an + * invocation from an external source or service.

+ * + *

Canceling this session will not result in logging metric data. + * + * @see LatencyTracker + */ + public static void cancelHotwordTriggerToUiLatencySession(Context context) { + LatencyTracker.getInstance(context).onActionCancel(ACTION_SHOW_VOICE_INTERACTION); + } + private static int getCreateMetricsDetectorType(int detectorType) { switch (detectorType) { case HotwordDetector.DETECTOR_TYPE_TRUSTED_HOTWORD_SOFTWARE: diff --git a/services/voiceinteraction/java/com/android/server/voiceinteraction/VoiceInteractionManagerService.java b/services/voiceinteraction/java/com/android/server/voiceinteraction/VoiceInteractionManagerService.java index 1a76295c251f9..e1da2ca2a086c 100644 --- a/services/voiceinteraction/java/com/android/server/voiceinteraction/VoiceInteractionManagerService.java +++ b/services/voiceinteraction/java/com/android/server/voiceinteraction/VoiceInteractionManagerService.java @@ -97,7 +97,6 @@ import com.android.internal.app.IVoiceInteractor; import com.android.internal.content.PackageMonitor; import com.android.internal.os.BackgroundThread; import com.android.internal.util.DumpUtils; -import com.android.internal.util.LatencyTracker; import com.android.server.FgThread; import com.android.server.LocalServices; import com.android.server.SystemService; @@ -443,6 +442,10 @@ public class VoiceInteractionManagerService extends SystemService { final int callingUid = Binder.getCallingUid(); final long caller = Binder.clearCallingIdentity(); try { + // HotwordDetector trigger uses VoiceInteractionService#showSession + // We need to cancel here because UI is not being shown due to a SoundTrigger + // HAL event. + HotwordMetricsLogger.cancelHotwordTriggerToUiLatencySession(mContext); mImpl.showSessionLocked(options, VoiceInteractionSession.SHOW_SOURCE_ACTIVITY, attributionTag, new IVoiceInteractionSessionShowCallback.Stub() { @@ -994,6 +997,13 @@ public class VoiceInteractionManagerService extends SystemService { Slog.w(TAG, "showSessionFromSession without running voice interaction service"); return false; } + // If the token is null, then the request to show the session is not coming from + // the active VoiceInteractionService session. + // We need to cancel here because UI is not being shown due to a SoundTrigger + // HAL event. + if (token == null) { + HotwordMetricsLogger.cancelHotwordTriggerToUiLatencySession(mContext); + } final long caller = Binder.clearCallingIdentity(); try { return mImpl.showSessionLocked(sessionArgs, flags, attributionTag, null, null); @@ -1862,6 +1872,11 @@ public class VoiceInteractionManagerService extends SystemService { final long caller = Binder.clearCallingIdentity(); try { + // HotwordDetector trigger uses VoiceInteractionService#showSession + // We need to cancel here because UI is not being shown due to a SoundTrigger + // HAL event. + HotwordMetricsLogger.cancelHotwordTriggerToUiLatencySession(mContext); + return mImpl.showSessionLocked(args, sourceFlags | VoiceInteractionSession.SHOW_WITH_ASSIST @@ -2521,8 +2536,11 @@ public class VoiceInteractionManagerService extends SystemService { public void onVoiceSessionWindowVisibilityChanged(boolean visible) throws RemoteException { if (visible) { - LatencyTracker.getInstance(mContext) - .onActionEnd(LatencyTracker.ACTION_SHOW_VOICE_INTERACTION); + // The AlwaysOnHotwordDetector trigger latency is always completed here even + // if the reason the window was shown was not due to a SoundTrigger HAL + // event. It is expected that the latency will be canceled if shown for + // other invocation reasons, and this call becomes a noop. + HotwordMetricsLogger.stopHotwordTriggerToUiLatencySession(mContext); } }