only start latency measurement on successful phrase triggers

Bug: 265850090
Test: atest SoundTriggerMiddlewareLoggingTest
Change-Id: Ifaba86daea8ab92551ed75a251cd3a6ca55ffaed

services/tests/voiceinteractiontests/Android.bp

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

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<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 */);
+    }
+}

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<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.