对Arthas-Trace命令的一次深度剖析，竟发现...

前言：此文仅为笔者学习Arthas源码的一次尝试，不对本文结论负全部责任。

一、背景

笔者在学习arthas这个十分方便的小工具的过程中，发现：

目前据arthas官方解释：因为trace多层是十分消耗资源的，因此trace命令只会支持一层的耗时分析。
如果出现如下图的情况，trace命令的处理就会变得十分麻烦。

因此，是否可以考虑在arthas中增加一个命令或者给trace命令增加一个参数，来使其支持分析多层结果？
那么理应设立一种规则，如：

• 展开最大耗时方法的明细
• 展开大于多少耗时的方法明细
• 展开耗时前n个方法的明细

本文假定将规则定为展开耗时前n个方法的调用明细。

二、一些初步尝试

2.1、正常trace命令流程

2.2、使用-E+多个类层级向下展开

一次Trace命令只会调用出一层方法耗时情况，那么在结果出来前应当是不知道哪个方法是耗时最长的，那么在不改变Trace底层逻辑的情况下，可以使用-E+ |来模拟到多层分析结果。例如：

2.2.1、使用Trace命令查看第一层调用情况

trace Main toPrint -n 5

2.2.2、将红框中的耗时最大的方法-的类名和方法名复制，写入命令中，然后再触发一次请求

trace -E Main|Main toPrint|toPrintD -n 5

可以看到，是可以实现多层展示的。

2.2.3、继续下钻

若需要继续下钻，则重复2.2.2的操作

2.2.4、总结

（本次案例结构简单，可能看上去不直观，可自行找复杂的场景试试）

这样做有两个不便之处：

• 需要多次动用复制粘贴快捷键，来复制到新的命令中
• 需要调用多次方法（但一般而言，调试过程中多调用几次，个人觉得影响不大）

三、源码分析

正所谓知己知彼方能百战不殆，接下来这部分通过分析源码，来了解shell上输入一个arthas命令执行从输入到输出，在这过程中arthas做了什么处理，怎么做到的。以jad java.lang.String为例。

这儿arthas已经是启动状态了，即arthas已经启动了监听器在监听命令行，就等着输入命令。

3.1、接收shell命令

首先会在com.taobao.arthas.core.shell.handlers.term.RequestHandler的accept方法，接收到该请求。参数line为输入的命令。

接着会调用handle方法，最终会走到ShellLineHandler的handle方法。

3.2、一些即时命令的处理&准备调用createJob

一些如jobs、fg等命令会直接处理返回，后续就不会创建job任务做处理。

其余情况，准备调用createJob方法。

3.3、createJob

这个方法会不断往深处调用，最终具体逻辑实现在com.taobao.arthas.core.shell.system.impl.JobControllerImpl#createJob。

这里有两个地方是主要的逻辑，一个是createProcess创建Process对象，一个是将创建的Process对象转换成job。这两步后面都会详说。

3.4、createProcess

这儿是先通过命令拿到command，然后创建用其创建Process返回。

3.5、createCommandProcess

除了这个方法会对管道符以及一些特殊命令做特殊处理外，就是对command做一个封装，吐出一个Process对象。

3.6、new JobImpl方法

在3.5后，一路返回走到3.3中所说的构建JobImpl方法。实际上也就是一个封装作用的方法，最后将构建好的job返回出去。

返回后，到3.2中的代码处，准备调用job.run方法。

3.7、job.run

实际上job.run也就是会去调用job中Process对象的run方法。最终也就是将process传入CommandProcessTask的构造方法，去创建线程跑。

CommandProcessTask的run方法实际上是在执行handler的handle方法去处理process。

1、handle方法会去调用command中的processHandler属性值去进行具体的命令处理。

2、接着AnnotatedCommandImpl的process方法最后又会去调用com.taobao.arthas.core.shell.command.AnnotatedCommand#process这个方法。

3、最后，AnnotatedCommand又如图一样多个子类，会去调用具体命令的AnnotatedCommand的子类的process方法。

此处即会走到JadComm的process方法。随即在此方法中进行详细处理，输出结果等。

四、设计方案&具体内容

4.1、方案A：模拟多层调用

4.2、方案B：Trace内部向下调用多层

4.3、方案分析

首先，大致讲一下Trace命令的执行原理。分两步：

第一步，在输入trace命令后，会对参数中需要监听的方法，进行字节码增强。

在com.taobao.arthas.core.command.monitor200.TraceAdviceListener#invokeBeforeTracing这个方法中插入，调试可以看到参数类中平层的所有方法都有调用到，如图中的toPrintB(i);toPrintD(i);toPrintE(i);三个方法均会进行字节码增强操作。

第二步，在监听的方法被调用后，输出相应的结果。

那么，理论上这儿可以在第一步进行字节码增强时进行多层字节码增强操作，但是此时耗时结果是没有出来的，即我们无法实现第一大节中假定的规则：展开耗时前n大方法的调用明细。最终可能会导致输出多层的全部调用链路，这显然是不合理的。那么理论上方案B实现效率比较低。

4.3.1、方案实现流程图

五、具体内容&效果

5.1、源码改动部分

5.1.1、TraceCommand新增参数

//新增参数analysisLen代表展开前n耗时方法
private int analysisLen = 0;
//绑定逻辑
@Option(shortName = "L", longName = "analysisLen")
@Description("the length to analysis time")
public void setAnalysisLen(int setLen) {
    this.analysisLen = setLen;
}
public int getAnalysisLen() {
    return analysisLen;
}

5.1.2、AbstractTraceAdviceListener新增新参数处理逻辑

//加在com.taobao.arthas.core.command.monitor200.AbstractTraceAdviceListener#finishing原逻辑if (conditionResult) {}前面

if(command.getAnalysisLen() >= 1){
    //多层分析
    List<String> stringRusults = AnalysisUtils.analysis(command.getAnalysisLen(),process.args(),command,traceEntity);

    String traceOneMethod = "";
    //将stringRusults.get(2)-最后 加在该字符串
    for(int i=2;i<stringRusults.size();i++){
        traceOneMethod+=stringRusults.get(i);
    }

    process.end(1, "the longest "+command.getAnalysisLen()+" method is "+stringRusults.get(0)
            +" and you can use this command to get more info:\n"+stringRusults.get(1)
            +"\n"+traceOneMethod);

}

5.1.3、AnalysisUtils工具类

public class AnalysisUtils {

    /** @Description: 将最长的n个方法以及优化的方法返回
    * @Param: [args, command, traceEntity]
    * @return: java.util.List<java.lang.String>
    * @Author: lz
    * @Date: 2023/5/19
    */
    public static List<String> analysis(Integer num , List<String> args,
                                        TraceCommand command, TraceEntity traceEntity) {
        List<String> stringRusult = new ArrayList<>();
        //1、找到所有的叶子节点，并存在一个list里面
        List<MethodAnalysis> methodList = new ArrayList<>();
        buildMethodList(methodList,traceEntity.getModel().getRoot());
        //2、排序一下
        Collections.sort(methodList, new Comparator<MethodAnalysis>() {
            @Override
            public int compare(MethodAnalysis o1, MethodAnalysis o2) {
                return o2.getTimeCost().compareTo(o1.getTimeCost());
            }
        });
        //3、取出最长的n个值 同时取一下方法名和类名
        StringBuilder methodLongestLength = new StringBuilder();
        StringBuilder classString = new StringBuilder(command.getClassPattern());
        StringBuilder methodStrign = new StringBuilder(command.getMethodPattern());
        for(int i = 0 ;i < num; i++){
            MethodAnalysis methodAnalysis = methodList.get(i);
            methodLongestLength.append(methodAnalysis.getMethodName());
            if(i != num-1){
                methodLongestLength.append(" and ");
            }
            classString.append("|").append(methodAnalysis.getClassName());
            methodStrign.append("|").append(methodAnalysis.getMethodName());

        }
        //考虑如何灵活赋值
        Integer classIndex = getArgsClassInxdex(args);
        args.set(classIndex, classString.toString());
        args.set(classIndex+1, methodStrign.toString());

        stringRusult.add(methodLongestLength.toString());
        //4、输出优化的方法
        String firstArg = "";
        if(command.isRegEx()){
            firstArg = "trace ";
        }else {
            firstArg = "trace -E ";
        }
        StringBuilder methodAfterDeal = new StringBuilder(firstArg);
        for(String childString : args){
            //遇到'-L'跳出
            if(childString.equals("-L")){
                break;
            }
            methodAfterDeal.append(childString);
            methodAfterDeal.append(" ");
        }


        stringRusult.add(methodAfterDeal.toString());

        //将每个单独的方法的trace命令也列出来
        for(int i = 0 ;i < num; i++){
            MethodAnalysis methodAnalysis = methodList.get(i);
            String oneTraceMethod = "";
            oneTraceMethod += "if you want just know the time-analysis for "+ methodAnalysis.getClassName()+"."+methodAnalysis.getMethodName();
            oneTraceMethod += " you can use this command: \n"+"trace "+methodAnalysis.getClassName()+" "+methodAnalysis.getMethodName()+" -n 5\n";
            stringRusult.add(oneTraceMethod);
        }

        //调试debug
//        String de = "";
//        de = JSONObject.toJSONString(methodList);
//        stringRusult.add(de);

        return stringRusult;
    }


    private static Integer getArgsClassInxdex(List<String> args) {
        //获取class的index，
        // 如trace -E com.dao.xxxx.controler 为2
        // 如trace com.dao.xxx.contoller 为1
        for(int i = 0 ; i < args.size(); i++){
            //-E
            String arg = args.get(i);
            if(arg.equals("-E")) {
                continue;
            }
            if(arg.equals("--skipJDKMethod")){
                continue;
            }
            if(arg.equals("false")){
                continue;
            }
            if(arg.equals("true")){
                continue;
            }
            return i;
        }
        return 0;
    }

    private static void buildMethodList(List<MethodAnalysis> methodList, TraceNode root) {

        if(root.getChildren() == null){
            MethodNode node = (MethodNode) root;
            MethodAnalysis methodAnalysis = new MethodAnalysis();
            methodAnalysis.setMethodName(node.getMethodName());
            methodAnalysis.setClassName(node.getClassName());
            methodAnalysis.setTimeCost(BigDecimal.valueOf(node.getTotalCost()));
            methodList.add(methodAnalysis);
        }else {

            for(TraceNode node : root.getChildren()){
                buildMethodList(methodList , node);
            }
        }

    }

    private static void getAllJsonString( TraceNode root,String re) {
        String s = JSONObject.toJSONString(root);
        re+=s;
        if(root.getChildren() == null){
            return;
        }
        for(TraceNode node : root.getChildren()){
            getAllJsonString(node,re);
        }

    }


    protected static class MethodAnalysis{
        private String methodName;
        private String className;
        private BigDecimal timeCost;
        //省略set get等方法
    }

}

5.1.4、其它

其它的是前期学习阶段，对pom文件的一些改动。如拉取的版本为3.6.7改为3.6.8、在sore模块中加了个maven的编译插件等。

• 1、如果编译不成功，报一些包找不到的话。可能是jdk版本不对，官方说法是jdk8一定可以编译成功，我下载了很多版本，最终用的评论区推荐的jdk1.8.0_372。
• 2、本地windows编译，推荐使用执行as-package.sh，将最新代码编译打包至C:\Users\用户名\.arthas\lib中。详情可点击->官方链接。

5.2、效果

• 可以看到，在Trace命令后加入-L 2 后，结果将返回耗时最长的两个方法，并将后续可以直接深入查看这两个方法的执行情况的Trace命令返回。
• 这儿还分别将单独Trace这两个方法的命令给出来了，算是一个小优化，如果不关心父方法的耗时情况，就可以直接往下Trace。

5.3、总结

1、本次方案是将2.2的步骤交给arthas执行，提高排查效率，减轻开发人员的操作成本。

2、当-L后的参数过大时，可能会超时，后续考虑优化分析效率。

六、后续升级思路

目前是需要两次调用来拿到最终数据。如果需要一次trace命令直接拿到最终数据，就需要在代码字节码增强时就直接将两层全部插入字节码。然后接口触发时，将原本应当返回多层的耗时分析树进行剪枝，如将所有的叶子节点的上一层进行比较，保留唯n的分枝，其余全部去除，最后返回。（思路如此，但感觉会超时，因为分析一旦超时，就无法正常地将TraceNode正常转换为MethodNode，或者说无法得到准确的分析数据）