使用Arthas分析慢调用接口

786 阅读3分钟

在生产中发现一个慢调用接口,正常来说是响应时间应该不超过1s

通过时序图查看了下,这个接口做的事有点多,既有外部接口调用,又有很多的查询和批量保存

可能是存在慢调用、可能是外部接口响应慢、也有可能是批量插入等其他的问题,在其他环境这个接口是正常的,怎么快速的定位到问题

这里介绍一下ArthasArthas官网

Arthas 是一款线上监控诊断产品,通过全局视角实时查看应用 load、内存、gc、线程的状态信息,并能在不修改应用代码的情况下,对业务问题进行诊断,包括查看方法调用的出入参、异常,监测方法执行耗时,类加载信息等,大大提升线上问题排查效率。

trace使用方式

通过Arthas里边有一个可以输出接口内,每个方法的耗时的命令trace,通过这个命令,可以直观的看到整个链路的耗时统计

trace 命令能主动搜索 class-patternmethod-pattern 对应的方法调用路径,渲染和统计整个调用链路上的所有性能开销和追踪调用链路

参数说明

参数名称参数说明
class-pattern类名表达式匹配
method-pattern方法名表达式匹配
condition-express条件表达式
[E]开启正则表达式匹配,默认为通配符匹配
[n:]命令执行次数
#cost方法执行耗时
[m <arg>]指定 Class 最大匹配数量,默认值为 50。长格式为[maxMatch <arg>]

也就是说,我只需要提供接口的路径就可以了

trace com.***.XXController xxxApi

然后再次调用接口,Arthas就能捕获到整个接口的耗时

image-20220921173414923

很直观的就发现了耗时最高的方法,接着继续监听这个耗时最高的方法,拿到这个方法的路径,继续重复trace

trace com.***.service xxxService

问题原因

最终定位到时两个批量插入方法耗时最久,看了下代码,在插入前,会将数据load到内存中,然后在批量插入数据库的逻辑,数据量大概是几万条

既然是load到内存中,那么查看一下是否是内存不够用了,用Arthasdashboard看了下项目的资源情况

发现堆快满了,只剩下10多m,那如果次数load大量数据到内存的话,会导致内存耗尽而频繁触发gc

通过jstat -gc查看这几分钟的gc情况,确实是full gc的次数多

那么慢调用的原因其实是服务内存不足,然后又有大量数据load到内存中,导致内存耗尽频繁触发GC的问题

后续的解决办法是加堆的大小调大,简单粗暴,然后就恢复正常了

在排查接口慢调用的时,如果不知道是哪个方法耗时多,可以使用Arthas来一步步分析