From 0cf35e854e0e0eee50de3416c282cb5194d95a05 Mon Sep 17 00:00:00 2001 From: Nicholas Ambur Date: Thu, 22 Sep 2022 00:38:35 -0700 Subject: [PATCH] Add Logging of the UI Latency for hotword invocation Log the UI latency with UIActionLatencyReported atom. We plan to calulate the latency from when the SoundTrigger HAL emits an event to when the VoiceInteraction system UI view is shown. Test: device_config put latency_tracker enabled true; verify traces and latency is logged in WW. Bug: 247879896 Change-Id: I3edb91691e81f8f23660c0823a6388338fe926ad --- .../android/internal/util/LatencyTracker.java | 12 +++++++ .../SoundTriggerMiddlewareLogging.java | 29 ++++++++++++++- .../SoundTriggerMiddlewareService.java | 21 +++++------ .../VoiceInteractionManagerService.java | 35 +++++++++++++++++++ 4 files changed, 86 insertions(+), 11 deletions(-) diff --git a/core/java/com/android/internal/util/LatencyTracker.java b/core/java/com/android/internal/util/LatencyTracker.java index d3f9e0a2729ed..8fcb6d5514d40 100644 --- a/core/java/com/android/internal/util/LatencyTracker.java +++ b/core/java/com/android/internal/util/LatencyTracker.java @@ -29,6 +29,7 @@ import static com.android.internal.util.FrameworkStatsLog.UIACTION_LATENCY_REPOR import static com.android.internal.util.FrameworkStatsLog.UIACTION_LATENCY_REPORTED__ACTION__ACTION_ROTATE_SCREEN_SENSOR; import static com.android.internal.util.FrameworkStatsLog.UIACTION_LATENCY_REPORTED__ACTION__ACTION_SHOW_BACK_ARROW; import static com.android.internal.util.FrameworkStatsLog.UIACTION_LATENCY_REPORTED__ACTION__ACTION_SHOW_SELECTION_TOOLBAR; +import static com.android.internal.util.FrameworkStatsLog.UIACTION_LATENCY_REPORTED__ACTION__ACTION_SHOW_VOICE_INTERACTION; import static com.android.internal.util.FrameworkStatsLog.UIACTION_LATENCY_REPORTED__ACTION__ACTION_START_RECENTS_ANIMATION; import static com.android.internal.util.FrameworkStatsLog.UIACTION_LATENCY_REPORTED__ACTION__ACTION_SWITCH_DISPLAY_UNFOLD; import static com.android.internal.util.FrameworkStatsLog.UIACTION_LATENCY_REPORTED__ACTION__ACTION_TOGGLE_RECENTS; @@ -174,6 +175,12 @@ public class LatencyTracker { */ public static final int ACTION_FOLD_TO_AOD = 18; + /** + * Time it takes to show the {@link android.service.voice.VoiceInteractionSession} system UI + * after a {@link android.hardware.soundtrigger3.ISoundTriggerHw} voice trigger. + */ + public static final int ACTION_SHOW_VOICE_INTERACTION = 19; + private static final int[] ACTIONS_ALL = { ACTION_EXPAND_PANEL, ACTION_TOGGLE_RECENTS, @@ -194,6 +201,7 @@ public class LatencyTracker { ACTION_LOAD_SHARE_SHEET, ACTION_SHOW_SELECTION_TOOLBAR, ACTION_FOLD_TO_AOD, + ACTION_SHOW_VOICE_INTERACTION, }; /** @hide */ @@ -217,6 +225,7 @@ public class LatencyTracker { ACTION_LOAD_SHARE_SHEET, ACTION_SHOW_SELECTION_TOOLBAR, ACTION_FOLD_TO_AOD, + ACTION_SHOW_VOICE_INTERACTION, }) @Retention(RetentionPolicy.SOURCE) public @interface Action { @@ -243,6 +252,7 @@ public class LatencyTracker { UIACTION_LATENCY_REPORTED__ACTION__ACTION_LOAD_SHARE_SHEET, UIACTION_LATENCY_REPORTED__ACTION__ACTION_SHOW_SELECTION_TOOLBAR, UIACTION_LATENCY_REPORTED__ACTION__ACTION_FOLD_TO_AOD, + UIACTION_LATENCY_REPORTED__ACTION__ACTION_SHOW_VOICE_INTERACTION, }; private static LatencyTracker sLatencyTracker; @@ -340,6 +350,8 @@ public class LatencyTracker { return "ACTION_SHOW_SELECTION_TOOLBAR"; case UIACTION_LATENCY_REPORTED__ACTION__ACTION_FOLD_TO_AOD: return "ACTION_FOLD_TO_AOD"; + case UIACTION_LATENCY_REPORTED__ACTION__ACTION_SHOW_VOICE_INTERACTION: + return "ACTION_SHOW_VOICE_INTERACTION"; default: throw new IllegalArgumentException("Invalid action"); } diff --git a/services/core/java/com/android/server/soundtrigger_middleware/SoundTriggerMiddlewareLogging.java b/services/core/java/com/android/server/soundtrigger_middleware/SoundTriggerMiddlewareLogging.java index dc4bdaaa81584..ce1157e1d80cb 100644 --- a/services/core/java/com/android/server/soundtrigger_middleware/SoundTriggerMiddlewareLogging.java +++ b/services/core/java/com/android/server/soundtrigger_middleware/SoundTriggerMiddlewareLogging.java @@ -18,6 +18,7 @@ package com.android.server.soundtrigger_middleware; import android.annotation.NonNull; import android.annotation.Nullable; +import android.content.Context; import android.media.permission.Identity; import android.media.permission.IdentityContext; import android.media.soundtrigger.ModelParameterRange; @@ -33,6 +34,8 @@ import android.os.IBinder; import android.os.RemoteException; import android.util.Log; +import com.android.internal.util.LatencyTracker; + import java.io.PrintWriter; import java.text.SimpleDateFormat; import java.util.Date; @@ -65,9 +68,12 @@ 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; - public SoundTriggerMiddlewareLogging(@NonNull ISoundTriggerMiddlewareInternal delegate) { + public SoundTriggerMiddlewareLogging(@NonNull Context context, + @NonNull ISoundTriggerMiddlewareInternal delegate) { mDelegate = delegate; + mContext = context; } @Override @@ -298,6 +304,7 @@ public class SoundTriggerMiddlewareLogging implements ISoundTriggerMiddlewareInt int captureSession) throws RemoteException { try { + startKeyphraseEventLatencyTracking(event); mCallbackDelegate.onPhraseRecognition(modelHandle, event, captureSession); logVoidReturn("onPhraseRecognition", modelHandle, event); } catch (Exception e) { @@ -347,6 +354,26 @@ 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(); diff --git a/services/core/java/com/android/server/soundtrigger_middleware/SoundTriggerMiddlewareService.java b/services/core/java/com/android/server/soundtrigger_middleware/SoundTriggerMiddlewareService.java index 1995e5497e553..807ed14e85ce3 100644 --- a/services/core/java/com/android/server/soundtrigger_middleware/SoundTriggerMiddlewareService.java +++ b/services/core/java/com/android/server/soundtrigger_middleware/SoundTriggerMiddlewareService.java @@ -20,14 +20,14 @@ import static android.Manifest.permission.SOUNDTRIGGER_DELEGATE_IDENTITY; import android.annotation.NonNull; import android.content.Context; -import android.media.soundtrigger.ModelParameterRange; -import android.media.soundtrigger.PhraseSoundModel; -import android.media.soundtrigger.RecognitionConfig; -import android.media.soundtrigger.SoundModel; import android.media.permission.ClearCallingIdentityContext; import android.media.permission.Identity; import android.media.permission.PermissionUtil; import android.media.permission.SafeCloseable; +import android.media.soundtrigger.ModelParameterRange; +import android.media.soundtrigger.PhraseSoundModel; +import android.media.soundtrigger.RecognitionConfig; +import android.media.soundtrigger.SoundModel; import android.media.soundtrigger_middleware.ISoundTriggerCallback; import android.media.soundtrigger_middleware.ISoundTriggerMiddlewareService; import android.media.soundtrigger_middleware.ISoundTriggerModule; @@ -226,12 +226,13 @@ public class SoundTriggerMiddlewareService extends ISoundTriggerMiddlewareServic HalFactory[] factories = new HalFactory[]{new DefaultHalFactory()}; publishBinderService(Context.SOUND_TRIGGER_MIDDLEWARE_SERVICE, - new SoundTriggerMiddlewareService(new SoundTriggerMiddlewareLogging( - new SoundTriggerMiddlewarePermission( - new SoundTriggerMiddlewareValidation( - new SoundTriggerMiddlewareImpl(factories, - new AudioSessionProviderImpl())), - getContext())), getContext())); + new SoundTriggerMiddlewareService( + new SoundTriggerMiddlewareLogging(getContext(), + new SoundTriggerMiddlewarePermission( + new SoundTriggerMiddlewareValidation( + new SoundTriggerMiddlewareImpl(factories, + new AudioSessionProviderImpl())), + getContext())), getContext())); } } } diff --git a/services/voiceinteraction/java/com/android/server/voiceinteraction/VoiceInteractionManagerService.java b/services/voiceinteraction/java/com/android/server/voiceinteraction/VoiceInteractionManagerService.java index 0ce0265c3dc5a..3da47110fb49e 100644 --- a/services/voiceinteraction/java/com/android/server/voiceinteraction/VoiceInteractionManagerService.java +++ b/services/voiceinteraction/java/com/android/server/voiceinteraction/VoiceInteractionManagerService.java @@ -95,6 +95,7 @@ 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; @@ -191,6 +192,8 @@ public class VoiceInteractionManagerService extends SystemService { mSoundTriggerInternal = LocalServices.getService(SoundTriggerInternal.class); } else if (phase == PHASE_THIRD_PARTY_APPS_CAN_START) { mServiceStub.systemRunning(isSafeMode()); + } else if (phase == PHASE_BOOT_COMPLETED) { + mServiceStub.registerVoiceInteractionSessionListener(mLatencyLoggingListener); } } @@ -2334,4 +2337,36 @@ public class VoiceInteractionManagerService extends SystemService { } }; } + + /** + * End the latency tracking log for keyphrase hotword invocation. + * The measurement covers from when the SoundTrigger HAL emits an event, captured in + * {@link com.android.server.soundtrigger_middleware.SoundTriggerMiddlewareLogging} + * to when the {@link android.service.voice.VoiceInteractionSession} system UI view is shown. + */ + private final IVoiceInteractionSessionListener mLatencyLoggingListener = + new IVoiceInteractionSessionListener.Stub() { + @Override + public void onVoiceSessionShown() throws RemoteException {} + + @Override + public void onVoiceSessionHidden() throws RemoteException {} + + @Override + public void onVoiceSessionWindowVisibilityChanged(boolean visible) + throws RemoteException { + if (visible) { + LatencyTracker.getInstance(mContext) + .onActionEnd(LatencyTracker.ACTION_SHOW_VOICE_INTERACTION); + } + } + + @Override + public void onSetUiHints(Bundle args) throws RemoteException {} + + @Override + public IBinder asBinder() { + return mServiceStub; + } + }; }