From 5b27ef13b6aa35a80987ff3c725aa32e1a37e517 Mon Sep 17 00:00:00 2001 From: Tim Yu Date: Mon, 7 Nov 2022 21:27:46 +0000 Subject: [PATCH] Add Latency Logs to Autofill Server Test: manual build + manual test of logging, cts tests added later This adds the following latency metrics: 1. fill_request_sent_timestamp_ms, set when frameworks requests a FillRequest from the autofill provider 2. fill_response_received_timestamp_ms, set when autofill provider provides a FillResponse 3. suggestion_sent_timestamp_ms, set when framework sends the FillResponse suggestions to be displayed 4. suggestion_presented_timestamp_ms, set when the suggestions are actually displayed Fixes: 243719509 Change-Id: I577266b1b2bbdc53663c4707b5c9578f0c0e14ca --- .../PresentationStatsEventLogger.java | 40 +++++++++++++- .../com/android/server/autofill/Session.java | 52 ++++++++++++++++++- 2 files changed, 89 insertions(+), 3 deletions(-) diff --git a/services/autofill/java/com/android/server/autofill/PresentationStatsEventLogger.java b/services/autofill/java/com/android/server/autofill/PresentationStatsEventLogger.java index 6bb19ce058137..5f1da7b18bf9b 100644 --- a/services/autofill/java/com/android/server/autofill/PresentationStatsEventLogger.java +++ b/services/autofill/java/com/android/server/autofill/PresentationStatsEventLogger.java @@ -201,6 +201,30 @@ public final class PresentationStatsEventLogger { }); } + public void maybeSetFillRequestSentTimestampMs(int timestamp) { + mEventInternal.ifPresent(event -> { + event.mFillRequestSentTimestampMs = timestamp; + }); + } + + public void maybeSetFillResponseReceivedTimestampMs(int timestamp) { + mEventInternal.ifPresent(event -> { + event.mFillResponseReceivedTimestampMs = timestamp; + }); + } + + public void maybeSetSuggestionSentTimestampMs(int timestamp) { + mEventInternal.ifPresent(event -> { + event.mSuggestionSentTimestampMs = timestamp; + }); + } + + public void maybeSetSuggestionPresentedTimestampMs(int timestamp) { + mEventInternal.ifPresent(event -> { + event.mSuggestionPresentedTimestampMs = timestamp; + }); + } + public void maybeSetInlinePresentationAndSuggestionHostUid(Context context, int userId) { mEventInternal.ifPresent(event -> { event.mDisplayPresentationType = @@ -262,7 +286,11 @@ public final class PresentationStatsEventLogger { + " mDisplayPresentationType=" + event.mDisplayPresentationType + " mAutofillServiceUid=" + event.mAutofillServiceUid + " mInlineSuggestionHostUid=" + event.mInlineSuggestionHostUid - + " mIsRequestTriggered=" + event.mIsRequestTriggered); + + " mIsRequestTriggered=" + event.mIsRequestTriggered + + " mFillRequestSentTimestampMs=" + event.mFillRequestSentTimestampMs + + " mFillResponseReceivedTimestampMs=" + event.mFillResponseReceivedTimestampMs + + " mSuggestionSentTimestampMs=" + event.mSuggestionSentTimestampMs + + " mSuggestionPresentedTimestampMs=" + event.mSuggestionPresentedTimestampMs); } // TODO(b/234185326): Distinguish empty responses from other no presentation reasons. @@ -283,7 +311,11 @@ public final class PresentationStatsEventLogger { event.mDisplayPresentationType, event.mAutofillServiceUid, event.mInlineSuggestionHostUid, - event.mIsRequestTriggered); + event.mIsRequestTriggered, + event.mFillRequestSentTimestampMs, + event.mFillResponseReceivedTimestampMs, + event.mSuggestionSentTimestampMs, + event.mSuggestionPresentedTimestampMs); mEventInternal = Optional.empty(); } @@ -300,6 +332,10 @@ public final class PresentationStatsEventLogger { int mAutofillServiceUid = -1; int mInlineSuggestionHostUid = -1; boolean mIsRequestTriggered; + int mFillRequestSentTimestampMs; + int mFillResponseReceivedTimestampMs; + int mSuggestionSentTimestampMs; + int mSuggestionPresentedTimestampMs; PresentationStatsEventInternal() {} } diff --git a/services/autofill/java/com/android/server/autofill/Session.java b/services/autofill/java/com/android/server/autofill/Session.java index 64b7688cc196a..b3f8af5338144 100644 --- a/services/autofill/java/com/android/server/autofill/Session.java +++ b/services/autofill/java/com/android/server/autofill/Session.java @@ -323,6 +323,13 @@ final class Session implements RemoteFillService.FillServiceCallbacks, ViewState */ private final long mStartTime; + /** + * Starting timestamp of latency logger. + * This is set when Session created or when the view is reset. + */ + @GuardedBy("mLock") + private long mLatencyBaseTime; + /** * When the UI was shown for the first time (using elapsed time since boot). */ @@ -1041,6 +1048,11 @@ final class Session implements RemoteFillService.FillServiceCallbacks, ViewState return; } + final long fillRequestSentRelativeTimestamp = + SystemClock.elapsedRealtime() - mLatencyBaseTime; + mPresentationStatsEventLogger.maybeSetFillRequestSentTimestampMs( + (int) (fillRequestSentRelativeTimestamp)); + // Now request the assist structure data. requestAssistStructureLocked(requestId, flags); } @@ -1085,6 +1097,7 @@ final class Session implements RemoteFillService.FillServiceCallbacks, ViewState this.taskId = taskId; this.uid = uid; mStartTime = SystemClock.elapsedRealtime(); + mLatencyBaseTime = mStartTime; mService = service; mLock = lock; mUi = ui; @@ -1116,6 +1129,14 @@ final class Session implements RemoteFillService.FillServiceCallbacks, ViewState @Override public void notifyInlineUiShown(AutofillId autofillId) { notifyFillUiShown(autofillId); + + synchronized (mLock) { + // TODO(b/262448552): Log when chip inflates instead of here + final long inlineUiShownRelativeTimestamp = + SystemClock.elapsedRealtime() - mLatencyBaseTime; + mPresentationStatsEventLogger.maybeSetSuggestionPresentedTimestampMs( + (int) (inlineUiShownRelativeTimestamp)); + } } @Override @@ -1209,6 +1230,12 @@ final class Session implements RemoteFillService.FillServiceCallbacks, ViewState return; } + // Time passed since session was created + final long fillRequestReceivedRelativeTimestamp = + SystemClock.elapsedRealtime() - mLatencyBaseTime; + mPresentationStatsEventLogger.maybeSetFillResponseReceivedTimestampMs( + (int) (fillRequestReceivedRelativeTimestamp)); + requestLog = mRequestLogs.get(requestId); if (requestLog != null) { requestLog.setType(MetricsEvent.TYPE_SUCCESS); @@ -3128,6 +3155,7 @@ final class Session implements RemoteFillService.FillServiceCallbacks, ViewState } break; case ACTION_VIEW_ENTERED: + mLatencyBaseTime = SystemClock.elapsedRealtime(); boolean wasPreviouslyFillDialog = mPreviouslyFillDialogPotentiallyStarted; mPreviouslyFillDialogPotentiallyStarted = false; if (sVerbose && virtualBounds != null) { @@ -3181,7 +3209,7 @@ final class Session implements RemoteFillService.FillServiceCallbacks, ViewState return; } } - + // If previous request was FillDialog request, a logger event was already started if (!wasPreviouslyFillDialog) { mPresentationStatsEventLogger.startNewEvent(); mPresentationStatsEventLogger.maybeSetAutofillServiceUid( @@ -3405,6 +3433,14 @@ final class Session implements RemoteFillService.FillServiceCallbacks, ViewState return; } + synchronized (mLock) { + // Time passed since Session was created + long suggestionSentRelativeTimestamp = + SystemClock.elapsedRealtime() - mLatencyBaseTime; + mPresentationStatsEventLogger.maybeSetSuggestionSentTimestampMs( + (int) (suggestionSentRelativeTimestamp)); + } + final AutofillId[] ids = response.getFillDialogTriggerIds(); if (ids != null && ArrayUtils.contains(ids, filledId)) { if (requestShowFillDialog(response, filledId, filterText, flags)) { @@ -3421,6 +3457,13 @@ final class Session implements RemoteFillService.FillServiceCallbacks, ViewState // Note: Cannot disable before requestShowFillDialog() because the method // need to check whether fill dialog enabled. setFillDialogDisabled(); + synchronized (mLock) { + // Logs when fill dialog ui is shown; time since Session was created + final long fillDialogUiShownRelativeTimestamp = + SystemClock.elapsedRealtime() - mLatencyBaseTime; + mPresentationStatsEventLogger.maybeSetSuggestionPresentedTimestampMs( + (int) (fillDialogUiShownRelativeTimestamp)); + } return; } else { setFillDialogDisabled(); @@ -3431,6 +3474,8 @@ final class Session implements RemoteFillService.FillServiceCallbacks, ViewState if (response.supportsInlineSuggestions()) { synchronized (mLock) { if (requestShowInlineSuggestionsLocked(response, filterText)) { + // Cannot tell for sure that InlineSuggestions are shown yet, IME needs to send + // back a response via callback. final ViewState currentView = mViewStates.get(mCurrentViewId); currentView.setState(ViewState.STATE_INLINE_SHOWN); // TODO(b/248378401): Fix it to log showed only when IME asks for inflation, @@ -3464,6 +3509,11 @@ final class Session implements RemoteFillService.FillServiceCallbacks, ViewState // Log first time UI is shown. mUiShownTime = SystemClock.elapsedRealtime(); final long duration = mUiShownTime - mStartTime; + // This logs when dropdown ui was shown. Timestamp is relative to + // when the session was created + mPresentationStatsEventLogger.maybeSetSuggestionPresentedTimestampMs( + (int) (mUiShownTime - mLatencyBaseTime)); + if (sDebug) { final StringBuilder msg = new StringBuilder("1st UI for ") .append(mActivityToken)