Android 性能优化系列 - 04 Matrix 中 TraceCanary 源码解析

字数 4300阅读 514

一.概述

在做 UI 性能优化的时候,很重要的一点就是需要做好优化前和优化后的对比,否则怎么判断自己的优化是否有效果,效果有多大呢?对比的话,个人认为可以分为两类,一类是通过观察直观的对比,另一类是通过数据客观的对比

直观对比,我们可以通过 开发者选项 中的 过渡绘制GPU 分析 查看页面中是否存在过渡绘制和 UI 渲染时的 GPU 渲染图

客观对比,我们可以通过各种测试工具分析、对比,比如网易的 Emmagee 、腾讯的 matrix 等等,很遗憾的是 Emmagee 在 Android 7.0 以上由于系统限制无法使用,所以我使用的是 matrix

做软件开发,不仅要知其然,而且要知其所以然,这样才能有更大的进步。我在做 UI 性能优化的时候,使用了 matrix 中的 TraceCanary 模块,它是功能主要是检测 UI 卡顿、启动耗时、页面切换和慢函数检测,这里主要分析一下其中的帧率是怎么计算的,其他功能的代码应该也不是很复杂,有兴趣的朋友可以自行分析

二.原理

从一开始做 Android 应用开发的时候,就经常听说不能在主线程中做耗时的操作(比如:IO 数据读取、网络请求等等),会造成 UI 卡顿等问题,因为主线程每 16.67 ms 就会渲染一帧,如果在主线程中有耗时的任务,可能在 16.67 ms 内无法渲染下一帧就会造成掉帧,而掉帧从视觉上来讲就是通常所说的卡顿了。虽然造成掉帧的原因有很多种,但是有两个变量是固定的:主线程和 16.67 ms,我们就可以通过这两个固定值入手,分析、判断主线程中是否存在卡顿

了解过 Android 性能优化的朋友可能都知道,业内主流的实现卡顿监控的思想,都是通过监控主线程中任务的耗时情况,如果任务耗时超过一定的阈值,则 dump 当前主线程的堆栈信息,就可以分析卡顿原因了,这两种思想的典型代表有 ArgusAPMBlockCanaryBlockCanaryEx 等。思想是这样的,实现的方式可以归为两类,一类是通过主线程的 Looper 机制,另一类是通过 Choreographer 模块,下面先简单介绍下这两种方式

2.1 Looper 机制

大家都知道在主线程中有一个 MainLooper,主线程启动以后就会调用 MainLooper#loop() 方法,主线程中执行的任务都会间接地在 ActivityThread 中的一个内部类 H(它是一个 Handler 的子类)的 handleMessage(Message msg) 来执行,我们分析一下 Looper.loop() 方法如下

  • 代码 1:Looper.loop() 方法中会有个 for(;;) 死循环不断地从 MessageQueue 中读取消息并处理
  • 代码 3:最终调用了 msg.target.dispatchMessage(msg) 来处理此 Message,而 msg.target 其实就是 Handler,它是指在 MainLooper 对应的所有的 Handler
  • 代码 2 & 代码 4:在处理消息前后,都会通过 myLooper().mLogging 得到的 Printer 对象,分别打印 >>>>> Dispatching to<<<<< Finished to
  • myLooper().mLogging 是可以通过 Looper.getMainLooper().setMessageLogging(Printer printer) 设置的

所以我们只需要判断 >>>>> Dispatching to<<<<< Finished to 这两个 log 之间的时间是否超出阈值,就可以判定此时主线程中执行的任务是否是耗时任务

public final class Looper {

    ......

        public static void loop() {
        final Looper me = myLooper();
        if (me == null) {
            throw new RuntimeException("No Looper; Looper.prepare() wasn't called on this thread.");
        }
        final MessageQueue queue = me.mQueue;

        // Make sure the identity of this thread is that of the local process,
        // and keep track of what that identity token actually is.
        Binder.clearCallingIdentity();
        final long ident = Binder.clearCallingIdentity();

        for (;;) {                                                           // 代码 1
            Message msg = queue.next(); // might block
            if (msg == null) {
                // No message indicates that the message queue is quitting.
                return;
            }

            // This must be in a local variable, in case a UI event sets the logger
            final Printer logging = me.mLogging;                             // 代码 2
            if (logging != null) {
                logging.println(">>>>> Dispatching to " + msg.target + " " +
                        msg.callback + ": " + msg.what);
            }

            final long slowDispatchThresholdMs = me.mSlowDispatchThresholdMs;

            final long traceTag = me.mTraceTag;
            if (traceTag != 0 && Trace.isTagEnabled(traceTag)) {
                Trace.traceBegin(traceTag, msg.target.getTraceName(msg));
            }
            final long start = (slowDispatchThresholdMs == 0) ? 0 : SystemClock.uptimeMillis();
            final long end;
            try {
                msg.target.dispatchMessage(msg);                            // 代码 3
                end = (slowDispatchThresholdMs == 0) ? 0 : SystemClock.uptimeMillis();
            } finally {
                if (traceTag != 0) {
                    Trace.traceEnd(traceTag);
                }
            }

            if (logging != null) {                                          // 代码 4
                logging.println("<<<<< Finished to " + msg.target + " " + msg.callback);
            }

                    ......
        }
    }

    ......

}

示意代码如下

Looper.getMainLooper().setMessageLogging(new Printer() {

        private static final String START = ">>>>> Dispatching";
        private static final String END = "<<<<< Finished";

                @Override
        public void println(String x) {
                if (x.startsWith(">>>>> Dispatching")) {
                                ......       // 开始记录                    
            }
            if (x.startsWith("<<<<< Finished")) {
                                ......       // 结束记录,判断处理时间间隔是否超过阈值
            }
        }
});

2.2 Choreographer 模块

Android 系统每隔 16.67 ms 都会发送一个 VSYNC 信号触发 UI 的渲染,正常情况下两个 VSYNC 信号之间是 16.67 ms ,如果超过 16.67 ms 则可以认为渲染发生了卡顿

Android SDK 中的 Choreographer 类中的 FrameCallback.doFrame(long l) 在每次发送 VSYNC 信号的时候都会被回调,所以我们只需要判断相邻的两次 FrameCallback.doFrame(long l) 间隔是否超过阈值,如果超过阈值则发生了卡顿,则可以在另外一个子线程中 dump 当前主线程的堆栈信息进行分析

示意代码如下所示,需要注意的是,在 FrameCallback.doFrame(long l) 回调方法中,我们每次都需要重新注册回调 Choreographer.getInstance().postFrameCallback(this)

Choreographer.getInstance()
            .postFrameCallback(new Choreographer.FrameCallback() {
                @Override
                public void doFrame(long l) {
                     if(frameTimeNanos - mLastFrameNanos > 100) {
                        ...
                     }
                     mLastFrameNanos = frameTimeNanos;
                     Choreographer.getInstance().postFrameCallback(this);
                }
        });

2.3 Matrix-TraceCanary 的实现方式

判断 UI 中是否存在卡顿大概可以分为以上两种实现方式

在 Matrix 的 TraceCanary 模块中,旧版本使用的是 Choreographer
的方式,但是新版本中使用的是 Looper 机制了,至于为什么会有这种差异,暂时还不清楚

不过使用 Looper 机制实现的方式存在一个缺点:在打印消息处理开始日志和消息处理结束日志的时候,都会进行字符串的拼接,频繁地进行字符串的拼接也会影响性能

image1.png

issue 地址

三.源码解析

这里分析 Matrix 和 TraceCanary 是 0.5.2 版本

既然已经知道了它的实现原理,我们就直捣黄龙,去寻找和 Looper.getMainLooper().setMessageLogging() 相关的代码,顺藤摸瓜,这样顺着分析会更清晰一些。

Matrix 和 TraceCanary 的目录结构如下图所示

image2.png

3.1 向 Looper 添加 Printer

上图中被选中的 LooperMonitor 类就是我们入手的类,其中通过调用 Looper.getMainLooper().setMessageLogging() 方法添加了一个 Printer 对象,代码如下所示

  • 代码 1:LooperMonitor 的构造方法是私有的,且有一个静态的 final 对象 LooperMonitor monitor

  • 代码 2 & 代码 3:LooperMonitor 实现了 MessageQueue.IdleHandler 接口及其抽象方法 queueIdle(),并且在构造方法中根据版本差异使用不同的方法将此 MessageQueue.IdleHandler 实例对象添加到 MessageQueue 中,queueIdle() 方法返回 true 保证消息队列中的每个消息处理完以后,都会回调 queueIdle() 方法

  • 代码 4:在构造方法和 queueIdle() 方法中会调用 resetPrinter() 方法,其中才是真正通过 Looper.getMainLooper().setMessageLogging() 设置 Printer 的地方

    在每次添加前,都会通过反射得到当前 Looper.getMainLooper() 设置的 mLogging 对象,并判断是不是之前被 LooperMonitor 设置的,如果 Looper.getMainLooper() 中的 mLogging 对象是被 LooperMonitor 设置的,则不会再次设置,否则会为 Looper.getMainLooper() 设置自己的 Printer 对象

  • 代码 5:在 Printer.println(String x) 中,会根据传入的参数 String x 的第一个字符判断是否是有效的 Looper.loop() 日志,以 > 开头的则是消息处理开始的日志,以 > 开头的则是消息处理结束的日志,最终会调用 dispatch(boolean isBegin) 方法

public class LooperMonitor implements MessageQueue.IdleHandler {
    private static final HashSet<LooperDispatchListener> listeners = new HashSet<>();
    private static Printer printer;

    private static final LooperMonitor monitor = new LooperMonitor();                           // 代码 1

    private LooperMonitor() {                                                                                                           // 代码 2
        resetPrinter();

        if (Build.VERSION.SDK_INT >= Build.VERSION_CODES.M) {
            Looper.getMainLooper().getQueue().addIdleHandler(this);
        } else {
            MessageQueue queue = reflectObject(Looper.getMainLooper(), "mQueue");
            queue.addIdleHandler(this);
        }
    }

    @Override
    public boolean queueIdle() {                                                                                                    // 代码 3
        resetPrinter();
        return true;
    }

    private static void resetPrinter() {                                                                                    // 代码 4
        final Printer originPrinter = reflectObject(Looper.getMainLooper(), "mLogging");
        if (originPrinter == printer && null != printer) {
            return;
        }
        if (null != printer) {
            MatrixLog.w(TAG, "[resetPrinter] maybe looper printer was replace other!");
        }
        Looper.getMainLooper().setMessageLogging(printer = new Printer() {        // 代码 5
            boolean isHasChecked = false;
            boolean isValid = false;

            @Override
            public void println(String x) {
                if (null != originPrinter) {
                    originPrinter.println(x);
                }

                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) == '>');
                }

            }
        });
    }

}

已经监听到了 Looper.loop() 消息处理的开始和结束,接下来看下在消息处理开始和结束时是怎么处理的,主要看 dispatch(boolean isBegin) 方法

  • dispatch(boolean isBegin) 中,会依次处理添加到 LooperMonitor 中的 LooperDispatchListener 监听回调
  • 代码 1:dispatch(boolean isBegin) 方法中会根据参数 boolean isBeginlistener.isValid() 以及 listener.isHasDispatchStart 条件执行 listener.dispatchStart()listener.dispatchEnd() 方法,具体的在消息处理开始和结束时做什么,都在 listener.dispatchStart()listener.dispatchEnd() 中实现
  • 代码 2:这行代码,个人理解的就是要站好最后一班岗的意思,当 listener.isValid() == false && isBegin == false && listener.isHasDispatchStart == true 时最后调用一次 listener.dispatchEnd() 方法
  • 代码 3:可以通过 LooperMonitor.register(LooperDispatchListener listener) 方法向 LooperMonitor 中设置 LooperDispatchListener listener,接下来我们看下在哪儿调用这个方法设置LooperDispatchListener listener 监听的,就可以看到消息处理开始和结束时都有哪些具体的逻辑了
public class LooperMonitor implements MessageQueue.IdleHandler {

    private static final HashSet<LooperDispatchListener> listeners = new HashSet<>();     

    ......

    public abstract static class LooperDispatchListener {

        boolean isHasDispatchStart = false;

        boolean isValid() {
            return false;
        }

        @CallSuper
        void dispatchStart() {
            this.isHasDispatchStart = true;
        }

        @CallSuper
        void dispatchEnd() {
            this.isHasDispatchStart = false;
        }
    }

    ......

    public static void register(LooperDispatchListener listener) {                          // 代码 3         
        synchronized (listeners) {
            listeners.add(listener);
        }
    }

    private static void dispatch(boolean isBegin) {                                                                             

        for (LooperDispatchListener listener : listeners) {                       
            if (listener.isValid()) {                                                                                         // 代码 1
                if (isBegin) {
                    if (!listener.isHasDispatchStart) {
                        listener.dispatchStart();
                    }
                } else {
                    if (listener.isHasDispatchStart) {
                        listener.dispatchEnd();
                    }
                }
            } else if (!isBegin && listener.isHasDispatchStart) {                 // 代码 2
                listener.dispatchEnd();
            }
        }

    }  

    ......

}

3.2 消息处理

如下图所示,在 trace-canary 模块中有 AppMethodBeatUIThreadMonitor 两个类通过 LooperMonitor.register(LooperDispatchListener listener) 方法向 LooperMonitor 中设置 LooperDispatchListener listener,和本文相关的是 UIThreadMonitor 类,重点分析下这个类

image3.png

首先分析下 UIThreadMonitor 类的初始化方法,其中主要是通过反射拿到了 Choreographer 一些属性,并且通过 LooperMonitor.register(LooperDispatchListener listener) 方法向 LooperMonitor 中设置 LooperDispatchListener listener

  • 代码 1:通过反射拿到了 Choreographer 实例的 mCallbackQueues 属性,mCallbackQueues 是一个回调队列数组 CallbackQueue[] mCallbackQueues,其中包括四个回调队列,第一个是输入事件回调队列 CALLBACK_INPUT = 0,第二个是动画回调队列 CALLBACK_ANIMATION = 1,第三个是遍历绘制回调队列 CALLBACK_TRAVERSAL = 2,第四个是提交回调队列 CALLBACK_COMMIT = 3。这四个阶段在每一帧的 UI 渲染中是依次执行的,每一帧中各个阶段开始时都会回调 mCallbackQueues 中对应的回调队列的回调方法。关于 Choreographer 的文章推荐这篇 Android Choreographer 源码分析
  • 代码 2:通过反射拿到输入事件回调队列的 addCallbackLocked 方法
  • 代码 3:通过反射拿到动画回调队列的 addCallbackLocked 方法
  • 代码 4:通过反射拿到遍历绘制回调队列的addCallbackLocked 方法
  • 代码 5:通过 LooperMonitor.register(LooperDispatchListener listener) 方法向 LooperMonitor 中设置 LooperDispatchListener listener
  • 代码 6:在 Looper.loop() 中的消息处理开始时的回调
  • 代码 7:在 Looper.loop() 中的消息处理结束时的回调
public class UIThreadMonitor implements BeatLifecycle, Runnable {
    private static final String ADD_CALLBACK = "addCallbackLocked";

    public static final int CALLBACK_INPUT = 0;
    public static final int CALLBACK_ANIMATION = 1;
    public static final int CALLBACK_TRAVERSAL = 2;

    private final static UIThreadMonitor sInstance = new UIThreadMonitor();
    private Object callbackQueueLock;
    private Object[] callbackQueues;
    private Method addTraversalQueue;
    private Method addInputQueue;
    private Method addAnimationQueue;
    private Choreographer choreographer;
    private long frameIntervalNanos = 16666666;

    ......

    public static UIThreadMonitor getMonitor() {
        return sInstance;
    }

    public void init(TraceConfig config) {
        if (Thread.currentThread() != Looper.getMainLooper().getThread()) {
            throw new AssertionError("must be init in main thread!");
        }
        this.isInit = true;
        this.config = config;
        choreographer = Choreographer.getInstance();
        callbackQueueLock = reflectObject(choreographer, "mLock");              
        callbackQueues = reflectObject(choreographer, "mCallbackQueues");                                                                    // 代码 1

        addInputQueue = reflectChoreographerMethod(callbackQueues[CALLBACK_INPUT], ADD_CALLBACK, long.class, Object.class, Object.class);             // 代码 2
        addAnimationQueue = reflectChoreographerMethod(callbackQueues[CALLBACK_ANIMATION], ADD_CALLBACK, long.class, Object.class, Object.class);     // 代码 3
        addTraversalQueue = reflectChoreographerMethod(callbackQueues[CALLBACK_TRAVERSAL], ADD_CALLBACK, long.class, Object.class, Object.class);     // 代码 4  
        frameIntervalNanos = reflectObject(choreographer, "mFrameIntervalNanos");

        LooperMonitor.register(new LooperMonitor.LooperDispatchListener() {                                                                  // 代码 5  
            @Override
            public boolean isValid() {
                return isAlive;
            }

            @Override
            public void dispatchStart() {
                super.dispatchStart();
                UIThreadMonitor.this.dispatchBegin();                                                                                       // 代码 6
            }

            @Override
            public void dispatchEnd() {
                super.dispatchEnd();
                UIThreadMonitor.this.dispatchEnd();                                                                                      // 代码 7
            }

        });

                ......

    }  
}

在 3.1 节就讲过,在 Looper 处理消息开始和结束时,分别会回调 LooperDispatchListener 的 dispatchStart()dispatchEnd() 方法,也就是如上代码所示的 代码6 和 代码7 处

dispatchStart() 方法相对简单,其中调用了 UIThreadMonitor.this.dispatchBegin() 记录两个起始时间,一个是线程起始时间,另一个是 cpu 起始时间,并且依次回调 LooperObserver#dispatchBegin() 方法,如下所示

public class UIThreadMonitor implements BeatLifecycle, Runnable {
        private long[] dispatchTimeMs = new long[4];
    private volatile long token = 0L;

    ......

    private void dispatchBegin() {
        token = dispatchTimeMs[0] = SystemClock.uptimeMillis();
        dispatchTimeMs[2] = SystemClock.currentThreadTimeMillis();
        AppMethodBeat.i(AppMethodBeat.METHOD_ID_DISPATCH);

        synchronized (observers) {
            for (LooperObserver observer : observers) {
                if (!observer.isDispatchBegin()) {
                    observer.dispatchBegin(dispatchTimeMs[0], dispatchTimeMs[2], token);
                }
            }
        }
    }  

    ......

}

dispatchEnd() 方法相对复杂一些,根据变量 isBelongFrame 判断是否调用 doFrameEnd(long token),然后记录线程结束时间和 cpu 结束时间,最终回调 LooperObserver#dispatchEnd() 方法

  • 代码 1,在 UIThreadMonitor 中有两个长度是三的数组 queueStatusqueueCost 分别对应着每一帧中输入事件阶段、动画阶段、遍历绘制阶段的状态和耗时,queueStatus 有三个值:DO_QUEUE_DEFAULT、DO_QUEUE_BEGIN 和 DO_QUEUE_END
  • 代码 2,变量 isBelongFrame 初始值是 false,是在 doFrameBegin(long token) 方法中将其置位 true 的,doFrameBegin(long token) 是在 run() 方法中被调用的,UIThreadMonitor 实现了 Runnable 接口,自然重写了 run() 方法,那么 UIThreadMonitor 对象是什么时候被线程执行的呢?下面再分析
  • 代码 3,在消息处理结束时,会调用 dispatchEnd() 方法,其中根据变量 isBelongFrame 判断是否调用 doFrameEnd(long token)
  • 代码 4,在 run() 方法中,首先会调用 doFrameBegin(long token) 将变量 isBelongFrame 设置为 true,然后通过 doQueueBegin() 方法记录输入事件回调 CALLBACK_INPUT 开始的状态和时间;之后又通过 addFrameCallback() 方法为 Choreographer 设置动画回调 CALLBACK_ANIMATION 和遍历绘制回调 CALLBACK_TRAVERSAL 的回调方法
  • 代码 5,在动画回调 CALLBACK_ANIMATION 的回调方法 run() 中,记录 CALLBACK_INPUT 的结束的状态和时间,同时也记录 CALLBACK_ANIMATION 的开始状态和时间
  • 代码 6,在遍历绘制 CALLBACK_TRAVERSAL 的回调方法 run() 中,记录 CALLBACK_ANIMATION 的结束状态和时间,同时也记录 CALLBACK_TRAVERSAL 的开始状态和时间
  • 其实这里已经可以猜测到 UIThreadMonitor 实现 Runnable 接口,也是为了将 UIThreadMonitor 作为输入事件回调 CALLBACK_INPUT 的回调方法,设置到 Choreographer 中去的
public class UIThreadMonitor implements BeatLifecycle, Runnable {
    public static final int CALLBACK_INPUT = 0;
    public static final int CALLBACK_ANIMATION = 1;
    public static final int CALLBACK_TRAVERSAL = 2;
    private static final int CALLBACK_LAST = CALLBACK_TRAVERSAL;

    private boolean isBelongFrame = false;
    private int[] queueStatus = new int[CALLBACK_LAST + 1];                                   // 代码 1                               
    private long[] queueCost = new long[CALLBACK_LAST + 1];

    private static final int DO_QUEUE_DEDO_QUEUE_DEFAULT、FAULT = 0;
    private static final int DO_QUEUE_BEGIN = 1;
    private static final int DO_QUEUE_END = 2;

    private void doFrameBegin(long token) {                                                                 // 代码 2
        this.isBelongFrame = true;
    }

    private void dispatchEnd() {                                                                                            // 代码 3
        if (isBelongFrame) {
            doFrameEnd(token);
        }

        dispatchTimeMs[3] = SystemClock.currentThreadTimeMillis();
        dispatchTimeMs[1] = SystemClock.uptimeMillis();

        AppMethodBeat.o(AppMethodBeat.METHOD_ID_DISPATCH);

        synchronized (observers) {
            for (LooperObserver observer : observers) {
                if (observer.isDispatchBegin()) {
                    observer.dispatchEnd(dispatchTimeMs[0], dispatchTimeMs[2], dispatchTimeMs[1], dispatchTimeMs[3], token, isBelongFrame);
                }
            }
        }

    }  

    @Override
    public void run() {                                                                                                             // 代码 4
        final long start = System.nanoTime();
        try {
            doFrameBegin(token);                                                                                            // 将 isBelongFrame 置位 true                              
            doQueueBegin(CALLBACK_INPUT);                                                                           // 通过 doQueueBegin(int type) 记录输入事件回调 CALLBACK_INPUT 开始状态和时间

            addFrameCallback(CALLBACK_ANIMATION, new Runnable() {                           // 通过 addFrameCallback() 方法向 Choreographer 中添加动画 CALLBACK_ANIMATION 回调 
                                                                                                                                                            // 每个回调其实都是一个 Runnable,执行时会主动调用 `run()` 方法
                @Override
                public void run() {                                                                                     // 代码 5
                    doQueueEnd(CALLBACK_INPUT);                                                             // 输入事件回调 CALLBACK_INPUT 结束
                    doQueueBegin(CALLBACK_ANIMATION);                                                   // 动画回调 CALLBACK_ANIMATION 开始
                }
            }, true);

            addFrameCallback(CALLBACK_TRAVERSAL, new Runnable() {                           // 通过 addFrameCallback() 方法向 Choreographer 中添加遍历绘制 CALLBACK_TRAVERSAL 回调

                @Override
                public void run() {                                                                                     // 代码 6
                    doQueueEnd(CALLBACK_ANIMATION);                                                     // 动画回调 CALLBACK_ANIMATION 结束
                    doQueueBegin(CALLBACK_TRAVERSAL);                                                   // 遍历绘制回调 CALLBACK_TRAVERSAL 开始
                }
            }, true);

        } finally {
            if (config.isDevEnv()) {
                MatrixLog.d(TAG, "[UIThreadMonitor#run] inner cost:%sns", System.nanoTime() - start);
            }
        }
    }

    private synchronized void addFrameCallback(int type, Runnable callback, boolean isAddHeader) {

        if (callbackExist[type]) {
            MatrixLog.w(TAG, "[addFrameCallback] this type %s callback has exist!", type);
            return;
        }

        if (!isAlive && type == CALLBACK_INPUT) {
            MatrixLog.w(TAG, "[addFrameCallback] UIThreadMonitor is not alive!");
            return;
        }
        try {
            synchronized (callbackQueueLock) {
                Method method = null;
                switch (type) {
                    case CALLBACK_INPUT:
                        method = addInputQueue;
                        break;
                    case CALLBACK_ANIMATION:
                        method = addAnimationQueue;
                        break;
                    case CALLBACK_TRAVERSAL:
                        method = addTraversalQueue;
                        break;
                }
                if (null != method) {
                    method.invoke(callbackQueues[type], !isAddHeader ? SystemClock.uptimeMillis() : -1, callback, null);
                    callbackExist[type] = true;
                }
            }
        } catch (Exception e) {
            MatrixLog.e(TAG, e.toString());
        }
    }

    private void doQueueBegin(int type) {
        queueStatus[type] = DO_QUEUE_BEGIN;
        queueCost[type] = System.nanoTime();
    }

    private void doQueueEnd(int type) {
        queueStatus[type] = DO_QUEUE_END;
        queueCost[type] = System.nanoTime() - queueCost[type];
        synchronized (callbackExist) {
            callbackExist[type] = false;
        }
    }

    ......

}

接下来看下,是什么时候将输入事件回调 CALLBACK_INPUT 设置进 Choreographer 中去的

image4.png

如上图所示,addFrameCallback() 方法除了添加动画回调 CALLBACK_ANIMATION 和遍历绘制回调 CALLBACK_TRAVERSAL,有两处添加了 CALLBACK_INPUT 回调,分别是下面两处

  • 代码 1,首次调用 UIThreadMonitor#onStart() 方法时会调用一次 addFrameCallback(CALLBACK_INPUT, this, true) 方法,将此 Runnable 作为输入事件 CALLBACK_INPUT 的回调添加进 Choreographyer 中
  • 代码 2,在 doFrameEnd(long token) 方法中,每一帧完成以后也会调用一次 addFrameCallback(CALLBACK_INPUT, this, true) 方法,再次添加以供下一帧回调这三个回调。 doFrameEnd(long token) 方法是在处理消息结束时的 dispatchEnd() 方法中回调的
  • 代码 3,在上面的代码分析中,最后只调用了 doQueueBegin(CALLBACK_TRAVERSAL),在 doFrameEnd(long token) 方法中调用了 doQueueEnd(CALLBACK_TRAVERSAL),完成了遍历绘制回调 CALLBACK_TRAVERSAL 的监听
  • 代码 4,新创建一个长度为 3 的数组并赋值给 queueStatus,其实这里有一个疑问,doFrameEnd(long token) 方法在每一帧绘制的时候都会被回调,在这个方法中创建数组对象,会不会造成内存抖动
  • 代码 5,遍历 LooperObserver 的 HashSet 对象,回调其 doFrame(String focusedActivityName, long start, long end, long frameCostMs, long inputCostNs, long animationCostNs, long traversalCostNs) 方法,其中会将输入事件、动画、遍历绘制的耗时作为参数传入
public class UIThreadMonitor implements BeatLifecycle, Runnable {

    @Override
    public synchronized void onStart() {
        if (!isInit) {
            throw new RuntimeException("never init!");
        }
        if (!isAlive) {
            MatrixLog.i(TAG, "[onStart] %s", Utils.getStack());
            this.isAlive = true;
            addFrameCallback(CALLBACK_INPUT, this, true);                                           // 代码 1
        }
    }

    private void doFrameEnd(long token) {

        doQueueEnd(CALLBACK_TRAVERSAL);                                                                             // 代码 3

        for (int i : queueStatus) {
            if (i != DO_QUEUE_END) {
                queueCost[i] = DO_QUEUE_END_ERROR;
                if (config.isDevEnv) {
                    throw new RuntimeException(String.format("UIThreadMonitor happens type[%s] != DO_QUEUE_END", i));
                }
            }
        }
        queueStatus = new int[CALLBACK_LAST + 1];                                                     // 代码 4

        long start = token;
        long end = SystemClock.uptimeMillis();
        synchronized (observers) {                                                                                  // 代码 5
            for (LooperObserver observer : observers) {
                if (observer.isDispatchBegin()) {
                    observer.doFrame(AppMethodBeat.getFocusedActivity(), start, end, end - start, queueCost[CALLBACK_INPUT], queueCost[CALLBACK_ANIMATION], queueCost[CALLBACK_TRAVERSAL]);
                }
            }
        }

        addFrameCallback(CALLBACK_INPUT, this, true);                                               // 代码 2

        this.isBelongFrame = false;
    }  
}

3.3 帧率计算

从上面代码,可以看到最后会将每一帧的时间信息通过 HashSet<LooperObserver> observers 回调出去,看一下是在哪里向 observers 添加 LooperObserver 回调的,如下图所示

这里主要看一下 FrameTracer 这个类,其中涉及到了帧率 FPS 的计算,其他的类有兴趣的朋友可以自己分析

image5.png

FrameTracer 的代码如下所示,我相信仔细看看并不难懂,主要逻辑在 notifyListener(final String focusedActivityName, final long frameCostMs) 方法中,其中涉及到一个变量 frameIntervalMs = 16.67 ms

  • 代码 1:会遍历 HashSet<IDoFrameListener> listeners,并根据 doFrame() 中传入的 long frameCost 时间计算掉帧个数,最后将 frameCostMsdropFrame 通过 IDoFrameListener 接口中的两个方法回调出去
  • 掉帧个数是通过:final int dropFrame = (int) (frameCostMs / frameIntervalMs) 计算的,frameCostMs 是这一帧绘制的耗时,frameIntervalMs 其实就是 16.67ms
public class FrameTracer extends Tracer {
    private final long frameIntervalMs;

    private HashSet<IDoFrameListener> listeners = new HashSet<>();

     public FrameTracer(TraceConfig config) {
        this.frameIntervalMs = TimeUnit.MILLISECONDS.convert(UIThreadMonitor.getMonitor().getFrameIntervalNanos(), TimeUnit.NANOSECONDS) + 1;
        ......
    }

    public void addListener(IDoFrameListener listener) {
        synchronized (listeners) {
            listeners.add(listener);
        }
    }

    public void removeListener(IDoFrameListener listener) {
        synchronized (listeners) {
            listeners.remove(listener);
        }
    }

    @Override
    public void onAlive() {
        super.onAlive();
        UIThreadMonitor.getMonitor().addObserver(this);
    }

    @Override
    public void onDead() {
        super.onDead();
        UIThreadMonitor.getMonitor().removeObserver(this);
    }

    @Override
    public void doFrame(String focusedActivityName, long start, long end, long frameCostMs, long inputCostNs, long animationCostNs, long traversalCostNs) {
        notifyListener(focusedActivityName, frameCostMs);
    }  

    private void notifyListener(final String focusedActivityName, final long frameCostMs) {
        long start = System.currentTimeMillis();
        try {
            synchronized (listeners) {
                for (final IDoFrameListener listener : listeners) {
                    final int dropFrame = (int) (frameCostMs / frameIntervalMs);                                // 代码 1
                    listener.doFrameSync(focusedActivityName, frameCostMs, dropFrame);
                    if (null != listener.getHandler()) {
                        listener.getHandler().post(new Runnable() {
                            @Override
                            public void run() {
                                listener.doFrameAsync(focusedActivityName, frameCostMs, dropFrame);
                            }
                        });
                    }
                }
            }
        } finally {
            long cost = System.currentTimeMillis() - start;
            if (config.isDevEnv()) {
                MatrixLog.v(TAG, "[notifyListener] cost:%sms", cost);
            }
            if (cost > frameIntervalMs) {
                MatrixLog.w(TAG, "[notifyListener] warm! maybe do heavy work in doFrameSync,but you can replace with doFrameAsync! cost:%sms", cost);
            }
            if (config.isDebug() && !isForeground()) {
                backgroundFrameCount++;
            }
        }
    }  
}

看一下在哪些地方调用 addListener(IDoFrameListener listener) 向 FrameTracer 中添加了 IDoFrameListener,如下图所示,主要有两个地方:FrameDecorator 和 FrameTracer,这两个地方的逻辑其实差不多,主要看一下 addListener(new FPSCollector());

image6.png

FPSCollectorFrameTracer 的一个内部类,实现了 IDoFrameListener 接口,主要逻辑是在 doFrameAsync() 方法中

  • 代码 1:会根据当前 ActivityName 创建一个对应的 FrameCollectItem 对象,存放在 HashMap 中
  • 代码 2:调用 FrameCollectItem#collect(),计算帧率 FPS 等一些信息
  • 代码 3:如果此 Activity 的绘制总时间超过 timeSliceMs(默认是 10s),则调用 FrameCollectItem#report() 上报统计数据,并从 HashMap 中移除当前 ActivityName 和对应的 FrameCollectItem 对象
    private class FPSCollector extends IDoFrameListener {

        private Handler frameHandler = new Handler(MatrixHandlerThread.getDefaultHandlerThread().getLooper());
        private HashMap<String, FrameCollectItem> map = new HashMap<>();

        @Override
        public Handler getHandler() {
            return frameHandler;
        }

        @Override
        public void doFrameAsync(String focusedActivityName, long frameCost, int droppedFrames) {
            super.doFrameAsync(focusedActivityName, frameCost, droppedFrames);
            if (Utils.isEmpty(focusedActivityName)) {
                return;
            }

            FrameCollectItem item = map.get(focusedActivityName);       // 代码 1
            if (null == item) {
                item = new FrameCollectItem(focusedActivityName);
                map.put(focusedActivityName, item);
            }

            item.collect(droppedFrames);                                                                // 代码 2

            if (item.sumFrameCost >= timeSliceMs) { // report                       // 代码 3
                map.remove(focusedActivityName);
                item.report();
            }
        }

    }

FrameCollectItem 也是 FrameTracer 的一个内部类,其中最重要的是两个方法 collect(int droppedFrames)report() 方法

  • 代码 1:将每一帧的耗时相加,sumFrameCost 代表总耗时
  • 代码 2:sumDroppedFrames 统计总的掉帧个数
  • 代码 3:sumFrame 表示总帧数
  • 代码 4:根据掉帧的个数,判断此次掉帧行为属于哪个程度区间并记录其个数
  • 代码 5:根据 float fps = Math.min(60.f, 1000.f * sumFrame / sumFrameCost) 计算 fps 值
  • 代码 6:将统计得到的信息封装到一个 Issue 对象中,并通过 TracePlugin#onDetectIssue() 方法回调出去
    private class FrameCollectItem {
        String focusedActivityName;
        long sumFrameCost;
        int sumFrame = 0;
        int sumDroppedFrames;
        // record the level of frames dropped each time
        int[] dropLevel = new int[DropStatus.values().length];
        int[] dropSum = new int[DropStatus.values().length];

        FrameCollectItem(String focusedActivityName) {
            this.focusedActivityName = focusedActivityName;
        }

        void collect(int droppedFrames) {
            long frameIntervalCost = UIThreadMonitor.getMonitor().getFrameIntervalNanos();
            sumFrameCost += (droppedFrames + 1) * frameIntervalCost / Constants.TIME_MILLIS_TO_NANO;            // 代码 1
            sumDroppedFrames += droppedFrames;                                                                                                                      // 代码 2
            sumFrame++;                                                                                                                                                                     // 代码 3

            if (droppedFrames >= frozenThreshold) {                                                                                                             // 代码 4
                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);
            }
        }

        void report() {
            float fps = Math.min(60.f, 1000.f * sumFrame / sumFrameCost);                                                                           // 代码 5
            MatrixLog.i(TAG, "[report] FPS:%s %s", fps, toString());

            try {
                TracePlugin plugin = Matrix.with().getPluginByClass(TracePlugin.class);                                             // 代码 6
                JSONObject dropLevelObject = new JSONObject();
                dropLevelObject.put(DropStatus.DROPPED_FROZEN.name(), dropLevel[DropStatus.DROPPED_FROZEN.index]);
                dropLevelObject.put(DropStatus.DROPPED_HIGH.name(), dropLevel[DropStatus.DROPPED_HIGH.index]);
                dropLevelObject.put(DropStatus.DROPPED_MIDDLE.name(), dropLevel[DropStatus.DROPPED_MIDDLE.index]);
                dropLevelObject.put(DropStatus.DROPPED_NORMAL.name(), dropLevel[DropStatus.DROPPED_NORMAL.index]);
                dropLevelObject.put(DropStatus.DROPPED_BEST.name(), dropLevel[DropStatus.DROPPED_BEST.index]);

                JSONObject dropSumObject = new JSONObject();
                dropSumObject.put(DropStatus.DROPPED_FROZEN.name(), dropSum[DropStatus.DROPPED_FROZEN.index]);
                dropSumObject.put(DropStatus.DROPPED_HIGH.name(), dropSum[DropStatus.DROPPED_HIGH.index]);
                dropSumObject.put(DropStatus.DROPPED_MIDDLE.name(), dropSum[DropStatus.DROPPED_MIDDLE.index]);
                dropSumObject.put(DropStatus.DROPPED_NORMAL.name(), dropSum[DropStatus.DROPPED_NORMAL.index]);
                dropSumObject.put(DropStatus.DROPPED_BEST.name(), dropSum[DropStatus.DROPPED_BEST.index]);

                JSONObject resultObject = new JSONObject();
                resultObject = DeviceUtil.getDeviceInfo(resultObject, plugin.getApplication());

                resultObject.put(SharePluginInfo.ISSUE_SCENE, focusedActivityName);
                resultObject.put(SharePluginInfo.ISSUE_DROP_LEVEL, dropLevelObject);
                resultObject.put(SharePluginInfo.ISSUE_DROP_SUM, dropSumObject);
                resultObject.put(SharePluginInfo.ISSUE_FPS, fps);

                Issue issue = new Issue();
                issue.setTag(SharePluginInfo.TAG_PLUGIN_FPS);
                issue.setContent(resultObject);
                plugin.onDetectIssue(issue);

            } catch (JSONException e) {
                MatrixLog.e(TAG, "json error", e);
            }
        }

        @Override
        public String toString() {
            return "focusedActivityName=" + focusedActivityName
                    + ", sumFrame=" + sumFrame
                    + ", sumDroppedFrames=" + sumDroppedFrames
                    + ", sumFrameCost=" + sumFrameCost
                    + ", dropLevel=" + Arrays.toString(dropLevel);
        }
    }

这里主要是根据每一帧的总耗时,统计掉帧个数、FPS 等数据,最后将这些数据以一定的格式回调出去

四.总结

这篇文章主要分析了 Matrix-TraceCanary 模块中帧率 FPS、掉帧个数等数据的原理和大概流程,原理是通过 Looper.getMainLooper().setMessageLogging(Printer printer) 向其中添加 Printer 对象监听主线程中 MainLooper 每个消息的处理时间,当前处理的是不是绘制阶段产生的消息是根据 Choreographer 机制判断的,如果当前处理的是绘制阶段产生的消息,在处理消息的同时一定会回调 Choreographer 中回调队列 mCallbackQueues 中的回调方法,向回调队列 mCallbackQueues 添加回调是通过反射在 UIThreadMonitor 中实现的。

通过 Looper.getMainLooper().setMessageLogging(Printer printer) 方式实现 FPS 统计一直有一个问题,在 2.1 和 2.3 小节中也提到过,使用 Looper 机制实现的方式存在一个缺点:在打印消息处理开始日志和消息处理结束日志的时候,都会进行字符串的拼接,频繁地进行字符串的拼接也会影响性能

推荐阅读更多精彩内容