背景  

     最近接手一个项目,里面有个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,还是有了极大的提升。   

Logo

开放原子开发者工作坊旨在鼓励更多人参与开源活动,与志同道合的开发者们相互交流开发经验、分享开发心得、获取前沿技术趋势。工作坊有多种形式的开发者活动,如meetup、训练营等,主打技术交流,干货满满,真诚地邀请各位开发者共同参与!

更多推荐