前言
我相信大家肯定遇到过下面这个LOG，表面意思是在主线程做了太多的事，但是可能你们不知道这条LOG的真实含义。换句话说你们能写一个Demo生成这条LOG吗？我建议你们先写写看，再继续看下去。
Choreographer: Skipped 60 frames! The application may be doing too much work on its main thread.
一、可能是大多数人的Demo
public class MainActivity extends AppCompatActivity {
@Override
protected void onCreate(Bundle savedInstanceState) {
super.onCreate(savedInstanceState);
setContentView(R.layout.activity_main2);
}
@Override
protected void onResume() {
Log.d("KobeWang", "MainActivity : onResume start");
super.onResume();
try {
Thread.sleep(1000);
} catch (Exception e) {
}
Log.d("KobeWang", "MainActivity : onResume end");
}
}
我相信大多数人写的Demo是上面这样子的，但是很遗憾，不会出现Choreographer Skipped的LOG，就算把1000ms改成10s，也不会出现。
03-11 19:01:25.679 15733 15733 D KobeWang: MainActivity : onResume start
03-11 19:01:26.682 15733 15733 D KobeWang: MainActivity : onResume end
二、Choreographer Skipped
2.1 那我们来分析一下Choreographer Skipped生成的流程
private Choreographer(Looper looper, int vsyncSource) {
...
//每一帧的时间，如果60hz的屏幕，就是16ms，但是这里是微秒
mFrameIntervalNanos = (long)(1000000000 / getRefreshRate())
...
}
private final class FrameDisplayEventReceiver extends DisplayEventReceiver
implements Runnable {
private long mTimestampNanos;
private int mFrame;
@Override
public void onVsync(long timestampNanos, long physicalDisplayId, int frame) {
...
//onVsync方法将会在Vsync信号接收之后被回调
//mTimestampNanos就是这次Vsync信号接收的时间
mTimestampNanos = timestampNanos;
mFrame = frame;
//往主线程的Looper中投放一个Asynchronous的Message，callback为this
//这个Message被处理的时候就会调用下面run-doFrame的方法
Message msg = Message.obtain(mHandler, this);
msg.setAsynchronous(true);
mHandler.sendMessageAtTime(msg, timestampNanos / TimeUtils.NANOS_PER_MS);
}
@Override
public void run() {
doFrame(mTimestampNanos, mFrame);
}
}
void doFrame(long frameTimeNanos, int frame) {
final long startNanos;
synchronized (mLock) {
...
//intendedFrameTimeNanos就是预计执行doFrame的时间点
long intendedFrameTimeNanos = frameTimeNanos;
//startNanos就是实际执行doFrame的时间点
startNanos = System.nanoTime();
//计算实际和预计的时间差
final long jitterNanos = startNanos - frameTimeNanos;
//如果时间差大于一帧的时间，也就是16ms
if (jitterNanos >= mFrameIntervalNanos) {
//计算丢掉的帧数=时间差/一帧的时长
final long skippedFrames = jitterNanos / mFrameIntervalNanos;
//SKIPPED_FRAME_WARNING_LIMIT默认是30
if (skippedFrames >= SKIPPED_FRAME_WARNING_LIMIT) {
//如果丢掉的帧数大于30帧就打印LOG
Log.i(TAG, "Skipped " + skippedFrames + " frames! "
+ "The application may be doing too much work on its main thread.");
}
}
...
}
}
第一步：onVsync方法中保存Vsync信号接收的时间点timestampNanos
第二步：doFrame方法中计算时间差jitterNanos=当前时间-timestampNanos
第三步：如果时间差jitterNanos大于mFrameIntervalNanos（16ms），计算丢失的帧数skippedFrames=jitterNanos/mFrameIntervalNanos
第四步：如果skippedFrames大于30帧，打印Choreographer Skipped
2.2 onVsync方法什么时候被调用
监听到Vsync信号就会调用onVsync
如何监听Vsync信号？
首先要调用ViewRootImpl.scheduleTraversals，对下一个Vsync信号进行监听。
MainActivity的onResume完成之后就会触发ViewRootImpl.scheduleTraversals。
有兴趣的可以看看下面整个调用逻辑
KobeWang: java.lang.Exception: KobeWang
KobeWang: at android.view.ViewRootImpl.scheduleTraversals(ViewRootImpl.java:1694)
KobeWang: at android.view.ViewRootImpl.requestLayout(ViewRootImpl.java:1425)
KobeWang: at android.view.ViewRootImpl.setView(ViewRootImpl.java:856)
KobeWang: at android.view.WindowManagerGlobal.addView(WindowManagerGlobal.java:387)
KobeWang: at android.view.WindowManagerImpl.addView(WindowManagerImpl.java:96)
KobeWang: at android.app.ActivityThread.handleResumeActivity(ActivityThread.java:4399)
KobeWang: at android.app.servertransaction.ResumeActivityItem.execute(ResumeActivityItem.java:52)
KobeWang: at android.app.servertransaction.TransactionExecutor.executeLifecycleState(TransactionExecutor.java:176)
KobeWang: at android.app.servertransaction.TransactionExecutor.execute(TransactionExecutor.java:97)
KobeWang: at android.app.ActivityThread$H.handleMessage(ActivityThread.java:2102)
KobeWang: at android.os.Handler.dispatchMessage(Handler.java:107)
KobeWang: at android.os.Looper.loop(Looper.java:214)
KobeWang: at android.app.ActivityThread.main(ActivityThread.java:7501)
KobeWang: at java.lang.reflect.Method.invoke(Native Method)
KobeWang: at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:492)
KobeWang: at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:935)
小结：onVsync方法将会在onResume完成之后的下一个Vsync信号接收的时候被调用。
2.3 doFrame方法什么时候被调用
onVsync方法中往主线程的Looper中投放一个Asynchronous的Message。
这个Asynchronous的Message什么时候被处理，doFrame就是什么时候被调用。
整个Message的处理流程有兴趣的可以看我朋友的文章
https://zhenkunhuang.github.io/2019/05/05/android-handler-java/
小结：主线程Looper会是按照Message.when时间以及入队顺序执行，如果遇到一个同步屏障的message，从队列中选取最靠前的Asynchronous的Message优先处理。
Asynchronous的Message是Android隐藏接口，主要是系统用于UI显示的Message，从侧面也是看出安卓设计的初衷UI相关的Message优先处理。
2.4 总结
Choreographer Skipped真正反映的是onVsync和doFrame两个方法调用的时间间隔
其实这句话并不准确，我在[037]Choreographer Skipped含义再探中进行了修正。
三、我的Demo
前面的Demo为什么会失败是因为在onResume中sleep 1000ms，只能整体推迟调用onVsync和doFrame而已，并不能增加onVsync和doFrame之间调用的时间。
如何增加onVsync和doFrame之间调用的时间
如果在onVsync方法中投放Asynchronous的Message之前，主线程Looper有未处理的Message，就可以增加onVsync和doFrame两个方法调用的时间间隔，就会打印出Choreographer Skipped的LOG。
我写了如下的Demo
public class MainActivity extends AppCompatActivity {
private Handler mHandler = new Handler();
@Override
protected void onCreate(Bundle savedInstanceState) {
super.onCreate(savedInstanceState);
setContentView(R.layout.activity_main2);
}
@Override
protected void onResume() {
Log.d("KobeWang", "MainActivity : onResume start");
super.onResume();
mHandler.post(new Runnable() {
@Override
public void run() {
try {
Thread.sleep(1000);
} catch (Exception e) {
}
}
});
Log.d("KobeWang", "MainActivity : onResume end");
}
}
我在onResume完成之前，post了一个Runnable，也就是普通Message，并且Runnable休眠了1000ms。看我运行的LOG，果然出现了 Skipped 60 frames，正好和休眠的1000ms对应上。
2020-03-11 19:19:38.281 19118-19118/com.kobe.jankblock D/KobeWang: MainActivity : onResume start
2020-03-11 19:19:38.281 19118-19118/com.kobe.jankblock D/KobeWang: MainActivity : onResume end
2020-03-11 19:19:39.294 19118-19118/com.kobe.jankblock I/Choreographer: Skipped 60 frames! The application may be doing too much work on its main thread.
四、为什么要理解Choreographer Skipped
因为在解决性能问题的时候，尤其是解决启动慢，丢帧问题的时候，大家要完整的梳理整个主线程中处理所有的Message任务，然后自己想办法写出Demo模拟，这样子才能从根本上解决这类性能问题，而不是简单的一句“少在主线程中做事情”，就可以解决问题。我在[035] onStop提前投放问题中就按照这个思路解决了一个启动慢的问题。
尾巴
在[037]Choreographer Skipped含义再探中我会介绍另外一种Demo。
