Merge "Added more events to user switch journey" into rvc-dev am: 6a468598f0 am: eca0ff9e29 (44013fc1) · Commits · e / os / android_frameworks_base

cmds/statsd/src/atoms.proto

+3 −0

Original line number	Diff line number	Diff line
		@@ -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;

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

+152 −52

Original line number	Diff line number	Diff line
		@@ -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);
		}
		// update session id
		userSessions.put(journey, newSessionId);

		if (DEBUG_MU) {
		Slog.d(TAG,
		"Starting a new journey: " + journey + " with session id: " + 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