线上机器Old GC问题排查记录

背景

上周五组队去团建，结果路上收到线上机器发生Old GC的短信告警。到达目的地后迅速连VPN执行了Tomcat的重启操作，问题得到解决。但是过了一会儿，又有两台机器发生了Old GC，此时判定是系统代码问题，便执行了回滚操作，系统恢复正常。

问题分析

Old GC发生时联系运维同学dump了机器内存，用Visual VM打开dump文件如下图

由图可见，内存中的BigDecimal、ConsumeDetails和Date的实例每种都有1500W个，所占用的内存共达1700MB，推测可能是代码中发生了死循环导致对象长时间不能被回收。

发生Old GC的JVM内存监控图如下图

可见在GC高峰期13:39分时，新生代的GC次数达到400多次，老年代的GC次数多达40次，此时JVM基本处于不可用状态，所以造成系统抛了大量超时异常。

问题代码

经过排查，造成此次问题的关键代码如下

List<ConsumeDetails> result = new ArrayList<ConsumeDetails>();

 while (begin.get(Calendar.DAY_OF_YEAR) <= end.get(Calendar.DAY_OF_YEAR)){
     Date key = end.getTime();
     if (dailyStatisticMap.containsKey(key)) {
         result.add(dailyStatisticMap.get(key));
     } else if (consumeMap.containsKey(key)) {
         result.add(consumeMap.get(key));
     } else {
         ConsumeDetails consumeDetails = new ConsumeDetails();
         consumeDetails.setAddDate(key);
         consumeDetails.setConsumeAmount(new BigDecimal(0));
         consumeDetails.setConsumeCount(0);
         result.add(consumeDetails);
     }
     end.add(Calendar.DAY_OF_YEAR,-1);
 }

这里是要构建起始时间和结束时间之间的数据，按天聚合。如果没有数据就设置一个默认值。

通常情况下并没有问题，但是如果begin的值是2017-01-01 00:00:00，end的值是是2017-01-01 23:59:59，begin.get(Calendar.DAY_OF_YEAR)值为1，end.get(Calendar.DAY_OF_YEAR)值为1，此时可以进入循环体。

当执行完end.add(Calendar.DAY_OF_YEAR,-1)后，end的值变为2016-12-31 23:59:59，此时问题就来了，end.get(Calendar.DAY_OF_YEAR)的值为365。

然后循环继续，等到end的值为2016-01-01 23:59:59时，执行完end.add(Calendar.DAY_OF_YEAR,-1)后，end的值变为2015-12-31 23:59:59。然后循环会一直进行下去，由于多数时间是没有数据的，所以绝大多数循环会进入else部分。

else代码块里会执行new ConsumeDetails()和new BigDecimal()操作，由于这里new出来的对象一直被result引用导致不能被回收，经过多次GC后可能进入到老年代中。当老年代内存不足时就会发生Old GC导致JVM失去响应。

总结

此次事故主要由代码不规范引起。使用while循环时，一定要非常清楚while循环的边界在哪里。相比之下，更推荐先确定循环边界，然后使用for循环。

曾经看过一本书上提到过类似下面的代码的优化。

for(int i = 0; i < list.length; i++){
    //do something
}

推荐写法为

int length = list.length;
for(int i = 0; i < length; i++){
    //do something
}

将循环边界提前计算好存在length变量里，可以避免每次循环都要去计算循环边界。