阅读目录
正文
问题出现:现网CPU飙高,Full GC告警
CGI 服务发布到现网后,现网机器出现了Full GC告警,同时CPU飙高99%。在优先恢复现网服务正常后,开始着手定位Full GC的问题。在现场只能够抓到四个GC线程占用了很高的CPU,无法抓到引发Full GC的线程。查看了服务故障期间的错误日志,发现更多的是由于Full GC引起的问题服务异常日志,无法确定Full GC的根源。为了查找问题的根源,只能从发布本身入手去查问题,发现一次bugfix的提交,有可能触发一个死循环逻辑:
for(int i = 1 ;i <= totalPage ;i++) { String path = path_prefix + "?cmd=txt_preview&page=" + String.valueOf(i) + "&sign=" + fileSignature; url_list.add(path); }循环中的参数totalPage为long类型,由一个外部参数进行赋值。当外部参数非常大,超过int的最大值时,i递增到int的最大值后,i++会发生翻转,变成一个负数,从而使for会进入死循环。利用下面这段代码可以试验:
public static void main(String[] args) { long totalPage = Long.MAX_VALUE; for(int i = 0 ;i<totalPage;i++){ if(i<0){ System.out.println(i); } } }通过日志,发现外部确实传递了一个非常大的参数:
确认了当命中逻辑的时候,会进入一个死循环。在循环中不断进行字符串的拼接与list的Add操作,很快就会耗尽JVM堆内存导致Full GC。经过测算,实际上并不需要死循环,只要是一个比较大的循环,就能够引发Full GC。对totlePage的大小做了限定后,发布了新版本,没有再出现Full GC的问题。
可以看到逻辑被命中的时候,CPU确实是升到100%的,此时也发生了Full GC告警。尝试着多发了几次请求,服务直接就挂掉了。这里有个问题是:不是已经Full GC了吗,为什么还会发生OOM?实际上,虽然JVM已经开始回收内存,但是由于对象被引用,这些内存是回收不掉的。从GC日志可以看到回收的情况:
从GC日志中可以看到,新生代的Eden区域与老年代都已经被占满。如果新生代放不下对象的时候,object会直接被放到老年代中。除了GC日志,也可以使用jstat命令来堆Java堆内存的使用情况进行统计展示:
jstat -gcutil 12309 1000 10
1000为统计的间隔,单位为毫秒,10为统计的次数,输出如下:
从输出中同样可以看到E(Eden)区与O(Old)区都已经被占满了。其他几个输出项的含义如下:
- YGC: 从启动到采样时Young Generation GC的次数
- YGCT: 从启动到采样时Young Generation GC所用的时间 (s).
- FGC: 从启动到采样时Old Generation GC的次数.
- FGCT: 从启动到采样时Old Generation GC所用的时间 (s).
- GCT: 从启动到采样时GC所用的总时间 (s).
可以看到JVM一直在尝试回收老年代,但是一直没能将内存回收回来。
如何获取占用CPU最高的线程id?
2)可以登上机器,确认下是什么线程使CPU飙高。先ps查看Java进程的PID:
拿到进程pid后,可以使用top命令,来看是什么线程占用了CPU。
