背景

部门内有个报表项目Project1，说是操作几次报表全表审核，容器就会重启，k8s容器给了4个G。然后这次的任务就是优化一下这个接口。
这个报表类似于一个在线Excel，全表审核就是对整套表的数据进行公式运算审核出不符合条件的单元格等信息。项目Project1的报表1功能模块有42张表，也就是点击全表审核的时候，需要对42张表进行审核。
前端点击全表审核的按钮，后台并发审核42张表，最后所有的表审核完成之后，得到结果返回给前端。
项目Project1使用到的报表控件是平台部门写的，年中的时候因为这个报表项目性能太差安排了我优化过一轮，相当于自己拿过来定制了一版，速度相比之后速度提升巨大。优化前，根节点那家一点击全表审核服务直接崩溃，开发组改成了前端单表循环请求单表审核，大概要20分钟左右才能完成。优化后部门B项目审核3000多家数据大约半个小时，根节点全表审核到了5秒以内。
也就是说对于项目Project1，应该不是我之前优化遇到的那些问题导致的，所以得重新排查。

这一轮优化前，选中的abc节点全表审核请求需要耗费12秒，因为全表审核涉及到报表和公式，需要耗费的内存比较多，所以只要把执行速度优化，崩溃的问题就能最大限度的解决。

用到的技术

公式审核的时候用到了aviator引擎，然后在上面二次封装。aviator是一个表达式引擎，每一个自定义公式都可以对应一个实现类，只要这个实现类继承AbstractVariadicFunction类，然后重新对应的call方法。
比如编造一个审核公式：sum('E') == sum('sheet1!F')，当aviator执行这个公式的时候，就会调用我们注册到aviator的sum公式。

evaluatorInstance.addFunction(new AbstractVariadicFunction() {
                @Override
                public String getName() {
                    return "sum";
                }

                @Override
                public AviatorObject variadicCall(Map<String, Object> env, AviatorObject... args) {
                	// 具体的执行逻辑
                    return null;
                }
            });

因为二次封装过，所以继承的是其他的类，然后通过SPI机制读取并添加的aviator中，效果同直接用aviator一样。

使用arthas排查

因为前面针对报表项目优化过一轮，所以报表公共代码是没有什么问题的了，所以这次排查的重点是公式类。

启动arthas并附加到Java进程

首先启动项目，然后启动arthas并附加到对应的项目上。

 java -jar arthas-boot.jar

monitor命令查看公式类被调用次数和平均耗时

监测CustomFormula所有子类call方法的执行（包名和类名这里瞎写的）

monitor com.test.CustomFormula call  -m 83 -c 13

-c代表统计周期，默认值为120秒，这里设置成13秒，因为全表审核需要12秒，当我们执行完全表审核之后，再过一下就能输出统计信息了。
-m用来指定 Class 最大匹配数量，默认值为50，因为我们这自定义的公式类数量大于50个，所以给到了83。如果大于默认值而又不设置-m，会报The number of matched classes is 82, greater than the limit value 50. Try to change the limit with option '-m <arg>'错误。
输入命令之后回车，然后操作全表审核，就会输出统计信息，输出完成之后，可以按ctrl + c退出monitor命令。下面这个图是优化之后的，所以avg-rt都很小，优化前有4个公式平均耗时很大。

如果需要把执行结果写入文件，可以使用如下命令把结果写入指定文件（类似于Linux里面的操作，覆盖附加之类的也可以，按需改造）

monitor com.test.CustomFormula call  -m 83 -c 13 > D:\\monitor01.txt

通过monitor命令，知道了项目Project1一次全表审核需要调用大概八万五千次自定义公式，其中五万次的那个公式A和另外三个B、C公式耗时最多（公式名这里瞎编的，还有上面的图是优化之后的，所以看上去不慢）。
公式A是用来获取报表数据的，写在报表控件里面，可以获取当前表的也可以跨表获取，可以获取单个单元格的值，也可以根据条件获取多列的（类似SUMIF，不过不是），这个调用了五万次，优化前耗费了8秒。
公式B、C是项目Project1自己自定义的，调用次数在一万次（2秒）和两千次（1秒）不等。
因为公式A代码逻辑比较复杂，而且不同的单元格取数规则执行速度不一，所以光靠这个命令无法得出结论，然后就去看了公式B、C的源码。发现里面只是拿当前用户的所在岗位和是否做了某一步处理。也就是说，一次全表审核的时候，这个公式执行的结果一定是一样的，只需要调用一次。然后在这两个公式中添加了一个缓存处理，确保其一次全表审核只调用一次获取数据的逻辑，后续调用直接从共享工具里面拿（年中优化的时候，引入了一个共享工具，主要用处是在同一请求当中，各子线程能共享数据，请求结束就销毁）。改造完成之后，重新执行monitor命令，发现这两个公式耗时已经可以忽略不记了。

tt命令查看公式单次调用信息

monitor命令只能查看总的调用次数和平均时间，无法查看单个调用的耗时以及请求参数等。想看的话，可以通过tt命令。如果你确定了具体的类，可以直接使用子类，而不是用父类，这里演示还是使用父类。

tt -t com.test.CustomFormula call -n 40000 -m 83

-t参数指定需要记录的次数，当达到记录次数时 Arthas 会主动中断 tt 命令的记录过程
-m用来指定 Class 最大匹配数量，同上
注意：tt 相关功能在使用完之后，需要手动释放内存，否则长时间可能导致OOM。退出 arthas 不会自动清除 tt 的缓存 map
使用tt --delete-all命令清除释放
如果执行的次数太多，可以通过> D:\\tt01.txt将结果写入到tt01.txt文件，然后来分析（可以把数据复制到excel里面，根据耗时排序，找出耗时占比最多的INDEX，还可以使用透视图等工具来统计信息）。这里我们可以看到单个公式被调用的耗时。

查看对应执行信息可以通过-i参数后边跟着对应的INDEX编号查看到他的详细信息。比如tt -i 45009可以查看到形参和返回值，形参有助于我们排查问题。

这里拿最慢的一张表的tt结果来讲：根据tt的结果，可以发现，公式A耗时在1毫秒以上的有340个，其中8毫秒以上的有320个，还有部分在10、50、100毫秒以上的，主要是这340个公式导致的速度很慢，剩下的几万个耗时3秒不到（其中最慢的一张表剩下的几万个耗时只有1.5秒，符合预期）
放一张优化前的最耗时的一张表的单表审核tt截图，这个是把tt的结果写入到了文件，然后复制到excel里面按距离分割，筛选（也可以在tt的时候使用条件表达式来过滤想要的），最后根据COST排序得出的。

通过tt -i INDEX查看耗时的几个参数的形参（可以加上 | grep xxxx来过滤），发现了两个现象，一个是有7张表大量的单元格被重复使用，但是每次都会执行拿单元格数据的逻辑，这7张表的数据是不需要每次都去重复执行的（其实这里是项目Project1当时设计这一块功能有问题，这几张表不属于这部分的，但是又要取数据，问了一下说暂时不动逻辑，所以不能剔除这几张表改成其他方式来获取），后面给公式A针对这几个表加了一个缓存机制，也是使用共享工具来存储，然后在项目Project1新建一个全类名一样的公式类A用来覆盖控件内的公式类A。

trace命令分析方法内部执行代码耗时

改造了一次之后，重新运行，发现速度大幅提升，但是还是需要好几秒，主要耗时在取sheet2的数据上，取这个表的数据需要根据某些条件获取部分单元格汇总数据，而且每个单元格只用了一次（所以不能使用缓存的方式），但是公式量多，所以这部分需要优化一下代码。
为了查看方法执行内部各代码耗时，就需要使用trace命令。

trace命令可以看到方法内部调用路径，并输出方法路径上的每个节点上耗时

因为现在可以确实是公式A需要优化，所以trace公式类A的call方法
trace com.test.A call -n 3 --skipJDKMethod false
-n设置命令执行次数，默认值为 100，这里设置了3次，也就是说如果被调用了三次，就会停止追踪。
--skipJDKMethod false 默认情况下，trace不会包含jdk里的函数调用，如果希望trace jdk里的函数，需要显式设置。
也可以通过>的方式将结果写入到文件中

通过排查call方法，发现某行代码执行占比过大，然后再继续trace那行代码所调用的方法，就找到了耗时最多的代码，然后改造那一行代码，把每次都从redis拿改成只拿一次，速度就提升了。
改造完成之后，一次全表审核速度到了2秒左右，符合预期。

cls清空屏幕

有时输出的内容太多，需要清空屏幕，可以使用cls命令。

history查询历史命令

如果下次启动arthas，想找到之前执行的命令，可以通过history命令

StopWatch工具类

其实如果公式量更大的话，使用tt来看是不太方便的（但是tt不用改代码，这个需要改动代码，看自己想用哪种了），因为只能每次查看一个INDEX的形参，所以还用到了StopWatch工具类来计时，然后为了统计方便，每个线程（表）创建一个StopWatch，然后在公式中获取这个对象来使用。
具体步骤如下：

1. 主线程创建一个容器，用来存放StopWatch对象，key为线程名称或者线程对象本身，value为StopWatch对象，这个容器得确保其他线程也能拿到，我这是方法一个本地线程共享工具当中，子线程中都可以访问工具里面存放的内容，代码执行完成后释放;
2. 使用CompletableFuture添加任务，任务代码体里面初始化一个StopWatch对象，然后放到容器中

   // org.springframework.util.StopWatch
   StopWatch stopWatch = new StopWatch("编号");
   容器.add("线程-" + Thread.currentThread().getName(), stopWatch);
   

3. 公式call方法里面获取使用（为了防止有报错的情况出现，可以用try包裹，防止任务停止代码不被执行导致报错）

   // 某个公式call方法内部
   StopWatch stopWatch = 容器.get("线程-" + Thread.currentThread().getName());
   // 启动任务
   //------具体代码逻辑
   // 停止任务
   

4. 所有任务执行完成之后，把结果写入文件（控制台输出的话太多了，几万行，如果实在想，记得代码筛选想要的任务）；

   CompletableFuture.allOf(tasks.toArray(new CompletableFuture[0])).join();
   StringBuilder stringBuilder = new StringBuilder();
   for (Map.Entry<String, Object> entry : 容器.entrySet()) {
   	StopWatch value = (StopWatch) entry.getValue();
   	stringBuilder.append("\r\n\r\n\r\n");
   	stringBuilder.append(value.prettyPrint());
   }
   // 写入文件，记得:得替换掉
   File file = FileUtil.newFile("E:\\" + DateUtil.formatDateTime(new Date()).replace(":", "_"));
   try {
   	file.createNewFile();
   } catch (IOException e) {
   	throw new RuntimeException(e);
   }
   FileUtil.writeUtf8String(stringBuilder.toString(), file);
   

5. 记得销毁对象，我这容器因为是方法共享工具中，在外部会直接销毁掉