Added fine-grained tracing to UserController.startUser()
Also refactored SystemServer.BOOT_TIMINGS_TRACE_LOG into a helper class, so it's not permanently
allocated.
Bug: 133242016
Test: manual verification
Test: atest CtsDevicePolicyManagerTestCases:com.android.cts.devicepolicy.DeviceOwnerTest#testCreateAndManageUser_StartInBackground
Change-Id: Id059d4d777bfc705e510d157930aefc7757d8cf8
diff --git a/services/core/java/com/android/server/am/ActivityManagerService.java b/services/core/java/com/android/server/am/ActivityManagerService.java
index a05a68df..8915b9a 100644
--- a/services/core/java/com/android/server/am/ActivityManagerService.java
+++ b/services/core/java/com/android/server/am/ActivityManagerService.java
@@ -292,7 +292,6 @@
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.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 @@
}
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 @@
mUserController.scheduleStartProfiles();
}
- Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER);
+ t.traceEnd();
}
@Override
@@ -8847,8 +8848,11 @@
}
}
- 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 @@
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 @@
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 @@
}
}, mHandler);
- traceLog.traceEnd(); // ActivityManagerStartApps
- traceLog.traceEnd(); // PhaseActivityManagerReady
+ t.traceEnd(); // ActivityManagerStartApps
+ t.traceEnd(); // PhaseActivityManagerReady
}
}
diff --git a/services/core/java/com/android/server/am/UserController.java b/services/core/java/com/android/server/am/UserController.java
index 8f6ac69..f4f2ec5 100644
--- a/services/core/java/com/android/server/am/UserController.java
+++ b/services/core/java/com/android/server/am/UserController.java
@@ -100,6 +100,7 @@
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 @@
@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 @@
// 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 @@
}
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 @@
// 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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
// 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 @@
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 @@
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);
diff --git a/services/core/java/com/android/server/pm/UserManagerService.java b/services/core/java/com/android/server/pm/UserManagerService.java
index 204f186..829dd0f 100644
--- a/services/core/java/com/android/server/pm/UserManagerService.java
+++ b/services/core/java/com/android/server/pm/UserManagerService.java
@@ -100,6 +100,7 @@
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 @@
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
}
/**
diff --git a/services/core/java/com/android/server/utils/TimingsTraceAndSlog.java b/services/core/java/com/android/server/utils/TimingsTraceAndSlog.java
new file mode 100644
index 0000000..704881a
--- /dev/null
+++ b/services/core/java/com/android/server/utils/TimingsTraceAndSlog.java
@@ -0,0 +1,63 @@
+/*
+ * 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);
+ }
+}