利用Arthas分析优化接口执行时长

傷城~ 2021-09-22 01:14 624阅读 0赞

# 背景   #

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

# 一、Arthas 简介 #

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

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

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

trace 命令使用，见[文档][Link 2]。

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

![watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3FxXzIyMDc2MzQ1_size_16_color_FFFFFF_t_70][]

可以看到测试环境该接口耗时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，还是有了极大的提升。

[Link 1]: https://arthas.aliyun.com/doc/
[Link 2]: https://arthas.aliyun.com/doc/trace.html
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3FxXzIyMDc2MzQ1_size_16_color_FFFFFF_t_70]: /images/20210920/5fb5ce4fac0c4e82b94fa020daa924d0.png