微信APM-Matrix 原理篇-Matrix TraceCanary源码分析

Matrix 原理篇-Matrix TraceCanary

前个月，微信开源了其 APM 框架，也就是 Matrix ，这篇文章，介绍 Matrix 的最后一个模块， Martix TraceCanary;

关于 TraceCanary 的官方文档

这里先总结一下，官方文档的相关概念，然后再对 TraceCanary 的源码进行分析。

卡顿以及卡顿检测

TraceCanary 认为，卡顿主要是连续的掉帧导致的，下面是一个表格，表示

Best Normal Middle High Frozen
[0:3) [3:9) [9:24) [24:42) [42:∞)

一般认为连续掉帧，则是卡顿，所以流畅度的指标，通常是根据一段时间内的掉帧情况来说明的。当然，也是要关注帧率的。所以，业界检查卡顿主要通过

  1. SM 流畅度，也就是一段时间内的掉帧情况
  2. FPS 帧率 当前帧率

然后针对出现卡顿的时间段，dump 出当前heap 分析内存情况，也会直接取出造成卡顿的函数调用栈，通过这两种类型的数据，进而分析出卡顿的根本原因。

传统的卡顿检测方案

卡顿检测方案，主要包括在主线程检测 Looper 里面，处理 dispatchMessage() 的时间是否超过阈值来检测，也就是 BlockCanary 的原理；其次还有通过 Choreographer doFrame() 回调，来统计两次 Vsync 事件的时间间隔，当超出阈值时，取出记录的堆栈进行分析。

下面简单看下这两种方案的原理和优劣。

通过 Looper 检测，原理源码如下：

//Looper.loop() 中
public static void loop() {
    final Looper me = myLooper();
    ........
    for (;;) {
        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;
        if (logging != null) {
            logging.println(">>>>> Dispatching to " + msg.target + " " +
                    msg.callback + ": " + msg.what);
        }
        ........
        final long end;
        try {
            msg.target.dispatchMessage(msg);//这里会进入处理消息的逻辑
            end = (slowDispatchThresholdMs == 0) ? 0 : SystemClock.uptimeMillis();
        } finally {
            if (traceTag != 0) {
                Trace.traceEnd(traceTag);
            }
        }
        ........
        if (logging != null) {
            logging.println("<<<<< Finished to " + msg.target + " " + msg.callback);
        }
       .........
    }
}

public void setMessageLogging(@Nullable Printer printer) {
    mLogging = printer;
}

就是在 Looper 每处理一条消息前后，都会通过Looper.mLogging 去打印消息，并且这个 Printer 可以通过 setMessageLogging() 设置进来，利用这个原理，我们可以自定义一个 Printer 实现记录主线程执行消息的时间。类似的代码如下，自定义 Printer 的print 方法如下：

@Override
public void println(String x) {
    if (mStopWhenDebugging && Debug.isDebuggerConnected()) {
        return;
    }
    //第一次print，记录执行前的时间，并且启动一个子线程，轮询 dump 主线程堆栈
    if (!mPrintingStarted) {
        mStartTimestamp = System.currentTimeMillis();
        mStartThreadTimestamp = SystemClock.currentThreadTimeMillis();
        mPrintingStarted = true;
        startDump();//开启子线程，dump 堆栈
    } else {//第二次print，计算耗时，判断是否达到阈值，并且停止 dump 堆栈
        final long endTime = System.currentTimeMillis();
        mPrintingStarted = false;
        if (isBlock(endTime)) {
            notifyBlockEvent(endTime);
        }
        stopDump();
    }
}

该方法的缺点在于：

  1. 时效性不是很强，可能会发送偏移

  2. 无法分析复杂的堆栈，因为 dispatch() 本身的机制，导致，你可能会看到这样的堆栈。

  3. at com.bdtt.sdk.wmsdk.core.o.e(NetApiImpl.java:580)
 at com.bdtt.sdk.wmsdk.core.o.a(NetApiImpl.java:271)
 at com.bdtt.sdk.wmsdk.c.f.e(AdEventThread.java:207)
 at com.bdtt.sdk.wmsdk.c.f.a(AdEventThread.java:187)
 at com.bdtt.sdk.wmsdk.c.f.handleMessage(AdEventThread.java:69)
 at android.os.Handler.dispatchMessage(Handler.java:98)
 at android.os.Looper.loop(Looper.java:136)
 at android.os.HandlerThread.run(HandlerThread.java:61)

出现这种堆栈的时候，很难分析到卡顿的源头。

第二种卡顿检测方案，是通过 Choreographer,其原理大概是这样的：

在View 的 draw，input，animation 的每一帧都会发送一个 vsync 垂直同步事件到 Choreographer，

该方案的缺点：

  1. 需要 api 16，也就是 4.1 以上，目前（2019.2月）还有少量的 4.1 以下 的系统

那么究竟用那种方式比较好呢？第一种看起来比较简单，但是存在一些致命的缺陷：

  1. 主线程一旦卡死，则无法上报
  2. 本身通过 loger 会拼接大量的字符串，源码如下,如果设置了 Printer,则这里会进行字符串拼接，本身导致性能消耗
//Looper.loop() 方法里面
if (logging != null) {
    logging.println("<<<<< Finished to " + msg.target + " " + msg.callback);
}

Matrix TraceCanary

使用介绍

引入依赖，配置，TraceCanary 模块的依赖，以及实现 Listener 等，具体参考官方文档

TracePlugin 启动：

tracePlugin.start();

TracePlugin 关闭：

Plugin plugin = Matrix.with().getPluginByClass(TracePlugin.class);
if(plugin.isPluginStarted()) {
    plugin.stop();
}

掉帧 FpsTrace

检测 掉帧

FPS 检测，对应的是类是 FPSTracer,开启检测 FPS，需要两步：

  1. 开启 FPSTracer

    if(!Matrix.with().getPluginByClass(TracePlugin.class).getFPSTracer().isCreated()) {
    Matrix.with().getPluginByClass(TracePlugin.class).getFPSTracer().onCreate();
}

  2. 设置 IDoFrameListener

    private IDoFrameListener mDoFrameListener = new IDoFrameListener(new Handler(sHandlerThread.getLooper())) {
        @Override
        public void doFrameAsync(long lastFrameNanos, long frameNanos, String scene, int droppedFrames) {
            super.doFrameAsync(lastFrameNanos, frameNanos, scene, droppedFrames);
        }

        @Override
public void doFrameSync(long lastFrameNanos, long frameNanos, String scene, int droppedFrames) {
            super.doFrameSync(lastFrameNanos, frameNanos, scene, droppedFrames);
            count += droppedFrames;
            MatrixLog.i(TAG, "[doFrameSync] scene:" + scene + " droppedFrames:" + droppedFrames);
        }
    };
Matrix.with().getPluginByClass(TracePlugin.class).getFrameTracer().register(mDoFrameListener);

  3. 退出的时候，关闭 FPSTrace

    Matrix.with().getPluginByClass(TracePlugin.class).getFrameTracer().unregister(mDoFrameListener);
Matrix.with().getPluginByClass(TracePlugin.class).getFPSTracer().onDestroy();

然后官方demo 检测的呈现形式是这样的：

image

这个是官方 Demo 的展现形式，主要包含以下可以设置的参数以及展示参数：

  1. scene 表示场景，使用 Activity + Fragment 类名作为唯一标志
  2. dropLevel 是表示掉帧情况
  3. fps 表示当前帧率

FrameTracer 帧率

这个类和 FpsTracer 类似，只不过会直接返回相关时间和帧率给监听者，掉帧计算如下：

final int droppedCount = (int) ((frameNanos - lastFrameNanos) / REFRESH_RATE_MS);

原理介绍

基本概念-Activity 生命周期

首先来介绍一些基类和接口。

ApplicationLifeObserver.IObserve

主要是为了回调 Activity 的生命周期（4.0 以后），类似 Application.ActivityLifecycleCallbacks 的作用，存微小区别，主要是，不回调 onActivitySaveInstanceState(),同时区分 onResume()/onPause() 是首次进入，还是非首次进入，其接口如下：

public interface IObserver {
    void onFront(Activity activity);//非首次 onResume()

    void onBackground(Activity activity);//之前状态是，mIsForeground的 onPause()

    void onChange(Activity activity, Fragment fragment);//onResume() 如果activity发送变化

    void onActivityCreated(final Activity activity);

    void onActivityPause(final Activity activity);

    void onActivityResume(final Activity activity);

    void onActivityStarted(final Activity activity);
}

具体的解释看 ApplicationLifeObserver.

ApplicationLifeObserver

用于注册 ActivityLifecycleCallbacks ，监听和分发 Activity 的生命周期，其结构如下：

public class ApplicationLifeObserver implements Application.ActivityLifecycleCallbacks {
}

在其构造方法里面，会register callback：

private ApplicationLifeObserver(@NonNull Application application) {
    if (null != application) {
        application.unregisterActivityLifecycleCallbacks(this);
        application.registerActivityLifecycleCallbacks(this);
    }
    mObservers = new LinkedList<>();
    mMainHandler = new Handler(Looper.getMainLooper());
}

以 onResume 的回调为例子，其如何回调生命周期的：

@Override
public void onActivityResumed(final Activity activity) {
    //先回调 onActivityResume
    for (IObserver listener : mObservers) {
        listener.onActivityResume(activity);
    }
    mIsPaused = false;
    final boolean wasBackground = !mIsForeground;
    mIsForeground = true;
    final String activityHash = getActivityHash(activity);

    //如果当前Activity 的hash 发送变化，则调用 onChange()
    if (!activityHash.equals(mCurActivityHash)) {
        for (IObserver listener : mObservers) {
            listener.onChange(activity, null);
        }
        mCurActivityHash = activityHash;
    }
    final WeakReference<Activity> mActivityWeakReference = new WeakReference<>(activity);
    mMainHandler.postDelayed(mCheckRunnable = new Runnable() {
        @Override
        public void run() {
            //如果之前状态处于 onPasue,则回调 onFront()
            if (wasBackground) {
                Activity ac = mActivityWeakReference.get();
                if (null == ac) {
                    MatrixLog.w(TAG, "onFront ac is null!");
                    return;
                }
                for (IObserver listener : mObservers) {
                    listener.onFront(activity);
                }
            }
        }
    }, CHECK_DELAY);
}

这里的代码比较简单，解释如上代码注释。

ApplicationLifeObserver 的初始化，在 TracePlugin的 init() 方法里面：

@Override
public void init(Application app, PluginListener listener) {
      ApplicationLifeObserver.init(app);
}

然后类似 BaseTrace，FrameBeat ,MethodBeat 需要监听 Activity 的生命周期的，跟随自生生命周期，有以下回调方法：

ApplicationLifeObserver.getInstance().register(this);
ApplicationLifeObserver.getInstance().unregister(this);

这样，关心 Activity 生命周期的模块，就知道了 Activity 的状态了。

基本概念-帧率监听

IFrameBeatListener

这个接口，主要是为了，管理和分发从 Choreographer.FrameCallback 转发的事件，只有两个方法，如下：

public interface IFrameBeatListener {
    void doFrame(long lastFrameNanos, long frameNanos);
    void cancelFrame();
}

所有的 Tracer 类都会实现这个接口；

FrameBeat

用于接收从 Choreographer 接收 frame 事件，并非分发给关心这个事件的模块，也就是通过注册 IFrameBeatListener,通过这些 Listener 转发。

public final class FrameBeat implements IFrameBeat, Choreographer.FrameCallback, ApplicationLifeObserver.IObserver {
}

FrameBeat 实现了 FrameCallback 接口，其相关内容，看下面分析：

//FrameBeat.onCreate()
@Override
public void onCreate() {
    //判断是否主线程，因为这里要监听MainLooper 的 Choreographer
    if (!MatrixUtil.isInMainThread(Thread.currentThread().getId())) {
        MatrixLog.e(TAG, "[onCreate] FrameBeat must create on main thread");
        return;
    }
    MatrixLog.i(TAG, "[onCreate] FrameBeat real onCreate!");
    if (!isCreated) {
        isCreated = true;
        //register FrameCallback
        ApplicationLifeObserver.getInstance().register(this);
        mChoreographer = Choreographer.getInstance();
        if (ApplicationLifeObserver.getInstance().isForeground()) {
            resume();
        }
    } else {
        MatrixLog.w(TAG, "[onCreate] FrameBeat is created!");
    }
}

上面的 onCreate()会在TracePlugin.start() 里面回调，这样 FrameBeat 就接收了 Choreographer 的 Frame 事件，接着在其 doFrame() 里面转发给所有注册的 IFrameBeatListener,代码如下：

@Override
public void doFrame(long frameTimeNanos) {
    if (isPause) {
        return;
    }
    if (frameTimeNanos < mLastFrameNanos || mLastFrameNanos <= 0) {
        mLastFrameNanos = frameTimeNanos;
        if (null != mChoreographer) {
            mChoreographer.postFrameCallback(this);
        }
        return;
    }
    if (null != mFrameListeners) {
        for (IFrameBeatListener listener : mFrameListeners) {
            listener.doFrame(mLastFrameNanos, frameTimeNanos);
        }
        if (null != mChoreographer) {//onCreate() 赋值，onDestory() 置为null
            mChoreographer.postFrameCallback(this);
        }
        mLastFrameNanos = frameTimeNanos;
    }
}

并且在 onFront()/onResume() 和 onPasue()/onBackground() 有对应的，重新绑定和remove FrameCallback 的操作。

然后在需要接收 Choreographer Frame 事件的地方，都会有类似的代码：

//BaseTracer.onCreate()
FrameBeat.getInstance().addListener(this);

基本概念-监听Activity 切换动画

在 TraceCanary 中，关注了 Activity 的切换动画，在切换动画期间，其对帧率监听是这样的，会丢弃这段时间，代码如下：

//BaseTracer.doFrame() 
public void doFrame(long lastFrameNanos, long frameNanos) {
    //这里判断是否 isEnterAnimationComplete，也就是Activity 切换动画是否已经完成
    if (!isInvalid && isDrawing && isEnterAnimationComplete() && mTraceConfig.isTargetScene(getScene())) {
        handleDoFrame(lastFrameNanos, frameNanos, getScene());
    }
    isDrawing = false;
}

实现这个机制，是通过两个类实现的，HackCallback 和 Hacker。

HackCallback

该类实现了 Handler 的 Callback，用于监听ActivityThread 里面的 Handler 发送的一些特定的 Message，其代码如下：

public class HackCallback implements Handler.Callback {
    private static final String TAG = "Matrix.HackCallback";
    private static final int LAUNCH_ACTIVITY = 100;
    private static final int ENTER_ANIMATION_COMPLETE = 149;
    private static final int CREATE_SERVICE = 114;
    private static final int RECEIVER = 113;
    private static boolean isCreated = false;

    private final Handler.Callback mOriginalCallback;

    public HackCallback(Handler.Callback callback) {
        this.mOriginalCallback = callback;
    }

    @Override
    public boolean handleMessage(Message msg) {
        if (msg.what == LAUNCH_ACTIVITY) {//处理 Launch 事件
            Hacker.isEnterAnimationComplete = false;
        } else if (msg.what == ENTER_ANIMATION_COMPLETE) {//处理动画完成事件
            Hacker.isEnterAnimationComplete = true;
        }
        if (!isCreated) {
            if (msg.what == LAUNCH_ACTIVITY || msg.what == CREATE_SERVICE || msg.what == RECEIVER) {
                Hacker.sApplicationCreateEndTime = System.currentTimeMillis();
                Hacker.sApplicationCreateEndMethodIndex = MethodBeat.getCurIndex();
                Hacker.sApplicationCreateScene = msg.what;
                isCreated = true;
            }
        }
        if (null == mOriginalCallback) {
            return false;
        }
        //最后还是转发回原来的 Callback，保证不会影响到原本系统的逻辑
        return mOriginalCallback.handleMessage(msg);
    }
}

这里会监听处理，两个事件:

private class H extends Handler {
    public static final int LAUNCH_ACTIVITY         = 100;
    public static final int ENTER_ANIMATION_COMPLETE = 149;
}

两者对应的时机分别是启动 asm 发送

Hacker

这个类主要是反射替换了 ActivityThread 中的 Handler，并且为它设置一个 Handler.Callback，源码如下：

public class Hacker {
    private static final String TAG = "Matrix.Hacker";
    public static boolean isEnterAnimationComplete = false;
    public static long sApplicationCreateBeginTime = 0L;
    public static int sApplicationCreateBeginMethodIndex = 0;
    public static long sApplicationCreateEndTime = 0L;
    public static int sApplicationCreateEndMethodIndex = 0;
    public static int sApplicationCreateScene = -100;

    public static void hackSysHandlerCallback() {
        try {
            sApplicationCreateBeginTime = System.currentTimeMillis();
            sApplicationCreateBeginMethodIndex = MethodBeat.getCurIndex();
            Class<?> forName = Class.forName("android.app.ActivityThread");
            Field field = forName.getDeclaredField("sCurrentActivityThread");
            field.setAccessible(true);
            Object activityThreadValue = field.get(forName);
            Field mH = forName.getDeclaredField("mH");
            mH.setAccessible(true);
            Object handler = mH.get(activityThreadValue);
            Class<?> handlerClass = handler.getClass().getSuperclass();
            Field callbackField = handlerClass.getDeclaredField("mCallback");
            callbackField.setAccessible(true);
            Handler.Callback originalCallback = (Handler.Callback) callbackField.get(handler);
            HackCallback callback = new HackCallback(originalCallback);
            callbackField.set(handler, callback);
            MatrixLog.i(TAG, "hook system handler completed. start:%s", sApplicationCreateBeginTime);
        } catch (Exception e) {
            MatrixLog.e(TAG, "hook system handler err! %s", e.getCause().toString());
        }
    }
}

在 MethodBeat 类中的 static 代码块中，会执行该 hackSysHandlerCallback() 方法，这里通过反射从 ActivityThread 中的 mH 字段，也就是 Handler 中，代理了 Activity 的上述两个事件，用于判断 Appliaction 创建，以及 Activity 切换动画。

那么判断 Activity 是否处于切换动画，有什么用呢？在监听 FPS 的时候，有这么一行代码：

//FPSTracer.java
public void doFrame(long lastFrameNanos, long frameNanos) {
    if (!isInvalid && isDrawing && isEnterAnimationComplete() && mTraceConfig.isTargetScene(getScene())) {
        handleDoFrame(lastFrameNanos, frameNanos, getScene());
    }
    isDrawing = false;
}

也就是说，不监听在执行Activity动画期间的帧率。

另外，Application 的创建时间，是直接用来计算 Application 初始化的时间的。

基本概念-方法调用监听

在 TraceCanary 模块，通过 asm 在 Activity.onCreate() 到 Activity.onWindowFocusChange() 执行期间，所有的执行函数中，在函数前后各插入代码，插入模式如下，有一个 functionA,

//插入前
private void functionA(){
}
//插入后
private void functionA(){
    MethodBeat.i(id);
    //原本方法逻辑
    MethodBeat.o(id);
}

tip：这一块的原理，后面会详细分析。

IMethodBeatListener

这个接口主要用于在启动或者Activity 切换的时候，回调Application 创建耗时以及Activity 切换耗时。

public interface IMethodBeatListener {
    //
    void pushFullBuffer(int start, int end, long[] buffer);
    void onActivityEntered(Activity activity, boolean isFocus, int nowIndex, long[] buffer);
    void onApplicationCreated(long startTime, long endTime);
}
IMethodBeat

MethodBeat 的接口类，接口定义的方法如下：

public interface IMethodBeat {

    void registerListener(IMethodBeatListener listener);

    void unregisterListener(IMethodBeatListener listener);

    boolean isHasListeners();

    void resetIndex();
    //对应其它Trace 的 onCreate()
    void onCreate();
   //对应其它Trace 的 onDestroy()
    void onDestroy();

    boolean isRealTrace();

    long getLastDiffTime();

    void lockBuffer(boolean isLock);

    boolean isLockBuffer();

}
MethodBeat

重点来看 MethodBeat 类，这个类是实际上插入代码到所有函数中的，用于统计函数耗时，计算启动时间，页面跳转(Activity切换)时间

其类结构如下：

public class MethodBeat implements IMethodBeat, ApplicationLifeObserver.IObserver {
}

这个类也关注了 Activity 的生命周期，同时也实现了 IMethodBeat 接口。

关注下该类的数据域：

private volatile static boolean isCreated = false;//标记 onCreate() 是否已经被调用
//IMethodBeatListenr LinkList 观察者列表
private static LinkedList<IMethodBeatListener> sListeners = new LinkedList<>();
//方法I/O 的Index
private volatile static int sIndex = 0;
private volatile static long sCurrentDiffTime;
private volatile static long sLastDiffTime;
private static long[] sBuffer;
private static boolean isRealTrace;
private static boolean sIsIn = false;
private volatile static boolean isBackground = false;//标记 Activity 是否进入onPause()
//用作是否主线程的判断标志，非主线程的函数，不处理
private static Thread sMainThread = Looper.getMainLooper().getThread();
//
private static final int UPDATE_TIME_MSG_ID = 0x100;
//
private static final int RELEASE_BUFFER_MSG_ID = 0x200;
//单独一个 HandlerThread 用于
private static HandlerThread sTimerUpdateThread = MatrixHandlerThread.getNewHandlerThread("matrix_time_update_thread");
private static Handler sTimeUpdateHandler = new Handler(sTimerUpdateThread.getLooper(), new Handler.Callback() {
    @Override
    public boolean handleMessage(Message msg) {
        if (msg.what == UPDATE_TIME_MSG_ID) {
            updateDiffTime();
            if (!isBackground) {
                sTimeUpdateHandler.sendEmptyMessageDelayed(UPDATE_TIME_MSG_ID, Constants.TIME_UPDATE_CYCLE_MS);
            } else {
                MatrixLog.w(TAG, "stop time update!");
            }
        }
        return true;
    }
});

//上述 HandlerThread 对应的
private static Handler sReleaseBufferHandler = new Handler(Looper.getMainLooper(), new Handler.Callback() {
    @Override
    public boolean handleMessage(Message msg) {
        if (msg.what == RELEASE_BUFFER_MSG_ID) {
            if (!isCreated) {
                MatrixLog.i(TAG, "Plugin is never init, release buffer!");
                sBuffer = null;
                sTimeUpdateHandler.removeCallbacksAndMessages(null);
                isBackground = true;
            }
        }
        return true;
    }
});

可以看得到，这里都是 static 类型的变量，关键变量的分析如代码注释。

在其 static 代码块里面：

static {
    Hacker.hackSysHandlerCallback();
    sCurrentDiffTime = sLastDiffTime = System.nanoTime() / Constants.TIME_MILLIS_TO_NANO;
    sReleaseBufferHandler.sendEmptyMessageDelayed(RELEASE_BUFFER_MSG_ID, Constants.DEFAULT_RELEASE_BUFFER_DELAY);
}

首先会调用 Hacker.hackSysHandlerCallback() 接管 ActivityThread 里 Handler 的一些 Message，具体看上面监听 Activity 切换这一章节的介绍。

接着这里进行了一些初始化设置，并且发送了 RELEASE_BUFFER_MSG_ID 这一消息，这里设置 isBackground = true。

接着到 onCreate() 函数：

@Override
public void onCreate() {
    if (!isCreated) {
        sReleaseBufferHandler.removeMessages(RELEASE_BUFFER_MSG_ID);
        sTimeUpdateHandler.removeMessages(UPDATE_TIME_MSG_ID);
        sTimeUpdateHandler.sendEmptyMessage(UPDATE_TIME_MSG_ID);
        ApplicationLifeObserver.getInstance().register(this);
        isCreated = true;
        //会进入if 这个分支，对 Buffer 数组进行扩容
        if (null != sBuffer && sBuffer.length < Constants.BUFFER_SIZE) {
            final long[] tmpBuffer = sBuffer;
            sBuffer = new long[Constants.BUFFER_SIZE];
            System.arraycopy(tmpBuffer, 0, sBuffer, 0, sIndex);
        } else {
            sBuffer = new long[Constants.BUFFER_SIZE];
        }
    }
}

onCreate() 覆盖了 IMethodBeat 的 onCreate() 方法，在 BaseTracer.onCreate() 中会被调用，默认第一次调用改 onCreate()，由于 isCreate 是false，所以一定会进入这个if 语句，接着 register 一个监听 Activity 生命周期，并且进行 sBuffer 的初始化，但是由于 sBuffer 会在 i() 方法里面被赋予 BUFFER_TMP_SIZE 长度，所以这里的if 会进入第一个条件，也就是扩容条件。

然后我们进入到关键的 i()方法，其源码如下：

public static void i(int methodId) {
    if (isBackground) {//如果当前Activity 处于 onPause()之后的状态，则直接return
        return;
    }
    //首次执行i()函数会进入，因为onCrate() 延后与 i() 执行，先给与 sBuffer 一个临时长度
    if (!isRealTrace) {
        updateDiffTime();
        sTimeUpdateHandler.sendEmptyMessage(UPDATE_TIME_MSG_ID);
        sBuffer = new long[Constants.BUFFER_TMP_SIZE];
    }
    isRealTrace = true;
    if (isCreated && Thread.currentThread() == sMainThread) {
        if (sIsIn) {
            android.util.Log.e(TAG, "ERROR!!! MethodBeat.i Recursive calls!!!");
            return;
        }
        sIsIn = true;
        if (sIndex >= Constants.BUFFER_SIZE) {
            //pushFullBuffer 会将 sBuffer 分发出去，做分析处理
            for (IMethodBeatListener listener : sListeners) {
                listener.pushFullBuffer(0, Constants.BUFFER_SIZE - 1, sBuffer);
            }
            sIndex = 0;
        } else {
            mergeData(methodId, sIndex, true);
        }
        ++sIndex;
        sIsIn = false;
    } else if (!isCreated && Thread.currentThread() == sMainThread && sBuffer != null) {
        if (sIsIn) {
            android.util.Log.e(TAG, "ERROR!!! MethodBeat.i Recursive calls!!!");
            return;
        }
        sIsIn = true;
        if (sIndex < Constants.BUFFER_TMP_SIZE) {
            mergeData(methodId, sIndex, true);
            ++sIndex;
        }
        sIsIn = false;
    }
}

首先会判断是否 isBackground，这个变量在 onBackground() 的时候，会置为 true，如果是 isBackGround 则直接 return。

接着由于第一次执行i() 函数，则 isRealTrace 必定为 false，则该 if 会进入执行，对 sBuffer 数组进行置空，重新赋予一个临时长度 10000，由于 i() 会在 onCreate() 执行，这里先简单给予 sBuffer 一个临时的长度。

接着进入最关键的逻辑了，这里主要区分 onCreate() 是否执行，如果已经执行，如果 sIndex，也就是记录的方法数，大于 BUFFER_SIZE 的时候，会将 sBuffer 取出，并且发送出去，例如发送给分析后端。两种情况下，都会调用 mergeData(),那么来看下 mergeData() 的源码：

//i阶段，isIn 为 true；o 阶段，isIn 为 false
private static void mergeData(int methodId, int index, boolean isIn) {
    long trueId = 0L;
    if (isIn) {
        trueId |= 1L << 63;//0亦或任何数，也就是 0|2的63次方
    }
    trueId |= (long) methodId << 43;
    trueId |= sCurrentDiffTime & 0x7FFFFFFFFFFL;
    sBuffer[index] = trueId;
}

这里贴一张官方的图，进行辅助解释

[图片上传失败...(image-8e0190-1557558678675)]

这里的 methodId 是在 Transfrom 期间，为这些函数分配的单独的一个 id，具体的值可以在 app/build/martix-output/Debug.methodmap 下可以看得到，对应函数的id，这里会将相关信息存储到一个 64 位的 long 数值里面，63 位标记这个是i 阶段还是 o 阶段，43-62位，标记 method id，低于 43 位，标记进入的时间，单位为毫秒值。

这里标记的时间，是每5毫秒，通过 updateDiffTime更新一次的，并不是实时去更新时间的，为什么呢？因为 Martix 认为，大量调用 System.nanoTime() 的损耗性能，而且本身i/o 之间，如果相隔不超过5毫秒的函数，似乎，也不会影响卡顿；但是貌似，如果高频率调用一些函数，有可能会影响到性能，不过这种情况，一般可以通过嵌套的函数反应出来，考虑这点也是合理的；其次，这里是新开了一个 HandlerThread 去更新这个时间，对主线程并无丝毫影响，这一点是非常不错的思路。我之前也写过，类似的日志插件，统计方法耗时，我是直接取主线程的时间，所以可能没有 matrix 处理得好。

简单做个试验，看下System.naoTime() 的耗时，代码如下：

private fun testGetNanoTime() {
    val timeMillis = System.currentTimeMillis()
    for (i in 1..1000000) {
        System.nanoTime()
    }
    Log.i("testGetNanoTime", "cost:${System.currentTimeMillis() - timeMillis}")
}

最终在我的测试机，小米 note3上，执行一百万次，nanoTime() 的时间为,405 毫秒左右

2019-02-23 18:04:03.454 2769-2769/com.yy.yylite.kotlinshare I/testGetNanoTime: cost:408
2019-02-23 18:04:14.461 2769-2769/com.yy.yylite.kotlinshare I/testGetNanoTime: cost:403
2019-02-23 18:04:18.013 2769-2769/com.yy.yylite.kotlinshare I/testGetNanoTime: cost:405

所以，理论上，从 Activity onCreate() 到 onWindowsChange() 一般可能有几万个函数，所以太频繁的调用 System.nanoTime() 也不是特别理想。

最后再来看下 o() 方法：

public static void o(int methodId) {
    if (isBackground || null == sBuffer) {
        return;
    }
    if (isCreated && Thread.currentThread() == sMainThread) {
        if (sIndex < Constants.BUFFER_SIZE) {
            mergeData(methodId, sIndex, false);
        } else {
            for (IMethodBeatListener listener : sListeners) {
                listener.pushFullBuffer(0, Constants.BUFFER_SIZE - 1, sBuffer);
            }
            sIndex = 0;
        }
        ++sIndex;
    } else if (!isCreated && Thread.currentThread() == sMainThread) {
        if (sIndex < Constants.BUFFER_TMP_SIZE) {
            mergeData(methodId, sIndex, false);
            ++sIndex;
        }
    }
}

这里的操作，也就是一个 mergeData() 的操作，i() 方法中已经解释过了，这里就不再进行重复得解释了。

总结一下，这里的流程图如下：

基本概念-耗时函数堆栈确认

一般来说，耗时统计主要分为三步：

  1. 获取数据
  2. 裁剪数据
  3. 分析数据

通过上一个章节的分析，我们知道了怎么获得函数耗时数据，那么下一步就是裁剪数据，聚类出有效的耗时函数堆栈。

基本概念-trace 基类 BaseTracer

先来看下这个类的继承结构：

public abstract class BaseTracer extends IssuePublisher implements ApplicationLifeObserver.IObserver, IFrameBeatListener, IMethodBeatListener {}

如之前介绍，这里实现的接口如下：

  1. ApplicationLifeObserver.IObserver 监听 Activity 的生命周期
  2. IFrameBeatListener 注册到 FrameBeat 能够监听 Choreographer 的回调，通过这个计算 FPS 以及卡顿。
  3. IMethodBeatListener 用于计算函数耗时

卡顿监听

Start Up 启动 耗时

在TraceCanary 中，包含了启动耗时的统计，其具体流程如下：

image

也就是说，计算时间是 Application 启动，到第一个 非 SplashActivity 的 onActivityEntered() 回调的时间，然后这个 onActivityEntered() 回调，也就是 Activity.onWindowFocusedChange()

//MethodBeat
public static void at(Activity activity, boolean isFocus) {
    MatrixLog.i(TAG, "[AT] activity: %s, isCreated: %b sListener size: %d，isFocus: %b",
            activity.getClass().getSimpleName(), isCreated, sListeners.size(), isFocus);
    if (isCreated && Thread.currentThread() == sMainThread) {
        for (IMethodBeatListener listener : sListeners) {
            listener.onActivityEntered(activity, isFocus, sIndex - 1, sBuffer);
        }
    }
}

在 gradle 插件中，会检测是否 Activity 的 onWindowFocusedChange()

//MethodTracer.TraceMethodAdapter.onMethodExit()
if (windowFocusChangeMethod.equals(traceMethod)) {
    traceWindowFocusChangeMethod(mv);
}
    private void traceWindowFocusChangeMethod(MethodVisitor mv) {
        mv.visitVarInsn(Opcodes.ALOAD, 0);
        mv.visitVarInsn(Opcodes.ILOAD, 1);
        mv.visitMethodInsn(Opcodes.INVOKESTATIC, TraceBuildConstants.MATRIX_TRACE_CLASS, "at", "(Landroid/app/Activity;Z)V", false);
    }

最终的插入效果如下：

public void onWindowFocusChanged(boolean var1) {
    super.onWindowFocusChanged(var1);
    MethodBeat.at(this, var1);
}

FPS 检测原理

主要是通过在 Choreographer 注册 FameCallback 监听每一帧回调的间隔，如下代码，在 TracePlugin 中：

//TracePlugin
@Override
public void start() {
    super.start();
    if (!isSupported()) {
        return;
    }
    //注册 Choreographer 的Callback,这里是为了注册到主线程的 Choreographer，每个Looper 对应一个
    //Choreographer，所以这里要的是主线程的
    new Handler(Looper.getMainLooper()).post(new Runnable() {
        @Override
        public void run() {
            FrameBeat.getInstance().onCreate();
        }
    });

    if (null != mFPSTracer) {
        mFPSTracer.onCreate();
    }
    if (null != mEvilMethodTracer) {
        mEvilMethodTracer.onCreate();
    }
    if (null != mFrameTracer) {
        mFrameTracer.onCreate();
    }
    if (null != mStartUpTracer) {
        mStartUpTracer.onCreate();
    }
}
// FrameBeat.onCreate()
    @Override
    public void onCreate() {
        if (!MatrixUtil.isInMainThread(Thread.currentThread().getId())) {
            MatrixLog.e(TAG, "[onCreate] FrameBeat must create on main thread");
            return;
        }
        MatrixLog.i(TAG, "[onCreate] FrameBeat real onCreate!");
        if (!isCreated) {
            isCreated = true;
            ApplicationLifeObserver.getInstance().register(this);
            mChoreographer = Choreographer.getInstance();
            if (ApplicationLifeObserver.getInstance().isForeground()) {
                resume();
            }
        } else {
            MatrixLog.w(TAG, "[onCreate] FrameBeat is created!");
        }
    }

启动耗时和界面调整耗时插桩

Matrix 的 TraceCanary 会对 Activity 的 onCreate() 到 onWindowFocusChange() 直接的执行函数，进行插桩，这个原理是怎么实现的呢？

实际上，并不难理解，Martix 的 gradle 插件，会对所有的函数，插入 i/o() 函数，并且对一些特定的函数时间节点，插入标记函数，at()。

比如某种场景下:

image

区分到 某个场景是 SplashActivity 的 onWindowFocusChange()，便可以区分为，这是是启动相关的函数，同理，在 Activity onCreate 到Activity onWindowFocusChange 期间，认为是界面启动耗时。

Matrix 卡顿检测流程

经过前面的分析，我们知道，matrix 检测卡顿的流程可以分为三个阶段：

检测保障期

这个时期，通过 Gradle 插件，在特定的相关函数头和尾，插入了耗时日志，见 MethodBeat 分析

检测期

这个阶段，通过注册 Choreographer 的监听者，然后这个类的实现在 EvilMethodTracer 里面，具体见后面的分析。

上报期

这里分普通卡顿上报，和 anr 上报

具体的分析如下：

MethodBeat 插入代码

Martix TraceCanary 会在执行方法头插入 i() 函数，在执行方法前插入 o()函数，具体见 MethodBeat 章节分析。

检测期

MethodBeat 会在 Activity onResume() 到 Activity onPaused() 之间写入 method id 和耗时到 long 数组也就是 sBuffer 数组。

同时通过 EveMethodTracer 接收 Choreographer 的回调，检测是否发生卡顿，如果卡顿则上报，上报完成或者不卡顿之后都会清空之前收集的 sBuffer 数组，只不过上报的话，需要把 sBuffer 先复制到一个临时数组里面去，在线程去分析这个 sBuffer 数组。

与此同时，会开启一个子线程去监听是否发生了 anr，如果发生了 anr 则上报 sBuffer 数组。

上报期

检测期间，如果需要上报会 post 一个 Runnable ，代码如下：

//EvilMethodTracer.java handleBuffer() 方法中，该 Handler 对应一个新的 HandlerThread 
mHandler.post(new AnalyseTask(tmp, info));

其分析和上报主要在 analyse() 方法里面，其源码如下：

        private void analyse(long[] buffer) {
            LinkedList<Long> rawData = new LinkedList<>();
            LinkedList<MethodItem> resultStack = new LinkedList<>();

            for (long trueId : buffer) {
                if (isIn(trueId)) {
                    rawData.push(trueId);
                } else {
                    int methodId = getMethodId(trueId);
                    if (!rawData.isEmpty()) {
                        long in = rawData.pop();
                        while (getMethodId(in) != methodId) {
                            MatrixLog.w(TAG, "[analyse] method[%s] not match in! continue to find!", methodId);
                            //complete out for not found in
                            long outTime = analyseExtraInfo.happenTime;
                            long inTime = getTime(in);
                            long during = outTime - inTime;
                            if (during < 0 || during >= Constants.MAX_EVIL_METHOD_DUR_TIME) {
                                MatrixLog.e(TAG, "[analyse] trace during invalid:%d", during);
                                return;
                            }

                            int methodId2 = getMethodId(in);
                            MethodItem methodItem = new MethodItem(methodId2, (int) during, rawData.size());
                            addMethodItem(resultStack, methodItem);

                            if (!rawData.isEmpty()) {
                                in = rawData.pop();
                            } else {
                                MatrixLog.e(TAG, "[analyse] method[%s] not match in finally! ", methodId);
                                in = 0;
                                break;
                            }
                        }
                        long outTime = getTime(trueId);
                        long inTime = getTime(in);
                        long during = outTime - inTime;
                        if (during < 0 || during >= Constants.MAX_EVIL_METHOD_DUR_TIME) {
                            MatrixLog.e(TAG, "[analyse] trace during invalid:%d", during);
                            return;
                        }

                        MethodItem methodItem = new MethodItem(methodId, (int) during, rawData.size());
                        addMethodItem(resultStack, methodItem);

                    } else {
                        MatrixLog.w(TAG, "[analyse] method[%s] not found in! ", methodId);
                    }
                }
            }

            // maybe ANR or Full
            while (!rawData.isEmpty()) {
                MatrixLog.w(TAG, "[analyse] has never out method. rawData size:%s result size:%s", rawData.size(), resultStack.size());
                long trueId = rawData.pop();
                int methodId = getMethodId(trueId);
                long inTime = getTime(trueId);
                MethodItem methodItem = new MethodItem(methodId, Math.min((int) (analyseExtraInfo.happenTime - inTime), Constants.DEFAULT_ANR), rawData.size());
                addMethodItem(resultStack, methodItem);
            }
            MatrixLog.i(TAG, "resultStack:%s", resultStack);
            LinkedList<MethodItem> finalResultStack = new LinkedList<>();
            TreeNode root = stackToTree(resultStack);
            int round = 1;
            while (true) {
                boolean ret = trimResultStack(root, analyseExtraInfo, 0, (.1f * (float) round));
                if (ret) {
                    MatrixLog.e(TAG, "type:%s [stack result is empty after trim, just ignore]", analyseExtraInfo.type.name());
                    return;
                }
                if (countTreeNode(root) <= Constants.MAX_EVIL_METHOD_STACK) {
                    break;
                }

                round++;
                if (round > 3) {
                    break;
                }
            }

            makeKey(root, analyseExtraInfo);

            preTraversalTree(root, finalResultStack);
//            trimResultStack(finalResultStack, analyseExtraInfo);
            if (finalResultStack.isEmpty()) {
                MatrixLog.e(TAG, "type:%s [stack result is empty after trim, just ignore]", analyseExtraInfo.type.name());
                return;
            }
            ListIterator<MethodItem> listIterator = finalResultStack.listIterator();
            StringBuilder printBuilder = new StringBuilder("\n"); // print to logcat
            StringBuilder reportBuilder = new StringBuilder(); // report result
            while (listIterator.hasNext()) {
                MethodItem item = listIterator.next();
                printBuilder.append(item.print()).append('\n');
                reportBuilder.append(item.toString()).append('\n');
            }
            MatrixLog.i(TAG, "[analyse result] %s", printBuilder.toString());

            StringBuilder keyBuilder = new StringBuilder(); // key for cache
            getKey(root, keyBuilder);
            String key = keyBuilder.toString();
            if (analyseExtraInfo.type == Type.FULL) {
                key = "TypeFull";
            } else if (key.length() == 0) {
                MatrixLog.e(TAG, "get key null, type:%s", analyseExtraInfo.type.name());
                return;
            }
            MatrixLog.i(TAG, "[analyse key] %s", key);

            // report
            try {
                JSONObject jsonObject = new JSONObject();
                jsonObject = DeviceUtil.getDeviceInfo(jsonObject, getPlugin().getApplication());

                jsonObject.put(SharePluginInfo.ISSUE_STACK_TYPE, analyseExtraInfo.type.name());
                jsonObject.put(SharePluginInfo.ISSUE_SUB_TYPE, analyseExtraInfo.subType);
                jsonObject.put(SharePluginInfo.ISSUE_COST, analyseExtraInfo.cost);

                if (analyseExtraInfo.type == Type.ENTER) {
                    JSONObject viewInfoJson = new JSONObject();
                    ViewUtil.ViewInfo viewInfo = analyseExtraInfo.viewInfo;
                    viewInfoJson.put(SharePluginInfo.ISSUE_VIEW_DEEP, null == viewInfo ? 0 : viewInfo.mViewDeep);
                    viewInfoJson.put(SharePluginInfo.ISSUE_VIEW_COUNT, null == viewInfo ? 0 : viewInfo.mViewCount);
                    viewInfoJson.put(SharePluginInfo.ISSUE_VIEW_ACTIVITY, null == viewInfo ? 0 : viewInfo.mActivityName);
                    jsonObject.put(SharePluginInfo.ISSUE_VIEW_INFO, viewInfoJson);
                }
                jsonObject.put(SharePluginInfo.ISSUE_STACK, reportBuilder.toString());
                jsonObject.put(SharePluginInfo.ISSUE_STACK_KEY, key);
                sendReport(jsonObject);

            } catch (JSONException e) {
                MatrixLog.e(TAG, "[JSONException for stack %s, error: %s", reportBuilder.toString(), e);
            }
        }
    }
最后编辑于 ：
©著作权归作者所有,转载或内容合作请联系作者
  • 人面猴
    序言：七十年代末，一起剥皮案震惊了整个滨河市，随后出现的几起案子，更是在滨河造成了极大的恐慌，老刑警刘岩，带你破解...
    沈念sama阅读 206,839评论 6赞 482
  • 死咒
    序言：滨河连续发生了三起死亡事件，死亡现场离奇诡异，居然都是意外死亡，警方通过查阅死者的电脑和手机，发现死者居然都...
    沈念sama阅读 88,543评论 2赞 382
  • 救了他两次的神仙让他今天三更去死
    文/潘晓璐 我一进店门，熙熙楼的掌柜王于贵愁眉苦脸地迎上来，“玉大人，你说我怎么就摊上这事。” “怎么了？”我有些...
    开封第一讲书人阅读 153,116评论 0赞 344
  • 道士缉凶录：失踪的卖姜人
    文/不坏的土叔 我叫张陵，是天一观的道长。 经常有香客问我，道长，这世上最难降的妖魔是什么？ 我笑而不...
    开封第一讲书人阅读 55,371评论 1赞 279
  • 港岛之恋（遗憾婚礼）
    正文 为了忘掉前任，我火速办了婚礼，结果婚礼上，老公的妹妹穿的比我还像新娘。我一直安慰自己，他们只是感情好，可当我...
    茶点故事阅读 64,384评论 5赞 374
  • 恶毒庶女顶嫁案：这布局不是一般人想出来的
    文/花漫 我一把揭开白布。 她就那样静静地躺着，像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上，一...
    开封第一讲书人阅读 49,111评论 1赞 285
  • 城市分裂传说
    那天，我揣着相机与录音，去河边找鬼。 笑死，一个胖子当着我的面吹牛，可吹牛的内容都是我干的。 我是一名探鬼主播，决...
    沈念sama阅读 38,416评论 3赞 400
  • 双鸳鸯连环套：你想象不到人心有多黑
    文/苍兰香墨 我猛地睁开眼，长吁一口气：“原来是场噩梦啊……” “哼！你这毒妇竟也来了？” 一声冷哼从身侧响起，我...
    开封第一讲书人阅读 37,053评论 0赞 259
  • 万荣杀人案实录
    序言：老挝万荣一对情侣失踪，失踪者是张志新（化名）和其女友刘颖，没想到半个月后，有当地人在树林里发现了一具尸体，经...
    沈念sama阅读 43,558评论 1赞 300
  • 护林员之死
    正文 独居荒郊野岭守林人离奇死亡，尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 36,007评论 2赞 325
  • 白月光启示录
    正文 我和宋清朗相恋三年，在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 38,117评论 1赞 334
  • 活死人
    序言：一个原本活蹦乱跳的男人离奇死亡，死状恐怖，灵堂内的尸体忽然破棺而出，到底是诈尸还是另有隐情，我是刑警宁泽，带...
    沈念sama阅读 33,756评论 4赞 324
  • 日本核电站爆炸内幕
    正文 年R本政府宣布，位于F岛的核电站，受9级特大地震影响，放射性物质发生泄漏。R本人自食恶果不足惜，却给世界环境...
    茶点故事阅读 39,324评论 3赞 307
  • 男人毒药：我在死后第九天来索命
    文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹，春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 30,315评论 0赞 19
  • 一桩弑父案，背后竟有这般阴谋
    文/苍兰香墨 我抬头看了看天上的太阳。三九已至，却和暖如春，着一层夹袄步出监牢的瞬间，已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 31,539评论 1赞 262
  • 情欲美人皮
    我被黑心中介骗来泰国打工， 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留，地道东北人。 一个月前我还...
    沈念sama阅读 45,578评论 2赞 355
  • 代替公主和亲
    正文 我出身青楼，却偏偏与公主长得像，于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子，可洞房花烛夜当晚...
    茶点故事阅读 42,877评论 2赞 345

推荐阅读更多精彩内容