Java线上项目cpu过高的排查思路

一、项目介绍

1.业务介绍

我们是一个网关项目，用于接收外部发送的监控数据，并转发到下游组件

项目启动时，会创建线程个数为16个的线程池，每个线程持有一个大小为1024000的队列。
当监控数据过来时，随机放入某个线程的队列里，当队列元素个数达到200个批次时再取出，通过http调用下游系统。

2.JVM配置

垃圾收集器配置

新生代用PS，老年代用CMS。

堆内存配置：

-Xmx6g -Xms6g -Xmn256m 

二、问题

项目在linux运行一段时间后，公司有用户反馈某个接口无响应。在排查过程中，我发现其他接口也是如此。于是查看cpu占用率，发现已超过100%。

三、排查步骤

1.top命令找到cpu占用高的进程号

发现进程号为2732

2.查看进程的所有线程信息，记下占用最高的进程

执行命令，单独监控该进程

top -p 2732

在界面按下H，获取当前进程下所有线程信息
占用cpu最高的线程为2734

3.将第2步得到的线程号转化为十六进制

将2734转化为十六进制数（可通过在线进制转化器转换）

4.查看进程堆栈信息

根据第1步得到的进程号2732，执行命令

jstack 2732

将第3步得到的十六进制字符串，去命令打印结果里搜索

5.定位问题

根据上步搜索到的结果，可以看到是GC线程。因此，需要分析gc情况。
通过 jstat –gc 命令查看gc情况，如下

可以看到，fullGC次数在不断增多。原来是因为gc线程在疯狂回收，最终导致cpu飙升。
那什么原因会导致不停地gc呢？猜想是业务在不停地创建对象。通过执行命令，可以看到对象分配情况

jmap -histo 2732

结果如图

有接近百万个MonitorData对象实例没有被回收掉

四、初版方案

起初并不知道是项目哪块出现的问题，只知道从对象分配情况来看，大量对象还存活着。于是通过jmap -heap查询堆内存，发现老年代被撑爆了。

于是决定增大新生代，由现在的256m调整到3g，避免fullGC

-Xmx6g -Xms6g -Xmn3g -XX:SurvivorRatio=8

然而重启项目后，cpu依旧飙升。
通过多次执行jmap -heap查看，发现某次新生代和新生代都满了

此时，通过 jstat –gc 命令查看gc情况，发现minorGC和fullGC都在不断递增。

本以为增大新生代后可以给对象足够的存活时间以进行回收，从而避免大部分对象进入from和老年代，但没想到没有任何改善，需要另辟蹊径。

五、MAT分析内存

既然调整堆大小没用，那就寻找根本原因，看是项目哪块业务导致的。我们需要导出dump日志。

1.导出dump日志

在机器上执行如下命令，导出文件

jmap -dump:format=b,file=gateway.hprof 2732

2.分析dump日志

使用MAT工具打开gateway.hprof文件。
首先查看对象的分配情况
其中MonitorData是项目中的监控数据对象，可以看到数量多达90多万；string对象是MonitorData中的成员，数量多达百万。

然后查看线程信息。
每个线程的深堆都多达百万。

查看某个线程里的信息
在第2个红框的doPost方法里，能看到实际的监控数据以k8s开头，其深堆多达百万。
展开每个线程信息，发现监控数据的内容和大小基本一致。

六、结论

线程的队列大小多达1024000，共16个线程，所以共可以容纳16*1024000个对象。
而外部k8s监控数据量太大、太频繁，导致每个线程的队列很快被填满。
队列中的对象以200个为一个批次推送到下游系统，其他的对象则需要等待。

综上所述，项目GC速度远赶不上监控对象的创建，导致项目堆内存爆满，从而cpu飙升。

七、最终解决

反馈给用户后，用户说他们很久以前也是这么推送的，从来没有变动过，如果出问题为什么现在才出现。
于是我和同事将他们推送的数据进行分析，发现其中有许多垃圾数据，本来可以在发往线程的队列前被业务逻辑过滤掉的，但现在全部没有过滤，都进入队列了。询问同事，他说前几天换过redis地址。

原来如此，原因是换了redis地址之后，业务逻辑里从redis获取到不到业务数据，导致没有触发垃圾数据的过滤逻辑。

现在已经刷新了redis数据，数据过来时大部分都已经被过滤了，cpu也恢复至正常水平。

于是，我将堆内存重新调整了下，由256m增至512m

-Xmx6g -Xms6g -Xmn512m -XX:SurvivorRatio=8

再结合jstat -gc查看

虽然minorGC还是有，但是fullGC已经没有了。