启动耗时分析（一）-测量应用启动时间

原创文章，转载请注明出处，多谢！

应用冷启动比较常用的时间统计方式是使用am start，本篇文章就来简单分析下am start的实现流程。

am命令是一个重要的调试工具,本身其实是一个shell脚本，主要功能包括：启动停止Activity Service，启动Broadcast等 , 具体对应命令可以自行Google.

am命令获取启动时间:

adb shell am start -S -R 10 -W  对应应用页面（com.miui.gallery/com.miui.gallery.activity.HomePageActivity 以小米手机的图库为例）

-S 表示每次启动前先强行停止
-R 表示重复测试次数
-W 表示等待app启动完成

执行一次冷启的统计:

➜  ~ adb shell am start -W com.miui.gallery/com.miui.gallery.activity.HomePageActivity
Starting: Intent { act=android.intent.action.MAIN cat=[android.intent.category.LAUNCHER] cmp=com.miui.gallery/.activity.HomePageActivity }
Status: ok
Activity: com.miui.gallery/.activity.HomePageActivity
ThisTime: 251
TotalTime: 251
WaitTime: 278
Complete

这里主要统计了3个时间：ThisTime 、 TotalTime 、 WaitTime.

为了搞清楚这三个时间分别统计的是什么, 决定探究一下am start -W 的源码流程，首先从源头Am.java开始(代码参考android 9.0):

public class Am extends BaseCommand {
public static void main(String[] args) {
    (new Am()).run(args); //run是执行的父类BaseCommand的，调用onRun
}
...
@Override
public void onRun() throws Exception {
    mAm = ActivityManager.getService();
if (mAm == null) {
        System.err.println(NO_SYSTEM_ERROR_CODE);
throw new AndroidException("Can't connect to activity manager; is the system running?");
}
    mPm = IPackageManager.Stub.asInterface(ServiceManager.getService("package"));
if (mPm == null) {
        System.err.println(NO_SYSTEM_ERROR_CODE);
throw new AndroidException("Can't connect to package manager; is the system running?");
}
    String op = nextArgRequired();
if (op.equals("instrument")) {
        runInstrument();
} else {
        runAmCmd(getRawArgs());
}
}
}

获取参数之后走runAmCmd

void runAmCmd(String[] args) throws AndroidException {
    final MyShellCallback cb = new MyShellCallback();
try {
        mAm.asBinder().shellCommand(FileDescriptor.in, FileDescriptor.out, FileDescriptor.err,
args, cb, new ResultReceiver(null) { });
} catch (RemoteException e) {
        System.err.println(NO_SYSTEM_ERROR_CODE);
throw new AndroidException("Can't call activity manager; is the system running?");
} finally {
        cb.mActive = false;
}
}

shellCommand是shell命令执行器

Binder.java
public void shellCommand(FileDescriptor in, FileDescriptor out, FileDescriptor err,
String[] args, ResultReceiver resultReceiver) throws RemoteException {
    onShellCommand(in, out, err, args, resultReceiver);//最终执行的方法
}

对am命令来说，binder call server端对应的是AMS, 对应方法为onShellCommand

frameworks/base/services/core/java/com/android/server/am/ActivityManagerService.java
@Override
public void onShellCommand(FileDescriptor in, FileDescriptor out,
FileDescriptor err, String[] args, ShellCallback callback,
ResultReceiver resultReceiver) {
    (new ActivityManagerShellCommand(this, false)).exec(
            this, in, out, err, args, callback, resultReceiver);
}

核心实现在ActivityManagerShellCommand，继续看：

frameworks/base/services/core/java/com/android/server/am/ActivityManagerShellCommand.java
final class ActivityManagerShellCommand extends ShellCommand {
@Override
public int onCommand(String cmd) {
    if (cmd == null) {
        return handleDefaultCommands(cmd);
}
    PrintWriter pw = getOutPrintWriter();
try {
        switch (cmd) {
            case "start":
            case "start-activity":
                return runStartActivity(pw);
case "startservice":
            case "start-service":
                return runStartService(pw, false);
... //对应的命令有很多，这里就省略了，主要看start
}

int runStartActivity(PrintWriter pw) throws RemoteException {
//mWaitOption默认是false , 如果带上-w 参数就为true
else if (opt.equals("-W")) {
    mWaitOption = true;
}
...
final long startTime = SystemClock.uptimeMillis();
if (mWaitOption) {
    result = mInterface.startActivityAndWait(null, null, intent, mimeType,
null, null, 0, mStartFlags, profilerInfo,
options != null ? options.toBundle() : null, mUserId);
res = result.result;
} else {
    res = mInterface.startActivityAsUser(null, null, intent, mimeType,
null, null, 0, mStartFlags, profilerInfo,
options != null ? options.toBundle() : null, mUserId);
}
final long endTime = SystemClock.uptimeMillis();
...
if (mWaitOption && launched) {
    if (result == null) {
        result = new WaitResult();
result.who = intent.getComponent();
}
    pw.println("Status: " + (result.timeout ? "timeout" : "ok"));
if (result.who != null) {
        pw.println("Activity: " + result.who.flattenToShortString());
}
    if (result.thisTime >= 0) {
        pw.println("ThisTime: " + result.thisTime);
}
    if (result.totalTime >= 0) {
        pw.println("TotalTime: " + result.totalTime);
}
    pw.println("WaitTime: " + (endTime-startTime));
pw.println("Complete");
pw.flush();
  }
}

exec方法是父类ShellCommand的，最终执行会调用onCommand, 而从实现来看，启动activity走的是runStartActivity。

而在runStartActivity方法中，-W是app启动完成的意思，带上它mWaitOption为true,则走的是startActivityAndWait，之后终于出现了thisTime、 totalTime和waitTime的相关打印了。

那么现在就来看看它们到底是怎么统计的。

首先从这里很明显能看出：startActivityAndWait 执行前后分别打了两个时间戳:startTime 和 endTime ，它俩的时间差就是WaitTime ，也就是说WaitTime就是整个startActivityAndWait的执行时间。

WaitTime解决了，下面再看看ThisTime和TotalTime，它俩都是result的成员变量，而result又是执行startActivityAndWait返回的，想必是在这个过程中赋值的.

frameworks/base/services/core/java/com/android/server/am/ActivityManagerService.java
@Override
public final WaitResult startActivityAndWait(IApplicationThread caller, String callingPackage,
Intent intent, String resolvedType, IBinder resultTo, String resultWho, int requestCode,
int startFlags, ProfilerInfo profilerInfo, Bundle bOptions, int userId) {
    enforceNotIsolatedCaller("startActivityAndWait");
userId = mUserController.handleIncomingUser(Binder.getCallingPid(), Binder.getCallingUid(),
userId, false, ALLOW_FULL_ONLY, "startActivityAndWait", null);
WaitResult res = new WaitResult();
// TODO: Switch to user app stacks here.
mActivityStarter.startActivityMayWait(caller, -1, callingPackage, intent, resolvedType,
null, null, resultTo, resultWho, requestCode, startFlags, profilerInfo, res, null,
bOptions, false, userId, null, null, "startActivityAndWait");
return res;
}

这里看到result对应的类是WaitResult

frameworks/base/core/java/android/app/WaitResult.java
public class WaitResult implements Parcelable {
    public int result;
public boolean timeout;
public ComponentName who;
public long thisTime;
public long totalTime;
...
}

我们看到初始化WaitResult之后，执行的mActivityStarter.startActivityMayWait ，然后return 了res值，那么继续看startActivityMayWait过程

frameworks/base/services/core/java/com/android/server/am/ActivityStarter.java
final int startActivityMayWait(IApplicationThread caller, int callingUid,
String callingPackage, Intent intent, String resolvedType,
IVoiceInteractionSession voiceSession, IVoiceInteractor voiceInteractor,
IBinder resultTo, String resultWho, int requestCode, int startFlags,
ProfilerInfo profilerInfo, WaitResult outResult,
Configuration globalConfig, Bundle bOptions, boolean ignoreTargetSecurity, int userId,
IActivityContainer iContainer, TaskRecord inTask, String reason) {
...
int res = startActivityLocked(caller, intent, ephemeralIntent, resolvedType,
aInfo, rInfo, voiceSession, voiceInteractor,
resultTo, resultWho, requestCode, callingPid,
callingUid, callingPackage, realCallingPid, realCallingUid, startFlags,
options, ignoreTargetSecurity, componentSpecified, outRecord, container,
inTask, reason);
...
if (outResult != null) {
    outResult.result = res;
if (res == ActivityManager.START_SUCCESS) {
        mSupervisor.mWaitingActivityLaunched.add(outResult);
do {
   try {
        mService.wait();
} catch (InterruptedException e) {
         }
     } while (outResult.result != START_TASK_TO_FRONT
                && !outResult.timeout && outResult.who == null);
if (outResult.result == START_TASK_TO_FRONT) {
            res = START_TASK_TO_FRONT;
}
    }
    if (res == START_TASK_TO_FRONT) {
        final ActivityRecord r = outRecord[0];
// ActivityRecord may represent a different activity, but it should not be in
// the resumed state.
if (r.nowVisible && r.state == RESUMED) {
   outResult.timeout = false;
  outResult.who = r.realActivity;
  outResult.totalTime = 0; //如果当前activity是前台可见，就不统计了。
  outResult.thisTime = 0;
} else { //这里才是真正统计时间的地方
  outResult.thisTime = SystemClock.uptimeMillis();
mSupervisor.waitActivityVisible(r.realActivity, outResult);
// Note: the timeout variable is not currently not ever set.
do {
   try {
      mService.wait();
} catch (InterruptedException e) {
        }
      } while (!outResult.timeout && outResult.who == null);
}
    }
}

思路很明显就是跟踪方法形参outResult，看它是怎么赋值的，相关代码如上。

核心统计位置：

outResult.thisTime = SystemClock.uptimeMillis();
mSupervisor.waitActivityVisible(r.realActivity, outResult);
// Note: the timeout variable is not currently not ever set.
do {
   try {
      mService.wait(); //mSerivce对应的是AMS
} catch (InterruptedException e) {
        }
} while (!outResult.timeout && outResult.who == null);

先执行mSupervisor.waitActivityVisible ，这里传入了outResult

void waitActivityVisible(ComponentName name, WaitResult result) {
    final WaitInfo waitInfo = new WaitInfo(name, result);
mWaitingForActivityVisible.add(waitInfo);
}

这里其实就是把WaitResult进一步包装为WaitInfo，并添加到mWaitingForActivityVisible集合中。

那这样就很明确了，核心点在于找到唤醒mService的逻辑。现在我并不清楚mService是在哪被notify/notifyAll的，怎么办？

两种思路：结合上下文看看有没有相关的类或者调用，这里WaitResult进一步包装为WaitInfo，并添加到mWaitingForActivityVisible集合，看上去有关联，可以跟一下。或者在这个位置打个trace标签，看是被谁唤醒的，这是备选方案。

那么先走第一条路：

还行，调用点不多，有惊喜发现:

frameworks/base/services/core/java/com/android/server/am/ActivityStackSupervisor.java
void sendWaitingVisibleReportLocked(ActivityRecord r) {
Slog.d("amstartdebug",Debug.getCallers(20)); //打印调用栈
boolean changed = false;
for (int i = mWaitingForActivityVisible.size() - 1; i >= 0; --i) {
        final WaitInfo w = mWaitingForActivityVisible.get(i);
if (w.matches(r.realActivity)) {
        final WaitResult result = w.getResult();
       changed = true;
       result.timeout = false;
       result.who = w.getComponent();
       result.totalTime = SystemClock.uptimeMillis() - result.thisTime;
       result.thisTime = result.totalTime;
       mWaitingForActivityVisible.remove(w);
}
    }
    if (changed) {
        mService.notifyAll();
  }
}

这里thisTime和totalTime都被赋值了，并且mService.notifyAll() ，nice!

那接下来就简单了，我们只要顺便捋清楚当前方法被执行的调用栈就好了

05-15 17:13:00.418 1458 1938 D amstartdebug:
[com.android.server.am](http://com.android.server.am/).ActivityRecord.onWindowsDrawn:2353
com.android.server.wm.AppWindowContainerController$H.handleMessage:92
android.os.Handler.dispatchMessage:106
android.os.Looper.loop:201
android.os.HandlerThread.run:65
com.android.server.ServiceThread.run:44

这里是startingwindow结束过程的回调, 但是因为startActivityMayWait执行并没有结束

05-15 17:13:00.487 1458 1938 D amstartdebug:
[com.android.server.am](http://com.android.server.am/).ActivityStackSupervisor.reportActivityVisibleLocked:1197
[com.android.server.am](http://com.android.server.am/).ActivityRecord.onWindowsVisible:2365
com.android.server.wm.AppWindowContainerController.lambda$new$0:114
com.android.server.wm.-$$Lambda$AppWindowContainerController$BD6wMjkwgPM5dckzkeLRiPrmx9Y.run:2
android.os.Handler.handleCallback:873
android.os.Handler.dispatchMessage:99
android.os.Looper.loop:201
android.os.HandlerThread.run:65
com.android.server.ServiceThread.run:44

经过打栈和debug， 总结出最终sendWaitingVisibleReportLocked方法调用的执行路径为如下时序图所示：


很明显走的就是finishDrawing流程。

好，我们来总结下目前已知的：

waitTime 是统计的整个startActivityAndWait的执行时间，也就是执行startActivityMayWait的时间。

而thisTime 和 totalTime:
终点时间戳如上流程, 记录的是首帧绘制完成回调.

private void performDraw() {
...
 //首帧绘制完成回调
mAttachInfo.mThreadedRenderer.setFrameCompleteCallback((long frameNr) -> {
    // TODO: Use the frame number
pendingDrawFinished();
});
...
}

起始时间是执行startActivityLocked return res 对应START_TASK_TO_FRONT case,
对应的时机描述：activity wasn't really started, but a task was simply brought to the foreground. 这部分就不跟了.

回顾Activity启动流程：

  1. startActivity 参数封装、数据以及权限验证、 调整任务栈
  2. fork process 冷启动需要创建进程
  3. attach application 创建并绑定application
  4. scheduleLaunchActivity activity的启动并走对应生命周期，首帧渲染完成

个人认为：
waitTime包括：1 - 4阶段
thisTime/totalTime包括：2 - 4阶段

所以站在应用角度看APP冷启时间，使用thisTime/totalTime, 而站在系统角度则看waitTime。

另外还有一种统计方式：

adb logcat -v time | grep "Displayed com.miui.gallery/com.miui.gallery.activity.HomePageActivity"

这是站在窗口显示的角度统计的。
对应的方法是：

frameworks/base/services/core/java/com/android/server/am/ActivityRecord.java
    private void reportLaunchTimeLocked(final long curTime) {
        final ActivityStack stack = getStack();
        if (stack == null) {
            return;
        }
        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); //这里有个launching的trace标签
            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(")");
            }
            Log.i(TAG, sb.toString());
        }
        mStackSupervisor.reportActivityLaunchedLocked(false, this, thisTime, totalTime);
        if (totalTime > 0) {
            //service.mUsageStatsService.noteLaunchTime(realActivity, (int)totalTime);
        }
        displayStartTime = 0;
        stack.mLaunchStartTime = 0;
    }

我们来解释下代码里curTime、displayStartTime、mLaunchStartTime三个时间变量:

  • curTime: 窗口界面显示出来后，WMS 才调用reportLaunchTimeLocked() 通知 AMS Activity 启动完成. 表示该函数调用的时间点.
  • displayStartTime: 表示一连串启动Activity中的最后一个Activity的启动时间点.
  • mLaunchStartTime: 表示一连串启动Activity中第一个Activity的启动时间点.
    调用栈感兴趣的可以自行分析下。

最后来看下systrace:

Display统计的launching时间与am start统计的totalTime是基本一致的。

最后编辑于 ：
©著作权归作者所有,转载或内容合作请联系作者
禁止转载，如需转载请通过简信或评论联系作者。
  • 人面猴
    序言：七十年代末，一起剥皮案震惊了整个滨河市，随后出现的几起案子，更是在滨河造成了极大的恐慌，老刑警刘岩，带你破解...
    沈念sama阅读 212,816评论 6赞 492
  • 死咒
    序言：滨河连续发生了三起死亡事件，死亡现场离奇诡异，居然都是意外死亡，警方通过查阅死者的电脑和手机，发现死者居然都...
    沈念sama阅读 90,729评论 3赞 385
  • 救了他两次的神仙让他今天三更去死
    文/潘晓璐 我一进店门，熙熙楼的掌柜王于贵愁眉苦脸地迎上来，“玉大人，你说我怎么就摊上这事。” “怎么了？”我有些...
    开封第一讲书人阅读 158,300评论 0赞 348
  • 道士缉凶录：失踪的卖姜人
    文/不坏的土叔 我叫张陵，是天一观的道长。 经常有香客问我，道长，这世上最难降的妖魔是什么？ 我笑而不...
    开封第一讲书人阅读 56,780评论 1赞 285
  • 港岛之恋（遗憾婚礼）
    正文 为了忘掉前任，我火速办了婚礼，结果婚礼上，老公的妹妹穿的比我还像新娘。我一直安慰自己，他们只是感情好，可当我...
    茶点故事阅读 65,890评论 6赞 385
  • 恶毒庶女顶嫁案：这布局不是一般人想出来的
    文/花漫 我一把揭开白布。 她就那样静静地躺着，像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上，一...
    开封第一讲书人阅读 50,084评论 1赞 291
  • 城市分裂传说
    那天，我揣着相机与录音，去河边找鬼。 笑死，一个胖子当着我的面吹牛，可吹牛的内容都是我干的。 我是一名探鬼主播，决...
    沈念sama阅读 39,151评论 3赞 410
  • 双鸳鸯连环套：你想象不到人心有多黑
    文/苍兰香墨 我猛地睁开眼，长吁一口气：“原来是场噩梦啊……” “哼！你这毒妇竟也来了？” 一声冷哼从身侧响起，我...
    开封第一讲书人阅读 37,912评论 0赞 268
  • 万荣杀人案实录
    序言：老挝万荣一对情侣失踪，失踪者是张志新（化名）和其女友刘颖，没想到半个月后，有当地人在树林里发现了一具尸体，经...
    沈念sama阅读 44,355评论 1赞 303
  • 护林员之死
    正文 独居荒郊野岭守林人离奇死亡，尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 36,666评论 2赞 327
  • 白月光启示录
    正文 我和宋清朗相恋三年，在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 38,809评论 1赞 341
  • 活死人
    序言：一个原本活蹦乱跳的男人离奇死亡，死状恐怖，灵堂内的尸体忽然破棺而出，到底是诈尸还是另有隐情，我是刑警宁泽，带...
    沈念sama阅读 34,504评论 4赞 334
  • 日本核电站爆炸内幕
    正文 年R本政府宣布，位于F岛的核电站，受9级特大地震影响，放射性物质发生泄漏。R本人自食恶果不足惜，却给世界环境...
    茶点故事阅读 40,150评论 3赞 317
  • 男人毒药：我在死后第九天来索命
    文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹，春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 30,882评论 0赞 21
  • 一桩弑父案，背后竟有这般阴谋
    文/苍兰香墨 我抬头看了看天上的太阳。三九已至，却和暖如春，着一层夹袄步出监牢的瞬间，已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 32,121评论 1赞 267
  • 情欲美人皮
    我被黑心中介骗来泰国打工， 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留，地道东北人。 一个月前我还...
    沈念sama阅读 46,628评论 2赞 362
  • 代替公主和亲
    正文 我出身青楼，却偏偏与公主长得像，于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子，可洞房花烛夜当晚...
    茶点故事阅读 43,724评论 2赞 351

推荐阅读更多精彩内容