Matrix 之 FrameTracer 源码分析

1,761 阅读7分钟

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 方法,但目前的源码来看,这两个方法没有实际上的作用。

分析

分析部分我们需要来拆解一下,分为如下几个部分:

  1. 注册 fps 监听
  2. Main Looper 设置 Printer
  3. 分发 Printer 的 begin 和 end 消息
  4. 计算帧率
  5. 上报

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
}