Merge "Add Latency Logs to Autofill Server" into tm-qpr-dev

2 files changed, 89 insertions, 2 deletions

diff --git a/services/autofill/java/com/android/server/autofill/PresentationStatsEventLogger.java b/services/autofill/java/com/android/server/autofill/PresentationStatsEventLogger.java
index 6bb19ce05813..5f1da7b18bf9 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 60890d529ef2..a706b0df9c24 100644
--- a/services/autofill/java/com/android/server/autofill/Session.java
+++ b/services/autofill/java/com/android/server/autofill/Session.java
@@ -322,6 +322,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).
      */
     @GuardedBy("mLock")
@@ -993,6 +1000,11 @@ final class Session implements RemoteFillService.FillServiceCallbacks, ViewState
             mAssistReceiver.newAutofillRequestLocked(viewState, /* isInlineRequest= */ false);
         }
 
+        final long fillRequestSentRelativeTimestamp =
+                SystemClock.elapsedRealtime() - mLatencyBaseTime;
+        mPresentationStatsEventLogger.maybeSetFillRequestSentTimestampMs(
+                (int) (fillRequestSentRelativeTimestamp));
+
         // Now request the assist structure data.
         requestAssistStructureLocked(requestId, flags);
     }
@@ -1037,6 +1049,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;
@@ -1066,6 +1079,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
@@ -1159,6 +1180,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);
@@ -3052,6 +3079,8 @@ final class Session implements RemoteFillService.FillServiceCallbacks, ViewState
             case ACTION_VIEW_ENTERED:
                 boolean startedEventWithoutFocus = mStartedLogEventWithoutFocus;
                 mStartedLogEventWithoutFocus = false;
+                mLatencyBaseTime = SystemClock.elapsedRealtime();
+
                 if (sVerbose && virtualBounds != null) {
                     Slog.v(TAG, "entered on virtual child " + id + ": " + virtualBounds);
                 }
@@ -3318,6 +3347,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)) {
@@ -3334,6 +3371,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();
@@ -3344,6 +3388,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,
@@ -3377,6 +3423,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)