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

Commit 807e6508 authored by Fyodor Kupolov's avatar Fyodor Kupolov
Browse files

Report only missing user switching callbacks 

Right now we Slog.wtf all callbacks that occur after USER_SWITCH_TIMEOUT
It adds noise, especially for slower devices. And in most cases, the error
is not actionable.

This change continues to log errors for all timeouts, but use wtf only
when callback was never called (or took significantly more than
USER_SWITCH_TIMEOUT). This is enforced through additional timeout
mechanism which is triggered 5 seconds after the first timeout, but
doesn't prevent device from switching the user.

Test: simulating timeout by adding artificial delay in one of listeners
Bug: 64725373
Change-Id: I397bdfdf463bd7ba74fa9a983c6fcafc9e8b6a54
parent dd0f38c8

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

+5 −0
Original line number Diff line number Diff line
@@ -1685,6 +1685,7 @@ public class ActivityManagerService extends IActivityManager.Stub 
    static final int DISPATCH_PENDING_INTENT_CANCEL_MSG = 67;

    static final int PUSH_TEMP_WHITELIST_UI_MSG = 68;

    static final int SERVICE_FOREGROUND_CRASH_MSG = 69;

    static final int USER_SWITCH_CALLBACKS_TIMEOUT_MSG = 70;

    static final int START_USER_SWITCH_FG_MSG = 712;















    static final int FIRST_ACTIVITY_STACK_MSG = 100;










@@ -2143,6 +2144,10 @@ public class ActivityManagerService extends IActivityManager.Stub













                mUserController.timeoutUserSwitch((UserState) msg.obj, msg.arg1, msg.arg2);















                break;















            }













            case USER_SWITCH_CALLBACKS_TIMEOUT_MSG: {













                mUserController.timeoutUserSwitchCallbacks(msg.arg1, msg.arg2);













                break;













            }















            case IMMERSIVE_MODE_LOCK_MSG: {















                final boolean nextState = (msg.arg1 != 0);















                if (mUpdateLock.isHeld() != nextState) {

























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



+37
−12




























Original line number
Diff line number
Diff line








@@ -36,6 +36,7 @@ import static com.android.server.am.ActivityManagerService.REPORT_USER_SWITCH_MS













import static com.android.server.am.ActivityManagerService.SYSTEM_USER_CURRENT_MSG;















import static com.android.server.am.ActivityManagerService.SYSTEM_USER_START_MSG;















import static com.android.server.am.ActivityManagerService.SYSTEM_USER_UNLOCK_MSG;













import static com.android.server.am.ActivityManagerService.USER_SWITCH_CALLBACKS_TIMEOUT_MSG;















import static com.android.server.am.ActivityManagerService.USER_SWITCH_TIMEOUT_MSG;















import static com.android.server.am.UserState.STATE_BOOTING;















import static com.android.server.am.UserState.STATE_RUNNING_LOCKED;










@@ -115,7 +116,12 @@ class UserController {





























    // 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 = 3 * 1000;













    static final int USER_SWITCH_TIMEOUT_MS = 3 * 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.













    private static final int USER_SWITCH_CALLBACKS_TIMEOUT_MS = 5 * 1000;































    private final Object mLock;















    private final Injector mInjector;










@@ -171,6 +177,12 @@ class UserController {













    @GuardedBy("mLock")















    private volatile ArraySet<String> mCurWaitingUserSwitchCallbacks;





























    /**













     * Callbacks that are still active after {@link #USER_SWITCH_TIMEOUT_MS}













     */













    @GuardedBy("mLock")













    private ArraySet<String> mTimeoutUserSwitchCallbacks;





























    private final LockPatternUtils mLockPatternUtils;































    UserController(ActivityManagerService service) {










@@ -924,7 +936,7 @@ class UserController {













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













                            oldUserId, userId, uss), USER_SWITCH_TIMEOUT_MS);















                }































                if (needStart) {










@@ -1130,8 +1142,23 @@ class UserController {





























    void timeoutUserSwitch(UserState uss, int oldUserId, int newUserId) {















        synchronized (mLock) {













            Slog.wtf(TAG, "User switch timeout: from " + oldUserId + " to " + newUserId);













            Slog.e(TAG, "User switch timeout: from " + oldUserId + " to " + newUserId);













            mTimeoutUserSwitchCallbacks = mCurWaitingUserSwitchCallbacks;













            mHandler.removeMessages(USER_SWITCH_CALLBACKS_TIMEOUT_MSG);















            sendContinueUserSwitchLocked(uss, oldUserId, newUserId);













            // Report observers that never called back (USER_SWITCH_CALLBACKS_TIMEOUT)













            mHandler.sendMessageDelayed(mHandler.obtainMessage(USER_SWITCH_CALLBACKS_TIMEOUT_MSG,













                    oldUserId, newUserId), USER_SWITCH_CALLBACKS_TIMEOUT_MS);













        }













    }



























    void timeoutUserSwitchCallbacks(int oldUserId, int newUserId) {













        synchronized (mLock) {













            if (mTimeoutUserSwitchCallbacks != null && !mTimeoutUserSwitchCallbacks.isEmpty()) {













                Slog.wtf(TAG, "User switch timeout: from " + oldUserId + " to " + newUserId













                        + ". Observers that didn't respond: " + mTimeoutUserSwitchCallbacks);













                mTimeoutUserSwitchCallbacks = null;













            }















        }















    }

























@@ -1158,18 +1185,16 @@ class UserController {













                        public void sendResult(Bundle data) throws RemoteException {















                            synchronized (mLock) {















                                long delay = SystemClock.elapsedRealtime() - dispatchStartedTime;













                                if (delay > USER_SWITCH_TIMEOUT) {













                                    Slog.wtf(TAG, "User switch timeout: observer "  + name













                                if (delay > USER_SWITCH_TIMEOUT_MS) {













                                    Slog.e(TAG, "User switch timeout: observer "  + name















                                            + " sent result after " + delay + " ms");















                                }













                                // Early return if this session is no longer valid













                                if (curWaitingUserSwitchCallbacks













                                        != mCurWaitingUserSwitchCallbacks) {













                                    return;













                                }















                                curWaitingUserSwitchCallbacks.remove(name);













                                // Continue switching if all callbacks have been notified













                                if (waitingCallbacksCount.decrementAndGet() == 0) {













                                // Continue switching if all callbacks have been notified and













                                // user switching session is still valid













                                if (waitingCallbacksCount.decrementAndGet() == 0













                                        && (curWaitingUserSwitchCallbacks













                                        == mCurWaitingUserSwitchCallbacks)) {















                                    sendContinueUserSwitchLocked(uss, oldUserId, newUserId);















                                }















                            }