Merge "Add Latency Logs to Autofill Server" into tm-qpr-dev (aab31806) · Commits · e / os / android_frameworks_base

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)