Logs how long it took to show the Autofill UI after a field was focused.
Test: adb shell logcat -b events | grep sysui_
Test: adb dumpsys autofill
Test: cts-tradefed run commandAndExit cts-dev -m CtsAutoFillServiceTestCases
Bug: 65376559
Bug: 66508098
Merged-In: Ia17f8b30d6eef0141b020085985b9ebacff7a455
Change-Id: Ia17f8b30d6eef0141b020085985b9ebacff7a455
diff --git a/proto/src/metrics_constants.proto b/proto/src/metrics_constants.proto
index ccb3d59..54c9ec5 100644
--- a/proto/src/metrics_constants.proto
+++ b/proto/src/metrics_constants.proto
@@ -4532,6 +4532,12 @@
// OS: O MR
AUTOFILL_SERVICE_DISABLED_SELF = 1135;
+ // Counter showing how long it took (in ms) to show the autofill UI after a field was focused
+ // Tag FIELD_AUTOFILL_SERVICE: Package of service that processed the request
+ // Package: Package of the autofill service
+ // OS: O MR
+ AUTOFILL_UI_LATENCY = 1136;
+
// ---- End O-MR1 Constants, all O-MR1 constants go above this line ----
// Add new aosp constants above this line.
diff --git a/services/autofill/java/com/android/server/autofill/AutofillManagerService.java b/services/autofill/java/com/android/server/autofill/AutofillManagerService.java
index b9bea16..1f4161a 100644
--- a/services/autofill/java/com/android/server/autofill/AutofillManagerService.java
+++ b/services/autofill/java/com/android/server/autofill/AutofillManagerService.java
@@ -115,6 +115,7 @@
private final SparseBooleanArray mDisabledUsers = new SparseBooleanArray();
private final LocalLog mRequestsHistory = new LocalLog(20);
+ private final LocalLog mUiLatencyHistory = new LocalLog(20);
private final BroadcastReceiver mBroadcastReceiver = new BroadcastReceiver() {
@Override
@@ -306,7 +307,7 @@
AutofillManagerServiceImpl service = mServicesCache.get(resolvedUserId);
if (service == null) {
service = new AutofillManagerServiceImpl(mContext, mLock, mRequestsHistory,
- resolvedUserId, mUi, mDisabledUsers.get(resolvedUserId));
+ mUiLatencyHistory, resolvedUserId, mUi, mDisabledUsers.get(resolvedUserId));
mServicesCache.put(userId, service);
}
return service;
@@ -736,6 +737,8 @@
if (showHistory) {
pw.println("Requests history:");
mRequestsHistory.reverseDump(fd, pw, args);
+ pw.println("UI latency history:");
+ mUiLatencyHistory.reverseDump(fd, pw, args);
}
} finally {
setDebugLocked(oldDebug);
diff --git a/services/autofill/java/com/android/server/autofill/AutofillManagerServiceImpl.java b/services/autofill/java/com/android/server/autofill/AutofillManagerServiceImpl.java
index 5c27127..3a3b570 100644
--- a/services/autofill/java/com/android/server/autofill/AutofillManagerServiceImpl.java
+++ b/services/autofill/java/com/android/server/autofill/AutofillManagerServiceImpl.java
@@ -100,6 +100,8 @@
private static final Random sRandom = new Random();
private final LocalLog mRequestsHistory;
+ private final LocalLog mUiLatencyHistory;
+
/**
* Whether service was disabled for user due to {@link UserManager} restrictions.
*/
@@ -141,10 +143,11 @@
private long mLastPrune = 0;
AutofillManagerServiceImpl(Context context, Object lock, LocalLog requestsHistory,
- int userId, AutoFillUI ui, boolean disabled) {
+ LocalLog uiLatencyHistory, int userId, AutoFillUI ui, boolean disabled) {
mContext = context;
mLock = lock;
mRequestsHistory = requestsHistory;
+ mUiLatencyHistory = uiLatencyHistory;
mUserId = userId;
mUi = ui;
updateLocked(disabled);
@@ -399,7 +402,7 @@
final Session newSession = new Session(this, mUi, mContext, mHandlerCaller, mUserId, mLock,
sessionId, uid, activityToken, appCallbackToken, hasCallback,
- mInfo.getServiceInfo().getComponentName(), packageName);
+ mUiLatencyHistory, mInfo.getServiceInfo().getComponentName(), packageName);
mSessions.put(newSession.id, newSession);
return newSession;
diff --git a/services/autofill/java/com/android/server/autofill/Session.java b/services/autofill/java/com/android/server/autofill/Session.java
index 2d10aff..905db67 100644
--- a/services/autofill/java/com/android/server/autofill/Session.java
+++ b/services/autofill/java/com/android/server/autofill/Session.java
@@ -50,6 +50,7 @@
import android.os.IBinder;
import android.os.Parcelable;
import android.os.RemoteException;
+import android.os.SystemClock;
import android.service.autofill.AutofillService;
import android.service.autofill.Dataset;
import android.service.autofill.FillContext;
@@ -61,8 +62,10 @@
import android.service.autofill.ValueFinder;
import android.util.ArrayMap;
import android.util.ArraySet;
+import android.util.LocalLog;
import android.util.Slog;
import android.util.SparseArray;
+import android.util.TimeUtils;
import android.view.autofill.AutofillId;
import android.view.autofill.AutofillManager;
import android.view.autofill.AutofillValue;
@@ -177,6 +180,20 @@
private PendingUi mPendingSaveUi;
/**
+ * When the session started (using elapsed time since boot).
+ */
+ private final long mStartTime;
+
+ /**
+ * When the UI was shown for the first time (using elapsed time since boot).
+ */
+ @GuardedBy("mLock")
+ private long mUiShownTime;
+
+ @GuardedBy("mLock")
+ private final LocalLog mUiLatencyHistory;
+
+ /**
* Receiver of assist data from the app's {@link Activity}.
*/
private final IResultReceiver mAssistReceiver = new IResultReceiver.Stub() {
@@ -397,10 +414,11 @@
Session(@NonNull AutofillManagerServiceImpl service, @NonNull AutoFillUI ui,
@NonNull Context context, @NonNull HandlerCaller handlerCaller, int userId,
@NonNull Object lock, int sessionId, int uid, @NonNull IBinder activityToken,
- @NonNull IBinder client, boolean hasCallback,
+ @NonNull IBinder client, boolean hasCallback, @NonNull LocalLog uiLatencyHistory,
@NonNull ComponentName componentName, @NonNull String packageName) {
id = sessionId;
this.uid = uid;
+ mStartTime = SystemClock.elapsedRealtime();
mService = service;
mLock = lock;
mUi = ui;
@@ -408,6 +426,7 @@
mRemoteFillService = new RemoteFillService(context, componentName, userId, this);
mActivityToken = activityToken;
mHasCallback = hasCallback;
+ mUiLatencyHistory = uiLatencyHistory;
mPackageName = packageName;
mClient = IAutoFillManagerClient.Stub.asInterface(client);
@@ -1347,6 +1366,31 @@
getUiForShowing().showFillUi(filledId, response, filterText,
mService.getServicePackageName(), mPackageName, this);
+
+ synchronized (mLock) {
+ if (mUiShownTime == 0) {
+ // Log first time UI is shown.
+ mUiShownTime = SystemClock.elapsedRealtime();
+ final long duration = mUiShownTime - mStartTime;
+ if (sDebug) {
+ final StringBuilder msg = new StringBuilder("1st UI for ")
+ .append(mActivityToken)
+ .append(" shown in ");
+ TimeUtils.formatDuration(duration, msg);
+ Slog.d(TAG, msg.toString());
+ }
+ final StringBuilder historyLog = new StringBuilder("id=").append(id)
+ .append(" app=").append(mActivityToken)
+ .append(" svc=").append(mService.getServicePackageName())
+ .append(" latency=");
+ TimeUtils.formatDuration(duration, historyLog);
+ mUiLatencyHistory.log(historyLog.toString());
+
+ final LogMaker metricsLog = newLogMaker(MetricsEvent.AUTOFILL_UI_LATENCY)
+ .setCounterValue((int) duration);
+ mMetricsLogger.write(metricsLog);
+ }
+ }
}
boolean isDestroyed() {
@@ -1655,6 +1699,14 @@
pw.print(prefix); pw.print("uid: "); pw.println(uid);
pw.print(prefix); pw.print("mPackagename: "); pw.println(mPackageName);
pw.print(prefix); pw.print("mActivityToken: "); pw.println(mActivityToken);
+ pw.print(prefix); pw.print("mStartTime: "); pw.println(mStartTime);
+ pw.print(prefix); pw.print("Time to show UI: ");
+ if (mUiShownTime == 0) {
+ pw.println("N/A");
+ } else {
+ TimeUtils.formatDuration(mUiShownTime - mStartTime, pw);
+ pw.println();
+ }
pw.print(prefix); pw.print("mResponses: ");
if (mResponses == null) {
pw.println("null");