From 807e6508c48067b9e6aa893fed95008af0d51b38 Mon Sep 17 00:00:00 2001 From: Fyodor Kupolov Date: Mon, 21 Aug 2017 16:07:14 -0700 Subject: 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 --- .../android/server/am/ActivityManagerService.java | 5 +++ .../java/com/android/server/am/UserController.java | 49 ++++++++++++++++------ 2 files changed, 42 insertions(+), 12 deletions(-) diff --git a/services/core/java/com/android/server/am/ActivityManagerService.java b/services/core/java/com/android/server/am/ActivityManagerService.java index 132ce1200eb5..a1f85579d2e3 100644 --- a/services/core/java/com/android/server/am/ActivityManagerService.java +++ b/services/core/java/com/android/server/am/ActivityManagerService.java @@ -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) { diff --git a/services/core/java/com/android/server/am/UserController.java b/services/core/java/com/android/server/am/UserController.java index 29445673dfff..db6bb7d8e653 100644 --- a/services/core/java/com/android/server/am/UserController.java +++ b/services/core/java/com/android/server/am/UserController.java @@ -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 mCurWaitingUserSwitchCallbacks; + /** + * Callbacks that are still active after {@link #USER_SWITCH_TIMEOUT_MS} + */ + @GuardedBy("mLock") + private ArraySet 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); } } -- cgit v1.2.3-59-g8ed1b