Hope is a good thing, and maybe the best thing of all

通过JVM定位和分析一次生产案例

Sep 27, 2016

早晨刚到公司，牛牛同学就走过来跟我说昨天上线的一个数据同步的功能有点问题，大概情况是一开始时执行得很好，然后越来越慢，过一会儿就报错了。

起初我并没有太在意这个问题，只是建议他先加些日志定位问题，看看具体是慢在哪一步。大半天过去了，看着牛牛同学一脸严肃的样子，我知道她还在思考人生，正好手中的活刚刚弄完，过去调侃调侃牛牛同学。

功能很简单，通过远程接口获取数据，并保存到本地数据库。代码的实现大概如下：

// 从远程系统获取数据，每次取200条记录
List<Map<String, Object>> list = anyService.queryFromRemote(...);

while (null != list && !list.isEmpty()) {
    // 批量播入到本地数据库
    localService.batchSave(list);

    list = anyService.queryFromRemote(...);
}

经过日志的分析，得到的信息有：

• 从远程系统接口获取数据在开始时非常快，10ms以内，然后逐渐变慢，有时会接近1秒。
• 本地的批量插入在开始的时候也很快，200条的插入在几十ms，然后越来越慢，有时会达到4、5秒，最后报错。

一开始我的猜想可能是因为表的数据量越来越大，sql插入的性能越来越慢导致的。但是在前一次出错的基础上再次触发该功能，在开始的一小段时间内数据写入性能确又很快，然后又慢下来，接着再次报错；而且表的数据量还没有超过200万行，所以我的假设并不成立。

数据同步中的取数和写入都同时变慢，说不准具体是哪个操作引起的，于是我们开始监控应用，发现在同步功能启动后，系统CPU直线飙升，full GC明显增多，一会儿sql insert报错，之后系统恢复正常。取数和写入两个操作都是纯IO，不论是哪一个出了问题，都会使得同步功能变慢，但不应该导致应用的CPU飙升，所以我们把问题的定位方向放到了应用本身。再次审阅代码，我的目光转移到了list对象上，虽然每次只取200条记录，但是并不知道每条记录到底有多大。询问牛牛同学后得知相关的表有60多个字段，且大部字段都是varchar类型的，说明每次从远程系统获取的list对象并不小。

至此，基本可以确定问题是list对象导致的，至于具体的原因，却花费了我们不少的功夫。

为了说明具体的原因，我们可以在自己的机器上模拟一下类似的场景。

/*
 * -Xms50m -Xmx50m -Xmn10m -XX:SurvivorRatio=8
*/
public static void main(String[] args) throws InterruptedException {
    byte[] obj = null;

    while (true) {
        obj = new byte[1 * 1024 * 1025];//obj对象的大小比1M大一点点

        TimeUnit.MILLISECONDS.sleep(50);
    }
}

上面程序VM参数-Xmn10m -XX:SurvivorRatio=8，表示新生代大小为10M，且Eden区与Survivor比例为8，也就是说每个Survivor区的小大为1M，不足于存放示例中的obj对象（注意obj对象的大小为1024 * 1025个字节，比1M稍微大一点点）。

在执行obj = new byte[1 * 1024 * 1025]前，如果Eden空间不足，会触发一次minor GC（注意在GC时obj对象（在前一轮循环时创建）还是可用的，所占的空间还不能被回收），这时obj对象会还是存活的，并且Survivor空间容纳不下，所以obj会被移动到老年代。

执行上面程序时，通过jstat命令得到下面的输出：

$ jstat -gcutil 935 300
  S0     S1     E      O      P     YGC     YGCT    FGC    FGCT     GCT   
  0.98   0.00   0.00  25.89  22.19     29    0.025     2    0.000    0.026
  0.00   0.00  75.03  25.89  22.19     29    0.025     2    0.000    0.026
  0.00   0.00  62.53  28.39  22.19     30    0.026     2    0.000    0.026
  0.00   0.00  50.03  30.89  22.19     31    0.026     2    0.000    0.026
  0.00   0.00  37.52  33.39  22.19     32    0.026     2    0.000    0.027
  0.00   0.00  12.50  35.89  22.19     33    0.027     2    0.000    0.027
  0.00   0.00  87.53  35.89  22.19     33    0.027     2    0.000    0.027
  0.00   0.00  75.03  38.39  22.19     34    0.027     2    0.000    0.027
  0.00   0.00  62.53  40.89  22.19     35    0.027     2    0.000    0.028
  0.00   0.00  37.52  43.39  22.19     36    0.028     2    0.000    0.028
  0.00   0.00  25.02  45.89  22.19     37    0.028     2    0.000    0.028
  0.00   0.00  12.50  48.39  22.19     38    0.028     2    0.000    0.029
  0.00   0.00  87.53  48.39  22.19     38    0.028     2    0.000    0.029
  0.00   0.00  75.03  50.89  22.19     39    0.029     2    0.000    0.029
  0.00   0.00  62.53  53.39  22.19     40    0.030     2    0.000    0.030
  0.00   0.00  37.52  55.89  22.19     41    0.030     2    0.000    0.031
  0.00   0.00  25.02  58.39  22.19     42    0.032     2    0.000    0.032
  0.00   0.00  12.50  60.89  22.19     43    0.033     2    0.000    0.033
  0.00   0.00  87.53  60.89  22.19     43    0.033     2    0.000    0.033
  0.00   0.00  62.53  63.39  22.19     44    0.033     2    0.000    0.034
  0.00   0.00  37.52  65.89  22.19     45    0.034     2    0.000    0.035

S0与S1两列都是0，而O列的值是递新的，说明每次minor GC发生后，obj对象没有进入到survivor区域，而是直接进入了老年代，导致了频繁的full GC。

这样就成功的模拟了我们上面数据同步的问题，list对象虽然不是非常巨大（以至于直接分配到老年代），但是它却大于Survivor区的大小，每次Minor GC后都会进入老年代，导致了频繁的full GC，以致于在执行批量写入成功后并返回时，应用层出现长时间stop the world的情况而报错。

分析出具体的原因后，解决办法也随之而来：

• 我们可以修改访问远程接口的代码，每次取更少的记录，保证每次获取的数据量小于survivor区域的大小。使得在Minor GC发生时，list对象可以进入到survivor区域，避免full GC的发生。

• 不改代码的情况下，我们可以增大Survivor区的大小。使得在Minor GC发生时，list对象可以进入到survivor区域，避免full GC的发生。

• 我们可以在循环的最后显式的执行list.clear，或者把list的声明放在循环内，使得在Minor GC发生时，可以回收Eden中所有的list对象，避免full GC的发生。