- 背景:昨天下午4点多上线一个需求之后,发现服务整体rt由之前的1.x ms上涨到6~8ms,刚开始以为是增加了某些逻辑导致rt上涨,没放心上。结果晚上8点多下班路上,该服务就有2个pod开始告警,cpu使用率>=90%,慌得一匹,赶紧下了地铁就近打开热点吧问题pod删除了,同时扩容了一下机器。
- 到家后,发现整体pod的rt比下午上完线之后高了不少,而且每个pod的cpu都很高,一个批量接口上游调用方也在告警。
排查路径:
- 挑一个rt最高的pod,登陆终端,使用top看看CPU 使用情况,了解哪些 Java 进程消耗了大量的CPU资源
- 通过使用
jstack <pid> > thread_dump.txt
命令可以获取 Java 进程的线程 dump,并将其输出到文件中。在这个过程中,获取线程 dump 的确会对 CPU 产生一定的影响,但通常是暂时的和相对较小的(这里的<pid>替换为上一步top时看到的应用进程号);这样生成的thread_dump.txt是存放在当前路径下,可以通过curl -T thread_dump.txt https://dl.xxxx/xx/thread_dump.txt上传到相关文件服务器,方便下载下来分析 - 分析thread_dump.txt文件时,着重关注runnable状态的线程都在处理什么业务,可以搜索com.xxx.user(自己公司项目包路径),这样可以快速定位哪里的代码在消化cpu,着重看重复出现的包路径下的那个方法,然后去看这个方法改动的代码逻辑,是不是有隐藏bug
- 我是通过搜索com.xxx.user找到一个方法出现的频次很高,一看就是下午自己上线改动过的方法,对比之前逻辑,发现自己在该批量接口里面for循环每次都会去查询2个java本地缓存,主要是这里本地缓存是很大很大的对象,问题就出在这里,批量查询接口,疯狂查询大对象的本地缓存(这里的本地缓存除了对象大,还有序列化&反序列化),所以导致jvm内存、GC都大大增加,cpu开销也变大,慢慢拖垮服务,rt越来越高,直到报警
- 上一步,是大概猜想,然后我对for循环逻辑进行改动,把本地缓存读取外移出去了,只调用1次,发布上线之后,发现cpu开销rt什么的都恢复到下午4点多之前的水平
总结:大对象&序列号、反序列化,在读取使用的时候,如果是批量场景,一定要注意!!!