Android Activity启动耗时统计方案
作者:林基宗
Activity的启动速度是很多开发者关心的问题,当页面跳转耗时过长时,App就会给人一种非常笨重的感觉。在遇到某个页面启动过慢的时候,开发的第一直觉一般是onCreate执行速度太慢了,然后在onCreate方法前后记录下时间戳计算出耗时。不过有时候即使把onCreate方法的耗时优化了,效果仍旧不明显。实际上影响到Activity启动速度的原因是多方面的,需要从Activity的启动流程入手,才能找到真正问题所在。
Activity启动流程
如果要给Activity的“启动”做一个定义的话,个人觉得应该是:从调用startActivity到
Activity可被操作为止,代表启动成功。所谓的可被操作,是指可接受各种输入事件,比如手势、键盘输入之类的。换个角度来说,也可以看成是主线程处于空闲状态,能执行后续进入的各种Message。
Activity的启动可以分为三个步骤,以ActivityA启动ActivityB为例,三步骤分别为:
- 以ActivityA调用startActivity,到ActivityA成功pause为止
- ActivityB成功初始化,到执行完resume为止
- ActivityB向WSM注册窗口,到第一帧绘制完成为止
Activity启动涉及到App进程与ActivityManagerService(AMS)、WindowManagerService(WMS)的通信,网上关于这个流程的文章很多,这边就不再具体描述了,只列一下关键方法的调用链路。
ActiivtyA Pause流程
当ActivityA使用startActivity方法启动ActivityB时,执行函数链路如下
ActivityA.startActivity->
Instrumentation.execStartActivity->
ActivityManagerNative.getDefault.startActivity->
ActivityManagerService.startActivityAsUser->
ActivityStarter.startActivityMayWait->
ActivityStarter.startActivityLocked->
ActivityStarter.startActivityUnchecked->
ActivityStackSupervisor.resumeFocusedStackTopActivityLocked->
ActivityStack.resumeTopActivityUncheckedLocked->
ActivityStack.resumeTopActivityInnerLocked->
ActivityStack.startPausingLocked->
ActivityThread$$ApplicationThread.schedulePauseActivity->
ActivityThread.handlePauseActivity->
└ActivityA.onPause
ActivityManagerNative.getDefault().activityPaused
当App请求AMS要启动一个新页面的时候,AMS首先会pause掉当前正在显示的Activity,当然,这个Activity可能与请求要开启的Activity不在一个进程,比如点击桌面图标启动App,当前要暂停的Activity就是桌面程序Launcher。在onPause内执行耗时操作是一种很不推荐的做法,从上述调用链路可以看出,如果在onPause内执行了耗时操作,会直接影响到ActivityManagerNative.getDefault().activityPaused()方法的执行,而这个方法的作用就是通知AMS,“当前Activity已经已经成功暂停,可以启动新Activity了”。
ActivityB Launch流程
在AMS接收到App进程对于activityPaused方法的调用后,执行函数链路如下
ActivityManagerService.activityPaused->
ActivityStack.activityPausedLocked->
ActivityStack.completePauseLocked->
ActivityStackSupervisor.resumeFocusedStackTopActivityLocked->
ActivityStackSupervisor.resumeFocusedStackTopActivityLocked->
ActivityStack.resumeTopActivityUncheckedLocked->
ActivityStack.resumeTopActivityInnerLocked->
ActivityStackSupervisor.startSpecificActivityLocked->
└1.启动新进程:ActivityManagerService.startProcessLocked 暂不展开
└2.当前进程:ActivityStackSupervisor.realStartActivityLocked->
ActivityThread$$ApplicationThread.scheduleLaunchActivity->
Activity.handleLaunchActivity->
└Activity.onCreate
└Activity.onRestoreInstanceState
└handleResumeActivity
└Activity.onStart->
└Activity.onResume->
└WindowManager.addView->
AMS在经过一系列方法调用后,通知App进程正式启动一个Actviity,注意如果要启动Activity所在进程不存在,比如点击桌面图标第一次打开应用,或者App本身就是多进程的,要启动的新页面处于另外一个进程,那就需要走到ActivityManagerService.startProcessLocked流程,等新进程启动完毕后再通知AMS,这里不展开。按照正常流程,会依次走过Activity生命周期内的onCreate、onRestoreInstanceState、onStart、onResume方法,这一步的耗时基本也可以看成就是这四个方法的耗时,由于这四个方法是同步调用的,所以可以通过以onCreate方法为起点,onResume方法为终点,统计出这一步骤的总耗时。
ActivityB Render流程
在ActivityB执行完onResume方法后,就可以显示该Activity了,调用流程如下
WindowManager.addView->
WindowManagerImpl.addView->
ViewRootImpl.setView->
ViewRootImpl.requestLayout->
└ViewRootImpl.scheduleTraversals->
└Choreographer.postCallback->
WindowManagerSerivce.add
这一步的核心实际上是Choreographer.postCallback,向Choreographer注册了一个回调,当Vsync事件到来时,就会执行下面的回调进行ui的渲染
ViewRootImpl.doTraversal->
ViewRootImpl.performTraversals->
└ViewRootImpl.relayoutWindow
└ViewRootImpl.performMeasure
└ViewRootImpl.performLayout
└ViewRootImpl.performDraw
ViewRootImpl.reportDrawFinished
这里分别执行了performMeasure、performLayout、performDraw,实际上就是对应到DecorView的测量、布局、绘制三个流程。由于Android的UI是个树状结构,作为根View的DecorView的测量、布局、绘制,会调用到所有子View相应的方法,因此,这一步的总耗时就是所有子View在测量、布局、绘制中的耗时之和,如果某个子View在这三个方法中如果进行了耗时操作,就会拖慢整个UI的渲染,进而影响Activity第一帧的渲染速度。
耗时统计方案
知道了Actviity启动流程的三个步骤和对应的方法耗时统计方法,那该如何设计一个统计方案呢?在这之前,可以先看看系统提供的耗时统计方法。
系统耗时统计
打开Android Studio的Logcat,输入过滤关键字ActivityManager,在启动一个Actviity后就能看到如下日志
末尾的+59ms便是启动该Activity的耗时。这个日志是Android系统在AMS端直接输出的,《WMS常见问题一(Activity displayed延迟)》这篇文章分析了系统耗时统计的方法,简单来说,上述日志是通过ActivityRecord.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(")");
}
Log.i(TAG, sb.toString());
}
......
}
其中displayStartTime是在ActivityStack.setLaunchTime()方法中设置的,具体调用链路:
ActivityStackSupervisor.startSpecificActivityLocked->
└ActivityStack.setLaunchTime
ActivityStackSupervisor.realStartActivityLocked->
ActivityThread$$ApplicationThread.scheduleLaunchActivity->
Activity.handleLaunchActivity->
ActivityThread$$ApplicationThread.scheduleLaunchActivity->
Activity.handleLaunchActivity->
在ActivityStackSupervisor.startSpecificActivityLocked方法中调用了ActivityStack.setLaunchTime(),而startSpecificActivityLocked方法最终会走到App端的Activity.onCreate方法,所以统计开始的时间实际上就是App启动中的第二步开始的时间。
而ActivityRecord.reportLaunchTimeLocked方法自身的调用链如下:
ViewRootImpl.reportDrawFinished->
Session.finishDrawing->
WindowManagerService.finishDrawingWindow->
WindowSurfacePlacer.requestTraversal->
WindowSurfacePlacer.performSurfacePlacement->
WindowSurfacePlacer.performSurfacePlacementLoop->
RootWindowContainer.performSurfacePlacement->
WindowSurfacePlacer.handleAppTransitionReadyLocked->
WindowSurfacePlacer.handleOpeningApps->
AppWindowToken.updateReportedVisibilityLocked->
AppWindowContainerController.reportWindowsDrawn->
ActivityRecord.onWindowsDrawn->
ActivityRecord.reportLaunchTimeLocked
在启动流程第三步UI渲染完成后,App会通知WMS,紧接着WMS执行一系列和切换动画相关的方法后,调用到ActivityRecord.reportLaunchTimeLocked,最终打印出启动耗时。
由上述流程可以看到,系统统计并没有把ActivityA的pause操作耗时计入Activity启动耗时中。不过,如果我们在ActivityA的onPause中做一个Thread.sleep(2000)操作,会很神奇地看到系统打印的耗时也跟着变了
这次启动耗时变成了1.571s,明显是把onPause的时间算进去了,但是却小于onPause内休眠的2秒。其实,这是由于AMS对于pause操作的超时处理导致的,在ActivityStack.startPausingLocked方法中,会执行到schedulePauseTimeout方法
ActivityThread.Java
private static final int PAUSE_TIMEOUT = 500;
private void schedulePauseTimeout(ActivityRecord r) {
final Message msg = mHandler.obtainMessage(PAUSE_TIMEOUT_MSG);
msg.obj = r;
r.pauseTime = SystemClock.uptimeMillis();
mHandler.sendMessageDelayed(msg, PAUSE_TIMEOUT);
if (DEBUG_PAUSE) Slog.v(TAG_PAUSE, "Waiting for pause to complete...");
}
...
private class ActivityStackHandler extends Handler {
@Override
public void handleMessage(Message msg) {
switch (msg.what) {
case PAUSE_TIMEOUT_MSG: {
ActivityRecord r = (ActivityRecord)msg.obj;
// We don't at this point know if the activity is fullscreen,
// so we need to be conservative and assume it isn't.
Slog.w(TAG, "Activity pause timeout for " + r);
synchronized (mService) {
if (r.app != null) {
mService.logAppTooSlow(r.app, r.pauseTime, "pausing " + r);
}
activityPausedLocked(r.appToken, true);
}
} break;
这个方法的作用在于,如果过了500ms,上一个要暂停Activity的进程还没有回调activityPausedLocked方法,AMS就会自己调用activityPausedLocked方法,继续之后的Launch流程。所以过了500ms之后,AMS就会通知App进程启动ActivityB的操作,然而此时App进程仍旧被onPause的Thread.sleep阻塞着,所以只能再等待1.5s才能继续操作,因此打印出来的时间是2s-0.5s+正常的耗时。
三种耗时
说完了系统的统计方案,接下去介绍下应用内的统计方案。根据前面的介绍,若想自己实现Activity的启动耗时统计功能,只需要以startActivity执行为起始点,以第一帧渲染为结束点,就能得出一个较为准确的耗时。不过,这种统计方式无法帮助我们定位具体的问题,当遇到一个页面启动较慢时,我们可能需要知道它具体慢在哪里。而且,由于启动过程中涉及到大量的系统进程耗时和App端Framework层的方法耗时,这块耗时又是难以对其进行干涉的,所以接下去会把统计的重点放在通过编码能影响到的耗时上,按照启动流程的三个步骤,划分为三种耗时。
Pause耗时
尽管启动Activity的起点是startActivity方法,但是从调用这个方法开始,到onPause被执行到为止,其实都是App端Framework层与AMS之间的交互,所以这里把第一阶段Pause的耗时统计放在onPause方法开始时候。这一块的统计也很简单,只需要计算一下onPause方法的耗时就足够了。有些同学可能会疑惑:是否onStop也要计入Pause耗时。并不需要,onStop操作其实是在主线程空余时才会执行的,在Activity.handleResumeActivity方法中,会执行Looper.myQueue().addIdleHandler(new Idler())方法,Idler定义如下
ActivityThread.java
private class Idler implements MessageQueue.IdleHandler {
@Override
public final boolean queueIdle() {
......
am.activityIdle(a.token, a.createdConfig,
......
return false;
}
}
addIdleHandler表示会放入一个低优先级的任务,只有在线程空闲的时候才去执行,而am.activityIdle方法会通知AMS找到处于stop状态的Activity,通过Binder回调ActivityThread.scheduleStopActivity,最终执行到onStop。而这个时候,UI第一帧已经渲染完毕。
Launch耗时
Launch耗时可以通过onCreate、onRestoreInstanceState、onStart、onResume四个函数的耗时相加得出。在这四个方法中,onCreate一般是最重的那个方法,因为很多变量的初始化都会放在这里进行。另外,onCreate方法中还有个耗时大户是LayoutInfalter.infalte方法,调用setContentView会执行到这个方法,对于一些复杂布局的第一次解析,会消耗大量时间。由于这四个方法是同步顺序执行的,单独把某些操作从onCreate移到onResume之类的并没有什么意义,Launch耗时只关心这几个方法的总耗时。
Render耗时
从onResume执行完成到第一帧渲染完成所花费的时间就是Render耗时。Render耗时可以用三种方式计算出来。
第一种,IdleHandler:
Activity.java
@Override
protected void onResume() {
super.onResume();
final long start = System.currentTimeMillis();
Looper.myQueue().addIdleHandler(new MessageQueue.IdleHandler() {
@Override
public boolean queueIdle() {
Log.d(TAG, "onRender cost:" + (System.currentTimeMillis() - start));
return false;
}
});
}
前面说过IdleHandler只会在线程处于空闲的时候被执行。
第二种方法,DecorView的两次post:
Activity.java
@Override
protected void onResume() {
super.onResume();
final long start = System.currentTimeMillis();
getWindow().getDecorView().post(new Runnable() {
@Override
public void run() {
new Hanlder().post(new Runnable() {
@Override
public void run() {
Log.d(TAG, "onPause cost:" + (System.currentTimeMillis() - start));
}
});
}
});
}
View.java
public boolean post(Runnable action) {
final AttachInfo attachInfo = mAttachInfo;
if (attachInfo != null) {
return attachInfo.mHandler.post(action);
}
// Postpone the runnable until we know on which thread it needs to run.
// Assume that the runnable will be successfully placed after attach.
getRunQueue().post(action);
return true;
}
void dispatchAttachedToWindow(AttachInfo info, int visibility) {
mAttachInfo = info;
......
// Transfer all pending runnables.
if (mRunQueue != null) {
mRunQueue.executeActions(info.mHandler);
mRunQueue = null;
}
......
}
ViewRootImpl.java
private void performTraversals() {
......
// host即DecorView
host.dispatchAttachedToWindow(mAttachInfo, 0);
.......
performMeasure(childWidthMeasureSpec, childHeightMeasureSpec);
.......
performLayout(lp, mWidth, mHeight);
.......
performDraw();
.......
}
通过getWindow().getDecorView()获取到DecorView后,调用post方法,此时由于DecorView的attachInfo为空,会将这个Runnable放置runQueue中。runQueue内的任务会在ViewRootImpl.performTraversals的开始阶段被依次取出执行,我们知道这个方法内会执行到DecorView的测量、布局、绘制操作,不过runQueue的执行顺序会在这之前,所以需要再进行一次post操作。第二次的post操作可以继续用DecorView().post或者其普通Handler.post(),并无影响。此时mAttachInfo已不为空,DecorView().post也是调用了mHandler.post()。
第三种方法:new Handler的两次post:
Activity.java
@Override
protected void onResume() {
super.onResume();
final long start = System.currentTimeMillis();
new Handler.post(new Runnable() {
@Override
public void run() {
getWindow().getDecorView().post(new Runnable() {
@Override
public void run() {
Log.d(TAG, "onPause cost:" + (System.currentTimeMillis() - start));
}
});
}
});
}
乍看一下第三种方法和第二种方法区别不大,实际上原理大不相同。这是因为ViewRootImpl.scheduleTraversals方法会往主线程队列插入一个屏障消息,代码如下所示:
ViewRootImpl.java
void scheduleTraversals() {
......
mTraversalBarrier = mHandler.getLooper().getQueue().postSyncBarrier();
mChoreographer.postCallback(
Choreographer.CALLBACK_TRAVERSAL, mTraversalRunnable, null);
......
}
}
屏障消息的作用在于阻塞在它之后的同步消息的执行,当我们在onResume方法中执行第一次new Handler().post方法,向主线程消息队列放入一条消息时,从前面的内容可以知道onResume是在ViewRootImpl.scheduleTraversals方法之前执行的,所以这条消息会在屏障消息之前,能被正常执行;而第二次post的消息就在屏障消息之后了,必须等待屏障消息被移除掉才能执行。屏障消息的移除操作在ViewRootImpl.doTraversal方法
ViewRootImpl.java
void doTraversal() {
.......
mHandler.getLooper().getQueue().removeSyncBarrier(mTraversalBarrier);
.......
performTraversals();
.......
}
}
在这之后就将执行performTraversals方法,所以移除屏障消息后,等待performTraversals执行完毕,就能正常执行第二次post操作了。在这个地方,其实有个小技巧可以只进行一次post操作,就是在第一次post的时候进行一次小的延迟:
Activity.java
@Override
protected void onResume() {
super.onResume();
final long start = System.currentTimeMillis();
new Handler.postDelay(new Runnable() {
@Override
public void run() {
Log.d(TAG, "onPause cost:" + (System.currentTimeMillis() - start));
}
},10);
}
通过添加一点小延迟,可以把消息的执行时间延迟到屏障消息之后,这条消息就会被屏障消息阻塞,直到屏障消息被移除时才执行了。不过由于系统函数执行时间不可控,这种方式并不保险。
Frament耗时
这里单独说一下Fragment的耗时。Fragment本质上是一个View,只不过这个View有自己的声明周期管理。
应用内统计方案
耗时统计是非常适合使用AOP思想来实现的功能。我们当然不希望在每个Activity的onPause、onCreate、onResume等方法中进行手动方法统计,第一这会增加编码量,第二这对代码有侵入,第三对于第三方sdk内的Activity代码,无法进行修改。使用AOP,表示需要找到一个切入点,这个切入点是Activity生命周期回调的入口。这里推荐两三方案。
Hook Instrumentation
Hook Instrumentation是指通过反射将ActivtyThread内的Instrumentation对象替换成我们自定义的Instrumentation对象。在插件化方案中,Hook Instrumentation是种很常见的方式。由于所有Activity生命周期的回调都要经过Instrumentation对象,因此通过Hook Instrumentation对象,可以很方便地统计出Actvity每个生命周期的耗时。以启动流程第一阶段的Pause耗时为例,可以这么修改Instrumentation:
public class TestInstrumentation extends Instrumentation {
private static final String TAG="TestInstrumentation";
private static final Instrumentation mBase;
public TestInstrumentation(Instrumentation base){
mBase = base;
}
.......
@Override
public void callActivityOnPause(Activity activity) {
long startTime = System.currentTimeMillis();
mBase.callActivityOnPause(activity);
Log.d(TAG,"onPause cost:"+(System.currentTimeMillis()-startTime));
}
.......
}
而Render耗时,可以在callActivityOnResume方法最后,通过Post Message的方式进行统计。
Hook Instrumentation是种很理想的解决方案,唯一的问题是太多人喜欢Hook 它了。由于很多功能,比如插件化都喜欢Hook Instrumentation,为了不影响他们的使用,不得不重写大量的方法执行mBase.xx()。
如果Instrumentation是个接口,能够使用动态代理就更理想了。
Hook Looper-Printer
Hook Looper是种比较取巧的方案,做法是通过Looper.getMainLooper().setMessageLogging(Printer)方法设置一个日志对象
public static void loop() {
......
for (;;) {
......
final Printer logging = me.mLogging;
if (logging != null) {
logging.println(">>>>> Dispatching to " + msg.target + " " +
msg.callback + ": " + msg.what);
}
......
try {
msg.target.dispatchMessage(msg);
end = (slowDispatchThresholdMs == 0) ? 0 : SystemClock.uptimeMillis();
} finally {
if (traceTag != 0) {
Trace.traceEnd(traceTag);
}
}
.......
if (logging != null) {
logging.println("<<<<< Finished to " + msg.target + " " + msg.callback);
}
.......
}
}
在Looper执行消息前后,如果Printer对象不为空,就会各输出一段日志,而我们知道Activity的生命周期回调的起点其实都是ActviityThread内的mH这个Handler,通过解析日志,就能知道当前msg是否是相应的生命周期任务,解析大致流程如下:
- 匹配“>>>>> Dispatching to”和“<<<<< Finished to ”,区分msg开始和结束节点
- 匹配msg.target是否等于“android.app.ActivityThread$H”,确定是否为生命周期调消息
- 匹配msg.what,确定当前消息码,不同生命周期回调对应不同消息码,比如LAUNCH_ACTIVITY = 100、PAUSE_ACTIVITY = 101
- 统计开始节点和结束节点之前的耗时,就能得出响应生命周期的耗时。同样的,Render耗时需要在Launch结束时,通过Post Message的方式得出。
这个方案的优点是不需要通过反射等方式,修改系统对象,所以安全性很高。但是通过该方法只能区分Pause、Launch、Render三个步骤的相应耗时,无法细分Launch方法中各个生命周期的耗时,因为是以每个消息的执行为统计单位,而Launch消息实际上同时包含了onCreate、onStart、onResume等的回调。更致命的一点是在Android P中,系统对生命周期的处理做了一次大的重构,不再细分Pause、Launch、Stop、Finish等消息,统一使用EXECUTE_TRANSACTION=159来处理,而具体生命周期的处理则是用多态的方式实现。所以该方案无法兼容Android P及以上版本
Hook ActivityThread$H
每当ASM通过Binder调用到到App端时,会根据不同的调用方法转化成不同的消息放入ActivityThread$H这个Handler中,因此,只要Hook住了ActivityThread$H,就能得到所有生命周期的起点。
另外,Handler事实上可以设置一个mCallback字段(需要通过反射设置),在执行dispatchMessage方法时,如果mCallback不为空,则优先执行mCallback
Handler.java
public void dispatchMessage(Message msg) {
if (msg.callback != null) {
handleCallback(msg);
} else {
if (mCallback != null) {
if (mCallback.handleMessage(msg)) {
return;
}
}
handleMessage(msg);
}
}
因此,可以通过反射获取ActivityThread中的H对象,将mCallback修改为自己实现的Handler.Callback对象,实现消息的拦截,而不需要替换Hanlder对象
class ProxyHandlerCallback implements Handler.Callback {
//设置当前的callback,防止其他sdk也同时设置了callback被覆盖
public final Handler.Callback mOldCallback;
public final Handler mHandler;
ProxyHandlerCallback(Handler.Callback oldCallback, Handler handler) {
mOldCallback = oldCallback;
mHandler = handler;
}
@Override
public boolean handleMessage(Message msg) {
// 处理消息开始,同时返回消息类型,主要为了兼容Android P,把159消息转为101(Pause)和100(Launch)
int msgType = preDispatch(msg);
// 如果旧的callback返回true,表示已经被它拦截,而它内部必定调用了Handler.handleMessage,直接返回
if (mOldCallback != null && mOldCallback.handleMessage(msg)) {
postDispatch(msgType);
return true;
}
// 直接调用handleMessage执行消息处理
mHandler.handleMessage(msg);
// 处理消息结束
postDispatch(msgType);
// 返回true,表示callback会拦截消息,Hanlder不需要再处理消息因为我们上一步已经处理过了
return true;
}
.......
}
为了统计mHandler.handleMessage(msg)方法耗时,Callback的handleMessage方法会返回true。preDispatch和postDispatch的处理和Hook Looper流程差不多,不过增加了Android P下,消息类行为159时的处理,方案可以参考《Android的插件化兼容性》。
和Hook Looper一样,Hook Hanlder也有个缺点是无法分别获取Launch中各个生命周期的耗时。
总结
最后做下总结:
- Activity的启动分为Pause、Launch和Render三个步骤,在启动一个新Activity时,会先Pause前一个正在显示的Activity,再加载新Activity,然后开始渲染,直到第一帧渲染成功,Activity才算启动完毕
- 可以利用Logcat查看系统输出的Activity启动耗时,系统会统计Activity Launch+Render的时间做为耗时时间,而系统最多允许Pause操作超时500ms,到时见就会自己调用Pause完成方法进行后续流程。
- 可以使用Hook Instrumentation、Hook Looper、Hook Handler三种方式实现AOP的耗时统计,其中Hook Looper方式无法兼容Android P
推广下DoraemonKit,
是一款功能齐全的客户端( iOS 、Android )研发助手,已集成耗时统计功能!