Merge "Test only: extend timeout to detect slow callbacks."

apct-tests/perftests/multiuser/src/android/multiuser/UserLifecycleTests.java

@@ -15,6 +15,7 @@
  */
 package android.multiuser;
 
+import static org.junit.Assert.assertEquals;
 import static org.junit.Assume.assumeTrue;
 
 import android.annotation.NonNull;
@@ -42,6 +43,7 @@ import android.os.SystemProperties;
 import android.os.UserHandle;
 import android.os.UserManager;
 import android.perftests.utils.ShellHelper;
+import android.text.TextUtils;
 import android.util.Log;
 import android.view.WindowManagerGlobal;
 
@@ -116,13 +118,14 @@ public class UserLifecycleTests {
     private boolean mHasManagedUserFeature;
     private BroadcastWaiter mBroadcastWaiter;
     private UserSwitchWaiter mUserSwitchWaiter;
+    private String mUserSwitchTimeoutMs;
 
     private final BenchmarkRunner mRunner = new BenchmarkRunner();
     @Rule
     public BenchmarkResultsReporter mReporter = new BenchmarkResultsReporter(mRunner);
 
     @Before
-    public void setUp() {
+    public void setUp() throws Exception {
         final Context context = InstrumentationRegistry.getContext();
         mUm = UserManager.get(context);
         mAm = context.getSystemService(ActivityManager.class);
@@ -141,10 +144,16 @@ public class UserLifecycleTests {
             Log.w(TAG, "WARNING: Tests are being run from user " + mAm.getCurrentUser()
                     + " rather than the system user");
         }
+        mUserSwitchTimeoutMs = setSystemProperty("debug.usercontroller.user_switch_timeout_ms",
+                "100000");
+        if (TextUtils.isEmpty(mUserSwitchTimeoutMs)) {
+            mUserSwitchTimeoutMs = "invalid";
+        }
     }
 
     @After
-    public void tearDown() {
+    public void tearDown() throws Exception {
+        setSystemProperty("debug.usercontroller.user_switch_timeout_ms", mUserSwitchTimeoutMs);
         mBroadcastWaiter.close();
         for (int userId : mUsersToRemove) {
             try {
@@ -236,7 +245,7 @@ public class UserLifecycleTests {
 
     /** Tests switching to an uninitialized user. */
     @Test(timeout = TIMEOUT_MAX_TEST_TIME_MS)
-    public void switchUser() throws RemoteException {
+    public void switchUser() throws Exception {
         while (mRunner.keepRunning()) {
             mRunner.pauseTiming();
             final int startUser = mAm.getCurrentUser();
@@ -867,4 +876,10 @@ public class UserLifecycleTests {
     private void attestFalse(@NonNull String message, boolean assertion) {
         attestTrue(message, !assertion);
     }
+
+    private String setSystemProperty(String name, String value) throws Exception {
+        final String oldValue = ShellHelper.runShellCommand("getprop " + name);
+        assertEquals("", ShellHelper.runShellCommand("setprop " + name + " " + value));
+        return oldValue;
+    }
 }

services/core/java/com/android/server/am/UserController.java

@@ -91,6 +91,7 @@ import android.os.UserHandle;
 import android.os.UserManager;
 import android.os.storage.IStorageManager;
 import android.os.storage.StorageManager;
+import android.text.TextUtils;
 import android.text.format.DateUtils;
 import android.util.ArraySet;
 import android.util.EventLog;
@@ -145,7 +146,7 @@ class UserController implements Handler.Callback {
 
     // Amount of time we wait for observers to handle a user switch before
     // giving up on them and unfreezing the screen.
-    static final int USER_SWITCH_TIMEOUT_MS = 3 * 1000;
+    static final int DEFAULT_USER_SWITCH_TIMEOUT_MS = 3 * 1000;
 
     /**
      * Amount of time we wait for an observer to handle a user switch before we log a warning. This
@@ -182,9 +183,11 @@ class UserController implements Handler.Callback {
     // UI thread message constants
     static final int START_USER_SWITCH_UI_MSG = 1000;
 
-    // If a callback wasn't called within USER_SWITCH_CALLBACKS_TIMEOUT_MS after
-    // USER_SWITCH_TIMEOUT_MS, an error is reported. Usually it indicates a problem in the observer
-    // when it never calls back.
+    /**
+     * If a callback wasn't called within USER_SWITCH_CALLBACKS_TIMEOUT_MS after
+     * {@link #getUserSwitchTimeoutMs}, an error is reported. Usually it indicates a problem in the
+     * observer when it never calls back.
+     */
     private static final int USER_SWITCH_CALLBACKS_TIMEOUT_MS = 5 * 1000;
 
     /**
@@ -348,7 +351,7 @@ class UserController implements Handler.Callback {
     private String mSwitchingToSystemUserMessage;
 
     /**
-     * Callbacks that are still active after {@link #USER_SWITCH_TIMEOUT_MS}
+     * Callbacks that are still active after {@link #getUserSwitchTimeoutMs}
      */
     @GuardedBy("mLock")
     private ArraySet<String> mTimeoutUserSwitchCallbacks;
@@ -1642,7 +1645,7 @@ class UserController implements Handler.Callback {
                 mHandler.sendMessage(mHandler.obtainMessage(REPORT_USER_SWITCH_MSG,
                         oldUserId, userId, uss));
                 mHandler.sendMessageDelayed(mHandler.obtainMessage(USER_SWITCH_TIMEOUT_MSG,
-                        oldUserId, userId, uss), USER_SWITCH_TIMEOUT_MS);
+                        oldUserId, userId, uss), getUserSwitchTimeoutMs());
             }
 
             if (userInfo.preCreated) {
@@ -1955,6 +1958,7 @@ class UserController implements Handler.Callback {
                 mCurWaitingUserSwitchCallbacks = curWaitingUserSwitchCallbacks;
             }
             final AtomicInteger waitingCallbacksCount = new AtomicInteger(observerCount);
+            final long userSwitchTimeoutMs = getUserSwitchTimeoutMs();
             final long dispatchStartedTime = SystemClock.elapsedRealtime();
             for (int i = 0; i < observerCount; i++) {
                 final long dispatchStartedTimeForObserver = SystemClock.elapsedRealtime();
@@ -1978,7 +1982,7 @@ class UserController implements Handler.Callback {
 
                                 long totalDelay = SystemClock.elapsedRealtime()
                                         - dispatchStartedTime;
-                                if (totalDelay > USER_SWITCH_TIMEOUT_MS) {
+                                if (totalDelay > userSwitchTimeoutMs) {
                                     Slogf.e(TAG, "User switch timeout: observer " + name
                                             + "'s result was received " + totalDelay
                                             + " ms after dispatchUserSwitch.");
@@ -3109,6 +3113,19 @@ class UserController implements Handler.Callback {
         return bOptions;
     }
 
+    private static int getUserSwitchTimeoutMs() {
+        final String userSwitchTimeoutMs = SystemProperties.get(
+                "debug.usercontroller.user_switch_timeout_ms");
+        if (!TextUtils.isEmpty(userSwitchTimeoutMs)) {
+            try {
+                return Integer.parseInt(userSwitchTimeoutMs);
+            } catch (NumberFormatException ignored) {
+                // Ignored.
+            }
+        }
+        return DEFAULT_USER_SWITCH_TIMEOUT_MS;
+    }
+
     /**
      * Uptime when any user was being unlocked most recently. 0 if no users have been unlocked
      * yet. To avoid lock contention (since it's used by OomAdjuster), it's volatile internally.