欧阳亮的博客

编程不止是一份工作,还是一种乐趣!!!

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

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

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

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

// 从远程系统获取数据,每次取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的发生。