From 287afa19015a32d09522adde7fd5f3d6cac7f2eb Mon Sep 17 00:00:00 2001 From: Varun Shah Date: Wed, 20 Oct 2021 16:52:25 -0700 Subject: [PATCH] Run the service start user lifecycle phase in parallel. Execute the on start user lifecycle phase in parallel. Services will be a added to a new thread pool, and depending on which category they are in, they will either be executed right away (bootstrap and core categories), or run in parallel along with other services in that category (other category). This change will only apply for non-system users for now. Additionally, low ram devices will have this change disabled. Initial results show about 16% improvement in execution times. Note: This CL does not enable the thread pool, a separate CL will enable it. Bug: 197257926 Test: atest UserLifecycleTests Change-Id: I76ba673f78b69c7f0caac2d843fa77079e92138a --- core/java/android/util/TimingsTraceLog.java | 34 ++++-- .../android/server/SystemServiceManager.java | 101 +++++++++++++++++- .../server/utils/TimingsTraceAndSlog.java | 8 ++ .../java/com/android/server/SystemServer.java | 1 + 4 files changed, 132 insertions(+), 12 deletions(-) diff --git a/core/java/android/util/TimingsTraceLog.java b/core/java/android/util/TimingsTraceLog.java index 5370645d31bc1..066709fd8744c 100644 --- a/core/java/android/util/TimingsTraceLog.java +++ b/core/java/android/util/TimingsTraceLog.java @@ -61,13 +61,33 @@ public class TimingsTraceLog { mTraceTag = traceTag; mThreadId = Thread.currentThread().getId(); mMaxNestedCalls = maxNestedCalls; - if (maxNestedCalls > 0) { - mStartNames = new String[maxNestedCalls]; - mStartTimes = new long[maxNestedCalls]; - } else { - mStartNames = null; - mStartTimes = null; - } + this.mStartNames = createAndGetStartNamesArray(); + this.mStartTimes = createAndGetStartTimesArray(); + } + + /** + * Note: all fields will be copied except for {@code mStartNames} and {@code mStartTimes} + * in order to save memory. The copied object is only expected to be used at levels deeper than + * the value of {@code mCurrentLevel} when the object is copied. + * + * @param other object to be copied + */ + protected TimingsTraceLog(TimingsTraceLog other) { + this.mTag = other.mTag; + this.mTraceTag = other.mTraceTag; + this.mThreadId = Thread.currentThread().getId(); + this.mMaxNestedCalls = other.mMaxNestedCalls; + this.mStartNames = createAndGetStartNamesArray(); + this.mStartTimes = createAndGetStartTimesArray(); + this.mCurrentLevel = other.mCurrentLevel; + } + + private String[] createAndGetStartNamesArray() { + return mMaxNestedCalls > 0 ? new String[mMaxNestedCalls] : null; + } + + private long[] createAndGetStartTimesArray() { + return mMaxNestedCalls > 0 ? new long[mMaxNestedCalls] : null; } /** diff --git a/services/core/java/com/android/server/SystemServiceManager.java b/services/core/java/com/android/server/SystemServiceManager.java index cb6e73af56ace..c5b23790c918a 100644 --- a/services/core/java/com/android/server/SystemServiceManager.java +++ b/services/core/java/com/android/server/SystemServiceManager.java @@ -19,12 +19,14 @@ package com.android.server; import android.annotation.NonNull; import android.annotation.Nullable; import android.annotation.UserIdInt; +import android.app.ActivityManager; import android.content.Context; import android.content.pm.UserInfo; import android.os.Build; import android.os.Environment; import android.os.SystemClock; import android.os.Trace; +import android.os.UserHandle; import android.util.ArrayMap; import android.util.EventLog; import android.util.IndentingPrintWriter; @@ -45,6 +47,9 @@ import java.io.File; import java.lang.reflect.Constructor; import java.lang.reflect.InvocationTargetException; import java.util.ArrayList; +import java.util.concurrent.ExecutorService; +import java.util.concurrent.Executors; +import java.util.concurrent.TimeUnit; /** * Manages creating, starting, and other lifecycle events of @@ -67,6 +72,19 @@ public final class SystemServiceManager implements Dumpable { private static final String USER_STOPPING = "Stop"; // Logged as onStopUser private static final String USER_STOPPED = "Cleanup"; // Logged as onCleanupUser + // Whether to use multiple threads to run user lifecycle phases in parallel. + private static boolean sUseLifecycleThreadPool = false; + // The default number of threads to use if lifecycle thread pool is enabled. + private static final int DEFAULT_MAX_USER_POOL_THREADS = 3; + // The number of threads to use if lifecycle thread pool is enabled, dependent on the number of + // available cores on the device. + private final int mNumUserPoolThreads; + // Maximum time to wait for a particular lifecycle phase to finish. + private static final long USER_POOL_SHUTDOWN_TIMEOUT_SECONDS = 30; + // Indirectly indicates how many services belong in the bootstrap and core service categories. + // This is used to decide which services the user lifecycle phases should be parallelized for. + private static volatile int sOtherServicesStartIndex; + private static File sSystemDir; private final Context mContext; private boolean mSafeMode; @@ -100,6 +118,11 @@ public final class SystemServiceManager implements Dumpable { SystemServiceManager(Context context) { mContext = context; + // Disable using the thread pool for low ram devices + sUseLifecycleThreadPool = sUseLifecycleThreadPool + && !ActivityManager.isLowRamDeviceStatic(); + mNumUserPoolThreads = Math.min(Runtime.getRuntime().availableProcessors(), + DEFAULT_MAX_USER_POOL_THREADS); } /** @@ -260,6 +283,18 @@ public final class SystemServiceManager implements Dumpable { return mCurrentPhase >= SystemService.PHASE_BOOT_COMPLETED; } + /** + * Called from SystemServer to indicate that services in the other category are now starting. + * This is used to keep track of how many services are in the bootstrap and core service + * categories for the purposes of user lifecycle parallelization. + */ + public void updateOtherServicesStartIndex() { + // Only update the index if the boot phase has not been completed yet + if (!isBootCompleted()) { + sOtherServicesStartIndex = mServices.size(); + } + } + /** * Called at the beginning of {@code ActivityManagerService.systemReady()}. */ @@ -373,6 +408,13 @@ public final class SystemServiceManager implements Dumpable { Slog.i(TAG, "Calling on" + onWhat + "User " + curUserId + (prevUser != null ? " (from " + prevUser + ")" : "")); final int serviceLen = mServices.size(); + // Limit the lifecycle parallelization to all users other than the system user + // and only for the user start lifecycle phase for now. + final boolean useThreadPool = sUseLifecycleThreadPool + && curUserId != UserHandle.USER_SYSTEM + && onWhat.equals(USER_STARTING); + final ExecutorService threadPool = + useThreadPool ? Executors.newFixedThreadPool(mNumUserPoolThreads) : null; for (int i = 0; i < serviceLen; i++) { final SystemService service = mServices.get(i); final String serviceName = service.getClass().getName(); @@ -395,7 +437,11 @@ public final class SystemServiceManager implements Dumpable { } continue; } - t.traceBegin("ssm.on" + onWhat + "User-" + curUserId + "_" + serviceName); + // Only submit this service to the thread pool if it's in the "other" category. + final boolean submitToThreadPool = useThreadPool && i >= sOtherServicesStartIndex; + if (!submitToThreadPool) { + t.traceBegin("ssm.on" + onWhat + "User-" + curUserId + "_" + serviceName); + } long time = SystemClock.elapsedRealtime(); try { switch (onWhat) { @@ -403,7 +449,11 @@ public final class SystemServiceManager implements Dumpable { service.onUserSwitching(prevUser, curUser); break; case USER_STARTING: - service.onUserStarting(curUser); + if (submitToThreadPool) { + threadPool.submit(getOnStartUserRunnable(t, service, curUser)); + } else { + service.onUserStarting(curUser); + } break; case USER_UNLOCKING: service.onUserUnlocking(curUser); @@ -424,13 +474,54 @@ public final class SystemServiceManager implements Dumpable { Slog.wtf(TAG, "Failure reporting " + onWhat + " of user " + curUser + " to service " + serviceName, ex); } - warnIfTooLong(SystemClock.elapsedRealtime() - time, service, - "on" + onWhat + "User-" + curUserId); - t.traceEnd(); // what on service + if (!submitToThreadPool) { + warnIfTooLong(SystemClock.elapsedRealtime() - time, service, + "on" + onWhat + "User-" + curUserId); + t.traceEnd(); // what on service + } + } + if (useThreadPool) { + boolean terminated = false; + threadPool.shutdown(); + try { + terminated = threadPool.awaitTermination( + USER_POOL_SHUTDOWN_TIMEOUT_SECONDS, TimeUnit.SECONDS); + } catch (InterruptedException e) { + Slog.wtf(TAG, "User lifecycle thread pool was interrupted while awaiting completion" + + " of " + onWhat + " of user " + curUser, e); + Slog.e(TAG, "Couldn't terminate, disabling thread pool. " + + "Please capture a bug report."); + sUseLifecycleThreadPool = false; + } + if (!terminated) { + Slog.wtf(TAG, "User lifecycle thread pool was not terminated."); + } } t.traceEnd(); // main entry } + private Runnable getOnStartUserRunnable(TimingsTraceAndSlog oldTrace, SystemService service, + TargetUser curUser) { + return () -> { + final TimingsTraceAndSlog t = new TimingsTraceAndSlog(oldTrace); + final String serviceName = service.getClass().getName(); + try { + final int curUserId = curUser.getUserIdentifier(); + t.traceBegin("ssm.on" + USER_STARTING + "User-" + curUserId + "_" + serviceName); + long time = SystemClock.elapsedRealtime(); + service.onUserStarting(curUser); + warnIfTooLong(SystemClock.elapsedRealtime() - time, service, + "on" + USER_STARTING + "User-" + curUserId); + t.traceEnd(); + } catch (Exception e) { + Slog.wtf(TAG, "Failure reporting " + USER_STARTING + " of user " + curUser + + " to service " + serviceName, e); + Slog.e(TAG, "Disabling thread pool - please capture a bug report."); + sUseLifecycleThreadPool = false; + } + }; + } + /** Sets the safe mode flag for services to query. */ void setSafeMode(boolean safeMode) { mSafeMode = safeMode; diff --git a/services/core/java/com/android/server/utils/TimingsTraceAndSlog.java b/services/core/java/com/android/server/utils/TimingsTraceAndSlog.java index 6bdb5cea7f9c5..397acfac2812d 100644 --- a/services/core/java/com/android/server/utils/TimingsTraceAndSlog.java +++ b/services/core/java/com/android/server/utils/TimingsTraceAndSlog.java @@ -78,6 +78,14 @@ public final class TimingsTraceAndSlog extends TimingsTraceLog { mTag = tag; } + /** + * @see TimingsTraceLog#TimingsTraceLog(TimingsTraceLog) + */ + public TimingsTraceAndSlog(@NonNull TimingsTraceAndSlog other) { + super(other); + this.mTag = other.mTag; + } + @Override public void traceBegin(@NonNull String name) { Slog.i(mTag, name); diff --git a/services/java/com/android/server/SystemServer.java b/services/java/com/android/server/SystemServer.java index fc60bab116db2..b237f518515b9 100644 --- a/services/java/com/android/server/SystemServer.java +++ b/services/java/com/android/server/SystemServer.java @@ -1353,6 +1353,7 @@ public final class SystemServer implements Dumpable { */ private void startOtherServices(@NonNull TimingsTraceAndSlog t) { t.traceBegin("startOtherServices"); + mSystemServiceManager.updateOtherServicesStartIndex(); final Context context = mSystemContext; DynamicSystemService dynamicSystem = null;