Donate to e Foundation | Murena handsets with /e/OS | Own a part of Murena! Learn more

Commit 91d64821 authored by Tim Yu's avatar Tim Yu
Browse files

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
Merged-In: I577266b1b2bbdc53663c4707b5c9578f0c0e14ca
parent 05dbbf29

services/autofill/java/com/android/server/autofill/PresentationStatsEventLogger.java

+38 −2
Original line number Diff line number Diff line
@@ -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() {}

    }

services/autofill/java/com/android/server/autofill/Session.java

+51 −0
Original line number Diff line number Diff line
@@ -321,6 +321,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).

     */
@@ -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)