Merge "Added fine-grained tracing to UserController.startUser()" (b45f2aae) · Commits · e / os / android_frameworks_base

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

+14 −10

Original line number	Diff line number	Diff line
		@@ -292,7 +292,6 @@ import android.util.SparseArray;
		import android.util.SparseIntArray;
		import android.util.StatsLog;
		import android.util.TimeUtils;
		import android.util.TimingsTraceLog;
		import android.util.proto.ProtoOutputStream;
		import android.util.proto.ProtoUtils;
		import android.view.Display;
		@@ -359,6 +358,7 @@ import com.android.server.pm.Installer.InstallerException;
		import com.android.server.uri.GrantUri;
		import com.android.server.uri.UriGrantsManagerInternal;
		import com.android.server.utils.PriorityDump;
		import com.android.server.utils.TimingsTraceAndSlog;
		import com.android.server.vr.VrManagerInternal;
		import com.android.server.wm.ActivityServiceConnectionsHolder;
		import com.android.server.wm.ActivityTaskManagerInternal;
		@@ -5074,7 +5074,8 @@ public class ActivityManagerService extends IActivityManager.Stub
		}

		final void finishBooting() {
		Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER, "FinishBooting");
		TimingsTraceAndSlog t = new TimingsTraceAndSlog(TAG, Trace.TRACE_TAG_ACTIVITY_MANAGER);
		t.traceBegin("FinishBooting");

		synchronized (this) {
		if (!mBootAnimationComplete) {
		@@ -5191,7 +5192,7 @@ public class ActivityManagerService extends IActivityManager.Stub
		mUserController.scheduleStartProfiles();
		}

		Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER);
		t.traceEnd();
		}

		@Override
		@@ -8847,8 +8848,11 @@ public class ActivityManagerService extends IActivityManager.Stub
		}
		}

		public void systemReady(final Runnable goingCallback, TimingsTraceLog traceLog) {
		traceLog.traceBegin("PhaseActivityManagerReady");
		/**
		* Ready. Set. Go!
		*/
		public void systemReady(final Runnable goingCallback, @NonNull TimingsTraceAndSlog t) {
		t.traceBegin("PhaseActivityManagerReady");
		synchronized(this) {
		if (mSystemReady) {
		// If we're done calling all the receivers, run the next "boot phase" passed in
		@@ -8933,7 +8937,7 @@ public class ActivityManagerService extends IActivityManager.Stub
		throw new RuntimeException("System user not started while current user is:"
		+ currentUserId);
		}
		traceLog.traceBegin("ActivityManagerStartApps");
		t.traceBegin("ActivityManagerStartApps");
		mBatteryStatsService.noteEvent(BatteryStats.HistoryItem.EVENT_USER_RUNNING_START,
		Integer.toString(currentUserId), currentUserId);
		mBatteryStatsService.noteEvent(BatteryStats.HistoryItem.EVENT_USER_FOREGROUND_START,
		@@ -8992,8 +8996,8 @@ public class ActivityManagerService extends IActivityManager.Stub
		new String[] {INTERACT_ACROSS_USERS}, OP_NONE,
		null, true, false, MY_PID, SYSTEM_UID, callingUid, callingPid,
		UserHandle.USER_ALL);
		} catch (Throwable t) {
		Slog.wtf(TAG, "Failed sending first user broadcasts", t);
		} catch (Throwable e) {
		Slog.wtf(TAG, "Failed sending first user broadcasts", e);
		} finally {
		Binder.restoreCallingIdentity(ident);
		}
		@@ -9019,8 +9023,8 @@ public class ActivityManagerService extends IActivityManager.Stub
		}
		}, mHandler);

		traceLog.traceEnd(); // ActivityManagerStartApps
		traceLog.traceEnd(); // PhaseActivityManagerReady
		t.traceEnd(); // ActivityManagerStartApps
		t.traceEnd(); // PhaseActivityManagerReady
		}
		}

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

+46 −0

Original line number	Diff line number	Diff line
		@@ -100,6 +100,7 @@ import com.android.server.LocalServices;
		import com.android.server.SystemServiceManager;
		import com.android.server.am.UserState.KeyEvictedCallback;
		import com.android.server.pm.UserManagerService;
		import com.android.server.utils.TimingsTraceAndSlog;
		import com.android.server.wm.ActivityTaskManagerInternal;
		import com.android.server.wm.WindowManagerService;

		@@ -998,12 +999,26 @@ class UserController implements Handler.Callback {
		@Nullable IProgressListener unlockListener) {

		checkCallingPermission(INTERACT_ACROSS_USERS_FULL, "startUser");

		TimingsTraceAndSlog t = new TimingsTraceAndSlog();

		t.traceBegin("startUser-" + userId + "-" + (foreground ? "fg" : "bg"));
		try {
		return startUserInternal(userId, foreground, unlockListener, t);
		} finally {
		t.traceEnd();
		}
		}

		private boolean startUserInternal(int userId, boolean foreground,
		@Nullable IProgressListener unlockListener, @NonNull TimingsTraceAndSlog t) {
		Slog.i(TAG, "Starting userid:" + userId + " fg:" + foreground);

		final int callingUid = Binder.getCallingUid();
		final int callingPid = Binder.getCallingPid();
		final long ident = Binder.clearCallingIdentity();
		try {
		t.traceBegin("getStartedUserState");
		final int oldUserId = getCurrentUserId();
		if (oldUserId == userId) {
		final UserState state = getStartedUserState(userId);
		@@ -1020,16 +1035,23 @@ class UserController implements Handler.Callback {
		// unlocked.
		notifyFinished(userId, unlockListener);
		}
		t.traceEnd(); //getStartedUserState
		return true;
		}
		}
		}
		t.traceEnd(); //getStartedUserState

		if (foreground) {
		t.traceBegin("clearAllLockedTasks");
		mInjector.clearAllLockedTasks("startUser");
		t.traceEnd();
		}

		t.traceBegin("getUserInfo");
		final UserInfo userInfo = getUserInfo(userId);
		t.traceEnd();

		if (userInfo == null) {
		Slog.w(TAG, "No user info for user #" + userId);
		return false;
		@@ -1040,8 +1062,10 @@ class UserController implements Handler.Callback {
		}

		if (foreground && mUserSwitchUiEnabled) {
		t.traceBegin("startFreezingScreen");
		mInjector.getWindowManager().startFreezingScreen(
		R.anim.screen_user_exit, R.anim.screen_user_enter);
		t.traceEnd();
		}

		boolean needStart = false;
		@@ -1050,6 +1074,7 @@ class UserController implements Handler.Callback {

		// If the user we are switching to is not currently started, then
		// we need to start it now.
		t.traceBegin("updateStartedUserArrayStarting");
		synchronized (mLock) {
		uss = mStartedUsers.get(userId);
		if (uss == null) {
		@@ -1063,6 +1088,7 @@ class UserController implements Handler.Callback {
		Slog.i(TAG, "User #" + userId
		+ " is shutting down - will start after full stop");
		mHandler.post(() -> startUser(userId, foreground, unlockListener));
		t.traceEnd(); // updateStartedUserArrayStarting
		return true;
		}
		final Integer userIdInt = userId;
		@@ -1072,9 +1098,14 @@ class UserController implements Handler.Callback {
		if (unlockListener != null) {
		uss.mUnlockProgress.addListener(unlockListener);
		}
		t.traceEnd(); // updateStartedUserArrayStarting

		if (updateUmState) {
		t.traceBegin("setUserState");
		mInjector.getUserManagerInternal().setUserState(userId, uss.state);
		t.traceEnd();
		}
		t.traceBegin("updateConfigurationAndProfileIds");
		if (foreground) {
		// Make sure the old user is no longer considering the display to be on.
		mInjector.reportGlobalUsageEventLocked(UsageEvents.Event.SCREEN_NON_INTERACTIVE);
		@@ -1101,10 +1132,12 @@ class UserController implements Handler.Callback {
		mUserLru.add(currentUserIdInt);
		}
		}
		t.traceEnd();

		// Make sure user is in the started state. If it is currently
		// stopping, we need to knock that off.
		if (uss.state == UserState.STATE_STOPPING) {
		t.traceBegin("updateStateStopping");
		// If we are stopping, we haven't sent ACTION_SHUTDOWN,
		// so we can just fairly silently bring the user back from
		// the almost-dead.
		@@ -1114,7 +1147,9 @@ class UserController implements Handler.Callback {
		updateStartedUserArrayLU();
		}
		needStart = true;
		t.traceEnd();
		} else if (uss.state == UserState.STATE_SHUTDOWN) {
		t.traceBegin("updateStateShutdown");
		// This means ACTION_SHUTDOWN has been sent, so we will
		// need to treat this as a new boot of the user.
		uss.setState(UserState.STATE_BOOTING);
		@@ -1123,9 +1158,11 @@ class UserController implements Handler.Callback {
		updateStartedUserArrayLU();
		}
		needStart = true;
		t.traceBegin("updateStateStopping");
		}

		if (uss.state == UserState.STATE_BOOTING) {
		t.traceBegin("updateStateBooting");
		// Give user manager a chance to propagate user restrictions
		// to other services and prepare app storage
		mInjector.getUserManager().onBeforeStartUser(userId);
		@@ -1135,8 +1172,10 @@ class UserController implements Handler.Callback {
		// which is important because it needs to go first.
		mHandler.sendMessage(
		mHandler.obtainMessage(SYSTEM_USER_START_MSG, userId, 0));
		t.traceEnd();
		}

		t.traceBegin("sendMessages");
		if (foreground) {
		mHandler.sendMessage(mHandler.obtainMessage(SYSTEM_USER_CURRENT_MSG, userId,
		oldUserId));
		@@ -1158,14 +1197,20 @@ class UserController implements Handler.Callback {
		null, null, 0, null, null, null, AppOpsManager.OP_NONE,
		null, false, false, MY_PID, SYSTEM_UID, callingUid, callingPid, userId);
		}
		t.traceEnd();

		if (foreground) {
		t.traceBegin("moveUserToForeground");
		moveUserToForeground(uss, oldUserId, userId);
		t.traceEnd();
		} else {
		t.traceBegin("finishUserBoot");
		finishUserBoot(uss);
		t.traceEnd();
		}

		if (needStart) {
		t.traceBegin("sendRestartBroadcast");
		Intent intent = new Intent(Intent.ACTION_USER_STARTING);
		intent.addFlags(Intent.FLAG_RECEIVER_REGISTERED_ONLY);
		intent.putExtra(Intent.EXTRA_USER_HANDLE, userId);
		@@ -1181,6 +1226,7 @@ class UserController implements Handler.Callback {
		new String[]{INTERACT_ACROSS_USERS}, AppOpsManager.OP_NONE,
		null, true, false, MY_PID, SYSTEM_UID, callingUid, callingPid,
		UserHandle.USER_ALL);
		t.traceEnd();
		}
		} finally {
		Binder.restoreCallingIdentity(ident);

services/core/java/com/android/server/pm/UserManagerService.java

+10 −0

Original line number	Diff line number	Diff line
		@@ -100,6 +100,7 @@ import com.android.server.LockGuard;
		import com.android.server.SystemService;
		import com.android.server.am.UserState;
		import com.android.server.storage.DeviceStorageMonitorInternal;
		import com.android.server.utils.TimingsTraceAndSlog;
		import com.android.server.wm.ActivityTaskManagerInternal;

		import libcore.io.IoUtils;
		@@ -3450,17 +3451,26 @@ public class UserManagerService extends IUserManager.Stub {
		if (userInfo == null) {
		return;
		}
		TimingsTraceAndSlog t = new TimingsTraceAndSlog();
		t.traceBegin("onBeforeStartUser-" + userId);
		final int userSerial = userInfo.serialNumber;
		// Migrate only if build fingerprints mismatch
		boolean migrateAppsData = !Build.FINGERPRINT.equals(userInfo.lastLoggedInFingerprint);
		t.traceBegin("prepareUserData");
		mUserDataPreparer.prepareUserData(userId, userSerial, StorageManager.FLAG_STORAGE_DE);
		t.traceEnd();
		t.traceBegin("reconcileAppsData");
		mPm.reconcileAppsData(userId, StorageManager.FLAG_STORAGE_DE, migrateAppsData);
		t.traceEnd();

		if (userId != UserHandle.USER_SYSTEM) {
		t.traceBegin("applyUserRestrictions");
		synchronized (mRestrictionsLock) {
		applyUserRestrictionsLR(userId);
		}
		t.traceEnd();
		}
		t.traceEnd(); // onBeforeStartUser
		}

		/**

services/core/java/com/android/server/utils/TimingsTraceAndSlog.java

0 → 100644

+63 −0

Original line number	Diff line number	Diff line
		/*
		* Copyright (C) 2019 The Android Open Source Project
		*
		* Licensed under the Apache License, Version 2.0 (the "License");
		* you may not use this file except in compliance with the License.
		* You may obtain a copy of the License at
		*
		* http://www.apache.org/licenses/LICENSE-2.0
		*
		* Unless required by applicable law or agreed to in writing, software
		* distributed under the License is distributed on an "AS IS" BASIS,
		* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
		* See the License for the specific language governing permissions and
		* limitations under the License.
		*/
		package com.android.server.utils;

		import android.annotation.NonNull;
		import android.os.Trace;
		import android.util.Slog;
		import android.util.TimingsTraceLog;

		/**
		* Helper class for reporting boot and shutdown timing metrics, also logging to {@link Slog}.
		*/
		public final class TimingsTraceAndSlog extends TimingsTraceLog {

		/**
		* Tag for timing measurement of main thread.
		*/
		public static final String SYSTEM_SERVER_TIMING_TAG = "SystemServerTiming";

		/**
		* Tag for timing measurement of non-main asynchronous operations.
		*/
		public static final String SYSTEM_SERVER_TIMING_ASYNC_TAG = SYSTEM_SERVER_TIMING_TAG + "Async";

		private final String mTag;

		/**
		* Default constructor using {@code system_server} tags.
		*/
		public TimingsTraceAndSlog() {
		this(SYSTEM_SERVER_TIMING_TAG, Trace.TRACE_TAG_SYSTEM_SERVER);
		}

		/**
		* Custom constructor.
		*
		* @param tag {@code logcat} tag
		* @param traceTag {@code atrace} tag
		*/
		public TimingsTraceAndSlog(@NonNull String tag, long traceTag) {
		super(tag, traceTag);
		mTag = tag;
		}

		@Override
		public void traceBegin(@NonNull String name) {
		Slog.i(mTag, name);
		super.traceBegin(name);
		}
		}

services/java/com/android/server/SystemServer.java

+432 −443

File changed.

Preview size limit exceeded, changes collapsed.