Matrix框架慢函数检测和分析

一、引子

Matrix 是一款微信研发并日常使用的 APM（Application Performance Manage），当前主要运行在 Android 平台上。Matrix 当前监控范围包括：应用安装包大小，帧率变化，启动耗时，卡顿，慢方法，SQLite 操作优化，文件读写，内存泄漏等等。

  本文主要介绍下对于慢函数的监控。

二、使用方法

1.在项目根目录下的 gradle.properties 中配置要依赖的 Matrix 版本号，如：

MATRIX_VERSION=0.4.10

2.在项目根目录下的 build.gradle 文件添加 Matrix 依赖，如：

dependencies {
      classpath ("com.tencent.matrix:matrix-gradle-plugin:${MATRIX_VERSION}") { changing = true }
 }

3.在 app/build.gradle 文件中添加 Matrix 各模块的依赖，如：

apply plugin: 'com.tencent.matrix-plugin'
matrix {
    trace {
        enable = true //if you don't want to use trace canary, set false
        baseMethodMapFile = "${project.buildDir}/matrix_output/Debug.methodmap"
        blackListFile = "${project.projectDir}/matrixTrace/blackMethodList.txt"
 }
}
dependencies {
    debugImplementation group: "com.tencent.matrix", name: "matrix-android-lib", version: MATRIX_VERSION, changing: true
    debugImplementation group: "com.tencent.matrix", name: "matrix-android-commons", version: MATRIX_VERSION, changing: true
    debugImplementation group: "com.tencent.matrix", name: "matrix-trace-canary", version: MATRIX_VERSION, changing: true
    debugImplementation group: "com.tencent.matrix", name: "matrix-resource-canary-android", version: MATRIX_VERSION, changing: true
    debugImplementation group: "com.tencent.matrix", name: "matrix-resource-canary-common", version: MATRIX_VERSION, changing: true
    debugImplementation group: "com.tencent.matrix", name: "matrix-io-canary", version: MATRIX_VERSION, changing: true
    debugImplementation group: "com.tencent.matrix", name: "matrix-sqlite-lint-android-sdk", version: MATRIX_VERSION, changing: true
}

4.实现 PluginListener，接收 Matrix 处理后的数据, 如：

public class TestPluginListener extends DefaultPluginListener {
    public static final String TAG = "Matrix.TestPluginListener";
    public TestPluginListener(Context context) {
        super(context);
    }

    @Override
    public void onReportIssue(Issue issue) {
        super.onReportIssue(issue);
        // add your code to process data
    }
}

5.实现动态配置接口，可修改 Matrix 内部参数：

public class DynamicConfigImplDemo implements IDynamicConfig {
    public DynamicConfigImplDemo() {
    }

    public boolean isFPSEnable() {
        return true;
    }

    public boolean isTraceEnable() {
        return true;
    }

    public boolean isMatrixEnable() {
        return true;
    }

    public boolean isDumpHprof() {
        return false;
    }

    @Override
    public long get(String key, long defLong) {
        if (IDynamicConfig.ExptEnum.clicfg_matrix_trace_evil_method_threshold.name().equals(key)) {
            return 500; // 默认为1000ms public static final long DEFAULT_EVIL_METHOD_THRESHOLD_MS = 1000L;
        }

        return defLong;
    }

}

6.选择程序启动的位置对 Matrix 进行初始化，如在 Application 的继承类中：

val builder = Matrix.Builder(this) // build matrix
builder.patchListener(TestPluginListener(this)) // add general pluginListener
val dynamicConfig = DynamicConfigImplDemo() // dynamic config

//trace
val traceConfig = TraceConfig.Builder()
        .dynamicConfig(dynamicConfig)
        .enableFPS(true)
        .enableMethodTrace(true)
        .enableStartUp(true)
        .splashActivity(SplashActivity::class.java.canonicalName)
        .build()
val tracePlugin = TracePlugin(traceConfig)
builder.plugin(tracePlugin)

val matrix = builder.build()
matrix?.let {
    Matrix.init(matrix)
    matrix.startAllPlugins()
}

7.运行app，查看日志
  出现慢函数时，可以看到以Matrix.EvilMethodTracer为tag的日志输出。
  首先输出的为resultStack，是一个一维数组，按序记录了统计周期内调用过的所有函数。数组内部每四个整数一组，代表一个函数调用，这四组数字分别为调用栈深度、函数id、连续调用次数、执行耗时（以ms为单位）。

  之后输出的为具体的分析结果，包括analyse result和analyse key。

  其中analyse result为分析出的慢函数调用栈，每一行代表一个函数调用，与resultStack中四位数字的意义相同，只是调用栈深度直接用点的个数来表示，更加直观：0个点代表在调用栈底，点数越多代表越靠近栈顶。也就是说，函数58103调用了函数2701，函数2701又调用了函数2699，...，最后调用了函数26861，它们都只（连续）调用了一次，执行耗时分别为1093ms、1082ms和1067ms。
  数字和函数的映射关系保存在app/build/matrix_out/Debug.methodmap中，比如7854，代表的是WelcomeImagesDbManager 类的addAllWelcomeImages()方法。

  根据映射关系，查出慢函数栈为
58103 1 1093 platform.http.CallbackHandler handleMessage (Landroid.os.Message;)V .2701 1 1093 com.ss.android.tuchong.common.service.TuChongService$1 success (Ljava.lang.Object;)V
..2699 1 1093 com.ss.android.tuchong.common.service.TuChongService$1 success (Lcom.ss.android.tuchong.common.entity.WelcomeImgsResult;)V
...7854 1 1093 com.ss.android.tuchong.common.db.WelcomeImagesDbManager addAllWelcomeImages (Lcom.ss.android.tuchong.common.entity.WelcomeImgsResult;)V
....7856 1 1082 com.ss.android.tuchong.common.db.WelcomeImagesDbManager addWelcomeImages (Ljava.util.List;)V
.....26861 1 1067 org.greenrobot.greendao.database.StandardDatabase endTransaction ()V
看下项目代码

  可以看到，在网络接口请求的回调中，在UI线程直接操作了数据库，造成了UI线程阻塞，阻塞时长达1093ms（Hisense M30T, 6.0.1）。与日志中显示的Choreographer: Skipped 59 frames 大致相符（59*16ms=944ms）。需要说明，这款手机性能比较差，所以问题暴露比较明显。

三、原理分析

  从2.7可以看到，Matrix框架查找慢函数是非常易用，非常高效的，那它的实现原理是什么呢？
  对于慢函数检测，需要解决几个问题，包括如何记录各个函数的耗时，如何触发分析和如何分析等。下面从Matrix源码中找下答案。

（一）记录函数的耗时

  matrix框架记录函数耗时的原理很简单：在每个函数的开始和结束处记录下函数id、时间戳和开始结束标示。

private static void mergeData(int methodId, int index, boolean isIn) {
    long trueId = 0L;
    if (isIn) {
        trueId |= 1L << 63;//函数开始，首位为1；函数结束，首位为0
    }
    trueId |= (long) methodId << 43;//methodId最多占用20位，65536*16
    trueId |= sCurrentDiffTime & 0x7FFFFFFFFFFL;//相对时间戳占用43位
    sBuffer[index] = trueId;
}

  但困难的是如何在每个函数的开始和结束处添加统计代码，而且不能耦合到业务代码中。
  这种情况非常适合使用面向切面编程框架，matrix使用的是AOP三剑客中的ASM框架。看下2.3中配置build.gradle时，增加的matrix-plugin。

apply plugin: 'com.tencent.matrix-plugin'

  在项目编译时，MatrixPlugin会添加扫描源代码路径和jar包的任务，在任务中使用ASM框架对几乎所有的.class文件进行操作，在文件中每个函数的开始和结束处都加入统计代码，这样生成的apk在运行时就可以统计每个函数的耗时了。例如看下2.7中回调代码块反编译后的字节码，可以看到函数开始和结束分别调用了MethodBeat的i()和o()方法。

（二）触发分析

  Matrix框架对于慢函数的检测，目前只针对UI线程，以后也许会增加非UI线程的慢函数分析。Matrix采用的是在Choreographer.FrameCallback的doFrame()回调中触发分析。Choreographer的回调伴随着页面刷新，两次页面刷新的间隔比较大，对用户而言是卡顿，对开发者而言，有可能出现了慢函数。

@Override
public void doFrame(long lastFrameNanos, long frameNanos) {
    if (isIgnoreFrame) {
        mActivityCreatedInfoMap.clear();
        setIgnoreFrame(false);
        getMethodBeat().resetIndex();
        return;
    }

    int index = getMethodBeat().getCurIndex();
    if (hasEntered && frameNanos - lastFrameNanos > mTraceConfig.getEvilThresholdNano()) {
        MatrixLog.e(TAG, "[doFrame] dropped frame too much! lastIndex:%s index:%s", 0, index);
        handleBuffer(Type.NORMAL, 0, index - 1, getMethodBeat().getBuffer(), (frameNanos - lastFrameNanos) / Constants.TIME_MILLIS_TO_NANO);
    }
    getMethodBeat().resetIndex();
    mLazyScheduler.cancel();
    mLazyScheduler.setUp(this, false);
}

（三）分析慢函数

  慢函数的分析在后台线程中，matrix框架通过HandlerThread来实现。分析代码在EvilMethodTracer.AnalyseTask中，主要采用了栈和树这两种数据结构。

 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();
                        // 省略异常代码
                        long outTime = getTime(trueId);
                        long inTime = getTime(in);
                        long during = outTime - inTime;

                        MethodItem methodItem = new MethodItem(methodId, (int) during, rawData.size());
                        addMethodItem(resultStack, methodItem);
                    } else {
                        MatrixLog.w(TAG, "[analyse] method[%s] not found in! ", methodId);
                    }
                }
            }

            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);
            
            // report
        }
    }

举个例子，

  假设，在两个frame中间，只调用了函数a()，耗时为1.0；函数a()又调用了函数b()和c()，分别耗时为0.9和0.1；函数b()又调用了函数b1()和函数b2()，耗时分别占为函数b()耗时的0.1和0.9，即0.09和0.81；函数c()又调用了c1()、c2()和c3()，c3()又调用了c31()和c32()。
1.根据3.1得出一维数组result_stack为: aIN bIN b1IN b1OUT b2IN b2OUT bOUT cIN c1IN c1OUT c2IN c2OUT c3IN c31IN c31OUT c32IN c32OUT c3OUT cOUT aOUT
2.经过步骤①，将result_stack变为调用栈: b1(2, 0.09) b2(2, 0.81) b(1,0.9) c1(2,0.03) c2(2,0.05) c31(3,0.006) c32(3,0.014) c3(2,0.02) c(1,0.1) a(0, 1.0)
3.经过步骤②，将调用栈转化为树：

4.经过步骤③进行裁枝 裁枝规则为：
a.某节点耗时小于等于总时长的0.05，则干掉该节点及其子节点； b.第n(n=1,2,3)轮，如果某节点耗时小于或等于父节点耗时的0.1*n，则干掉该节点及其子节点； c.直到树的总节点数小于20或者经过了三轮裁剪。   这里只经过第一轮裁剪，根据规则b，就干掉c及其子节点和b1及其子节点，剩余节点3个，满足裁枝终止条件。
裁剪结果为：

打印出来结果为：
a 1 1.0
.b 1 0.9
..b2 1 0.81
这样就找到了慢函数调用栈。

四、Q&A

1.会在MethodBeat的i()和o()方法中也插入统计代码吗？
  不会，Matrix框架在3.1介绍的查找过程中对特定的包和类进行了过滤。默认会过滤所有名称以android.或com.tencent.matrix开始的包内的所有类

public final static String DEFAULT_BLACK_TRACE =
                "[package]\n"
                + "-keeppackage android/\n"
                + "-keeppackage com/tencent/matrix/\n";

  开发者也可以增加自定义要过滤的类或包，在之前配置matrix的地方，blackListFile.txt即为配置过滤类或包的文件。

matrix {
    trace {
        enable = true //if you don't want to use trace canary, set false
        baseMethodMapFile = "${project.buildDir}/matrix_output/Debug.methodmap"
        blackListFile = "${project.projectDir}/matrixTrace/blackMethodList.txt"
 }
}

  例如，可以按以下配置忽略LogcatUtils和TcMatrixLog两个类

[class]
# -keeppackage com/ss/android/tuchong/common/util
-keepclass com/ss/android/tuchong/common/util/LogcatUtils
-keepclass com/ss/android/tuchong/matrix/TcMatrixLog

2.为何只对UI线程进行慢函数检测
（1）用户大多数情况对UI线程阻塞敏感，对UI线程的检测有需求；
（2）只对UI线程处理，不需同步，效率高，因为所有函数都要调用统计代码，不能太影响性能