FullGC实战:业务小姐姐查看图片时一直在转圈圈

业务小姐姐说图片访问不了,我开始慌了:

loading配图

看到业务小姐姐发的这个图片,你说能不慌嘛?但是再慌也要排查问题呀!对于这种前端响应不过来的问题,首先就用浏览器的F12看看接口响应速度(获取图片地址的接口)从而确认是接口响应慢还是网络等其他问题。我勒个去,耗时10多秒呀!这时候我的心里更慌了。

问题排查

既然能确认问题在服务端,那么就查看服务端日志,准备寻找蛛丝马迹。由于服务端日志都有通过AOP记录耗时情况的,实时观察一下就能发现问题所在(说明:这个服务还没有对接APM,否则这种问题更好定位)。不看不知道,一看吓一跳,接口耗时都是10多秒,甚至20多秒,你说这客户端能不转圈圈嘛:

 2019-04-19 10:11:18.533 http-nio-8007-exec-14 INFO com.xxx.image.advice.LogRequestBodyAdvice:40
 2019-04-19 10:11:38.543 http-nio-8007-exec-14 INFO com.xxx.image.advice.LogResponseBodyAdvice:35 elapsed time: 20s
 ... ...
 2019-04-19 10:31:10.111 http-nio-8007-exec-11 INFO com.xxx.image.advice.LogRequestBodyAdvice:40
 2019-04-19 10:31:22.121 http-nio-8007-exec-11 INFO com.xxx.image.advice.LogResponseBodyAdvice:35 elapsed time: 12s
 ... ...
 2019-04-19 10:45:16.244 http-nio-8007-exec-13 INFO com.xxx.image.advice.LogRequestBodyAdvice:40
 2019-04-19 10:45:29.678 http-nio-8007-exec-13 INFO com.xxx.image.advice.LogResponseBodyAdvice:35 elapsed time: 13s

而且出问题的不是某一个接口,而是所有接口。那么,接下来准备从我怀疑的地方开始排查:

  1. 数据库问题(数据库服务器一切指标正常,也没有慢日志);
  2. 同步日志阻塞问题(此问题也不存在);
  3. 系统问题,如SWAP等(sar命令以及zabbix查看一切OK);
  4. GC问题;
  5. ... ...

说明:我们这个服务的特点是,只会访问数据库,没有任何其他HTPP和RPC调用,也没有缓存。

接下来就是怀疑的GC问题了,因为以前也碰到过频繁FGC导致系统无法响应,jstat命令用起来,输出结果如下:

bash-4.4$ /app/jdk1.8.0_192/bin/jstat -gc 1 2s
 S0C     S1C       S0U    S1U   EC       EU       OC          OU        MC      MU      CCSC   CCSU      YGC   YGCT   FGC    FGCT     GCT 
170496.0 170496.0  0.0    0.0   171008.0 130368.9 1024000.0   590052.8  70016.0 68510.8 8064.0 7669.0    983   13.961 1400   275.606  289.567
170496.0 170496.0  0.0    0.0   171008.0 41717.2  1024000.0   758914.9  70016.0 68510.8 8064.0 7669.0    987   14.011 1401   275.722  289.733
170496.0 170496.0  0.0    0.0   171008.0 126547.2 1024000.0   770587.2  70016.0 68510.8 8064.0 7669.0    990   14.091 1403   275.986  290.077
170496.0 170496.0  0.0    0.0   171008.0 45488.7  1024000.0   650767.0  70016.0 68531.9 8064.0 7669.0    994   14.148 1405   276.222  290.371
170496.0 170496.0  0.0    0.0   171008.0 146029.1 1024000.0   714857.2  70016.0 68531.9 8064.0 7669.0    995   14.166 1406   276.366  290.531
170496.0 170496.0  0.0    0.0   171008.0 118073.5 1024000.0   669163.2  70016.0 68531.9 8064.0 7669.0    998   14.226 1408   276.736  290.962
170496.0 170496.0  0.0    0.0   171008.0  3636.1  1024000.0   687630.0  70016.0 68535.6 8064.0 7669.6   1001   14.342 1409   276.871  291.213
170496.0 170496.0  0.0    0.0   171008.0 87247.2  1024000.0   704977.5  70016.0 68535.6 8064.0 7669.6   1005   14.463 1411   277.099  291.562

如果你以前没有排查太多的GC问题,那么可能你看到这段日子有点头晕。笔者以前的文章说过很多次怎么排查GC问题,有兴趣的同学可以翻看笔者公众号的JVM专栏。首先,我们要把注意力放在最后几列(YGC、YGCT、FGC、FGCT、GCT),对应的结果如下:

bash-4.4$ /log/plms/jdk1.8.0_192/bin/jstat -gc 1 2s
... ...  YGC   YGCT   FGC    FGCT     GCT 
... ...  983   13.961 1400   275.606  289.567
... ...  987   14.011 1401   275.722  289.733
... ...  990   14.091 1403   275.986  290.077
... ...  994   14.148 1405   276.222  290.371
... ...  995   14.166 1406   276.366  290.531
... ...  998   14.226 1408   276.736  290.962
... ... 1001   14.342 1409   276.871  291.213
... ... 1005   14.463 1411   277.099  291.562

这样就容易理解多了,看看FGC那一列:几乎每1秒都有一次FGC(说明,笔者这个服务用的是默认的PS垃圾回收器,所以FGC这一列的值一定是FullGC的次数)。而且,再看FGCT这一列,停顿时间那是相当恐怖。那么会是什么原因呢?

继续分析问题前,笔者先介绍3个JVM参数:MaxRAMPercentageInitialRAMPercentageMinRAMPercentage。这三个参数是JDK8U191为适配Docker容器新增的几个参数,类比Xmx、Xms,至于-XX:InitialRAMFraction、-XX:MaxRAMFraction、-XX:MinRAMFraction已经被标记为deprecated 。这几个参数的好处是什么呢?Docker容器模式下,我们可以给每个JVM实例所属的POD分配任意大小的内存上限。比如,给每个账户服务分配4G,给每个支付服务分配8G。如此一来,启动脚本就不好写成通用的了,指定3G也不是,指定6G也不是。但是,有了这三个新增参数,我们就可以在通用的启动脚本中指定75%(-XX:MaxRAMPercentage=75 -XX:InitialRAMPercentage=75 -XX:MinRAMPercentage=75)。那么,账户服务就相当于设置了-Xmx3g -Xms3g。而支付服务相当于设置了-Xmx6g -Xms6g,是不是很赞。

再给出我们的JVM参数配置(说明:POD内存限制是6G):

-XX:MaxRAMPercentage=75 -XX:InitialRAMPercentage=75 -XX:MinRAMPercentage=75
-XX:MetaspaceSize=256m -XX:MaxMetaspaceSize=256m

等价于:
-Xmx4608m -Xms4608m -XX:MetaspaceSize=256m -XX:MaxMetaspaceSize=256m

原因分析

再回到前面那一段完整的GC日志(jstat的输出结果),我们分析命令结果输出时这个JVM的一些情况:

  1. S0/S1区容量为170496K(对应S0C/S1C两列);
  2. Eden区容量为171008K(对应EC列);
  3. Old区容量为1024000K(对应OC列);
  4. Metaspace容量为70M;

根据各个区的容量大小,发现和JVM参数配置的4.5G内存出入非常大。整个堆的大小缩容了很多,从4.5G缩小到现在的大概1.5G(170496K*2+171008K+1024000K+70M ≈ 1.5G),WHY ?

如果对默认的PS垃圾回收器有一定了解的同学,可能大概知道问题所在了。没错,就是参数-XX:+UseAdaptiveSizePolicy的锅。这个参数在PS前提下默认是开启的,其作用是自动调整堆的大小,以及对象从S区晋升到Old区的年龄阈值(threshold),调节threshold逻辑为:判断Young GC和Full GC消耗的时间差:

  • 如果Young gc > 1.1 * Full GC,threshold就会一直减少。
  • 如果1.1* Young GC < Full GC,threshold就会一直增加。

也就是说,如果Young GC比较频繁,那么threshold可能会一直减小,直到最小值1,这时候S区的对象很容易晋升到Old区,导致Old区空间涨幅过快而触发Full GC的频率也加快。另外,这个参数是如何调整堆的大小就不在这里介绍了,因为很复杂,我也不知道,哈哈哈:


和笨神的聊天

问题验证

默认PS垃圾回收器调整堆大小的这个问题很好验证,笔者写了一段简短的代码,如下所示:

/**
 * @author afei, 公众号:阿飞的博客
 */
public class ParallelGcTest {
    private static final int _1M = 1024 * 1024;

    public static void main(String[] args) {
        allocate();
    }

    private static void allocate(){
        // 强引用分配的对象, 为了触发FGC
        List<byte[]> holder = new ArrayList<>();
        for (int i = 0; i < Integer.MAX_VALUE; i++) {
            byte[] tmp = new byte[_1M];
            // 不要让FGC来的太快
            if (i%10==0) {
                holder.add(tmp);
            }
        }
    }
}

配置JVM参数(-Xmx256m -Xms256m -Xmn128m -XX:+PrintGCDetails)运行的GC日志如下,默认情况下,即-XX:+UseAdaptiveSizePolicy时,初始第一次YGC时堆大小为245760K,OOM之前最后一次FGC时堆大小为224768K,从而验证了堆缩小的现象:

[GC (Allocation Failure) [PSYoungGen: 97896K->10497K(114688K)] 97896K->10505K(245760K), 0.0030860 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC (Allocation Failure) [PSYoungGen: 108661K->16312K(114688K)] 108669K->20424K(245760K), 0.0057851 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
... ...
[Full GC (Ergonomics) [PSYoungGen: 82946K->81922K(93696K)] [ParOldGen: 130906K->130906K(131072K)] 213852K->212828K(224768K), [Metaspace: 3308K->3308K(1056768K)], 0.0054117 secs] [Times: user=0.03 sys=0.00, real=0.00 secs] 
[Full GC (Ergonomics) [PSYoungGen: 82946K->82946K(93696K)] [ParOldGen: 130906K->130906K(131072K)] 213852K->213852K(224768K), [Metaspace: 3308K->3308K(1056768K)], 0.0150534 secs] [Times: user=0.02 sys=0.00, real=0.02 secs]

配置JVM参数(-Xmx256m -Xms256m -Xmn128m -XX:+PrintGCDetails -XX:-UseAdaptiveSizePolicy)运行的GC日志如下,配置了-XX:-UseAdaptiveSizePolicy后,无论是初始第一次YGC时,还是OOM之前最后一次FGC时堆大小都是245760K:

[GC (Allocation Failure) [PSYoungGen: 97896K->10545K(114688K)] 97896K->10553K(245760K), 0.0030478 secs] [Times: user=0.03 sys=0.03, real=0.00 secs] 
[GC (Allocation Failure) [PSYoungGen: 108709K->16264K(114688K)] 108717K->20376K(245760K), 0.0053165 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
... ...
[Full GC (Ergonomics) [PSYoungGen: 97282K->96258K(114688K)] [ParOldGen: 130906K->130906K(131072K)] 228189K->227164K(245760K), [Metaspace: 3308K->3308K(1056768K)], 0.0026970 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[Full GC (Ergonomics) [PSYoungGen: 97282K->97282K(114688K)] [ParOldGen: 130906K->130906K(131072K)] 228189K->228189K(245760K), [Metaspace: 3308K->3308K(1056768K)], 0.0058994 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 

解决方案

已经知道问题所在,那么就把这个参数关闭( -XX:-UseAdaptiveSizePolicy),优化后重启服务,运行一天的springboot-admin截图如下,业务小姐姐访问速度又飞起来了,图片看都看不过来,嘿嘿:


springboot-admin

如图所示,每天还是有9次FGC,还能再优化么?后面分析业务发现,有个每分钟运行的JOB,其作用是将用户上传的PDF转成PNG图片,一个PDF有多少页就会转成多少张图片。并且,根据统计信息发现,一个有20页的PDF转成图片总计需要几十秒。那么就会导致YGC时,很可能这些正在压缩的图片任务还没有完成,从而导致这些对象(而且比较大的对象)晋升到S区,甚至晋升到Old区。所以,这个FGC不好再降低。当然,事实上也没必要再优化,因为,现在的FGC次数已经对业务基本上无感知了:每天9次FGC,每次FGC停顿时间才不到1秒(8411ms/9 ≈ 935ms),而且我们的系统并不是OLTP系统,而是给业务人员使用的。所以,有时候没必要过度优化,因为还要考虑付出的成本和获得的收益,判断是否值得我们去做这件事情。

©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 151,829评论 1 331
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 64,603评论 1 273
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 101,846评论 0 226
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 42,600评论 0 191
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 50,780评论 3 272
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 39,695评论 1 192
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 31,136评论 2 293
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 29,862评论 0 182
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 33,453评论 0 229
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 29,942评论 2 233
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 31,347评论 1 242
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 27,790评论 2 236
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 32,293评论 3 221
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 25,839评论 0 8
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 26,448评论 0 181
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 34,564评论 2 249
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 34,623评论 2 249

推荐阅读更多精彩内容