diff options
| -rw-r--r-- | cmds/statsd/src/atoms.proto | 3 | ||||
| -rw-r--r-- | services/core/java/com/android/server/am/UserController.java | 204 |
2 files changed, 155 insertions, 52 deletions
diff --git a/cmds/statsd/src/atoms.proto b/cmds/statsd/src/atoms.proto index 573a84f2fe33..12158b318676 100644 --- a/cmds/statsd/src/atoms.proto +++ b/cmds/statsd/src/atoms.proto @@ -9673,6 +9673,9 @@ message UserLifecycleEventOccurred { SWITCH_USER = 1; // Indicates that this is a user switch event START_USER = 2; // Indicates that this is a user start event CREATE_USER = 3; // Indicates that this is a user create event + USER_RUNNING_LOCKED = 4; // Indicates that user is running in locked state + UNLOCKING_USER = 5; // Indicates that this is a user unlocking event + UNLOCKED_USER = 6; // Indicates that this is a user unlocked event } optional Event event = 3; diff --git a/services/core/java/com/android/server/am/UserController.java b/services/core/java/com/android/server/am/UserController.java index fac4a1e95827..ea7059894f38 100644 --- a/services/core/java/com/android/server/am/UserController.java +++ b/services/core/java/com/android/server/am/UserController.java @@ -90,7 +90,6 @@ import android.util.Pair; import android.util.Slog; import android.util.SparseArray; import android.util.SparseIntArray; -import android.util.SparseLongArray; import android.util.proto.ProtoOutputStream; import com.android.internal.R; @@ -154,6 +153,15 @@ class UserController implements Handler.Callback { static final int REPORT_LOCKED_BOOT_COMPLETE_MSG = 110; static final int START_USER_SWITCH_FG_MSG = 120; + // Message constant to clear {@link UserJourneySession} from {@link mUserIdToUserJourneyMap} if + // the user journey, defined in the UserLifecycleJourneyReported atom for statsd, is not + // complete within {@link USER_JOURNEY_TIMEOUT}. + private static final int CLEAR_USER_JOURNEY_SESSION_MSG = 200; + // Wait time for completing the user journey. If a user journey is not complete within this + // time, the remaining lifecycle events for the journey would not be logged in statsd. + // Timeout set for 90 seconds. + private static final int USER_JOURNEY_TIMEOUT_MS = 90_000; + // UI thread message constants static final int START_USER_SWITCH_UI_MSG = 1000; @@ -194,14 +202,37 @@ class UserController implements Handler.Callback { FrameworkStatsLog.USER_LIFECYCLE_EVENT_OCCURRED__EVENT__START_USER; private static final int USER_LIFECYCLE_EVENT_CREATE_USER = FrameworkStatsLog.USER_LIFECYCLE_EVENT_OCCURRED__EVENT__CREATE_USER; + private static final int USER_LIFECYCLE_EVENT_USER_RUNNING_LOCKED = + FrameworkStatsLog.USER_LIFECYCLE_EVENT_OCCURRED__EVENT__USER_RUNNING_LOCKED; + private static final int USER_LIFECYCLE_EVENT_UNLOCKING_USER = + FrameworkStatsLog.USER_LIFECYCLE_EVENT_OCCURRED__EVENT__UNLOCKING_USER; + private static final int USER_LIFECYCLE_EVENT_UNLOCKED_USER = + FrameworkStatsLog.USER_LIFECYCLE_EVENT_OCCURRED__EVENT__UNLOCKED_USER; @IntDef(prefix = { "USER_LIFECYCLE_EVENT" }, value = { USER_LIFECYCLE_EVENT_UNKNOWN, USER_LIFECYCLE_EVENT_SWITCH_USER, USER_LIFECYCLE_EVENT_START_USER, USER_LIFECYCLE_EVENT_CREATE_USER, + USER_LIFECYCLE_EVENT_USER_RUNNING_LOCKED, + USER_LIFECYCLE_EVENT_UNLOCKING_USER, + USER_LIFECYCLE_EVENT_UNLOCKED_USER, }) @interface UserLifecycleEvent {} + // User lifecyle event state, defined in the UserLifecycleEventOccurred atom for statsd + private static final int USER_LIFECYCLE_EVENT_STATE_BEGIN = + FrameworkStatsLog.USER_LIFECYCLE_EVENT_OCCURRED__STATE__BEGIN; + private static final int USER_LIFECYCLE_EVENT_STATE_FINISH = + FrameworkStatsLog.USER_LIFECYCLE_EVENT_OCCURRED__STATE__FINISH; + private static final int USER_LIFECYCLE_EVENT_STATE_NONE = + FrameworkStatsLog.USER_LIFECYCLE_EVENT_OCCURRED__STATE__NONE; + @IntDef(prefix = { "USER_LIFECYCLE_EVENT_STATE" }, value = { + USER_LIFECYCLE_EVENT_STATE_BEGIN, + USER_LIFECYCLE_EVENT_STATE_FINISH, + USER_LIFECYCLE_EVENT_STATE_NONE, + }) + @interface UserLifecycleEventState {} + /** * Maximum number of users we allow to be running at a time, including system user. * @@ -311,11 +342,11 @@ class UserController implements Handler.Callback { private final ArrayList<Integer> mLastActiveUsers = new ArrayList<>(); /** - * A per-user, journey to session id map, used for statsd logging for the + * {@link UserIdInt} to {@link UserJourneySession} mapping used for statsd logging for the * UserLifecycleJourneyReported and UserLifecycleEventOccurred atoms. */ - @GuardedBy("mUserJourneyToSessionIdMap") - private final SparseArray<SparseLongArray> mUserJourneyToSessionIdMap = new SparseArray<>(); + @GuardedBy("mUserIdToUserJourneyMap") + private final SparseArray<UserJourneySession> mUserIdToUserJourneyMap = new SparseArray<>(); UserController(ActivityManagerService service) { this(new Injector(service)); @@ -447,6 +478,8 @@ class UserController implements Handler.Callback { // but we might immediately step into RUNNING below if the user // storage is already unlocked. if (uss.setState(STATE_BOOTING, STATE_RUNNING_LOCKED)) { + logUserLifecycleEvent(userId, USER_LIFECYCLE_EVENT_USER_RUNNING_LOCKED, + USER_LIFECYCLE_EVENT_STATE_NONE); mInjector.getUserManagerInternal().setUserState(userId, uss.state); // Do not report secondary users, runtime restarts or first boot/upgrade if (userId == UserHandle.USER_SYSTEM @@ -503,6 +536,8 @@ class UserController implements Handler.Callback { private boolean finishUserUnlocking(final UserState uss) { final int userId = uss.mHandle.getIdentifier(); EventLog.writeEvent(EventLogTags.UC_FINISH_USER_UNLOCKING, userId); + logUserLifecycleEvent(userId, USER_LIFECYCLE_EVENT_UNLOCKING_USER, + USER_LIFECYCLE_EVENT_STATE_BEGIN); // Only keep marching forward if user is actually unlocked if (!StorageManager.isUserKeyUnlocked(userId)) return false; synchronized (mLock) { @@ -2396,8 +2431,8 @@ class UserController implements Handler.Callback { case START_USER_SWITCH_FG_MSG: logUserJourneyInfo(getUserInfo(getCurrentUserId()), getUserInfo(msg.arg1), USER_JOURNEY_USER_SWITCH_FG); - logUserLifecycleEvent(msg.arg1, USER_JOURNEY_USER_SWITCH_FG, - USER_LIFECYCLE_EVENT_SWITCH_USER, true); + logUserLifecycleEvent(msg.arg1, USER_LIFECYCLE_EVENT_SWITCH_USER, + USER_LIFECYCLE_EVENT_STATE_BEGIN); startUserInForeground(msg.arg1); break; case REPORT_USER_SWITCH_MSG: @@ -2420,14 +2455,14 @@ class UserController implements Handler.Callback { BatteryStats.HistoryItem.EVENT_USER_RUNNING_START, Integer.toString(msg.arg1), msg.arg1); logUserJourneyInfo(null, getUserInfo(msg.arg1), USER_JOURNEY_USER_START); - logUserLifecycleEvent(msg.arg1, USER_JOURNEY_USER_START, - USER_LIFECYCLE_EVENT_START_USER, true); + logUserLifecycleEvent(msg.arg1, USER_LIFECYCLE_EVENT_START_USER, + USER_LIFECYCLE_EVENT_STATE_BEGIN); mInjector.getSystemServiceManager().startUser(TimingsTraceAndSlog.newAsyncLog(), msg.arg1); - logUserLifecycleEvent(msg.arg1, USER_JOURNEY_USER_START, - USER_LIFECYCLE_EVENT_START_USER, false); + logUserLifecycleEvent(msg.arg1, USER_LIFECYCLE_EVENT_START_USER, + USER_LIFECYCLE_EVENT_STATE_FINISH); clearSessionId(msg.arg1, USER_JOURNEY_USER_START); break; case USER_UNLOCK_MSG: @@ -2437,10 +2472,17 @@ class UserController implements Handler.Callback { FgThread.getHandler().post(() -> { mInjector.loadUserRecents(userId); }); + logUserLifecycleEvent(msg.arg1, USER_LIFECYCLE_EVENT_UNLOCKING_USER, + USER_LIFECYCLE_EVENT_STATE_FINISH); + logUserLifecycleEvent(msg.arg1, USER_LIFECYCLE_EVENT_UNLOCKED_USER, + USER_LIFECYCLE_EVENT_STATE_BEGIN); finishUserUnlocked((UserState) msg.obj); break; case USER_UNLOCKED_MSG: mInjector.getSystemServiceManager().onUserUnlocked(msg.arg1); + logUserLifecycleEvent(msg.arg1, USER_LIFECYCLE_EVENT_UNLOCKED_USER, + USER_LIFECYCLE_EVENT_STATE_FINISH); + clearSessionId(msg.arg1); break; case USER_CURRENT_MSG: mInjector.batteryStatsServiceNoteEvent( @@ -2458,11 +2500,8 @@ class UserController implements Handler.Callback { case REPORT_USER_SWITCH_COMPLETE_MSG: dispatchUserSwitchComplete(msg.arg1); - final int currentJourney = mUserSwitchUiEnabled ? USER_JOURNEY_USER_SWITCH_UI - : USER_JOURNEY_USER_SWITCH_FG; - logUserLifecycleEvent(msg.arg1, currentJourney, - USER_LIFECYCLE_EVENT_SWITCH_USER, false); - clearSessionId(msg.arg1, currentJourney); + logUserLifecycleEvent(msg.arg1, USER_LIFECYCLE_EVENT_SWITCH_USER, + USER_LIFECYCLE_EVENT_STATE_FINISH); break; case REPORT_LOCKED_BOOT_COMPLETE_MSG: dispatchLockedBootComplete(msg.arg1); @@ -2471,10 +2510,13 @@ class UserController implements Handler.Callback { final Pair<UserInfo, UserInfo> fromToUserPair = (Pair<UserInfo, UserInfo>) msg.obj; logUserJourneyInfo(fromToUserPair.first, fromToUserPair.second, USER_JOURNEY_USER_SWITCH_UI); - logUserLifecycleEvent(fromToUserPair.second.id, USER_JOURNEY_USER_SWITCH_UI, - USER_LIFECYCLE_EVENT_SWITCH_USER, true); + logUserLifecycleEvent(fromToUserPair.second.id, USER_LIFECYCLE_EVENT_SWITCH_USER, + USER_LIFECYCLE_EVENT_STATE_BEGIN); showUserSwitchDialog(fromToUserPair); break; + case CLEAR_USER_JOURNEY_SESSION_MSG: + clearSessionId(msg.arg1); + break; } return false; } @@ -2482,27 +2524,61 @@ class UserController implements Handler.Callback { /** * statsd helper method for logging the start of a user journey via a UserLifecycleEventOccurred * atom given the originating and targeting users for the journey. - * - * Note: these info atoms are currently logged more than once per journey since there is no - * state associated with the user's ongoing journey - this will be updated in a later CL. */ private void logUserJourneyInfo(UserInfo origin, UserInfo target, @UserJourney int journey) { final long newSessionId = ThreadLocalRandom.current().nextLong(1, Long.MAX_VALUE); - synchronized (mUserJourneyToSessionIdMap) { - SparseLongArray userSessions = mUserJourneyToSessionIdMap.get(target.id); - if (userSessions == null) { - userSessions = new SparseLongArray(); - mUserJourneyToSessionIdMap.put(target.id, userSessions); - } - final long oldSessionId = userSessions.get(journey); - if (oldSessionId != INVALID_SESSION_ID) { - // potentially an incomplete or timed-out session + synchronized (mUserIdToUserJourneyMap) { + UserJourneySession userJourneySession = mUserIdToUserJourneyMap.get(target.id); + if (userJourneySession != null) { + // TODO(b/157007231): Move this logic to a separate class/file. + if ((userJourneySession.mJourney == USER_JOURNEY_USER_SWITCH_UI + && journey == USER_JOURNEY_USER_START) + || (userJourneySession.mJourney == USER_JOURNEY_USER_SWITCH_FG + && journey == USER_JOURNEY_USER_START)) { + /* + * There is already a user switch journey, and a user start journey for the same + * target user received. User start journey is most likely a part of user switch + * journey so no need to create a new journey for user start. + */ + if (DEBUG_MU) { + Slog.d(TAG, journey + " not logged as it is expected to be part of " + + userJourneySession.mJourney); + } + return; + } + /* + * Possible reasons for this condition to be true: + * - A user switch journey is received while another user switch journey is in + * process for the same user. + * - A user switch journey is received while user start journey is in process for + * the same user. + * - A user start journey is received while another user start journey is in process + * for the same user. + * In all cases potentially an incomplete, timed-out session or multiple + * simultaneous requests. It is not possible to keep track of multiple sessions for + * the same user, so previous session is abandoned. + */ FrameworkStatsLog.write(FrameworkStatsLog.USER_LIFECYCLE_EVENT_OCCURRED, - oldSessionId, target.id, USER_LIFECYCLE_EVENT_UNKNOWN, - FrameworkStatsLog.USER_LIFECYCLE_EVENT_OCCURRED__STATE__NONE); + userJourneySession.mSessionId, target.id, USER_LIFECYCLE_EVENT_UNKNOWN, + USER_LIFECYCLE_EVENT_STATE_NONE); + } + + if (DEBUG_MU) { + Slog.d(TAG, + "Starting a new journey: " + journey + " with session id: " + newSessionId); } - // update session id - userSessions.put(journey, newSessionId); + + userJourneySession = new UserJourneySession(newSessionId, journey); + mUserIdToUserJourneyMap.put(target.id, userJourneySession); + /* + * User lifecyle journey would be complete when {@code #clearSessionId} is called after + * the last expected lifecycle event for the journey. It may be possible that the last + * event is not called, e.g., user not unlocked after user switching. In such cases user + * journey is cleared after {@link USER_JOURNEY_TIMEOUT}. + */ + mHandler.removeMessages(CLEAR_USER_JOURNEY_SESSION_MSG); + mHandler.sendMessageDelayed(mHandler.obtainMessage(CLEAR_USER_JOURNEY_SESSION_MSG, + target.id), USER_JOURNEY_TIMEOUT_MS); } FrameworkStatsLog.write(FrameworkStatsLog.USER_LIFECYCLE_JOURNEY_REPORTED, newSessionId, @@ -2511,41 +2587,65 @@ class UserController implements Handler.Callback { } /** - * statsd helper method for logging the begin or finish of the given event for the - * UserLifecycleEventOccurred statsd atom. - * Note: This does not clear the user's journey session id - if this event represents the end of - * a particular journey, call {@link #clearSessionId} to indicate that the session is over. + * statsd helper method for logging the given event for the UserLifecycleEventOccurred statsd + * atom. */ - private void logUserLifecycleEvent(@UserIdInt int userId, @UserJourney int journey, - @UserLifecycleEvent int event, boolean begin) { + private void logUserLifecycleEvent(@UserIdInt int userId, @UserLifecycleEvent int event, + @UserLifecycleEventState int eventState) { final long sessionId; - synchronized (mUserJourneyToSessionIdMap) { - final SparseLongArray eventToSessionMap = mUserJourneyToSessionIdMap.get(userId); - if (eventToSessionMap == null || eventToSessionMap.size() == 0) { - return; - } - sessionId = eventToSessionMap.get(journey); - if (sessionId == INVALID_SESSION_ID) { + synchronized (mUserIdToUserJourneyMap) { + final UserJourneySession userJourneySession = mUserIdToUserJourneyMap.get(userId); + if (userJourneySession == null || userJourneySession.mSessionId == INVALID_SESSION_ID) { + Slog.w(TAG, "UserLifecycleEvent " + event + + " received without an active userJourneySession."); return; } + sessionId = userJourneySession.mSessionId; } FrameworkStatsLog.write(FrameworkStatsLog.USER_LIFECYCLE_EVENT_OCCURRED, sessionId, userId, - event, begin ? FrameworkStatsLog.USER_LIFECYCLE_EVENT_OCCURRED__STATE__BEGIN - : FrameworkStatsLog.USER_LIFECYCLE_EVENT_OCCURRED__STATE__FINISH); + event, eventState); } /** - * Clears the user's session id associated with the given UserJourney (for statsd). + * Clears the {@link UserJourneySession} for a given {@link UserIdInt} and {@link UserJourney}. */ private void clearSessionId(@UserIdInt int userId, @UserJourney int journey) { - synchronized (mUserJourneyToSessionIdMap) { - if (mUserJourneyToSessionIdMap.get(userId) != null) { - mUserJourneyToSessionIdMap.get(userId).delete(journey); + synchronized (mUserIdToUserJourneyMap) { + final UserJourneySession userJourneySession = mUserIdToUserJourneyMap.get(userId); + if (userJourneySession != null && userJourneySession.mJourney == journey) { + clearSessionId(userId); } } } + /** + * Clears the {@link UserJourneySession} for a given {@link UserIdInt}. + */ + private void clearSessionId(@UserIdInt int userId) { + synchronized (mUserIdToUserJourneyMap) { + mHandler.removeMessages(CLEAR_USER_JOURNEY_SESSION_MSG); + mUserIdToUserJourneyMap.delete(userId); + } + } + + /** + * Helper class to store user journey and session id. + * + * <p> User journey tracks a chain of user lifecycle events occurring during different user + * activities such as user start, user switch, and user creation. + */ + // TODO(b/157007231): Move this class and user journey tracking logic to a separate file. + private static class UserJourneySession { + final long mSessionId; + @UserJourney final int mJourney; + + UserJourneySession(long sessionId, @UserJourney int journey) { + mJourney = journey; + mSessionId = sessionId; + } + } + private static class UserProgressListener extends IProgressListener.Stub { private volatile long mUnlockStarted; @Override |