From c37e3adeffd4e79193c9fc23f2795a043d673ab9 Mon Sep 17 00:00:00 2001 From: Nicholas Ambur Date: Mon, 13 Feb 2023 19:00:50 +0000 Subject: [PATCH 1/4] add LatencyTracker tracing cancel / timeout events Bug: 265850090 Test: manual invoke hotword trigger collecting trace and verify in Perfetto UI that trace has cancel and timeout events Change-Id: Ie5acefe043575b198ce1fbd1526cc82116649cb3 (cherry picked from commit 3f793d7daa59e5a4b94fcf8f54ba669a0a505764) Merged-In: Ie5acefe043575b198ce1fbd1526cc82116649cb3 --- .../com/android/internal/util/LatencyTracker.java | 12 ++++++++---- 1 file changed, 8 insertions(+), 4 deletions(-) diff --git a/core/java/com/android/internal/util/LatencyTracker.java b/core/java/com/android/internal/util/LatencyTracker.java index fe08083282c5e..c933bfd5b3724 100644 --- a/core/java/com/android/internal/util/LatencyTracker.java +++ b/core/java/com/android/internal/util/LatencyTracker.java @@ -605,23 +605,27 @@ public class LatencyTracker { void begin(@NonNull Runnable timeoutAction) { mStartRtc = SystemClock.elapsedRealtime(); - Trace.asyncTraceBegin(TRACE_TAG_APP, traceName(), 0); + Trace.asyncTraceForTrackBegin(TRACE_TAG_APP, traceName(), traceName(), 0); // start counting timeout. - mTimeoutRunnable = timeoutAction; + mTimeoutRunnable = () -> { + Trace.instantForTrack(TRACE_TAG_APP, traceName(), "timeout"); + timeoutAction.run(); + }; BackgroundThread.getHandler() .postDelayed(mTimeoutRunnable, TimeUnit.SECONDS.toMillis(15)); } void end() { mEndRtc = SystemClock.elapsedRealtime(); - Trace.asyncTraceEnd(TRACE_TAG_APP, traceName(), 0); + Trace.asyncTraceForTrackEnd(TRACE_TAG_APP, traceName(), "end", 0); BackgroundThread.getHandler().removeCallbacks(mTimeoutRunnable); mTimeoutRunnable = null; } void cancel() { - Trace.asyncTraceEnd(TRACE_TAG_APP, traceName(), 0); + Trace.instantForTrack(TRACE_TAG_APP, traceName(), "cancel"); + Trace.asyncTraceForTrackEnd(TRACE_TAG_APP, traceName(), "cancel", 0); BackgroundThread.getHandler().removeCallbacks(mTimeoutRunnable); mTimeoutRunnable = null; } From ca9e12eec9bb45f8c7f37c679fc21fd8df1b5a0b Mon Sep 17 00:00:00 2001 From: Nicholas Ambur Date: Wed, 22 Mar 2023 14:59:21 +0000 Subject: [PATCH 2/4] fix enable checks to check use action in LatencyTracker Without checking the per-action enable, logging is only allowed based on the global enable flag instead of the enable flag per action. Checking the per-action enable flag allows for action latencies to be rolled out independent of each other. Test: manual verify action is logged with only action specific enable set Bug: 265850090 Change-Id: I4f8d21bca4a9e52fb3875e88387b8c8641f64c94 Merged-In: I4f8d21bca4a9e52fb3875e88387b8c8641f64c94 --- core/java/com/android/internal/util/LatencyTracker.java | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/core/java/com/android/internal/util/LatencyTracker.java b/core/java/com/android/internal/util/LatencyTracker.java index c933bfd5b3724..c8a8b586590b2 100644 --- a/core/java/com/android/internal/util/LatencyTracker.java +++ b/core/java/com/android/internal/util/LatencyTracker.java @@ -471,7 +471,7 @@ public class LatencyTracker { */ public void onActionStart(@Action int action, String tag) { synchronized (mLock) { - if (!isEnabled()) { + if (!isEnabled(action)) { return; } // skip if the action is already instrumenting. @@ -495,7 +495,7 @@ public class LatencyTracker { */ public void onActionEnd(@Action int action) { synchronized (mLock) { - if (!isEnabled()) { + if (!isEnabled(action)) { return; } Session session = mSessions.get(action); From f74101e61583d4e45a53594b78c2c8d2c542abef Mon Sep 17 00:00:00 2001 From: Nicholas Ambur Date: Mon, 13 Feb 2023 18:32:30 +0000 Subject: [PATCH 3/4] only start latency measurement on successful phrase triggers Bug: 265850090 Test: atest SoundTriggerMiddlewareLoggingTest Change-Id: Ifaba86daea8ab92551ed75a251cd3a6ca55ffaed Merged-In: Ifaba86daea8ab92551ed75a251cd3a6ca55ffaed --- .../SoundTriggerMiddlewareLogging.java | 15 +++++++++++---- 1 file changed, 11 insertions(+), 4 deletions(-) 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 ce1157e1d80cb..70932fa50a3cf 100644 --- a/services/core/java/com/android/server/soundtrigger_middleware/SoundTriggerMiddlewareLogging.java +++ b/services/core/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; @@ -34,6 +35,7 @@ import android.os.IBinder; import android.os.RemoteException; import android.util.Log; +import com.android.internal.util.ArrayUtils; import com.android.internal.util.LatencyTracker; import java.io.PrintWriter; @@ -358,14 +360,19 @@ public class SoundTriggerMiddlewareLogging implements ISoundTriggerMiddlewareInt * 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) { - String latencyTrackerTag = null; - if (event.phraseExtras.length > 0) { - latencyTrackerTag = "KeyphraseId=" + event.phraseExtras[0].id; + if (event.common.status != RecognitionStatus.SUCCESS + || ArrayUtils.isEmpty(event.phraseExtras)) { + return; } + LatencyTracker latencyTracker = LatencyTracker.getInstance(mContext); - // To avoid adding cancel to all of the different failure modes between here and + 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. From 3453de6009aaa6c107bce6b8317d02918c574ef3 Mon Sep 17 00:00:00 2001 From: Nicholas Ambur Date: Mon, 13 Feb 2023 18:51:43 +0000 Subject: [PATCH 4/4] 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 Merged-In: 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 bc5c9ec7a29ca..56351202564c0 100644 --- a/services/voiceinteraction/java/com/android/server/voiceinteraction/VoiceInteractionManagerService.java +++ b/services/voiceinteraction/java/com/android/server/voiceinteraction/VoiceInteractionManagerService.java @@ -95,7 +95,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; @@ -404,6 +403,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, new IVoiceInteractionSessionShowCallback.Stub() { @@ -954,6 +957,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, null, null); @@ -1718,6 +1728,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 @@ -2361,8 +2376,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); } }