在生产中发现一个慢调用接口,正常来说是响应时间应该不超过1s
通过时序图查看了下,这个接口做的事有点多,既有外部接口调用,又有很多的查询和批量保存
可能是存在慢调用、可能是外部接口响应慢、也有可能是批量插入等其他的问题,在其他环境这个接口是正常的,怎么快速的定位到问题
这里介绍一下Arthas,Arthas官网
Arthas 是一款线上监控诊断产品,通过全局视角实时查看应用 load、内存、gc、线程的状态信息,并能在不修改应用代码的情况下,对业务问题进行诊断,包括查看方法调用的出入参、异常,监测方法执行耗时,类加载信息等,大大提升线上问题排查效率。
trace使用方式
通过Arthas里边有一个可以输出接口内,每个方法的耗时的命令trace,通过这个命令,可以直观的看到整个链路的耗时统计
trace命令能主动搜索class-pattern/method-pattern对应的方法调用路径,渲染和统计整个调用链路上的所有性能开销和追踪调用链路
参数说明
| 参数名称 | 参数说明 |
|---|---|
| class-pattern | 类名表达式匹配 |
| method-pattern | 方法名表达式匹配 |
| condition-express | 条件表达式 |
| [E] | 开启正则表达式匹配,默认为通配符匹配 |
[n:] | 命令执行次数 |
#cost | 方法执行耗时 |
[m <arg>] | 指定 Class 最大匹配数量,默认值为 50。长格式为[maxMatch <arg>]。 |
也就是说,我只需要提供接口的路径就可以了
trace com.***.XXController xxxApi
然后再次调用接口,Arthas就能捕获到整个接口的耗时
很直观的就发现了耗时最高的方法,接着继续监听这个耗时最高的方法,拿到这个方法的路径,继续重复trace
trace com.***.service xxxService
问题原因
最终定位到时两个批量插入方法耗时最久,看了下代码,在插入前,会将数据load到内存中,然后在批量插入数据库的逻辑,数据量大概是几万条
既然是load到内存中,那么查看一下是否是内存不够用了,用Arthas的dashboard看了下项目的资源情况
发现堆快满了,只剩下10多m,那如果次数load大量数据到内存的话,会导致内存耗尽而频繁触发gc
通过jstat -gc查看这几分钟的gc情况,确实是full gc的次数多
那么慢调用的原因其实是服务内存不足,然后又有大量数据load到内存中,导致内存耗尽频繁触发GC的问题
后续的解决办法是加堆的大小调大,简单粗暴,然后就恢复正常了
在排查接口慢调用的时,如果不知道是哪个方法耗时多,可以使用Arthas来一步步分析