FrameTracer 是 TraceCanary 下的一个分析当前屏幕刷新率的子模块,并且还提供了自定义的 FrameDecorator 来实时显示当前的帧率情况。
这次我们先讲结论,再讲分析,主要是为了方便那些想直接看结论的读者。
结论
在实际的分析过程中,FrameTracer 的实现过程是:给主线程 Looper 设置 Printer,监听每个消息的 ">" 和 ”<“ 来识别每个消息的开始和结束所花费的时间,如果这个消息所花费的时间除以 16.6ms 在判断的区间状态内,则给这个状态进行累计加 1,并且累计花费的时间,区间状态有:
- frozen:阈值为 42
- high : 阈值为 24
- middle : 阈值为 9
- normal :阈值为 3
- best:阈值为小于 3
然后累计每个页面的消息所花费的时间,累计消息执行的次数,如果累计的消息时间大于周期 12s ,则会进行一次上报,上报的内容为每个阈值累计的次数和花费的时间,这样可以很简单的看出,当前页面的消息执行状态在不同的阈值所表现的状态。
在 FrameDecorator 中,为了实时显示当前 fps 的执行情况,他会以周期大于 200ms 的总消息时间进行一次帧率分析,并且同步给 FloatFrameView 进行展示,计算 fps 的公式为:
Math.min(60.f, 1秒 * 消息次数 / 消息总的花费时间);
增大分母的情况下,fps 值也就会越小,即意味着,消息执行的时间过长导致了帧率不够,造成卡顿。由于 fps 取的是平均值,所以,是会存在一定的 fps 实时性问题。
FrameTracer 采用的是给主线程的 Looper 设置 Printer 来监听消息执行时间,即意味着,凡是使用了主线程 Looper 的,都会被记录进去计算,包括我们自己创建的 Handler(Looper.getMainLooper()),即 FrameTrancer 统计的是 UI 操作和非 UI 操作的耗时。
在阅读源码时,也有一个比较有疑虑的地方,FrameTracer hook 了 Choreographer 的 mCallbackQueues 队列,插入了自定义的 CALLBACK_INPUT、CALLBACK_ANIMATION、CALLBACK_TRAVERSAL 回调,但我没有看到该回调的用处在哪,我所理解的是,FrameTracer 的作者可能在设计之初是想统计 UI 的耗时时间,我们可以在 UIThreadMonitor
中可以看到 doFrameBegin
和 doFrameEnd
方法,但目前的源码来看,这两个方法没有实际上的作用。
分析
分析部分我们需要来拆解一下,分为如下几个部分:
- 注册 fps 监听
- Main Looper 设置 Printer
- 分发 Printer 的 begin 和 end 消息
- 计算帧率
- 上报
1、注册 fps 监听
初始化 FrameTracer 时,构造方法就注册了实现 IDoFrameListener 的 FPSCollector 监听:
FrameTracer.java
public FrameTracer(TraceConfig config) {
...
if (isFPSEnable) {
addListener(new FPSCollector());
}
}
该监听会等待 Printer 开始分发消息时回调。
2、Main Looper 设置 Printer
Printer 的设置在 LooperMonitor 中 :
private static final LooperMonitor mainMonitor = new LooperMonitor();
public LooperMonitor(Looper looper) {
Objects.requireNonNull(looper);
this.looper = looper;
resetPrinter();
addIdleHandler(looper);
}
private LooperMonitor() {
this(Looper.getMainLooper());
}
addIdleHandler 方法会为自己注册一个 Handler message 空闲时的监听,他会以 1 分钟的周期来重置 resetPrinter。
resetPrinter 方法会 hook Looper 的 mLogging ,为其设置 LooperPrinter 对象:
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) {
...
}
looper.setMessageLogging(printer = new LooperPrinter(originPrinter));
...
}
3、分发 Printer 的 begin 和 end 消息
在设置好 LooperPrinter 后,LooperPrinter 的 println 方法就能收到 Main Looper 分发出来的消息:
class LooperPrinter implements Printer {
...
@Override
public void println(String x) {
// 移除无关紧要的代码
....
if (isValid) {
// 分发消息
dispatch(x.charAt(0) == '>', x);
}
}
}
// 分发 begin 和 end 消息
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();
}
}
}
dispatch 会识别 mLogging 的消息是开始还是结束,并将该结果回调给注册了 LooperDispatchListener 的监听,查找 listeners 的注册源时, 发现在 UIThreadMonitor 注册了该监听:
LooperMonitor.register(new LooperMonitor.LooperDispatchListener() {
@Override
public boolean isValid() {
return isAlive;
}
@Override
public void dispatchStart() {
super.dispatchStart();
UIThreadMonitor.this.dispatchBegin();
}
@Override
public void dispatchEnd() {
super.dispatchEnd();
UIThreadMonitor.this.dispatchEnd();
}
});
继续跟踪 UIThreadMonitor 的 dispatchBegin 和 dispatchEnd 方法:
private void dispatchBegin() {
// 记录消息开始时的时间戳,一个是手机启动的时间戳,一个是当前线程运行的时间戳
token = dispatchTimeMs[0] = SystemClock.uptimeMillis();
dispatchTimeMs[2] = SystemClock.currentThreadTimeMillis();
...
// 分发注册了 observers 的 LooperObserver 的监听
synchronized (observers) {
for (LooperObserver observer : observers) {
if (!observer.isDispatchBegin()) {
observer.dispatchBegin(dispatchTimeMs[0], dispatchTimeMs[2], token);
}
}
}
}
在 FrameTracer 启动时的 onAlive 方法中,有注册 observers 的监听:
@Override
public void onAlive() {
super.onAlive();
UIThreadMonitor.getMonitor().addObserver(this);
}
当前 FrameTracer 即是一个 LooperObserver,dispatchBegin 和 dispatchEnd 并没有去实现。
private void dispatchEnd() {
// 该处即是结论中疑虑的地方,具体的可以自己去看源码,
// isBelongFrame 为 true 时调用 doFrameBegin , 最后会设置 isBelongFrame 为 false
// doFrameBegin 为 input、animation、traversal 的 run 方法触发
//
if (isBelongFrame) {
doFrameEnd(token);
}
// token 即在 dispatchBegin 记录的开始时间戳
long start = token;
// 获取 dispatchEnd 时的时间戳
long end = SystemClock.uptimeMillis();
// 分发注册了 observers 的 LooperObserver 的监听
synchronized (observers) {
for (LooperObserver observer : observers) {
if (observer.isDispatchBegin()) {
observer.doFrame(AppMethodBeat.getVisibleScene(), token, SystemClock.uptimeMillis(), isBelongFrame ? end - start : 0, queueCost[CALLBACK_INPUT], queueCost[CALLBACK_ANIMATION], queueCost[CALLBACK_TRAVERSAL]);
}
}
}
...
// dispatchEnd 的分发
}
最终会分发所有注册了 observers 的 doFrame 方法,这几个参数需要说明一下:
- AppMethodBeat.getVisibleScene() : 当前 Activity 的类名称
- token : 消息分发之前的时间
- SystemClock.uptimeMillis() :消息分发结束的时间
- isBelongFrame ? end - start : 0 : isBelongFrame 一直为 false,所以该一直为 0
- 后面的三个 queueCost 就不说了,用不到
4、计算帧率
最终 FrameTracer 的 doFrame 方法会被回调:
@Override
public void doFrame(String focusedActivityName, long start, long end, long frameCostMs, long inputCostNs, long animationCostNs, long traversalCostNs) {
// ①、
if (isForeground()) {
notifyListener(focusedActivityName, end - start, frameCostMs, frameCostMs >= 0);
}
}
private void notifyListener(final String visibleScene, final long taskCostMs, final long frameCostMs, final boolean isContainsFrame) {
...
try {
synchronized (listeners) {
// ②、
for (final IDoFrameListener listener : listeners) {
...
// ③、
final int dropFrame = (int) (taskCostMs / frameIntervalMs);
// 同步计算帧率
listener.doFrameSync(visibleScene, taskCostMs, frameCostMs, dropFrame, isContainsFrame);
if (null != listener.getExecutor()) {
listener.getExecutor().execute(new Runnable() {
@Override
public void run() {
// ④、异步计算帧率
listener.doFrameAsync(visibleScene, taskCostMs, frameCostMs, dropFrame, isContainsFrame);
}
});
}
...
}
①:当应用在前台时,才计算帧率
②:分发注册 listeners 的 IDoFrameListener,在分析步骤 1 中,注册的 FPSCollector 即是 IDoFrameListener
③:计算 dropFrame,taskCostMs 为消息的结束时间戳减去开始时间戳,也就是一个 message 所花费的时间,frameIntervalMs 为 17 ms,则 dropFrame = 消息花费时间 / 17 ms,这个地方需要注意一下,dropFrame 是一个整型,则 dropFrame 是一个 17 的倍数
④:异步计算帧率,最终会走到 FPSCollector 的 doFrameAsync 方法,这个地方参数说明一下
- visibleScene : 当前 Activity 的类名称
- taskCostMs : 消息执行的时间
- frameCostMs :一直为 0
- dropFrame :消息花费时间 / 17 ms
- isContainsFrame :一直为 true
@Override
public void doFrameAsync(String visibleScene, long taskCost, long frameCostMs, int droppedFrames, boolean isContainsFrame) {
super.doFrameAsync(visibleScene, taskCost, frameCostMs, droppedFrames, isContainsFrame);
...
// 一个 Activity 对应一个 FrameCollectItem
FrameCollectItem item = map.get(visibleScene);
if (null == item) {
item = new FrameCollectItem(visibleScene);
map.put(visibleScene, item);
}
// 收集消息的累计时间 和 消息次数
item.collect(droppedFrames, isContainsFrame);
// 上报
...
}
上报部分我们在第五个步骤来讲,先把 collect 收集部分看一下:
void collect(int droppedFrames, boolean isContainsFrame) {
// ① 计算消息花费时间和消息次数
long frameIntervalCost = UIThreadMonitor.getMonitor().getFrameIntervalNanos();
sumFrameCost += (droppedFrames + 1) * frameIntervalCost / Constants.TIME_MILLIS_TO_NANO;
sumDroppedFrames += droppedFrames;
sumFrame++;
if (!isContainsFrame) {
sumTaskFrame++;
}
// ② 根据不同的阈值,设置当前消息的状态
if (droppedFrames >= frozenThreshold) {
dropLevel[DropStatus.DROPPED_FROZEN.index]++;
dropSum[DropStatus.DROPPED_FROZEN.index] += droppedFrames;
} else if (droppedFrames >= highThreshold) {
dropLevel[DropStatus.DROPPED_HIGH.index]++;
dropSum[DropStatus.DROPPED_HIGH.index] += droppedFrames;
} else if (droppedFrames >= middleThreshold) {
dropLevel[DropStatus.DROPPED_MIDDLE.index]++;
dropSum[DropStatus.DROPPED_MIDDLE.index] += droppedFrames;
} else if (droppedFrames >= normalThreshold) {
dropLevel[DropStatus.DROPPED_NORMAL.index]++;
dropSum[DropStatus.DROPPED_NORMAL.index] += droppedFrames;
} else {
dropLevel[DropStatus.DROPPED_BEST.index]++;
dropSum[DropStatus.DROPPED_BEST.index] += (droppedFrames < 0 ? 0 : droppedFrames);
}
}
①:计算消息花费时间和消息次数:
- frameIntervalCost 为 16666666 纳秒
- droppedFrames 为 单个消息花费时间 / 17 ms
- Constants.TIME_MILLIS_TO_NANO 为 1000000 纳秒
1、则每次累加的 sumFrameCost 的值为:
(单个消息花费时间 / 17 ms + 1) * 16666666 / 1000000
该公式代表的是:只要单个消息花费时间在 16ms 完成,则 sumFrameCost 得到的值就为 16ms,是一个正常的帧率
2、sumDroppedFrames 为累加 droppedFrames 的值
3、sumFrame 为消息执行的次数
②:根据不同的阈值,设置当前消息的状态
droppedFrames = 单个消息花费时间 / 17 ms ,则计算出来的阈值是在如下范围:
- frozenThreshold:阈值为 42
- highThreshold : 阈值为 24
- middleThreshold : 阈值为 9
- normalThreshold :阈值为 3
- DROPPED_BEST:阈值为小于 3
如果在其中的某个范围内,则 dropLevel 会累计一次当前的消息处于这个阈值 level,并且 dropSum 会累加 droppedFrames 值
5、上报
@Override
public void doFrameAsync(String visibleScene, long taskCost, long frameCostMs, int droppedFrames, boolean isContainsFrame) {
super.doFrameAsync(visibleScene, taskCost, frameCostMs, droppedFrames, isContainsFrame);
...
①、
if (item.sumFrameCost >= timeSliceMs) { // report
map.remove(visibleScene);
item.report();
}
...
}
void report() {
②、
float fps = Math.min(60.f, 1000.f * sumFrame / sumFrameCost);
JSONObject dropLevelObject = new JSONObject();
....
}
①:如果累计的帧时间超过 timeSliceMs(该值为 12s),则进行上报
②:计算出 1秒 内平均的 fps 值,并将 dropLevel 和 dropSum 等信息一起上报,上报的 json 串如下:
{
"machine": "BEST",
"cpu_app": 0,
"mem": 6000824320,
"mem_free": 1571584,
"scene": "sample.tencent.matrix.trace.TestTraceMainActivity",
"dropLevel": {
"DROPPED_FROZEN": 0,
"DROPPED_HIGH": 0,
"DROPPED_MIDDLE": 0,
"DROPPED_NORMAL": 3,
"DROPPED_BEST": 700
},
"dropSum": {
"DROPPED_FROZEN": 0,
"DROPPED_HIGH": 0,
"DROPPED_MIDDLE": 0,
"DROPPED_NORMAL": 13,
"DROPPED_BEST": 32
},
"fps": 58.5394287109375,
"dropTaskFrameSum": 0,
"tag": "Trace_FPS",
"process": "sample.tencent.matrix",
"time": 1578478298423
}