Donate to e Foundation | Murena handsets with /e/OS | Own a part of Murena! Learn more

Commit 3aad1be7 authored by Felipe Leme's avatar Felipe Leme
Browse files

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
parent f817e8a4
Loading
Loading
Loading
Loading
+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
        }
    }
+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);
+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
    }

    /**
+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);
    }
}
+432 −443

File changed.

Preview size limit exceeded, changes collapsed.