ActivityManagerService解读之Activity启动时间闲聊--Android Framework层时间计算介绍

从ActivityManagerService解读之Activity启动初探，到ActivityManagerService解读之Activity启动再探，到ActivityManagerService解读之Activity启动再探-细节补充ActivityStarter中方法属性介绍，再到ActivityManagerService解读之Activity启动三探--Activity中Task与Stack已经粗糙的写了四篇关于Activity启动的文章了，回头再看看还是有很多需要补充的地方，对ActivityManagerService还是有很多未理解透彻的地方，只能说大致上了解了一些基本的常见场景下Activity启动流程，不过庆幸的是如果我们了解了这些基本的东西，对付应用启动时间优化这方面的问题还是绰绰有余的。本文将闲聊一波应用启动时间这方面的东西。

如何查看你的应用启动时间？

方法一：查看Log，event log和main log都有对应用启动显示时间的描述，比如下例Log中，我们com.android.settings/.Settings这个Activity的启动显示时间便是852ms。

01-04 23:51:57.933  5382  5404 I am_activity_launch_time: [0,107776452,com.android.settings/.Settings,852,852]
01-04 23:51:57.933  5382  5404 I ActivityManager: Displayed com.android.settings/.Settings: +852ms

Tip：这是一段单Activity启动的Log，此时ThisTime=TotalTime

方法二：使用am命令adb shell am start -W，例如：

adb shell am start -W -n com.android.settings/.Settings -S 
Stopping: com.android.settings
Starting: Intent { cmp=com.android.settings/.Settings }
Status: ok
Activity: com.android.settings/.Settings
ThisTime: 663
TotalTime: 663
WaitTime: 783
Complete

这里的ThisTime，TotalTime，WaitTime到底是什么？请继续阅读下面的分析。

系统是如何计算应用启动的时间的？

先贴上之前的一段启动Log分析，再看这段Log，第一感觉仍然是Perfect，相当之完美，该有的信息全都涵盖了。

09-19 15:58:37.864  1311  3040 I ActivityManager: START u0 {act=android.intent.action.MAIN cat=[android.intent.category.LAUNCHER] flg=0x10200000 cmp=com.tencent.mobileqq/.activity.SplashActivity bnds=[329,1575][497,1743] (has extras)} from uid 10032
09-19 15:58:37.879  1311  3040 I wm_task_created: [6415,1]//来自TaskWindowContainerController构造方法，
09-19 15:58:37.880  1311  3040 I wm_task_moved: [6415,1,9]//来自TaskWindowContainerController构造方法，具体是在TaskStack中打出的，因为这里调用了stack.addTask
09-19 15:58:37.880  1311  3040 I am_focused_stack: [0,1,0,reuseOrNewTask]
09-19 15:58:37.880  1311  3040 I wm_task_moved: [6415,1,9]//会做一次位置调整addOrReparentStartingActivity，来自于此，之后还会移动一次ActivityStack
09-19 15:58:37.882  1311  3040 I am_create_task: [0,6415]//打印出如下的Log的时候，此时ams启动Activity已经就该应用Activity创建了属于他的TaskRecord
09-19 15:58:37.882  1311  3040 I am_create_activity: [0,72463824,6415,com.tencent.mobileqq/.activity.SplashActivity,android.intent.action.MAIN,NULL,NULL,270532608]
09-19 15:58:37.882  1311  3040 I wm_task_moved: [6415,1,9]//ActivityStack.startActivityLocked 先做一次ActivityStack的移动
09-19 15:58:37.885  1311  3040 I am_pause_activity: [3167,192963549,com.miui.home/.launcher.Launcher] //启动一个Activity之前先暂停之前显示的Activity
09-19 15:58:37.888  3167  3167 I am_on_paused_called: [0,com.miui.home.launcher.Launcher,handlePauseActivity]
09-19 15:58:37.888  1311  3311 I am_uid_running: 10158
09-19 15:58:37.900  1311  3311 I am_proc_start: [0,31868,10158,com.tencent.mobileqq,activity,com.tencent.mobileqq/.activity.SplashActivity]//来自ActivityManagerService startProcessLocked
09-19 15:58:37.905  1311  3311 I am_proc_bound: [0,31868,com.tencent.mobileqq]//来自ActivityManagerService  attachApplicationLocked 当系统创建好系统应用进程时，
                                                                              //会调用ActivityThread的main方法，此时会通过Binder调用ams的attachApplication，进而调用attachApplicationLocked
09-19 15:58:37.909  1311  3311 I am_restart_activity: [0,72463824,6415,com.tencent.mobileqq/.activity.SplashActivity,31868]
09-19 15:58:37.909  1311  3311 I am_restart_activity_ai: [31868,com.tencent.mobileqq/.activity.SplashActivity,false]//xmiaomi特有AI启动？黑科技？
09-19 15:58:37.912  1311  3311 I am_set_resumed_activity: [0,com.tencent.mobileqq/.activity.SplashActivity,minimalResumeActivityLocked]
09-19 15:58:38.045 31868 31868 I am_on_resume_called: [0,com.tencent.mobileqq.activity.SplashActivity,LAUNCH_ACTIVITY]//应用进程Log输出
09-19 15:58:38.104  1311  1388 I am_activity_launch_time: [0,72463824,com.tencent.mobileqq/.activity.SplashActivity,213,213]
09-19 15:58:38.426  1311  1327 I am_stop_activity: [0,192963549,com.miui.home/.launcher.Launcher]
09-19 15:58:38.436  3167  3167 I am_on_stop_called: [0,com.miui.home.launcher.Launcher,handleStopActivity]

您可以通过ActivityManagerService解读之Activity启动初探了解具体的信息。我们可以通过观察Log输出的时间戳来获取应用的启动各个环节的步骤，也能直接得到应用启动的时间，但是知其然，我们更要知其所以然，因此我们有必要跟踪一下源码，看Android是如何计算得到结果的，我们看下输出对应Log的代码，reportLaunchTimeLocked方法来自ActivityRecord.java

    private void reportLaunchTimeLocked(final long curTime) {
        final long thisTime = curTime - displayStartTime;
        final long totalTime = stack.mLaunchStartTime != 0
                ? (curTime - stack.mLaunchStartTime) : thisTime;
        if (SHOW_ACTIVITY_START_TIME) {
            Trace.asyncTraceEnd(TRACE_TAG_ACTIVITY_MANAGER, "launching: " + packageName, 0);
            EventLog.writeEvent(AM_ACTIVITY_LAUNCH_TIME,
                    userId, System.identityHashCode(this), shortComponentName,
                    thisTime, totalTime);
            StringBuilder sb = service.mStringBuilder;
            sb.setLength(0);
            sb.append("Displayed ");
            sb.append(shortComponentName);
            sb.append(": ");
            TimeUtils.formatDuration(thisTime, sb);
            if (thisTime != totalTime) {
                sb.append(" (total ");
                TimeUtils.formatDuration(totalTime, sb);
                sb.append(")");
                if (mUxPerf != null) {
                    mUxPerf.perfUXEngine_events(3, 0, packageName, (int)totalTime);
                }
            } else {
                if (mUxPerf != null) {
                    mUxPerf.perfUXEngine_events(3, 0, packageName, (int)thisTime);
                }
            }
            Log.i(TAG, sb.toString());
        }
        mStackSupervisor.reportActivityLaunchedLocked(false, this, thisTime, totalTime);
        displayStartTime = 0;
        stack.mLaunchStartTime = 0;
    }

方法参数curTime表示该方法调用的时间点，displayStartTime表示该ActivityRecord启动开始的时间，mLaunchStartTime是ActivityStack的属性成员，一般与单个Activity启动时间无关，与整个启动过程有关，我们搜索整个代码发现mLaunchStartTime只有当reportLaunchTimeLocked方法调用之后该值才会被设置为0，因此我们认为当一系列Activity启动的时候，只有当第一个有界面的Activity启动并显示的时候才会清零，mLaunchStartTime所代表的便是这系列Activity中第一个Activity启动时设置的时间，此时mLaunchStartTime等于第一个无界面Activity的displayStartTime。一般正常情况下我们启动的都为单个界面Activity，这个时候displayStartTime等于mLaunchStartTime。现在再来看下我们之前提出的三个时间This Total Wait Time，ThisTime看做是有界面的Activity启动耗时，TotalTime是包含新应用启动创建进程和Activity启动的时间，而WaitTime就是整个过程的耗时包含上一个应用的耗时时间。继续看下这些时间设置的地方，该方法来自ActivityStack.java

    void setLaunchTime(ActivityRecord r) {
        if (r.displayStartTime == 0) {
            r.fullyDrawnStartTime = r.displayStartTime = SystemClock.uptimeMillis();
            if (mLaunchStartTime == 0) {
                startLaunchTraces(r.packageName);
                mLaunchStartTime = mFullyDrawnStartTime = r.displayStartTime;
            }
        } else if (mLaunchStartTime == 0) {
            startLaunchTraces(r.packageName);
            mLaunchStartTime = mFullyDrawnStartTime = SystemClock.uptimeMillis();
        }
    }

setLaunchTime的调用有两个地方startSpecificActivityLocked和minimalResumeActivityLocked。看到第二个，我天！现在再看我们一开始贴的Log，是不是有点小激动？

    void minimalResumeActivityLocked(ActivityRecord r) {
        if (DEBUG_STATES) Slog.v(TAG_STATES, "Moving to RESUMED: " + r + " (starting new instance)"
                + " callers=" + Debug.getCallers(5));
        setResumedActivityLocked(r, "minimalResumeActivityLocked");
        r.completeResumeLocked();
        setLaunchTime(r);
        if (DEBUG_SAVED_STATE) Slog.i(TAG_SAVED_STATE,
                "Launch completed; removing icicle of " + r.icicle);
    }

minimalResumeActivityLocked？09-19 15:58:37.912  1311  3311 I am_set_resumed_activity: [0,com.tencent.mobileqq/.activity.SplashActivity,minimalResumeActivityLocked]？完美。不过太激动，这个是针对应用按Home键退到后台再次进入应用的时间点log，我们一般更多的需要关注应用界面重新创建的耗时。应用界面重新创建开始时间设置在下startSpecificActivityLocked方法中，我们来看下：

    void startSpecificActivityLocked(ActivityRecord r,
            boolean andResume, boolean checkConfig) {
        // Is this activity's application already running?
        ProcessRecord app = mService.getProcessRecordLocked(r.processName,
                r.info.applicationInfo.uid, true);

        r.getStack().setLaunchTime(r);

        if (app != null && app.thread != null) {
            try {
                if ((r.info.flags&ActivityInfo.FLAG_MULTIPROCESS) == 0
                        || !"android".equals(r.info.packageName)) {
                    // Don't add this if it is a platform component that is marked
                    // to run in multiple processes, because this is actually
                    // part of the framework so doesn't make sense to track as a
                    // separate apk in the process.
                    app.addPackage(r.info.packageName, r.info.applicationInfo.versionCode,
                            mService.mProcessStats);
                }
                realStartActivityLocked(r, app, andResume, checkConfig);
                return;
            } catch (RemoteException e) {
                Slog.w(TAG, "Exception when starting activity "
                        + r.intent.getComponent().flattenToShortString(), e);
            }

        }

        mService.startProcessLocked(r.processName, r.info.applicationInfo, true, 0,
                "activity", r.intent.getComponent(), false, false, true);
    }

startProcessLocked方法会输出am_proc_start event log，我们可以大致的认为该log输出的时间点就是系统开始为应用启动时间计时的起点。哇塞，有了起点log还有终点log，这么看来event log是相当的强大呀，几乎可以是我们看做分析应用启动时间的利器之一啊。来来来，我们结合代码分析，再来波小小的总结。一般情况下，我们可以将应用的时间分为三个时间段A，B和C。A时间段，起始标志Log是ActivityManager: START u0，系统在这段时间内为启动的Activity创建ActivityRecord，创建或者选择合理的ActivityStack，TaskRecord，将当前的Resume的Activity pause；B时间段起始标志Log是am_proc_start，系统在这段时间内为启动的应用创建进程，C时间段起始标志Logam_set_resumed_activity，这段时间内主要是调用启动Activity的onCreate，onStart，onResume，到最终界面显示结束时间计算，输出对应的Log。对于非正常情况，根据之前的分析介绍，我们直接来段Log实战分析这类场景（这段Log对应的场景是Android手机首次开机进入Launcher界面）

01-05 18:14:33.662  1063  2889 I ActivityManager: START u0 {act=android.intent.action.MAIN cat=[android.intent.category.HOME] flg=0x10208000 cmp=com.android.settings/.CryptKeeper} from uid 10024
01-05 18:14:33.692  1063  2889 I am_create_task: [0,2]
01-05 18:14:33.692  1063  2889 I am_create_activity: [0,168248320,2,com.android.settings/.CryptKeeper,android.intent.action.MAIN,NULL,NULL,278953984]
01-05 18:14:33.700  1063  2889 I am_pause_activity: [0,241166398,****Activity]
01-05 18:14:33.715  1063  2889 I am_finish_activity: [0,241166398,1,****Activity,app-request]
01-05 18:14:33.771  1063  2072 I am_proc_start: [0,3892,1000,com.android.settings:CryptKeeper,activity,com.android.settings/.CryptKeeper]
01-05 18:14:33.855  1063  2034 I am_proc_bound: [0,3892,com.android.settings:CryptKeeper]
01-05 18:14:33.922  1063  2034 I am_restart_activity: [0,168248320,2,com.android.settings/.CryptKeeper]
01-05 18:14:33.933  1063  2034 I am_set_resumed_activity: [0,com.android.settings/.CryptKeeper,minimalResumeActivityLocked]
01-05 18:14:34.078  1063  3918 I am_finish_activity: [0,168248320,2,com.android.settings/.CryptKeeper,app-request]
01-05 18:14:34.083  1063  3918 I am_pause_activity: [0,168248320,com.android.settings/.CryptKeeper]
01-05 18:14:34.130  1063  2413 I ActivityManager: START u0 {act=android.intent.action.MAIN cat=[android.intent.category.HOME] flg=0x10000100 cmp=com.android.provision/.DefaultActivity} from uid 0
01-05 18:14:34.148  1063  2413 I am_create_task: [0,3]
01-05 18:14:34.148  1063  2413 I am_create_activity: [0,262149567,3,com.android.provision/.DefaultActivity,android.intent.action.MAIN,NULL,NULL,276824320]
01-05 18:14:34.184  1063  2413 I am_proc_start: [0,3927,10020,com.android.provision,activity,com.android.provision/.DefaultActivity]
01-05 18:14:34.223  1063  2413 I am_proc_bound: [0,3927,com.android.provision]
01-05 18:14:34.246  1063  2413 I am_restart_activity: [0,262149567,3,com.android.provision/.DefaultActivity]
01-05 18:14:34.248  1063  2413 I am_set_resumed_activity: [0,com.android.provision/.DefaultActivity,minimalResumeActivityLocked]
01-05 18:14:34.350  1063  2413 I am_finish_activity: [0,262149567,3,com.android.provision/.DefaultActivity,app-request]
01-05 18:14:34.355  1063  2413 I am_pause_activity: [0,262149567,com.android.provision/.DefaultActivity]
01-05 18:14:34.418  1063  2413 I ActivityManager: START u0 {act=android.intent.action.MAIN cat=[android.intent.category.HOME] flg=0x10000100 cmp=com.android.launcher3/.Launcher} from uid 0
01-05 18:14:34.437  1063  2413 I am_create_task: [0,4]
01-05 18:14:34.437  1063  2413 I am_create_activity: [0,155711780,4,com.android.launcher3/.Launcher,android.intent.action.MAIN,NULL,NULL,268435712]
01-05 18:14:34.480  1063  2413 I am_proc_start: [0,3948,10013,com.android.launcher3,activity,com.android.launcher3/.Launcher]
01-05 18:14:34.519  1063  2413 I am_proc_bound: [0,3948,com.android.launcher3]
01-05 18:14:34.536  1063  2413 I am_restart_activity: [0,155711780,4,com.android.launcher3/.Launcher]
01-05 18:14:34.540  1063  2413 I am_set_resumed_activity: [0,com.android.launcher3/.Launcher,minimalResumeActivityLocked]
01-05 18:14:35.200  3948  3948 I am_on_resume_called: [0,com.android.launcher3.Launcher,LAUNCH_ACTIVITY]
01-05 18:14:35.950  1063  2044 I am_activity_launch_time: [0,155711780,com.android.launcher3/.Launcher,1407,2123]
01-05 18:14:35.953  1063  2044 I ActivityManager: Displayed com.android.launcher3/.Launcher: +1s407ms (total +2s123ms)

Log告诉我们这系列Activity启动中第一个启动的Activity是com.android.settings/.CryptKeeper，中间Activity是com.android.provision/.DefaultActivity，这两个Activity都是无界面的，最后一个启动的Activity便是有界面的Launcher，从Log中我们获取到ThisTime=1405ms，TotalTime=2123ms，此时ThisTime和TotalTime是不相等的，符合我们之前的分析，此时第一个Activity的displayStartTime大致为18:14:33.771，mLaunchStartTime也是第一个Activity的displayStartTime，最后一个Activity的displayStartTime大致为01-05 18:14:34.480，最终这波启动操作完成时间是18:14:35.950，我们在结合ThisTime和TotalTime加减一下，基本一致。

写在最后

一般我们测试自己开发的应用启动时间只需要关注ThisTime即可，如果时间过长，那我们就得找找我们自己应用的原因了，是否将一些耗时操作放在了onCreate方法onStart和onResume方法中了，还有需要特别注意的是我们一般写界面的时候，布局文件尽可能的层次结构简单一点，因为系统在绘制你的UI的时候，会不断的遍历你的View Tree进行测量操作，如果还想知道Activity的界面绘制，点击关注，后续持续更新相关的知识。本文皆为鄙人的一点拙见，还请各位多多指教，互相学习，互相进步。