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

作者: Stan_Z | 来源:发表于2019-05-16 19:30 被阅读204次

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

应用冷启动比较常用的时间统计方式是使用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启动流程：

startActivity 参数封装、数据以及权限验证、调整任务栈
fork process 冷启动需要创建进程
attach application 创建并绑定application
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是基本一致的。

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

相关文章

网友评论

延伸阅读

深度阅读

栏目导航

热点阅读

性能