Android/frameworks_base
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

Add Latency Logs to Autofill Server

Browse Source 
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
This commit is contained in:
Tim Yu
2022-11-07 21:27:46 +00:00
parent bed6078799
commit 5b27ef13b6
2 changed files with 89 additions and 3 deletions
Download Patch File Download Diff File Expand all files Collapse all files

40
services/autofill/java/com/android/server/autofill/PresentationStatsEventLogger.java
View File

@@ -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() {}
}

52
services/autofill/java/com/android/server/autofill/Session.java
View File

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