Donate to e Foundation | Murena handsets with /e/OS | Own a part of Murena! Learn more

Commit 4d5ef9ee authored by Alex Buynytskyy's avatar Alex Buynytskyy
Browse files

Test only: extend timeout to detect slow callbacks. 

WallpaperManagerService observer perf regressed quite a lot. But this was not caught by benchmarks because there is 3s fixed overall timeout.
This change allows benchmarks to increase the timeout and observe the overall latency.

Test: atest UserLifecycleTests#switchUser --iterations
Bug: 165030092
Bug: 195145506
Change-Id: I335035da3aa0b76243fc2ad60022ecc4a08b0076
parent c9f2fbe7

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

+18 −3
Original line number Diff line number Diff line
@@ -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

+24 −7
Original line number Diff line number Diff line
@@ -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.