Merge changes from topic "autofill-presentation-timestamps" into main
* changes:
Autofill Presentation Logs 2
Autofill Refactor Presentation Logging
diff --git a/services/autofill/java/com/android/server/autofill/PresentationStatsEventLogger.java b/services/autofill/java/com/android/server/autofill/PresentationStatsEventLogger.java
index f289115..aa76200 100644
--- a/services/autofill/java/com/android/server/autofill/PresentationStatsEventLogger.java
+++ b/services/autofill/java/com/android/server/autofill/PresentationStatsEventLogger.java
@@ -62,6 +62,7 @@
import android.content.ComponentName;
import android.content.Context;
import android.content.pm.PackageManager;
+import android.os.SystemClock;
import android.provider.Settings;
import android.service.autofill.Dataset;
import android.text.TextUtils;
@@ -211,17 +212,21 @@
AUTOFILL_FILL_RESPONSE_REPORTED__DETECTION_PREFERENCE__DETECTION_PREFER_AUTOFILL_PROVIDER;
public static final int DETECTION_PREFER_PCC =
AUTOFILL_FILL_RESPONSE_REPORTED__DETECTION_PREFERENCE__DETECTION_PREFER_PCC;
- private final int mSessionId;
+ private static final int DEFAULT_VALUE_INT = -1;
+
+ private final int mSessionId;
/**
* For app_package_uid.
*/
private final int mCallingAppUid;
private Optional<PresentationStatsEventInternal> mEventInternal;
+ private final long mSessionStartTimestamp;
- private PresentationStatsEventLogger(int sessionId, int callingAppUid) {
+ private PresentationStatsEventLogger(int sessionId, int callingAppUid, long timestamp) {
mSessionId = sessionId;
mCallingAppUid = callingAppUid;
+ mSessionStartTimestamp = timestamp;
mEventInternal = Optional.empty();
}
@@ -229,8 +234,8 @@
* Create PresentationStatsEventLogger, populated with sessionId and the callingAppUid
*/
public static PresentationStatsEventLogger createPresentationLog(
- int sessionId, int callingAppUid) {
- return new PresentationStatsEventLogger(sessionId, callingAppUid);
+ int sessionId, int callingAppUid, long timestamp) {
+ return new PresentationStatsEventLogger(sessionId, callingAppUid, timestamp);
}
public void startNewEvent() {
@@ -370,28 +375,50 @@
});
}
+ public void maybeSetFillRequestSentTimestampMs() {
+ maybeSetFillRequestSentTimestampMs(getElapsedTime());
+ }
+
public void maybeSetFillResponseReceivedTimestampMs(int timestamp) {
mEventInternal.ifPresent(event -> {
event.mFillResponseReceivedTimestampMs = timestamp;
});
}
+ public void maybeSetFillResponseReceivedTimestampMs() {
+ maybeSetFillResponseReceivedTimestampMs(getElapsedTime());
+ }
+
public void maybeSetSuggestionSentTimestampMs(int timestamp) {
mEventInternal.ifPresent(event -> {
event.mSuggestionSentTimestampMs = timestamp;
});
}
+ public void maybeSetSuggestionSentTimestampMs() {
+ maybeSetSuggestionSentTimestampMs(getElapsedTime());
+ }
+
public void maybeSetSuggestionPresentedTimestampMs(int timestamp) {
mEventInternal.ifPresent(event -> {
- event.mSuggestionPresentedTimestampMs = timestamp;
+ // mSuggestionPresentedTimestampMs only tracks the first suggested timestamp.
+ if (event.mSuggestionPresentedTimestampMs == DEFAULT_VALUE_INT) {
+ event.mSuggestionPresentedTimestampMs = timestamp;
+ }
+
+ event.mSuggestionPresentedLastTimestampMs = timestamp;
});
}
+ public void maybeSetSuggestionPresentedTimestampMs() {
+ maybeSetSuggestionPresentedTimestampMs(getElapsedTime());
+ }
+
public void maybeSetSelectedDatasetId(int selectedDatasetId) {
mEventInternal.ifPresent(event -> {
event.mSelectedDatasetId = selectedDatasetId;
});
+ setPresentationSelectedTimestamp();
}
public void maybeSetDialogDismissed(boolean dialogDismissed) {
@@ -479,6 +506,11 @@
});
}
+ /** Set latency_authentication_ui_display_millis as long as mEventInternal presents. */
+ public void maybeSetLatencyAuthenticationUiDisplayMillis() {
+ maybeSetLatencyAuthenticationUiDisplayMillis(getElapsedTime());
+ }
+
/**
* Set latency_dataset_display_millis as long as mEventInternal presents.
*/
@@ -488,6 +520,11 @@
});
}
+ /** Set latency_dataset_display_millis as long as mEventInternal presents. */
+ public void maybeSetLatencyDatasetDisplayMillis() {
+ maybeSetLatencyDatasetDisplayMillis(getElapsedTime());
+ }
+
/**
* Set available_pcc_count.
*/
@@ -524,6 +561,53 @@
});
}
+ /**
+ * Set various timestamps whenever the ViewState is modified
+ *
+ * <p>If the ViewState contains ViewState.STATE_AUTOFILLED, sets field_autofilled_timestamp_ms
+ * else, set field_first_modified_timestamp_ms (if unset) and field_last_modified_timestamp_ms
+ */
+ public void onFieldTextUpdated(ViewState state) {
+ mEventInternal.ifPresent(
+ event -> {
+ int timestamp = getElapsedTime();
+ // Focused id should be set before this is called
+ if (state.id != null && state.id.getViewId() != event.mFocusedId) {
+ // if these don't match, the currently field different than before
+ Slog.w(
+ TAG,
+ "current id: "
+ + state.id.getViewId()
+ + " is different than focused id: "
+ + event.mFocusedId);
+ return;
+ }
+
+ if ((state.getState() & ViewState.STATE_AUTOFILLED) != 0) {
+ event.mAutofilledTimestampMs = timestamp;
+ } else {
+ if (event.mFieldModifiedFirstTimestampMs == DEFAULT_VALUE_INT) {
+ event.mFieldModifiedFirstTimestampMs = timestamp;
+ }
+ event.mFieldModifiedLastTimestampMs = timestamp;
+ }
+ });
+ }
+
+ public void setPresentationSelectedTimestamp() {
+ mEventInternal.ifPresent(event -> {
+ event.mSelectionTimestamp = getElapsedTime();
+ });
+ }
+
+ /**
+ * Returns timestamp (relative to mSessionStartTimestamp)
+ */
+ private int getElapsedTime() {
+ return (int)(SystemClock.elapsedRealtime() - mSessionStartTimestamp);
+ }
+
+
private int convertDatasetPickReason(@Dataset.DatasetEligibleReason int val) {
switch (val) {
case 0:
@@ -648,7 +732,17 @@
+ " mViewFillFailureCount=" + event.mViewFillFailureCount
+ " mFocusedId=" + event.mFocusedId
+ " mViewFillSuccessCount=" + event.mViewFillSuccessCount
- + " mViewFilledButUnexpectedCount=" + event.mViewFilledButUnexpectedCount);
+ + " mViewFilledButUnexpectedCount=" + event.mViewFilledButUnexpectedCount
+ + " event.mSelectionTimestamp=" + event.mSelectionTimestamp
+ + " event.mAutofilledTimestampMs=" + event.mAutofilledTimestampMs
+ + " event.mFieldModifiedFirstTimestampMs="
+ + event.mFieldModifiedFirstTimestampMs
+ + " event.mFieldModifiedLastTimestampMs=" + event.mFieldModifiedLastTimestampMs
+ + " event.mSuggestionPresentedLastTimestampMs="
+ + event.mSuggestionPresentedLastTimestampMs
+ + " event.mFocusedVirtualAutofillId=" + event.mFocusedVirtualAutofillId
+ + " event.mFieldFirstLength=" + event.mFieldFirstLength
+ + " event.mFieldLastLength=" + event.mFieldLastLength);
}
// TODO(b/234185326): Distinguish empty responses from other no presentation reasons.
@@ -694,7 +788,15 @@
event.mViewFillFailureCount,
event.mFocusedId,
event.mViewFillSuccessCount,
- event.mViewFilledButUnexpectedCount);
+ event.mViewFilledButUnexpectedCount,
+ event.mSelectionTimestamp,
+ event.mAutofilledTimestampMs,
+ event.mFieldModifiedFirstTimestampMs,
+ event.mFieldModifiedLastTimestampMs,
+ event.mSuggestionPresentedLastTimestampMs,
+ event.mFocusedVirtualAutofillId,
+ event.mFieldFirstLength,
+ event.mFieldLastLength);
mEventInternal = Optional.empty();
}
@@ -708,31 +810,39 @@
int mCountNotShownImePresentationNotDrawn;
int mCountNotShownImeUserNotSeen;
int mDisplayPresentationType = AUTOFILL_PRESENTATION_EVENT_REPORTED__DISPLAY_PRESENTATION_TYPE__UNKNOWN_AUTOFILL_DISPLAY_PRESENTATION_TYPE;
- int mAutofillServiceUid = -1;
- int mInlineSuggestionHostUid = -1;
+ int mAutofillServiceUid = DEFAULT_VALUE_INT;
+ int mInlineSuggestionHostUid = DEFAULT_VALUE_INT;
boolean mIsRequestTriggered;
- int mFillRequestSentTimestampMs;
- int mFillResponseReceivedTimestampMs;
- int mSuggestionSentTimestampMs;
- int mSuggestionPresentedTimestampMs;
- int mSelectedDatasetId = -1;
+ int mFillRequestSentTimestampMs = DEFAULT_VALUE_INT;
+ int mFillResponseReceivedTimestampMs = DEFAULT_VALUE_INT;
+ int mSuggestionSentTimestampMs = DEFAULT_VALUE_INT;
+ int mSuggestionPresentedTimestampMs = DEFAULT_VALUE_INT;
+ int mSelectedDatasetId = DEFAULT_VALUE_INT;
boolean mDialogDismissed = false;
boolean mNegativeCtaButtonClicked = false;
boolean mPositiveCtaButtonClicked = false;
int mAuthenticationType = AUTHENTICATION_TYPE_UNKNOWN;
int mAuthenticationResult = AUTHENTICATION_RESULT_UNKNOWN;
- int mLatencyAuthenticationUiDisplayMillis = -1;
- int mLatencyDatasetDisplayMillis = -1;
- int mAvailablePccCount = -1;
- int mAvailablePccOnlyCount = -1;
+ int mLatencyAuthenticationUiDisplayMillis = DEFAULT_VALUE_INT;
+ int mLatencyDatasetDisplayMillis = DEFAULT_VALUE_INT;
+ int mAvailablePccCount = DEFAULT_VALUE_INT;
+ int mAvailablePccOnlyCount = DEFAULT_VALUE_INT;
@DatasetPickedReason int mSelectedDatasetPickedReason = PICK_REASON_UNKNOWN;
@DetectionPreference int mDetectionPreference = DETECTION_PREFER_UNKNOWN;
- int mFieldClassificationRequestId = -1;
+ int mFieldClassificationRequestId = DEFAULT_VALUE_INT;
boolean mIsCredentialRequest = false;
boolean mWebviewRequestedCredential = false;
- int mViewFillableTotalCount = -1;
- int mViewFillFailureCount = -1;
- int mFocusedId = -1;
+ int mViewFillableTotalCount = DEFAULT_VALUE_INT;
+ int mViewFillFailureCount = DEFAULT_VALUE_INT;
+ int mFocusedId = DEFAULT_VALUE_INT;
+ int mSelectionTimestamp = DEFAULT_VALUE_INT;
+ int mAutofilledTimestampMs = DEFAULT_VALUE_INT;
+ int mFieldModifiedFirstTimestampMs = DEFAULT_VALUE_INT;
+ int mFieldModifiedLastTimestampMs = DEFAULT_VALUE_INT;
+ int mSuggestionPresentedLastTimestampMs = DEFAULT_VALUE_INT;
+ int mFocusedVirtualAutofillId = DEFAULT_VALUE_INT;
+ int mFieldFirstLength = DEFAULT_VALUE_INT;
+ int mFieldLastLength = DEFAULT_VALUE_INT;
// Default value for success count is set to 0 explicitly. Setting it to -1 for
// uninitialized doesn't help much, as this would be non-zero only if callback is received.
diff --git a/services/autofill/java/com/android/server/autofill/Session.java b/services/autofill/java/com/android/server/autofill/Session.java
index c46464b..aa67ffe 100644
--- a/services/autofill/java/com/android/server/autofill/Session.java
+++ b/services/autofill/java/com/android/server/autofill/Session.java
@@ -1553,7 +1553,7 @@
mLatencyBaseTime = mStartTime;
mRequestCount = 0;
mPresentationStatsEventLogger = PresentationStatsEventLogger.createPresentationLog(
- sessionId, uid);
+ sessionId, uid, mLatencyBaseTime);
mFillRequestEventLogger = FillRequestEventLogger.forSessionId(sessionId);
mFillResponseEventLogger = FillResponseEventLogger.forSessionId(sessionId);
mSessionCommittedEventLogger = SessionCommittedEventLogger.forSessionId(sessionId);
@@ -1575,14 +1575,6 @@
@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
@@ -2678,6 +2670,7 @@
mLoggedInlineDatasetShown = true;
}
mService.logDatasetShown(this.id, mClientState, uiType);
+ mPresentationStatsEventLogger.maybeSetSuggestionPresentedTimestampMs();
Slog.d(TAG, "onShown(): " + uiType);
}
}
@@ -4788,7 +4781,6 @@
updateFilteringStateOnValueChangedLocked(textValue, viewState);
viewState.setCurrentValue(value);
-
final String filterText = textValue;
final AutofillValue filledValue = viewState.getAutofilledValue();
@@ -4815,6 +4807,7 @@
currentView.maybeCallOnFillReady(flags);
}
}
+ mPresentationStatsEventLogger.onFieldTextUpdated(viewState);
if (viewState.id.equals(this.mCurrentViewId)
&& (viewState.getState() & ViewState.STATE_INLINE_SHOWN) != 0) {
@@ -4902,10 +4895,7 @@
synchronized (mLock) {
// Time passed since Session was created
- final long suggestionSentRelativeTimestamp =
- SystemClock.elapsedRealtime() - mLatencyBaseTime;
- mPresentationStatsEventLogger.maybeSetSuggestionSentTimestampMs(
- (int) (suggestionSentRelativeTimestamp));
+ mPresentationStatsEventLogger.maybeSetSuggestionSentTimestampMs();
}
final AutofillId[] ids = response.getFillDialogTriggerIds();
@@ -4922,13 +4912,6 @@
// 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();
@@ -4970,10 +4953,6 @@
// 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 ")