背景  

     最近接手一个项目，里面有个http接口请求超过了100s的时间，居然还有调用方来调用这个接口。。。于是受命优化这个接口的请求时长，就想到了Arthas工具。

一、Arthas 简介

Arthas 是Alibaba开源的Java诊断工具，深受开发者喜爱，使用详见官方文档。

二、trace 命令分析接口执行耗时

Arthas 中的 trace 命令能够输出方法内部调用路径，并输出方法路径上的每个节点上耗时。

trace 命令使用，见文档。

由于生产容器运维不给权限安装Arthas，只能在测试环境容器安装了Arthas分析了一下。trace命令输出结果如下图：

        可以看到测试环境该接口耗时41905.992722ms（约合42s），时长非常长了。从方法内部调用路径，可以看出有个方法调用占据了大部分时间：dataPerformanceDeal() 方法。这个方法在代码中出现了两次，都是在循环体中执行的，从“count=507” 可以知道循环体执行了507次，该方法一共执行了 507 * 2 = 1014 次，累计耗时 17913ms + 20055ms = 37968ms，约38s，占了整个接口执行时长的绝大部分。经过阅读代码，发现dataPerformanceDeal() 方法可以认为就是从数据库中查数据，“min = 2.656515ms”和“max=81.50584ms”代表循环执行507次中调用耗时最短和最长的那一次。尽管这个SQL每次执行都不算慢，最长一次也才100ms，但是超过1000次的调用也导致累计时长很久（需要频繁获取数据库连接）。由于上图没有截全，底部还有一个SQL查询也是在循环体中，占去了41s-38s=3s中的一半时长。

三、优化

       改写dataPerformanceDeal() 方法中的SQL语句，把循环体中的每次单次查询，改为一次批量SQL查询。这里需要对批量查询的SQL进行分析优化，避免出现慢查询。经过改写验证后的批量查询SQL一次执行只需要500ms左右，且该接口每天执行次数很低，每天只调用几次，因此认为500ms左右是可以接受的。SQL改写后，接口响应时长缩短了80%。因为批量查询的结果List较大，单线程处理比较耗时，后面又引入了线程池，通过测试合理地设置线程池参数，生产环境接口最终执行时长在3s左右。虽说 3s 还是很长，但是比优化之前的超过 100s，还是有了极大的提升。