背景
最近开始看gc日志,感觉颇有了解。但苦于手上没有例子来练手,结果昨天下午,受到joy-merchant-service的告警,表示有full gc,虽然这个不是我负责的服务,但是好不容易逮到怎么能不管,于是晚上饭后开始查看问题。
解决步骤
问题表现
我发现该服务线上共四台机器,每台机器在发布的时候都会发生full gc,但是
仅限于发布的时候,而且次数不多1-3次。
历史记录
想起以前阿菜改过一次joy-merchant的full-gc的问题,然后找到大象的记录:
第一次假想
看到上面之前的问题后,我第一个想法是,会不会还是同样的问题,jvm参数被改了。
然后一顿操作:
whereis tomcat
tomcat: /usr/local/tomcat
cat /usr/local/tomcat/bin/catalina.sh
找到启动参数配置如下:
然后其他几台机器的配置都是一样的。然后我知道我们这边机器都是java8的。
这个时候如果是老司机,就已经能发现问题了。
但是我还在看参数有什么不对,继续研究。
通过配置发现,线上机器老年代用的CMS垃圾回收器
然后需要了解一下配置参数的意义:
参数 | 意义 |
---|---|
-XX:SurvivorRatio=8 | 两个Survivor和eden的比,8表示eden:survivor1:survivor2=8:1:1 |
-XX:MaxTenuringThreshold=9 | 年龄阈值 |
-XX:+UseConcMarkSweepGC | 设置老年代为CMS收集器 |
-XX:+UseCMSInitiatingOccupancyOnly | 使用手动定义初始化定义开始CMS收集;不进行自动平衡 |
-XX:+CMSScavengeBeforeRemark | 开启在CMS重新标记阶段之前的清除尝试 |
-XX:+ScavengeBeforeFullGC | Full GC前调用YGC |
-XX:+UseCMSCompactAtFullCollection | 使用并发收集器时,开启对老年代的压缩 |
-XX:+CMSParallelRemarkEnabled | 降低标记停顿 |
-XX:CMSFullGCsBeforeCompaction=9 | 设置多少次Full GC后,对老年代进行压缩 |
-XX:CMSInitiatingOccupancyFraction=80 | 使用cms作为垃圾回收使用70%后开始CMS收集(老年代) |
-XX:+CMSClassUnloadingEnabled | 相对于并行收集器,CMS收集器默认不会对永久代进行垃圾回收。如果希望对永久代进行垃圾回收,可用设置标志 |
-XX:SoftRefLRUPolicyMSPerMB=0 | 每兆堆空闲空间中SoftReference的存活时间 |
-XX:-ReduceInitialCardMarks | 这个是为了解决 jdk 6u18 放入大对象导致 jvm crash bug 的一个配置参数 |
-XX:+CMSPermGenSweepingEnabled | 允许对持久代进行清理 |
-XX:CMSInitiatingPermOccupancyFraction=80 | 设置Perm Gen(永久代)使用到达多少比率时触发CMS GC |
-XX:+ExplicitGCInvokesConcurrent | HeapDumpOnOutOfMemoryError |
-XX:+PrintGCDetails | 开启了详细GC日志模式 |
-XX:+PrintGCDateStamps | GC发生的时间信息 |
-XX:+PrintGCApplicationConcurrentTime | 打印每次垃圾回收前,程序未中断的执行时间 |
-XX:+PrintGCApplicationStoppedTime | 打印垃圾回收期间程序暂停的时间 |
-XX:+PrintHeapAtGC | 打印GC前后的详细堆栈信息 |
-Xloggc:/data/applogs/heap_trace.txt | 把相关日志信息记录到文件以便分析 |
-XX:-HeapDumpOnOutOfMemoryError | 让JVM在出现内存溢出时候Dump出当前的内存转储快照 |
-XX:HeapDumpPath=/data/applogs/HeapDumpOnOutOfMemoryError | 指定导出堆的存放路径 |
待续 |
疯狂操作之后,发现更清晰了,然后发现关键配置 -Xloggc:/data/applogs/heap_trace.txt ,马上找到这个位置,查看fullGC相关日志。
fullGC日志
命令:
cat -n heap_trace.txt | grep -15 'CMS'
得到如下日志:
2018-10-10T17:22:02.983+0800: 15.371: Total time for which application threads were stopped: 0.0004046 seconds, Stopping threads took: 0.0001968 seconds
716 CMS: abort preclean due to time 2018-10-10T17:22:03.005+0800: 15.394: [CMS-concurrent-abortable-preclean: 3.996/5.201 secs] [Times: user=14.58 sys=0.54, real=5.21 secs]
717 2018-10-10T17:22:03.010+0800: 15.398: Application time: 0.0267885 seconds
718 2018-10-10T17:22:03.010+0800: 15.399: [GC (CMS Final Remark) [YG occupancy: 466879 K (1812800 K)]{Heap before GC invocations=3 (full 1):
719 par new generation total 1812800K, used 466879K [0x0000000680600000, 0x00000006fb500000, 0x00000006fb500000)
720 eden space 1611392K, 24% used [0x0000000680600000, 0x0000000698e95660, 0x00000006e2ba0000)
721 from space 201408K, 32% used [0x00000006ef050000, 0x00000006f2faa998, 0x00000006fb500000)
722 to space 201408K, 0% used [0x00000006e2ba0000, 0x00000006e2ba0000, 0x00000006ef050000)
723 concurrent mark-sweep generation total 3222528K, used 80301K [0x00000006fb500000, 0x00000007c0000000, 0x00000007c0000000)
724 Metaspace used 44821K, capacity 45488K, committed 45788K, reserved 1089536K
725 class space used 5365K, capacity 5541K, committed 5552K, reserved 1048576K
726 2018-10-10T17:22:03.011+0800: 15.399: [GC (CMS Final Remark) 15.399: [ParNew: 466879K->89071K(1812800K), 0.0922275 secs] 547181K->169373K(5035328K), 0.0923299 secs] [Times: user=0.23 sys=0.01, real=0.09 secs]
727 Heap after GC invocations=4 (full 1):
728 par new generation total 1812800K, used 89071K [0x0000000680600000, 0x00000006fb500000, 0x00000006fb500000)
729 eden space 1611392K, 0% used [0x0000000680600000, 0x0000000680600000, 0x00000006e2ba0000)
730 from space 201408K, 44% used [0x00000006e2ba0000, 0x00000006e829bf10, 0x00000006ef050000)
731 to space 201408K, 0% used [0x00000006ef050000, 0x00000006ef050000, 0x00000006fb500000)
732 concurrent mark-sweep generation total 3222528K, used 80301K [0x00000006fb500000, 0x00000007c0000000, 0x00000007c0000000)
733 Metaspace used 44821K, capacity 45488K, committed 45788K, reserved 1089536K
734 class space used 5365K, capacity 5541K, committed 5552K, reserved 1048576K
735 }
736 15.491: [Rescan (parallel) , 0.0329930 secs]15.524: [weak refs processing, 0.0008164 secs]15.525: [class unloading, 0.0109658 secs]15.536: [scrub symbol table, 0.0069518 secs]15.543: [scrub string table, 0.0012339 secs][1 CMS-remark: 80301K(3222528K)] 169373K(5035328K), 0.1479142 secs] [Times: user=0.36 sys=0.01, real=0.15 secs]
737 2018-10-10T17:22:03.158+0800: 15.547: Total time for which application threads were stopped: 0.1482674 seconds, Stopping threads took: 0.0000994 seconds
738 2018-10-10T17:22:03.159+0800: 15.547: [CMS-concurrent-sweep-start]
739 2018-10-10T17:22:03.172+0800: 15.560: Application time: 0.0133639 seconds
740 2018-10-10T17:22:03.172+0800: 15.561: Total time for which application threads were stopped: 0.0006498 seconds, Stopping threads took: 0.0000686 seconds
741 2018-10-10T17:22:03.178+0800: 15.566: [CMS-concurrent-sweep: 0.019/0.019 secs] [Times: user=0.06 sys=0.00, real=0.02 secs]
742 2018-10-10T17:22:03.178+0800: 15.566: [CMS-concurrent-reset-start]
743 2018-10-10T17:22:03.188+0800: 15.576: [CMS-concurrent-reset: 0.010/0.010 secs] [Times: user=0.03 sys=0.00, real=0.01 secs]
744 2018-10-10T17:22:04.173+0800: 16.561: Application time: 1.0000975 seconds
其中关键信息:
Metaspace used 44821K, capacity 45488K, committed 45788K, reserved 1089536K
这个说明metaspace使用空间达到44m的时候,就发生了full gc,然后扩容之后,第二次full gc时,情况是这样的:
Metaspace used 91845K, capacity 92995K, committed 93504K, reserved 1132544K
找到原因
上面可以发现是因为metaspace空间满了导致full gc。那么问题来了,我们metaspaceSize设置的多大呢?从上面的参数打印来看,并没有配置
好吧,这就是原因。线上的配置是-XX:PermSize=350m -XX:MaxPermSize=350m ,这都是永久代的配置,但我们线上已升级到java8,并没有永久代。java8取而代之的是metaspace,所以,最终原因是,升级了java8,但是启动参数没有修改。
网上说如果没有配置metaspaceSize,默认大小时20.8M,我在本地测试确实发现是这样,但是这里,为什么是45m?这个问题需要阅读的您帮我解决!!!
还有就是,我们升级了很多机器,为什么就这一个服务启动是会发生full gc?
这个也很简单,metaspace存放类和方法的元数据以及常量池,joy-merchant项目很老了,东西太多。
再次更新,事实证明我太大意了,其他服务启动的时候也发生了full gc,只不过没有配置告警而已。20.8m还是太小了
然后就是CMS的日志解析,有兴趣可以阅读文章:CMS收集过程和日志分析
解决办法
修改参数:-XX:MetaspaceSize=128m -XX:MaxMetaspaceSize=256m
知识补充
关于metaspaceSize这里有几个要点需要明确:
- 无论-XX:MetaspaceSize配置什么值,Metaspace的初始容量一定是21807104(约20.8m);
- Metaspace由于使用不断扩容到-XX:MetaspaceSize参数指定的量,就会发生FGC;且之后每次Metaspace扩容都会发生FGC;
- 如果Old区配置CMS垃圾回收,那么第2点的FGC也会使用CMS算法进行回收;
- Meta区容量范围为[20.8m, MaxMetaspaceSize);
- 如果MaxMetaspaceSize设置太小,可能会导致频繁FGC,甚至OOM;
总结
多背 多记 多实践 形成沉淀