Merge "Logs how long it took to show the Autofill UI after a field was focused." into oc-mr1-dev

proto/src/metrics_constants.proto

@@ -4532,6 +4532,12 @@ message MetricsEvent {
     // 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.

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

@@ -115,6 +115,7 @@ public final class AutofillManagerService extends SystemService {
     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 @@ public final class AutofillManagerService extends SystemService {
         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 @@ public final class AutofillManagerService extends SystemService {
                 if (showHistory) {
                     pw.println("Requests history:");
                     mRequestsHistory.reverseDump(fd, pw, args);
+                    pw.println("UI latency history:");
+                    mUiLatencyHistory.reverseDump(fd, pw, args);
                 }
             } finally {
                 setDebugLocked(oldDebug);

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

@@ -100,6 +100,8 @@ final class AutofillManagerServiceImpl {
     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 @@ final class AutofillManagerServiceImpl {
     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 class AutofillManagerServiceImpl {
 
         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;

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

@@ -50,6 +50,7 @@ import android.os.Bundle;
 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.SaveRequest;
 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;
@@ -176,6 +179,20 @@ final class Session implements RemoteFillService.FillServiceCallbacks, ViewState
     @GuardedBy("mLock")
     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}.
      */
@@ -397,10 +414,11 @@ final class Session implements RemoteFillService.FillServiceCallbacks, ViewState
     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 @@ final class Session implements RemoteFillService.FillServiceCallbacks, ViewState
         mRemoteFillService = new RemoteFillService(context, componentName, userId, this);
         mActivityToken = activityToken;
         mHasCallback = hasCallback;
+        mUiLatencyHistory = uiLatencyHistory;
         mPackageName = packageName;
         mClient = IAutoFillManagerClient.Stub.asInterface(client);
 
@@ -1347,6 +1366,31 @@ final class Session implements RemoteFillService.FillServiceCallbacks, ViewState
 
         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 @@ final class Session implements RemoteFillService.FillServiceCallbacks, ViewState
         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");