From 91701dd240f787f018f8de0ed150a1e6cf134d12 Mon Sep 17 00:00:00 2001 From: Nicholas Ambur Date: Mon, 13 Feb 2023 18:32:30 +0000 Subject: [PATCH 1/2] 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. From 0f8bbf882bf0913cda67d7636fecc58b24f56db1 Mon Sep 17 00:00:00 2001 From: Nicholas Ambur Date: Mon, 13 Feb 2023 18:51:43 +0000 Subject: [PATCH 2/2] cancel VI latency tracking for non ST triggers The VoiceInteraction UI latency is limited to measuring the SoundTrigger HAL invocation latency. This change cancels the latency measurment when the VoiceInteraction UI is shown due to a invocation outside of VoiceInteractionService#showSession. Bug: 265850090 Test: manual invocation of system UI and gesture to confirm latency is canceled Change-Id: Ib1c9464217e8a66fbd96d2192b13cf13713362e9 --- .../HotwordMetricsLogger.java | 43 +++++++++++++++++++ .../VoiceInteractionManagerService.java | 24 +++++++++-- 2 files changed, 64 insertions(+), 3 deletions(-) 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); } }