从一次线上故障思考Java问题定位思路

 阅读目录

 

正文

问题出现:现网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。

关键字:
50000+
5万行代码练就真实本领
17年
创办于2008年老牌培训机构
1000+
合作企业
98%
就业率

联系我们

电话咨询

0532-85025005

扫码添加微信