前言

有了前面的分析基础，现在EvilMethodTracer类看起来“简单”很多~

没有看过的话可以看之前写的系列文章~

[Matrix系列-2]： TracePlugin 之 LooperAnrTrace源码分析

[Matrix系列-3]： TracePlugin 之 FrameTrace 源码分析

背景

evil字面意思是邪恶的、有害的意思。这个方法很邪恶就是该方法存在耗时多的情况，糟老头子坏的很呐！！因此，matrix的目的就是想去统计每个方法的执行耗时。

大体的流程是这样的：在calss字节码转dex文件阶段，通过自定义transform插件，利用ASM工具来操作修改.class文件。在每个方法执行前后插入AppMethodBeat.i 和AppMethodBeat.o方法，在运行期计算两个的差值就得到方法的耗时。

优点：

兼容性好无需通过hook手段
优化插桩性能在方法收集阶段会主动过滤简单的set/get方法，以及一些匿名的构造函数

缺点：

无法统计到系统内执行的函数，但一般卡顿都是由我们自己的App代码导致，所以影响不大

我们先来看下编译期的基本实现（实现细节后续再单独分析）：

private class TraceMethodAdapter extends AdviceAdapter {

    private final String methodName;
    private final String name;
    private final String className;
    private final boolean hasWindowFocusMethod;
    private final boolean isNeedTrace;
    private final boolean isActivityOrSubClass;

    // ...省略

    @Override
    protected void onMethodEnter() {
        //注意：并不是所有的方法都执行插桩，只有是我们需要收集的方法才会走插桩逻辑，优化插桩性能！
        TraceMethod traceMethod = collectedMethodMap.get(methodName);
        if (traceMethod != null) {
            traceMethodCount.incrementAndGet();
            mv.visitLdcInsn(traceMethod.id);
            //1, 插入 AppMethodBeat.i 方法
            mv.visitMethodInsn(INVOKESTATIC, TraceBuildConstants.MATRIX_TRACE_CLASS, "i", "(I)V", false);

            if (checkNeedTraceWindowFocusChangeMethod(traceMethod)) {
                // 2, 插入AppMethodBeat.at方法
                traceWindowFocusChangeMethod(mv, className);
            }
        }
    }
       @Override
    protected void onMethodExit(int opcode) {
        TraceMethod traceMethod = collectedMethodMap.get(methodName);
        if (traceMethod != null) {
            traceMethodCount.incrementAndGet();
            mv.visitLdcInsn(traceMethod.id);
            //3, 插入 AppMethodBeat.o 方法
            mv.visitMethodInsn(INVOKESTATIC, TraceBuildConstants.MATRIX_TRACE_CLASS, "o", "(I)V", false);
        }
    }
  //...省略
}

traceWindowFocusChangeMethod()：

private void traceWindowFocusChangeMethod(MethodVisitor mv, String classname) {
    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);
}

总结编译期插桩主要做了三件事（图片来自官方）：

在onMethodEnter()中插入AppMethodBeat.i方法
收集所有的Activity及其子类，在onWindowFocusChange方法中插入AppMethodBeat.at方法
在onMethodExit() 插入 AppMethodBeat.o 方法
注意：并不是所有的方法都执行插桩，只有属于我们需要收集的方法才会走插桩逻辑，优化插桩性能！

onMethodEnter() App所有方法的进入都会回调； onMethodExit App所有方法的退出都会回调

OK，编译插桩的基本原理已经清楚，现在我们回到EvilMethodTracer类的分析。

一、构造方法

public EvilMethodTracer(TraceConfig config) {
    this.config = config;
    // evil阈值 默认是700ms，外部可以设置
    this.evilThresholdMs = config.getEvilThresholdMs();
    //evil 开关
    this.isEvilMethodTraceEnable = config.isEvilMethodTraceEnable();
}

简单，配置了两个变量值： evil阈值、evil开关。

二、触发时机 onAlive

在第三篇文章分析中我们知道，TracePlugin的start()方法会调用trace的onStartTrace方法。

@Override
public void start() {

//省略...

if (traceConfig.isEvilMethodTraceEnable()) {
    evilMethodTracer.onStartTrace();
}

if (traceConfig.isStartupEnable()) {
    startupTracer.onStartTrace();
}
//省略...
}

而trace的onStartTrace方法则会调用onAlive方法。所以，我们直接看onAlive方法：

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

向UIThreadMonitor中注册监听，肯定是监听三个回调方法：

dispatchBegin 消息分发开始前
dispatchEnd 消息分发结束后
doFrame 每一帧消息都会回调

每个方法的详细参数分析，可以参考第3篇文章。这里就不在详述了。

接着我看回调方法里面做了什么。

三、回调逻辑处理

3.1 dispatchBegin


@Override
public void dispatchBegin(long beginNs, long cpuBeginMs, long token) {
    super.dispatchBegin(beginNs, cpuBeginMs, token);
    indexRecord = AppMethodBeat.getInstance().maskIndex("EvilMethodTracer#dispatchBegin");
}

总结：

通过AppMethodBeat的maskIndex方法，记录looper中消息处理开始时的下标index。

这里肯定会有一个疑问：下标index是什么？

我们先简单理解：

AppMethodBeat内部会维护一个long[]数组:sBuffer。还记的之前的插桩函数吗？只要某个方法被调用那么就会回调到AppMethodBeat的i/o方法。

因此，matrix在i和o方法中会把 [ isIn标记（是不是i方法）+当前方法id（methodId）+耗时（duration）]，封装为一个长度64位的long数据，在插入到sBuffer数组中。

而插入的下标是成员变量index，在每次插入后都会自增操作。当index自增超过sBuffer的长度后，又会从0开始重新自增。

至此，我们知道上述方法其实就是记录一个index开始值，方便后续获取堆栈。

具体实现的细节暂时不去深究，有兴趣的可以看后续的第五篇文章。

3.2 doFrame


@Override
public void doFrame(String focusedActivity, long startNs, long endNs, boolean isVsyncFrame, long intendedFrameTimeNs, long inputCostNs, long animationCostNs, long traversalCostNs) {
    queueTypeCosts[0] = inputCostNs;
    queueTypeCosts[1] = animationCostNs;
    queueTypeCosts[2] = traversalCostNs;
}

简单：记录绘制耗时的三个子阶段的耗时： input、animation、traversal。

3.3 dispatchEnd

@Override
public void dispatchEnd(long beginNs, long cpuBeginMs, long endNs, long cpuEndMs, long token, boolean isVsyncFrame) {
    super.dispatchEnd(beginNs, cpuBeginMs, endNs, cpuEndMs, token, isVsyncFrame);
    long start = config.isDevEnv() ? System.currentTimeMillis() : 0;
    long dispatchCost = (endNs - beginNs) / Constants.TIME_MILLIS_TO_NANO;
    try {
        //达到阈值开始处理 默认是700ms
        if (dispatchCost >= evilThresholdMs) {
            //1，根据indexRecord标记，获取堆栈数据？？具体怎么弄？
            // startIndex：之前标记的index。
            //endIndex: 当前index。
            long[] data = AppMethodBeat.getInstance().copyData(indexRecord);
            long[] queueCosts = new long[3];
            //copy 三个阶段的耗时：input、animation、traversal
            System.arraycopy(queueTypeCosts, 0, queueCosts, 0, 3);
            //得到当前页面
            String scene = AppMethodBeat.getVisibleScene();
            //2，post 一个AnalyseTask，开始分析
            MatrixHandlerThread.getDefaultHandler().post(new AnalyseTask(isForeground(), scene, data, queueCosts, cpuEndMs - cpuBeginMs, dispatchCost, endNs / Constants.TIME_MILLIS_TO_NANO));
        }
    } finally {
        //3，删除改节点
        indexRecord.release();
        if (config.isDevEnv()) {
            String usage = Utils.calculateCpuUsage(cpuEndMs - cpuBeginMs, dispatchCost);
            MatrixLog.v(TAG, "[dispatchEnd] token:%s cost:%sms cpu:%sms usage:%s innerCost:%s",
                    token, dispatchCost, cpuEndMs - cpuBeginMs, usage, System.currentTimeMillis() - start);
        }
    }
}

总结

达到卡顿阈值，开始从AppMethodBeat的sBuffer数组中获取堆栈区间。得到一个long数组。
在matrix的工作线程中开始分析task
删除我们之前在dispatchBegin方法中标记的开始节点indexRecord

在1点中我们已经拿到卡顿的堆栈了！！所以优先看下第2点中AnalyseTask类的analyse方法：

void analyse() {

    // process
    //获取进程的信息：priority, nice。nice值越低表示进程抢占CPU的执行权越强
    int[] processStat = Utils.getProcessPriority(Process.myPid());
    //根据线程时间和当前花费的时间，计算得到线程（这里是主线程）处于running状态的时间占整个耗时的时间
    //用来干啥？ 用来判断主线程在App卡顿的时候是不是处于繁忙的状态。如果主线程的CPU占用率高，则以为着主线程做了太多的工作。
    String usage = Utils.calculateCpuUsage(cpuCost, cost);
    LinkedList<MethodItem> stack = new LinkedList();
    if (data.length > 0) {
        //根据data来构造堆栈集合
        TraceDataUtils.structuredDataToStack(data, stack, true, endMs);
        //裁剪堆栈
        TraceDataUtils.trimStack(stack, Constants.TARGET_EVIL_METHOD_STACK, new TraceDataUtils.IStructuredDataFilter() {
            @Override
            public boolean isFilter(long during, int filterCount) {
                //耗时小于 30*5=150ms,则过滤
                return during < filterCount * Constants.TIME_UPDATE_CYCLE_MS;
            }

            @Override
            public int getFilterMaxCount() {
                return Constants.FILTER_STACK_MAX_COUNT;
            }

            @Override
            public void fallback(List<MethodItem> stack, int size) {
                MatrixLog.w(TAG, "[fallback] size:%s targetSize:%s stack:%s", size, Constants.TARGET_EVIL_METHOD_STACK, stack);
                Iterator iterator = stack.listIterator(Math.min(size, Constants.TARGET_EVIL_METHOD_STACK));
                while (iterator.hasNext()) {
                    iterator.next();
                    iterator.remove();
                }
            }
        });
    }


    StringBuilder reportBuilder = new StringBuilder();
    StringBuilder logcatBuilder = new StringBuilder();
    //去最大耗时值
    long stackCost = Math.max(cost, TraceDataUtils.stackToString(stack, reportBuilder, logcatBuilder));
    //得到stackKey 唯一
    String stackKey = TraceDataUtils.getTreeKey(stack, stackCost);

    MatrixLog.w(TAG, "%s", printEvil(scene, processStat, isForeground, logcatBuilder, stack.size(), stackKey, usage, queueCost[0], queueCost[1], queueCost[2], cost)); // for logcat

    // report
    try {
        TracePlugin plugin = Matrix.with().getPluginByClass(TracePlugin.class);
        if (null == plugin) {
            return;
        }
        JSONObject jsonObject = new JSONObject();
        jsonObject = DeviceUtil.getDeviceInfo(jsonObject, Matrix.with().getApplication());

        jsonObject.put(SharePluginInfo.ISSUE_STACK_TYPE, Constants.Type.NORMAL);
        jsonObject.put(SharePluginInfo.ISSUE_COST, stackCost);
        jsonObject.put(SharePluginInfo.ISSUE_CPU_USAGE, usage);
        jsonObject.put(SharePluginInfo.ISSUE_SCENE, scene);
        jsonObject.put(SharePluginInfo.ISSUE_TRACE_STACK, reportBuilder.toString());
        jsonObject.put(SharePluginInfo.ISSUE_STACK_KEY, stackKey);

        Issue issue = new Issue();
        issue.setTag(SharePluginInfo.TAG_PLUGIN_EVIL_METHOD);
        issue.setContent(jsonObject);
        // 组合数据，格式为json，抛到上层
        plugin.onDetectIssue(issue);

    } catch (JSONException e) {
        MatrixLog.e(TAG, "[JSONException error: %s", e);
    }

}

说明：主要分为两个部分：

获取卡顿现场的信息
上报卡顿信息拼接各种耗时、堆栈、顶层view等抛给上层。

我们重点看下卡顿的信息怎么获取。

3.3.1 获取卡顿现场的信息

获取进程信息：包含优先级、nice值。 nice值越低表示进程抢占CPU的执行权越强
计算主线程CPU占用率
得到堆栈的耗时
获取堆栈并对堆栈进行裁剪，得到卡顿的唯一标识：stackKey

3.3.1.1CPU占用率问题：

我们知道不管什么卡顿，其实最终都会反映到CPU的执行耗时上。因此，当发生卡顿的时候我们一般会比较关心三个CPU指标：

系统的CPU占用率
当前进程的CPU占用率
某个线程（如主线程）的CPU占用率

1，系统的CPU占用率：

可以通过在T1、T2两个时间点分别访问系统/proc/stat中的CPU执行信息，计算得到T1~T2这段时间内CPU总的执行时间total和空闲idle的时间。两者相减得到占用时间used。 used/total就得到系统的CPU占用率。不过很遗憾，Android 8后，Google已经关闭了访问权限。暂时没有找到好的方法，有大神知道麻烦告诉我~~

2，进程的CPU占用率：

同理，我们分别去采样系统的/proc/stat（无法访问）和/proc/pid/status（可以访问）。得到总的CPU执行时间total和当前进程的CPU执行时间pUsed。 pUsed/total就得到当前进程的CPU占用率。matrix 也是用的这种。也是因为权限问题，所以计算一直都是0。

3，主线程的CPU占用率

matrix通过 SystemClock.currentThreadTimeMillis()方法，该方法会返回当前线程处于running状态的毫秒时间。因此，在dispatcheBegin和dispatcheEnd两个节点处，计算得到真个消息处理的过程红的主线程处于running耗时cpuCost。

//dispatchCost就是消息执行的总体耗时
String usage = Utils.calculateCpuUsage(cpuEndMs - cpuBeginMs, dispatchCost);

public static String calculateCpuUsage(long threadMs, long ms) {
    if (threadMs <= 0) {
        return ms > 1000 ? "0%" : "100%";
    }

    if (threadMs >= ms) {
        return "100%";
    }

    return String.format("%.2f", 1.f * threadMs / ms * 100) + "%";
}

因此可以得到卡顿过程中主线程处于running态的CPU时间占用。通过这个指标可以看出卡顿发生时候，如果占用率高则说明主线程是否有很多耗时的工作？需要引起我们注意。

举个例子（经测试），如果在主线程调用了sleep方法（会释放CPU），虽然检测到卡顿，但是usge肯定是很低的。2%左右

如果是主线程工作太多，如嵌套10000循环导致卡顿，那么usage肯定很高。97%左右

具体可以参考CPU占用率

3.3.1.2 堆栈的格式问题

可能会有人对matrix的堆栈格式感到疑惑。我们从源码中找下答案。

//去最大耗时值
long stackCost = Math.max(cost, TraceDataUtils.stackToString(stack, reportBuilder, logcatBuilder));

public static long stackToString(LinkedList<MethodItem> stack, StringBuilder reportBuilder, StringBuilder logcatBuilder) {
    logcatBuilder.append("|*\t\tTraceStack:").append("\n");
    logcatBuilder.append("|*\t\t[id count cost]").append("\n");
    Iterator<MethodItem> listIterator = stack.iterator();
    long stackCost = 0; // fix cost
    while (listIterator.hasNext()) {
        MethodItem item = listIterator.next();
        //拼接堆栈数据 
        reportBuilder.append(item.toString()).append('\n');
        logcatBuilder.append("|*\t\t").append(item.print()).append('\n');

        if (stackCost < item.durTime) {
            stackCost = item.durTime;
        }
    }
    return stackCost;
}

这里会拼接堆栈数据，我们继续看下item.toString()方法：

@Override
public String toString() {
       //调用深度+ 逗号+ 方法id+逗号+调用次数+逗号+耗时
    return depth + "," + methodId + "," + count + "," + durTime;
}

可以看到，格式就明朗了。

4 总结

总的来说，有了前面文章的铺垫，EvilMethodTracer类显得简单很多了。它主要职责是通过编译期插桩的i/o方法来计算在消息处理过程中每个函数的调用耗时。并且根据调用链生成调用堆栈，然后对堆栈进行裁剪，结合进程相关的一些信息抛给上层监听。

上层接收卡顿信息后可自己做处理。如：debug环境下弹窗显示卡顿信息或者上报到业务服务端，通过grafana大盘的形式进行实时统计展示。

[Matrix系列-4]： TracePlugin 之 EvilMethodTracer 源码分析

前言

背景