Merge changes Ib1c94642,Ifaba86da into udc-dev

* changes:
  cancel VI latency tracking for non ST triggers
  only start latency measurement on successful phrase triggers
This commit is contained in:
TreeHugger Robot
2023-03-22 16:18:12 +00:00
committed by Android (Google) Code Review
5 changed files with 288 additions and 27 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.

View File

@@ -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.
*
* <p>Completing this session will result in logging metric data.</p>
*
* @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.
*
* <p>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.</p>
*
* <p>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:

View File

@@ -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);
}
}