vert.x 源码

前言

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

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

[Matrix系列-1]： matrix 启动流程源码解析

[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); } 

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

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

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

• 总结

1. 达到卡顿阈值，开始从AppMethodBeat的sBuffer数组中获取堆栈区间。得到一个long数组。
2. 在matrix的工作线程中开始分析task
3. 删除我们之前在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); } } 

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

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

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

3.3.1 获取卡顿现场的信息

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

3.3.1.1CPU占用率问题：

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

1. 系统的CPU占用率
2. 当前进程的CPU占用率
3. 某个线程（如主线程）的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大盘的形式进行实时统计展示。