Moar SystemServer boot timing improvements: (137e7812) · Commits · e / os / android_frameworks_base

core/java/android/util/TimingsTraceLog.java

+24 −1

Original line number	Diff line number	Diff line
		@@ -16,16 +16,22 @@

		package android.util;

		import android.annotation.NonNull;
		import android.os.Build;
		import android.os.SystemClock;
		import android.os.Trace;

		import java.util.ArrayDeque;
		import java.util.ArrayList;
		import java.util.Collections;
		import java.util.Deque;
		import java.util.List;

		/**
		* Helper class for reporting boot and shutdown timing metrics.
		* <p>Note: This class is not thread-safe. Use a separate copy for other threads</p>
		*
		* <p><b>NOTE:</b> This class is not thread-safe. Use a separate copy for other threads.
		*
		* @hide
		*/
		public class TimingsTraceLog {
		@@ -88,4 +94,21 @@ public class TimingsTraceLog {
		public void logDuration(String name, long timeMs) {
		Slog.d(mTag, name + " took to complete: " + timeMs + "ms");
		}

		/**
		* Gets the names of the traces that {@link #traceBegin(String) have begun} but
		* {@link #traceEnd() have not finished} yet.
		*
		* <p><b>NOTE:</b> this method is expensive and it should not be used in "production" - it
		* should only be used for debugging purposes during development (and/or guarded by
		* static {@code DEBUG} constants that are {@code false}).
		*/
		@NonNull
		public final List<String> getUnfinishedTracesForDebug() {
		if (mStartTimes == null \|\| mStartTimes.isEmpty()) return Collections.emptyList();

		final ArrayList<String> stack = new ArrayList<>(mStartTimes.size());
		mStartTimes.descendingIterator().forEachRemaining((pair) -> stack.add(pair.first));
		return stack;
		}
		}

core/tests/coretests/src/android/util/TimingsTraceLogTest.java

+21 −3

Original line number	Diff line number	Diff line
		@@ -16,7 +16,7 @@

		package android.util;

		import static org.junit.Assert.assertTrue;
		import static com.google.common.truth.Truth.assertThat;

		import android.os.Trace;

		@@ -31,7 +31,8 @@ import java.util.List;

		/**
		* Tests for {@link TimingsTraceLog}.
		* <p>Usage: bit FrameworksCoreTests:android.util.TimingsTraceLogTest
		*
		* <p>Usage: {@code atest FrameworksCoreTests:android.util.TimingsTraceLogTest}
		*/
		@SmallTest
		@RunWith(AndroidJUnit4.class)
		@@ -64,7 +65,24 @@ public class TimingsTraceLogTest {
		});
		t.start();
		t.join();
		assertTrue(errors.toString(), errors.isEmpty());
		assertThat(errors).isEmpty();
		}

		@Test
		public void testGetUnfinishedTracesForDebug() {
		TimingsTraceLog log = new TimingsTraceLog("TEST", Trace.TRACE_TAG_APP);
		assertThat(log.getUnfinishedTracesForDebug()).isEmpty();

		log.traceBegin("One");
		assertThat(log.getUnfinishedTracesForDebug()).containsExactly("One").inOrder();

		log.traceBegin("Two");
		assertThat(log.getUnfinishedTracesForDebug()).containsExactly("One", "Two").inOrder();

		log.traceEnd();
		assertThat(log.getUnfinishedTracesForDebug()).containsExactly("One").inOrder();

		log.traceEnd();
		assertThat(log.getUnfinishedTracesForDebug()).isEmpty();
		}
		}

services/core/java/com/android/server/SystemServiceManager.java

+67 −29

Original line number	Diff line number	Diff line
		@@ -17,12 +17,15 @@
		package com.android.server;

		import android.annotation.NonNull;
		import android.annotation.UserIdInt;
		import android.content.Context;
		import android.os.Environment;
		import android.os.SystemClock;
		import android.os.Trace;
		import android.util.Slog;

		import com.android.server.utils.TimingsTraceAndSlog;

		import java.io.File;
		import java.lang.reflect.Constructor;
		import java.lang.reflect.InvocationTargetException;
		@@ -138,9 +141,10 @@ public class SystemServiceManager {
		* Starts the specified boot phase for all system services that have been started up to
		* this point.
		*
		* @param t trace logger
		* @param phase The boot phase to start.
		*/
		public void startBootPhase(final int phase) {
		public void startBootPhase(@NonNull TimingsTraceAndSlog t, int phase) {
		if (phase <= mCurrentPhase) {
		throw new IllegalArgumentException("Next phase must be larger than previous");
		}
		@@ -148,12 +152,12 @@ public class SystemServiceManager {

		Slog.i(TAG, "Starting phase " + mCurrentPhase);
		try {
		Trace.traceBegin(Trace.TRACE_TAG_SYSTEM_SERVER, "OnBootPhase " + phase);
		t.traceBegin("OnBootPhase " + phase);
		final int serviceLen = mServices.size();
		for (int i = 0; i < serviceLen; i++) {
		final SystemService service = mServices.get(i);
		long time = SystemClock.elapsedRealtime();
		Trace.traceBegin(Trace.TRACE_TAG_SYSTEM_SERVER, service.getClass().getName());
		t.traceBegin(service.getClass().getName());
		try {
		service.onBootPhase(mCurrentPhase);
		} catch (Exception ex) {
		@@ -163,10 +167,15 @@ public class SystemServiceManager {
		+ mCurrentPhase, ex);
		}
		warnIfTooLong(SystemClock.elapsedRealtime() - time, service, "onBootPhase");
		Trace.traceEnd(Trace.TRACE_TAG_SYSTEM_SERVER);
		t.traceEnd();
		}
		} finally {
		Trace.traceEnd(Trace.TRACE_TAG_SYSTEM_SERVER);
		t.traceEnd();
		}

		if (phase == SystemService.PHASE_BOOT_COMPLETED) {
		final long totalBootTime = SystemClock.uptimeMillis() - mRuntimeStartUptime;
		t.logDuration("TotalBootTime", totalBootTime);
		}
		}

		@@ -177,13 +186,17 @@ public class SystemServiceManager {
		return mCurrentPhase >= SystemService.PHASE_BOOT_COMPLETED;
		}

		public void startUser(final int userHandle) {
		/**
		* Starts the given user.
		*/
		public void startUser(@NonNull TimingsTraceAndSlog t, final @UserIdInt int userHandle) {
		t.traceBegin("ssm.startUser-" + userHandle);
		Slog.i(TAG, "Calling onStartUser u" + userHandle);
		final int serviceLen = mServices.size();
		for (int i = 0; i < serviceLen; i++) {
		final SystemService service = mServices.get(i);
		Trace.traceBegin(Trace.TRACE_TAG_SYSTEM_SERVER, "onStartUser "
		+ service.getClass().getName());
		final String serviceName = service.getClass().getName();
		t.traceBegin("onStartUser-" + userHandle + " " + serviceName);
		long time = SystemClock.elapsedRealtime();
		try {
		service.onStartUser(userHandle);
		@@ -192,84 +205,109 @@ public class SystemServiceManager {
		+ " to service " + service.getClass().getName(), ex);
		}
		warnIfTooLong(SystemClock.elapsedRealtime() - time, service, "onStartUser ");
		Trace.traceEnd(Trace.TRACE_TAG_SYSTEM_SERVER);
		t.traceEnd();
		}
		t.traceEnd();
		}

		public void unlockUser(final int userHandle) {
		/**
		* Unlocks the given user.
		*/
		public void unlockUser(final @UserIdInt int userHandle) {
		final TimingsTraceAndSlog t = TimingsTraceAndSlog.newAsyncLog();
		t.traceBegin("ssm.unlockUser-" + userHandle);
		Slog.i(TAG, "Calling onUnlockUser u" + userHandle);
		final int serviceLen = mServices.size();
		for (int i = 0; i < serviceLen; i++) {
		final SystemService service = mServices.get(i);
		Trace.traceBegin(Trace.TRACE_TAG_SYSTEM_SERVER, "onUnlockUser "
		+ service.getClass().getName());
		final String serviceName = service.getClass().getName();
		t.traceBegin("onUnlockUser-" + userHandle + " " + serviceName);
		long time = SystemClock.elapsedRealtime();
		try {
		service.onUnlockUser(userHandle);
		} catch (Exception ex) {
		Slog.wtf(TAG, "Failure reporting unlock of user " + userHandle
		+ " to service " + service.getClass().getName(), ex);
		+ " to service " + serviceName, ex);
		}
		warnIfTooLong(SystemClock.elapsedRealtime() - time, service, "onUnlockUser ");
		Trace.traceEnd(Trace.TRACE_TAG_SYSTEM_SERVER);
		t.traceEnd();
		}
		t.traceEnd();
		}

		public void switchUser(final int userHandle) {
		/**
		* Switches to the given user.
		*/
		public void switchUser(final @UserIdInt int userHandle) {
		final TimingsTraceAndSlog t = TimingsTraceAndSlog.newAsyncLog();
		t.traceBegin("ssm.switchUser-" + userHandle);
		Slog.i(TAG, "Calling switchUser u" + userHandle);
		final int serviceLen = mServices.size();
		for (int i = 0; i < serviceLen; i++) {
		final SystemService service = mServices.get(i);
		Trace.traceBegin(Trace.TRACE_TAG_SYSTEM_SERVER, "onSwitchUser "
		+ service.getClass().getName());
		final String serviceName = service.getClass().getName();
		t.traceBegin("onSwitchUser-" + userHandle + " " + serviceName);
		long time = SystemClock.elapsedRealtime();
		try {
		service.onSwitchUser(userHandle);
		} catch (Exception ex) {
		Slog.wtf(TAG, "Failure reporting switch of user " + userHandle
		+ " to service " + service.getClass().getName(), ex);
		+ " to service " + serviceName, ex);
		}
		warnIfTooLong(SystemClock.elapsedRealtime() - time, service, "onSwitchUser");
		Trace.traceEnd(Trace.TRACE_TAG_SYSTEM_SERVER);
		t.traceEnd();
		}
		t.traceEnd();
		}

		public void stopUser(final int userHandle) {
		/**
		* Stops the given user.
		*/
		public void stopUser(final @UserIdInt int userHandle) {
		final TimingsTraceAndSlog t = TimingsTraceAndSlog.newAsyncLog();
		t.traceBegin("ssm.stopUser-" + userHandle);
		Slog.i(TAG, "Calling onStopUser u" + userHandle);
		final int serviceLen = mServices.size();
		for (int i = 0; i < serviceLen; i++) {
		final SystemService service = mServices.get(i);
		Trace.traceBegin(Trace.TRACE_TAG_SYSTEM_SERVER, "onStopUser "
		+ service.getClass().getName());
		final String serviceName = service.getClass().getName();
		t.traceBegin("onStopUser-" + userHandle + " " + serviceName);
		long time = SystemClock.elapsedRealtime();
		try {
		service.onStopUser(userHandle);
		} catch (Exception ex) {
		Slog.wtf(TAG, "Failure reporting stop of user " + userHandle
		+ " to service " + service.getClass().getName(), ex);
		+ " to service " + serviceName, ex);
		}
		warnIfTooLong(SystemClock.elapsedRealtime() - time, service, "onStopUser");
		Trace.traceEnd(Trace.TRACE_TAG_SYSTEM_SERVER);
		t.traceEnd();
		}
		t.traceEnd();
		}

		public void cleanupUser(final int userHandle) {
		/**
		* Cleans up the given user.
		*/
		public void cleanupUser(final @UserIdInt int userHandle) {
		final TimingsTraceAndSlog t = TimingsTraceAndSlog.newAsyncLog();
		t.traceBegin("ssm.cleanupUser-" + userHandle);
		Slog.i(TAG, "Calling onCleanupUser u" + userHandle);
		final int serviceLen = mServices.size();
		for (int i = 0; i < serviceLen; i++) {
		final SystemService service = mServices.get(i);
		Trace.traceBegin(Trace.TRACE_TAG_SYSTEM_SERVER, "onCleanupUser "
		+ service.getClass().getName());
		final String serviceName = service.getClass().getName();
		t.traceBegin("onCleanupUser-" + userHandle + " " + serviceName);
		long time = SystemClock.elapsedRealtime();
		try {
		service.onCleanupUser(userHandle);
		} catch (Exception ex) {
		Slog.wtf(TAG, "Failure reporting cleanup of user " + userHandle
		+ " to service " + service.getClass().getName(), ex);
		+ " to service " + serviceName, ex);
		}
		warnIfTooLong(SystemClock.elapsedRealtime() - time, service, "onCleanupUser");
		Trace.traceEnd(Trace.TRACE_TAG_SYSTEM_SERVER);
		t.traceEnd();
		}
		t.traceEnd();
		}

		/** Sets the safe mode flag for services to query. */

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

+88 −46

Original line number	Diff line number	Diff line
		@@ -5094,7 +5094,8 @@ public class ActivityManagerService extends IActivityManager.Stub
		}

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

		synchronized (this) {
		@@ -5168,7 +5169,7 @@ public class ActivityManagerService extends IActivityManager.Stub
		}

		// Let system services know.
		mSystemServiceManager.startBootPhase(SystemService.PHASE_BOOT_COMPLETED);
		mSystemServiceManager.startBootPhase(t, SystemService.PHASE_BOOT_COMPLETED);

		synchronized (this) {
		// Ensure that any processes we had put on hold are now started
		@@ -8859,9 +8860,11 @@ public class ActivityManagerService extends IActivityManager.Stub
		if (goingCallback != null) {
		goingCallback.run();
		}
		t.traceEnd(); // PhaseActivityManagerReady
		return;
		}

		t.traceBegin("controllersReady");
		mLocalDeviceIdleController
		= LocalServices.getService(DeviceIdleController.LocalService.class);
		mActivityTaskManager.onSystemReady();
		@@ -8869,6 +8872,7 @@ public class ActivityManagerService extends IActivityManager.Stub
		mUserController.onSystemReady();
		mAppOpsService.systemReady();
		mSystemReady = true;
		t.traceEnd();
		}

		try {
		@@ -8877,6 +8881,7 @@ public class ActivityManagerService extends IActivityManager.Stub
		.getSerial();
		} catch (RemoteException e) {}

		t.traceBegin("killProcesses");
		ArrayList<ProcessRecord> procsToKill = null;
		synchronized(mPidsSelfLocked) {
		for (int i=mPidsSelfLocked.size()-1; i>=0; i--) {
		@@ -8904,17 +8909,28 @@ public class ActivityManagerService extends IActivityManager.Stub
		// we won't trample on them any more.
		mProcessesReady = true;
		}
		t.traceEnd(); // KillProcesses

		Slog.i(TAG, "System now ready");
		EventLog.writeEvent(EventLogTags.BOOT_PROGRESS_AMS_READY, SystemClock.uptimeMillis());

		t.traceBegin("updateTopComponentForFactoryTest");
		mAtmInternal.updateTopComponentForFactoryTest();
		t.traceEnd();

		t.traceBegin("watchDeviceProvisioning");
		watchDeviceProvisioning(mContext);
		t.traceEnd();

		t.traceBegin("retrieveSettings");
		retrieveSettings();
		t.traceEnd();

		t.traceBegin("Ugm.onSystemReady");
		mUgmInternal.onSystemReady();
		t.traceEnd();

		t.traceBegin("updateForceBackgroundCheck");
		final PowerManagerInternal pmi = LocalServices.getService(PowerManagerInternal.class);
		if (pmi != null) {
		pmi.registerLowPowerModeObserver(ServiceType.FORCE_BACKGROUND_CHECK,
		@@ -8924,8 +8940,11 @@ public class ActivityManagerService extends IActivityManager.Stub
		} else {
		Slog.wtf(TAG, "PowerManagerInternal not found.");
		}
		t.traceEnd();

		if (goingCallback != null) goingCallback.run();

		t.traceBegin("getCurrentUser"); // should be fast, but these methods acquire locks
		// Check the current user here as a user can be started inside goingCallback.run() from
		// other system services.
		final int currentUserId = mUserController.getCurrentUserId();
		@@ -8936,17 +8955,21 @@ public class ActivityManagerService extends IActivityManager.Stub
		throw new RuntimeException("System user not started while current user is:"
		+ currentUserId);
		}
		t.traceEnd();

		t.traceBegin("ActivityManagerStartApps");
		mBatteryStatsService.noteEvent(BatteryStats.HistoryItem.EVENT_USER_RUNNING_START,
		Integer.toString(currentUserId), currentUserId);
		mBatteryStatsService.noteEvent(BatteryStats.HistoryItem.EVENT_USER_FOREGROUND_START,
		Integer.toString(currentUserId), currentUserId);
		mSystemServiceManager.startUser(currentUserId);
		mSystemServiceManager.startUser(t, currentUserId);

		synchronized (this) {
		// Only start up encryption-aware persistent apps; once user is
		// unlocked we'll come back around and start unaware apps
		t.traceBegin("startPersistentApps");
		startPersistentApps(PackageManager.MATCH_DIRECT_BOOT_AWARE);
		t.traceEnd();

		// Start up initial activity.
		mBooting = true;
		@@ -8956,6 +8979,7 @@ public class ActivityManagerService extends IActivityManager.Stub
		if (UserManager.isSplitSystemUser() &&
		Settings.Secure.getInt(mContext.getContentResolver(),
		Settings.Secure.USER_SETUP_COMPLETE, 0) != 0) {
		t.traceBegin("enableHomeActivity");
		ComponentName cName = new ComponentName(mContext, SystemUserHomeActivity.class);
		try {
		AppGlobals.getPackageManager().setComponentEnabledSetting(cName,
		@@ -8964,11 +8988,19 @@ public class ActivityManagerService extends IActivityManager.Stub
		} catch (RemoteException e) {
		throw e.rethrowAsRuntimeException();
		}
		t.traceEnd();
		}
		t.traceBegin("startHomeOnAllDisplays");
		mAtmInternal.startHomeOnAllDisplays(currentUserId, "systemReady");
		t.traceEnd();

		t.traceBegin("showSystemReadyErrorDialogs");
		mAtmInternal.showSystemReadyErrorDialogsIfNeeded();
		t.traceEnd();

		boolean isSystemUser = currentUserId == UserHandle.USER_SYSTEM;
		if (isSystemUser) {
		t.traceBegin("sendUserStartBroadcast");
		final int callingUid = Binder.getCallingUid();
		final int callingPid = Binder.getCallingPid();
		long ident = Binder.clearCallingIdentity();
		@@ -8984,32 +9016,42 @@ public class ActivityManagerService extends IActivityManager.Stub
		intent = new Intent(Intent.ACTION_USER_STARTING);
		intent.addFlags(Intent.FLAG_RECEIVER_REGISTERED_ONLY);
		intent.putExtra(Intent.EXTRA_USER_HANDLE, currentUserId);
		broadcastIntentLocked(null, null, intent,
		null, new IIntentReceiver.Stub() {
		broadcastIntentLocked(null, null, intent, null,
		new IIntentReceiver.Stub() {
		@Override
		public void performReceive(Intent intent, int resultCode, String data,
		Bundle extras, boolean ordered, boolean sticky, int sendingUser)
		throws RemoteException {
		}
		}, 0, null, null,
		new String[] {INTERACT_ACROSS_USERS}, OP_NONE,
		null, true, false, MY_PID, SYSTEM_UID, callingUid, callingPid,
		public void performReceive(Intent intent, int resultCode,
		String data, Bundle extras, boolean ordered, boolean sticky,
		int sendingUser) {}
		}, 0, null, null, new String[] {INTERACT_ACROSS_USERS}, OP_NONE, null,
		true, false, MY_PID, SYSTEM_UID, callingUid, callingPid,
		UserHandle.USER_ALL);
		} catch (Throwable e) {
		Slog.wtf(TAG, "Failed sending first user broadcasts", e);
		} finally {
		Binder.restoreCallingIdentity(ident);
		}
		t.traceEnd();
		} else {
		Slog.i(TAG, "Not sending multi-user broadcasts for non-system user "
		+ currentUserId);
		}

		t.traceBegin("resumeTopActivities");
		mAtmInternal.resumeTopActivities(false /* scheduleIdle */);
		t.traceEnd();

		if (isSystemUser) {
		t.traceBegin("sendUserSwitchBroadcasts");
		mUserController.sendUserSwitchBroadcasts(-1, currentUserId);
		t.traceEnd();
		}

		t.traceBegin("setBinderProxies");
		BinderInternal.nSetBinderProxyCountWatermarks(BINDER_PROXY_HIGH_WATERMARK,
		BINDER_PROXY_LOW_WATERMARK);
		BinderInternal.nSetBinderProxyCountEnabled(true);
		BinderInternal.setBinderProxyCountCallback(
		new BinderInternal.BinderProxyLimitListener() {
		@Override
		public void onLimitReached(int uid) {
		(uid) -> {
		Slog.wtf(TAG, "Uid " + uid + " sent too many Binders to uid "
		+ Process.myUid());
		BinderProxy.dumpProxyDebugInfo();
		@@ -9019,8 +9061,8 @@ public class ActivityManagerService extends IActivityManager.Stub
		killUid(UserHandle.getAppId(uid), UserHandle.getUserId(uid),
		"Too many Binders sent to SYSTEM");
		}
		}
		}, mHandler);
		t.traceEnd(); // setBinderProxies

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

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

+6 −8

Original line number	Diff line number	Diff line
		@@ -72,7 +72,6 @@ import android.os.RemoteCallbackList;
		import android.os.RemoteException;
		import android.os.ServiceManager;
		import android.os.SystemClock;
		import android.os.Trace;
		import android.os.UserHandle;
		import android.os.UserManager;
		import android.os.UserManagerInternal;
		@@ -85,7 +84,6 @@ import android.util.Pair;
		import android.util.Slog;
		import android.util.SparseArray;
		import android.util.SparseIntArray;
		import android.util.TimingsTraceLog;
		import android.util.proto.ProtoOutputStream;

		import com.android.internal.R;
		@@ -2135,6 +2133,7 @@ class UserController implements Handler.Callback {
		}
		}

		@Override
		public boolean handleMessage(Message msg) {
		switch (msg.what) {
		case START_USER_SWITCH_FG_MSG:
		@@ -2159,7 +2158,8 @@ class UserController implements Handler.Callback {
		mInjector.batteryStatsServiceNoteEvent(
		BatteryStats.HistoryItem.EVENT_USER_RUNNING_START,
		Integer.toString(msg.arg1), msg.arg1);
		mInjector.getSystemServiceManager().startUser(msg.arg1);
		mInjector.getSystemServiceManager().startUser(TimingsTraceAndSlog.newAsyncLog(),
		msg.arg1);
		break;
		case SYSTEM_USER_UNLOCK_MSG:
		final int userId = msg.arg1;
		@@ -2215,14 +2215,12 @@ class UserController implements Handler.Callback {

		// Report system user unlock time to perf dashboard
		if (id == UserHandle.USER_SYSTEM) {
		new TimingsTraceLog("SystemServerTiming", Trace.TRACE_TAG_SYSTEM_SERVER)
		.logDuration("SystemUserUnlock", unlockTime);
		new TimingsTraceAndSlog().logDuration("SystemUserUnlock", unlockTime);
		} else {
		new TimingsTraceLog("SystemServerTiming", Trace.TRACE_TAG_SYSTEM_SERVER)
		.logDuration("User" + id + "Unlock", unlockTime);
		new TimingsTraceAndSlog().logDuration("User" + id + "Unlock", unlockTime);
		}
		}
		}
		};

		@VisibleForTesting
		static class Injector {