什么是卡顿，很多人能马上联系到的是帧率 FPS (每秒显示帧数)。那么多低的 FPS 才是卡顿呢？又或者低 FPS 真的就是卡顿吗？（以下 FPS 默认指平均帧率）
其实并非如此，举个例子，游戏玩家通常追求更流畅的游戏画面体验一般要达到 60FPS 以上，但我们平时看到的大部分电影或视频 FPS 其实不高，一般只有 25FPS ~ 30FPS，而实际上我们也没有觉得卡顿。 在人眼结构上看，当一组动作在 1 秒内有 12 次变化（即 12FPS），我们会认为这组动作是连贯的；而当大于 60FPS 时，人眼很难区分出来明显的变化，所以 60FPS 也一直作为业界衡量一个界面流畅程度的重要指标。一个稳定在 30FPS 的动画，我们不会认为是卡顿的，但一旦 FPS 很不稳定，人眼往往容易感知到。
FPS 低并不意味着卡顿发生，而卡顿发生 FPS 一定不高。 FPS 可以衡量一个界面的流程性，但往往不能很直观的衡量卡顿的发生，这里有另一个指标（掉帧程度）可以更直观地衡量卡顿。
什么是掉帧（跳帧）？ 按照理想帧率 60FPS 这个指标，计算出平均每一帧的准备时间有 1000ms/60 = 16.6667ms，如果一帧的准备时间超出这个值，则认为发生掉帧，超出的时间越长，掉帧程度越严重。假设每帧准备时间约 32ms，每次只掉一帧，那么 1 秒内实际只刷新 30 帧，即平均帧率只有 30FPS，但这时往往不会觉得是卡顿。反而如果出现某次严重掉帧（>300ms），那么这一次的变化，通常很容易感知到。所以界面的掉帧程度，往往可以更直观的反映出卡顿。
造成 掉帧 的直接原因通常是 doFrame 过于繁重执行超时，或者其他任务挤压了 doFrame 的执行时间，这些都会造成主线程不能在 帧间隔时间 内完成 ui 绘制
public static void Looper.loop() {
// ...
for (;;) {
// ...
final Printer logging = me.mLogging;
if (logging != null) {
logging.println(">>>>> Dispatching to " + msg.target + " " +
msg.callback + ": " + msg.what);
}
// ...
msg.target.dispatchMessage(msg);
// ...
if (logging != null) {
logging.println("<<<<< Finished to " + msg.target + " " + msg.callback);
}
// ...
}
}
计算 Message 耗时
我们知道主线程是「生产者 - 消费者」模型，任务（Message）都在消息队列（MessageQueue）里排队等待执行，如果能够度量出每个 Message 的耗时，然后与某个阈值进行比较，我们就能找出耗时任务做进一步的优化
从下面的代码可以看到，Message 执行前后都会有特定格式的日志输出，只要捕获这些日志，就能计算出每个 Message 的耗时
LooperMonitor 通过替换 Looper.mLogging，从而捕获到 >>>>> Dispatching to 和 <<<<< Finished to 的日志输出进而算出 Message 耗时，并提供 dispatchStart 和 dispatchEnd 两个钩子
public class LooperMonitor {
// 通过反射替换 Looper.mLogging
private synchronized void resetPrinter() {
Printer originPrinter = null;
try {
if (!isReflectLoggingError) {
originPrinter = ReflectUtils.get(looper.getClass(), "mLogging", looper);
if (originPrinter == printer && null != printer) {
return;
}
}
} catch (Exception e) {
isReflectLoggingError = true;
Log.e(TAG, "[resetPrinter] %s", e);
}
if (null != printer) {
MatrixLog.w(TAG, "maybe thread:%s printer[%s] was replace other[%s]!",
looper.getThread().getName(), printer, originPrinter);
}
looper.setMessageLogging(printer = new LooperPrinter(originPrinter));
if (null != originPrinter) {
MatrixLog.i(TAG, "reset printer, originPrinter[%s] in %s", originPrinter, looper.getThread().getName());
}
}
// 捕获根据特定格式的日志输出
class LooperPrinter implements Printer {
public void println(String x) {
if (null != origin) {
origin.println(x);
if (origin == this) {
throw new RuntimeException(TAG + " origin == this");
}
}
if (!isHasChecked) {
isValid = x.charAt(0) == '>' || x.charAt(0) == '<';
isHasChecked = true;
if (!isValid) {
MatrixLog.e(TAG, "[println] Printer is inValid! x:%s", x);
}
}
if (isValid) {
dispatch(x.charAt(0) == '>', x);
}
}
}
// 分发 Dispatching to 和 Finished to 事件
private void dispatch(boolean isBegin, String log) {
for (LooperDispatchListener listener : listeners) {
if (listener.isValid()) {
if (isBegin) {
if (!listener.isHasDispatchStart) {
listener.onDispatchStart(log);
}
} else {
if (listener.isHasDispatchStart) {
listener.onDispatchEnd(log);
}
}
} else if (!isBegin && listener.isHasDispatchStart) {
listener.dispatchEnd();
}
}
}
}
public boolean LooperMonitor.queueIdle() {
if (SystemClock.uptimeMillis() - lastCheckPrinterTime >= CHECK_TIME) {
resetPrinter();
lastCheckPrinterTime = SystemClock.uptimeMillis();
}
return true;
}
为了防止其他代码也替换 Looper.mLogging，LooperMonitor 还在主线程空闲的时候进行检查
public class UIThreadMonitor {
// 最开始先在 INPUT 头部插入钩子
public synchronized void UIThreadMonitor.onStart() {
// ...
queueStatus = new int[CALLBACK_LAST + 1];
queueCost = new long[CALLBACK_LAST + 1];
addFrameCallback(CALLBACK_INPUT, this, true);
}
// 依次往 ANIMATION/TRAVERSAL 插入钩子
public void run() {
final long start = System.nanoTime();
try {
doFrameBegin(token);
doQueueBegin(CALLBACK_INPUT);
addFrameCallback(CALLBACK_ANIMATION, new Runnable() {
@Override
public void run() {
doQueueEnd(CALLBACK_INPUT);
doQueueBegin(CALLBACK_ANIMATION);
}
}, true);
addFrameCallback(CALLBACK_TRAVERSAL, new Runnable() {
@Override
public void run() {
doQueueEnd(CALLBACK_ANIMATION);
doQueueBegin(CALLBACK_TRAVERSAL);
}
}, true);
} finally {
if (config.isDevEnv()) {
MatrixLog.d(TAG, "[UIThreadMonitor#run] inner cost:%sns", System.nanoTime() - start);
}
}
}
// 主线程消息队列的任务结束钩子，也作为 TRAVERSAL 的结束标志
private void dispatchEnd() {
// ...
long startNs = token;
long intendedFrameTimeNs = startNs;
if (isVsyncFrame) {
doFrameEnd(token);
intendedFrameTimeNs = getIntendedFrameTimeNs(startNs); // FrameDisplayEventReceiver.mTimestampNanos
}
// ...
}
private void doFrameEnd(long token) {
doQueueEnd(CALLBACK_TRAVERSAL);
// ...
addFrameCallback(CALLBACK_INPUT, this, true); // 继续放入下一轮 doFrame 的钩子
}
}
计算 doFrame 耗时
上面的方法可以统计主线程里每个 Message 的耗时，但并不是每个 Message 都在做 ui 绘制（doFrame），比如违规放入耗时的 IO 操作；为了更精确地捕获耗时的 doFrame，以及进行 FPS 统计，还需做更多的工作
参考 Vsync 这篇文章 我们知道，当 APP_VSYNC 到达时会走 FrameDisplayEventReceiver.onVsync -> Choreographer.doFrame -> Choreographer.doCallbacks，最后按 INPUT - ANIMATION - TRAVERSAL 的顺序执行 Choreographer.mCallbackQueues 里的 Runnable
动态地往这三个队列的头部插入钩子，从而计算出每个阶段开始时间和结束时间，加上捕获 Message 的方法（Choreographer.doFrame 是由 FrameDisplayEventReceiver.onVsync 放入主线程任务队列的 Message），最终形成完整的闭环：
dispatchBegin -> doFrameBegin -> doQueueBegin(INPUT) -> doQueueEnd(INPUT) -> doQueueBegin(ANIMATION) -> doQueueEnd(ANIMATION) -> doQueueBegin(TRAVERSAL) -> doQueueEnd(TRAVERSAL) -> doFrameEnd -> dispatchEnd
LooperObserver，结合上面捕获到的信息，提供一个「观察者」
public abstract class LooperObserver {
private boolean isDispatchBegin = false;
/**
* Message 开始执行
* @param beginNs 开始时间（System.nanoTime）
* @param cpuBeginNs 线程的开始时间（SystemClock.currentThreadTimeMillis）
* @param token 等于 beginNs
*/
@CallSuper
public void dispatchBegin(long beginNs, long cpuBeginNs, long token) {
isDispatchBegin = true;
}
/**
* Message 耗时统计
* @param focusedActivity 当前页面（Activity）
* @param startNs Message 的开始时间（等于 beginNs）
* @param endNs Message 的结束时间（等于 endNs）
* @param isVsyncFrame 是否 ui 绘制任务（doFrame）
* @param intendedFrameTimeNs 收到 APP_VSYNC 信号的时间（FrameDisplayEventReceiver.onVsync）
* @param inputCostNs doFrame INPUT 阶段耗时
* @param animationCostNs doFrame ANIMATION 阶段耗时
* @param traversalCostNs doFrame TRAVERSAL 阶段耗时
*/
public void doFrame(String focusedActivity, long startNs, long endNs, boolean isVsyncFrame, long intendedFrameTimeNs, long inputCostNs, long animationCostNs, long traversalCostNs) {
}
/**
* Message 结束执行
* @param beginNs 开始时间
* @param cpuBeginMs 线程的开始时间
* @param endNs 结束时间
* @param cpuEndMs 结束的线程时间
* @param token 等于 beginNs
* @param isVsyncFrame 此任务是否 ui 绘制任务（doFrame）
*/
@CallSuper
public void dispatchEnd(long beginNs, long cpuBeginMs, long endNs, long cpuEndMs, long token, boolean isVsyncFrame) {
isDispatchBegin = false;
}
public boolean isDispatchBegin() {
return isDispatchBegin;
}
}
计算 FPS
我们将掉帧数划分出几个区间进行定级，掉帧数小于 3 帧的情况属于最佳，依次类推，见下表：
Best Normal Middle High Frozen [0:3) [3:9) [9:24) [24:42) [42:∞) 相比单看平均帧率，掉帧程度的分布可以明显的看出，界面卡顿（平均帧率低）的原因是因为连续轻微的掉帧，还是某次严重掉帧造成的。再通过 Activity 区分不同场景，计算每个界面在有效绘制的时间片内，掉帧程度的分布情况及平均帧率，从而来评估出一个界面的整体流畅程度。
也就是说，一次掉帧可能掉了一帧、两帧或者更多帧（掉帧数），这里根据上表把一次掉帧划分为 Best/Normal/Middle/High/Frozen 五个级别，后续评价掉帧时就不再关注掉帧数而是 掉帧次数 及其严重级别
下图绿色的 62.00 FPS 指的是过去 200ms 内的平均帧率
灰色的 sum: 3.0 是总掉帧次数，下面的彩虹从左到右分别代表 Normal/Middle/High/Frozen 这四个级别的掉帧占总掉帧的比例，往下是当前页面的掉帧数和掉帧比例
最底下的图表是过去 10s 内平均帧率（200ms 时间段）的横向柱状图，每 5s 就会有 25 条记录，50 FPS 差不多是 Normal 的帧率下限，30 FPS 差不多是 Middle 的帧率下限
// 每帧的时间间隔，默认取 16ms（60 FPS）
public class UIThreadMonitor {
private long frameIntervalNanos = 16666666;
public void init(TraceConfig config) {
frameIntervalNanos = ReflectUtils.reflectObject(choreographer, "mFrameIntervalNanos", Constants.DEFAULT_FRAME_DURATION);
// ...
}
}
public class FrameTracer {
private final long frameIntervalNs; // UIThreadMonitor.getMonitor().getFrameIntervalNanos()
private void notifyListener(final String focusedActivity, final long startNs, final long endNs, final boolean isVsyncFrame,
final long intendedFrameTimeNs, final long inputCostNs, final long animationCostNs, final long traversalCostNs) {
long traceBegin = System.currentTimeMillis();
try {
final long jiter = endNs - intendedFrameTimeNs; // 从收到 vsync 到完成 doFrame 的时间，也就是实际渲染一帧的耗时
final int dropFrame = (int) (jiter / frameIntervalNs); // 计算出渲染这一帧对比理论 FPS 有没掉帧，掉了多少帧
// ...
}
}
}
public class FrameDecorator {
public void doFrameAsync(String focusedActivity, long startNs, long endNs, int dropFrame, boolean isVsyncFrame, long intendedFrameTimeNs, long inputCostNs, long animationCostNs, long traversalCostNs) {
super.doFrameAsync(focusedActivity, startNs, endNs, dropFrame, isVsyncFrame, intendedFrameTimeNs, inputCostNs, animationCostNs, traversalCostNs);
if (!Objects.equals(focusedActivity, lastVisibleScene)) { // 切换页面时，重置页面的统计数据
dropLevel = new int[FrameTracer.DropStatus.values().length];
lastVisibleScene = focusedActivity;
lastCost[0] = 0;
lastFrames[0] = 0;
}
// 为什么不是用 endNs ？
// 1，因为 doFrame 执行完还要等 surfacefling 在下一帧的时间点进行合成和显示，而不是 doFrame 后立即显示，所以要用 frameIntervalMs 的倍数
// 2，其次考虑用户无操作/页面静止的情况，主线程的任务队列为空，没有刷新页面，如果用设备时间 endNs 会导致计算出极低的错误 FPS
sumFrameCost += (dropFrame + 1) * frameIntervalMs;
sumFrames += 1;
float duration = sumFrameCost - lastCost[0]; // 距离上一次刷新 FPS 的时间间隔
if (dropFrame >= Constants.DEFAULT_DROPPED_FROZEN) { // 根据掉帧数，给发生的掉帧事故分级别统计
dropLevel[FrameTracer.DropStatus.DROPPED_FROZEN.index]++;
sumDropLevel[FrameTracer.DropStatus.DROPPED_FROZEN.index]++;
belongColor = frozenColor;
} else if (dropFrame >= Constants.DEFAULT_DROPPED_HIGH) {
dropLevel[FrameTracer.DropStatus.DROPPED_HIGH.index]++;
sumDropLevel[FrameTracer.DropStatus.DROPPED_HIGH.index]++;
if (belongColor != frozenColor) {
belongColor = highColor;
}
} // ...
long collectFrame = sumFrames - lastFrames[0]; // 200ms 内刷新了几帧
if (duration >= 200) { // 每隔 200ms 刷新一次 FPS
final float fps = Math.min(maxFps, 1000.f * collectFrame / duration); // 统计过去 200ms 的 FPS
updateView(view, fps, belongColor, dropLevel[FrameTracer.DropStatus.DROPPED_NORMAL.index], dropLevel[FrameTracer.DropStatus.DROPPED_MIDDLE.index] ...);
lastCost[0] = sumFrameCost;
lastFrames[0] = sumFrames;
// ...
}
}
}
public class EvilMethodTracer {
public void dispatchEnd(long beginNs, long cpuBeginMs, long endNs, long cpuEndMs, long token, boolean isVsyncFrame) {
long dispatchCost = (endNs - beginNs) / Constants.TIME_MILLIS_TO_NANO;
try {
if (dispatchCost >= evilThresholdMs) {
// ...
}
}
}
}
TraceCanary 把耗时超过 700ms 的 Message 作为 Evil Method 上报
无埋点插桩收集函数耗时
为了在捕捉到卡顿堆栈后，获取各个函数的执行耗时，需要对所有函数进行无埋点插桩，在函数执行前调用 MethodBeat.i，在函数执行后调用 MethodBeat.o
通过代理编译期间的任务 transformClassesWithDexTask，将全局 class 文件作为输入，利用 ASM 工具，高效地对所有 class 文件进行扫描及插桩
插桩过程有几个关键点：
- 选择在该编译任务执行时插桩，是因为
proguard操作是在该任务之前就完成的，意味着插桩时的class文件已经被混淆过的。而选择proguard之后去插桩，是因为如果提前插桩会造成部分方法不符合内联规则，没法在proguard时进行优化，最终导致程序方法数无法减少，从而引发方法数过大问题- 为了减少插桩量及性能损耗，通过遍历
class方法指令集，判断扫描的函数是否只含有PUT/READ FIELD等简单的指令，来过滤一些默认或匿名构造函数，以及get/set等简单不耗时函数- 针对界面启动耗时，因为要统计从
Activity.onCreate到Activity.onWindowFocusChange间的耗时，所以在插桩过程中需要收集应用内所有Activity的实现类，并覆盖onWindowFocusChange函数进行打点- 为了方便及高效记录函数执行过程，我们为每个插桩的函数分配一个独立 ID，在插桩过程中，记录插桩的函数签名及分配的 ID，在插桩完成后输出一份 mapping，作为数据上报后的解析支持。
归纳起来，编译期所做的工作如下图：
Gradle Transform
ignoreMethodMapFilePath 上面说过为了减少插桩量及性能损耗会忽略一些函数，这些被忽略的函数记录在此文件里（默认放在 /app/build/outputs/mapping/{var}/ignoreMethodMapping.txt），大概长这样：
ignore methods:
android.arch.core.executor.ArchTaskExecutor <clinit> ()V
android.arch.core.executor.ArchTaskExecutor <init> ()V
android.arch.core.executor.ArchTaskExecutor$1 execute (Ljava.lang.Runnable;)V
android.arch.core.executor.DefaultTaskExecutor executeOnDiskIO (Ljava.lang.Runnable;)V
android.arch.core.internal.FastSafeIterableMap <init> ()V
android.arch.core.internal.FastSafeIterableMap ceil (Ljava.lang.Object;)Ljava.util.Map$Entry;
android.arch.core.internal.SafeIterableMap size ()I
android.arch.core.internal.SafeIterableMap equals (Ljava.lang.Object;)Z
android.arch.core.internal.SafeIterableMap$AscendingIterator backward (Landroid.arch.core.internal.SafeIterableMap$Entry;)Landroid.arch.core.internal.SafeIterableMap$Entry;
android.arch.core.internal.SafeIterableMap$AscendingIterator forward (Landroid.arch.core.internal.SafeIterableMap$Entry;)Landroid.arch.core.internal.SafeIterableMap$Entry;
android.arch.core.internal.SafeIterableMap$AscendingIterator <init> (Landroid.arch.core.internal.SafeIterableMap$Entry;Landroid.arch.core.internal.SafeIterableMap$Entry;)V
methodMapFilePath 函数签名和函数 ID 的映射（默认放在 /app/build/outputs/mapping/{var}/methodMapping.txt），大概长这样：
1,1,sample.tencent.matrix.MainActivity$6 run ()V
2,10,sample.tencent.matrix.MatrixApplication initSQLiteLintConfig ()Lcom.tencent.sqlitelint.config.SQLiteLintConfig;
3,1,sample.tencent.matrix.MainActivity$5 onClick (Landroid.view.View;)V
4,1,sample.tencent.matrix.MainActivity$4 onClick (Landroid.view.View;)V
5,4,sample.tencent.matrix.MainActivity onResume ()V
6,1,sample.tencent.matrix.MatrixApplication onCreate ()V
7,1,sample.tencent.matrix.MainActivity$3 onClick (Landroid.view.View;)V
8,4,sample.tencent.matrix.MainActivity onCreate (Landroid.os.Bundle;)V
9,1,sample.tencent.matrix.MainActivity$2 onClick (Landroid.view.View;)V
10,1,org.apache.commons.io.comparator.DirectoryFileComparator compare (Ljava.io.File;Ljava.io.File;)I