本文采用的 JDK 版本:
- java version "1.8.0_144"
- Java(TM) SE Runtime Environment (build 1.8.0_144-b01)
- Java HotSpot(TM) 64-Bit Server VM (build 25.144-b01, mixed mode)
一, GC 日志参数
设置 JVM GC 格式日志的主要参数包括如下 8 个:
-XX:+PrintGC 输出简要 GC 日志
-XX:+PrintGCDetails 输出详细 GC 日志
-Xloggc:gc.log 输出 GC 日志到文件
-XX:+PrintGCTimeStamps 输出 GC 的时间戳 (以 JVM 启动到当期的总时长的时间戳形式)
-XX:+PrintGCDateStamps 输出 GC 的时间戳 (以日期的形式, 如 2013-05-04T21:53:59.234+0800)
-XX:+PrintHeapAtGC 在进行 GC 的前后打印出堆的信息
-verbose:gc
-XX:+PrintReferenceGC 打印年轻代各个引用的数量以及时长
本文假设读者已经熟悉 JVM 内存结构.
1.1 -XX:+PrintGC 与 - verbose:gc
如果想开启 GC 日志的信息, 可以通过设置如下的参数任一参数:
- -XX:+PrintGC
- -XX:+PrintGCDetails
- -Xloggc:gc.log
如果只设置 - XX:+PrintGC 那么打印的日志如下所示:
[GC (Allocation Failure) 61805K->9849K(256000K), 0.0041139 secs]
1,GC 表示是一次 YGC(Young GC)
2,Allocation Failure 表示是失败的类型
3,68896K->5080K 表示年轻代从 68896K 降为 5080K
4,256000K 表示整个堆的大小
5,0.0041139 secs 表示这次 GC 总计所用的时间
在 JDK 8 中,-verbose:gc 是 - XX:+PrintGC 一个别称, 日志格式等价与:-XX:+PrintGC,.
不过在 JDK 9 中 -XX:+PrintGC 被标记为 deprecated.
-verbose:gc 是一个标准的选项, -XX:+PrintGC 是一个实验的选项, 建议使用 - verbose:gc 替代 - XX:+PrintGC
参考: Difference between -XX:+PrintGC and -verbose:gc
- 1.2 -XX:+PrintGCDetails
- [GC (Allocation Failure) [PSYoungGen: 53248K->2176K(59392K)] 58161K->7161K(256000K), 0.0039189 secs] [Times: user=0.02 sys=0.01, real=0.00 secs]
1,GC 表示是一次 YGC(Young GC)
2,Allocation Failure 表示是失败的类型
3,PSYoungGen 表示年轻代大小
4,53248K->2176K 表示年轻代占用从 53248K 降为 2176K
5,59392K 表示年轻带的大小
6,58161K->7161K 表示整个堆占用从 53248K 降为 2176K
7,256000K 表示整个堆的大小
8, 0.0039189 secs 表示这次 GC 总计所用的时间
9,[Times: user=0.02 sys=0.01, real=0.00 secs] 分别表示, 用户态占用时长, 内核用时, 真实用时.
时间保留两位小数, 四舍五入.
- 1.3 -XX:+PrintGCTimeStamps
- 1.963: [GC (Allocation Failure) 61805K->9849K(256000K), 0.0041139 secs]
如果加上 - XX:+PrintGCTimeStamps 那么日志仅仅比 1.1 介绍的最前面多了一个时间戳: 1.963, 表示从 JVM 启动到打印 GC 时刻用了 1.963 秒.
- 1.4 -XX:+PrintGCDateStamps
- 2019-03-05T16:56:15.108+0800: [GC (Allocation Failure) 61805K->9849K(256000K), 0.0041139 secs]
如果加上 - XX:+PrintGCDateStamps 那么日志仅仅比 1.1 介绍的最前面多了一个日期时间: 2019-03-05T16:56:15.108+0800, 表示打印 GC 的时刻的时间是 2019-03-05T16:56:15.108+0800.+0800 表示是东 8 区.
1.5 -XX:+PrintHeapAtGC
这个参数开启后,
使用如下参数 - verbose:gc -XX:+PrintHeapAtGC -Xmn64M -Xms256M -Xmx256M
打印日志如下:
- {Heap before GC invocations=1 (full 0):
- PSYoungGen total 57344K, used 49152K [0x00000000fc000000, 0x0000000100000000, 0x0000000100000000)
- eden space 49152K, 100% used [0x00000000fc000000,0x00000000ff000000,0x00000000ff000000)
- from space 8192K, 0% used [0x00000000ff800000,0x00000000ff800000,0x0000000100000000)
- to space 8192K, 0% used [0x00000000ff000000,0x00000000ff000000,0x00000000ff800000)
- ParOldGen total 196608K, used 0K [0x00000000f0000000, 0x00000000fc000000, 0x00000000fc000000)
- object space 196608K, 0% used [0x00000000f0000000,0x00000000f0000000,0x00000000fc000000)
- Metaspace used 7901K, capacity 8264K, committed 8448K, reserved 1056768K
- class space used 888K, capacity 986K, committed 1024K, reserved 1048576K
- [GC (Allocation Failure) 49152K->2416K(253952K), 0.0030218 secs]
- Heap after GC invocations=1 (full 0):
- PSYoungGen total 57344K, used 2400K [0x00000000fc000000, 0x0000000100000000, 0x0000000100000000)
- eden space 49152K, 0% used [0x00000000fc000000,0x00000000fc000000,0x00000000ff000000)
- from space 8192K, 29% used [0x00000000ff000000,0x00000000ff258020,0x00000000ff800000)
- to space 8192K, 0% used [0x00000000ff800000,0x00000000ff800000,0x0000000100000000)
- ParOldGen total 196608K, used 16K [0x00000000f0000000, 0x00000000fc000000, 0x00000000fc000000)
- object space 196608K, 0% used [0x00000000f0000000,0x00000000f0004000,0x00000000fc000000)
- Metaspace used 7901K, capacity 8264K, committed 8448K, reserved 1056768K
- class space used 888K, capacity 986K, committed 1024K, reserved 1048576K
- }
由此可以看出在, 打印如下日志前后
[GC (Allocation Failure) 49152K->2416K(253952K), 0.0030218 secs]
详细打印出了日志信息
invocations 表示 GC 的次数, 每次 GC 增加一次, 每次 GC 前后的 invocations 相等
1,Heap before GC invocations=1 表示是第 1 次 GC 调用之前的堆内存状况
2,{Heap before GC invocations=1 (full 0): 表示是第 1 次 GC 调用之后的堆内存状况
1.6 -Xloggc:gc.log
如果使用该参数 - Xloggc 则默认开启如下两个参数
-XX:+PrintGC -XX:+PrintGCTimeStamps
如果启动参数如下:-Xloggc:gc.log -Xmn64M -Xms256M -Xmx256M 则日志格式如下所示
0.318: [GC (Allocation Failure) 49152K->2384K(253952K), 0.0038675 secs]
gc.log 也可以指定绝对的路径.
在 gc.log 最前面还会默认打印系统的 JDK 版本与启动的参数
- Java HotSpot(TM) 64-Bit Server VM (25.144-b01) for Linux-amd64 JRE (1.8.0_144-b01), built on Jul 21 2017 21:57:33 by "java_re" with gcc 4.3.0 20080428 (Red Hat 4.3.0-8)
- Memory: 4k page, physical 16287104k(1657700k free), swap 16636924k(15826632k free)
- CommandLine flags: -XX:InitialHeapSize=268435456 -XX:MaxHeapSize=268435456 -XX:MaxNewSize=67108864 -XX:NewSize=67108864 -XX:+PrintGC -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseParallelGC
1.7 -XX:+PrintReferenceGC
此设置 -XX:+PrintReferenceGC 可以打印出 SoftReference,WeakReference,FinalReference,PhantomReference,JNI Weak Reference 几种引用的数量, 以及清理所用的时长, 该参数在进行 YGC 调优时可以排上用场.
[GC (Allocation Failure) [SoftReference, 0 refs, 0.0000119 secs][WeakReference, 499 refs, 0.0000370 secs][FinalReference, 1045 refs, 0.0002313 secs][PhantomReference, 0 refs, 0 refs, 0.0000039 secs][JNI Weak Reference, 0.0000290 secs][PSYoungGen: 53456K->4880K(57344K)] 53496K->4928K(253952K), 0.0037199 secs] [Times: user=0.02 sys=0.01, real=0.01 secs]
具体可以参考占小狼的一篇实战: 一次 Young GC 的优化实践 (FinalReference 相关) https://www.jianshu.com/p/79d4a0516f11
二, CMS GC 日志详细分析
- [GC (CMS Initial Mark) [1 CMS-initial-mark: 19498K(32768K)] 36184K(62272K), 0.0018083 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
- [CMS-concurrent-mark-start]
- [CMS-concurrent-mark: 0.011/0.011 secs] [Times: user=0.02 sys=0.00, real=0.00 secs]
- [CMS-concurrent-preclean-start]
- [CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
- [CMS-concurrent-abortable-preclean-start]
- CMS: abort preclean due to time [CMS-concurrent-abortable-preclean: 0.558/5.093 secs] [Times: user=0.57 sys=0.00, real=5.09 secs]
- [GC (CMS Final Remark) [YG occupancy: 16817 K (29504 K)][Rescan (parallel) , 0.0021918 secs][weak refs processing, 0.0000245 secs][class unloading, 0.0044098 secs][scrub symbol table, 0.0029752 secs][scrub string table, 0.0006820 secs][1 CMS-remark: 19498K(32768K)] 36316K(62272K), 0.0104997 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
- [CMS-concurrent-sweep-start]
- [CMS-concurrent-sweep: 0.007/0.007 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
- [CMS-concurrent-reset-start]
- [CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
CMS 日志分为两个 STW(stop the world)
分别是 init remark(1) 与 remark(7) 两个阶段. 一般耗时比 YGC 长约 10 倍 (个人经验).
(1),[GC (CMS Initial Mark) [1 CMS-initial-mark: 19498K(32768K)] 36184K(62272K), 0.0018083 secs][Times: user=0.01 sys=0.00, real=0.01 secs]
会 STO(Stop The World), 这时候的老年代容量为 32768K, 在使用到 19498K 时开始初始化标记. 耗时短.
(2),[CMS-concurrent-mark-start]
并发标记阶段开始
(3),[CMS-concurrent-mark: 0.011/0.011 secs] [Times: user=0.02 sys=0.00, real=0.00 secs]
并发标记阶段花费时间.
(4),[CMS-concurrent-preclean-start]
并发预清理阶段, 也是与用户线程并发执行. 虚拟机查找在执行并发标记阶段新进入老年代的对象 (可能会有一些对象从新生代晋升到老年代, 或者有一些对象被分配到老年代). 通过重新扫描, 减少下一个阶段 "重新标记" 的工作, 因为下一个阶段会 Stop The World.
(5),[CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
并发预清理阶段花费时间.
(6),[CMS-concurrent-abortable-preclean-start] CMS: abort preclean due to time [CMS-concurrent-abortable-preclean: 0.558/5.093 secs][Times: user=0.57 sys=0.00, real=5.09 secs]
并发可中止预清理阶段, 运行在并行预清理和重新标记之间, 直到获得所期望的 eden 空间占用率. 增加这个阶段是为了避免在重新标记阶段后紧跟着发生一次垃圾清除
(7),[GC (CMS Final Remark) [YG occupancy: 16817 K (29504 K)][Rescan (parallel) , 0.0021918 secs][weak refs processing, 0.0000245 secs][class unloading, 0.0044098 secs][scrub symbol table, 0.0029752 secs][scrub string table, 0.0006820 secs][1 CMS-remark: 19498K(32768K)] 36316K(62272K), 0.0104997 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
会 STW(Stop The World), 收集阶段, 这个阶段会标记老年代全部的存活对象, 包括那些在并发标记阶段更改的或者新创建的引用对象
(8),[CMS-concurrent-sweep-start]
并发清理阶段开始, 与用户线程并发执行.
(9),[CMS-concurrent-sweep: 0.007/0.007 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
并发清理阶段结束, 所用的时间.
(10),[CMS-concurrent-reset-start]
开始并发重置. 在这个阶段, 与 CMS 相关数据结构被重新初始化, 这样下一个周期可以正常进行.
(11),[CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
并发重置所用结束, 所用的时间.
参考:
Geek-Yan https://me.csdn.net/bmwopwer1 : JVM 学习笔记 (四) CMS GC 日志详解
三, G1 垃圾收集器
建议在堆内存大于 6G 以上来使用, 这个是官网的推荐.
四, GC 调优
设置 JVM GC 性能的有如下参数
4.1 -Xmn
新生代大小官网推荐的大小是 3/8, 如果设置太小, 比如 1/10 会导致 Minor GC 与 Major GC 次数增多.
4.2 -XX:MaxTenuringThreshold=n
其中 n 的大小为区间为 [0,15], 如果高于 15,JDK7 会默认 15,JDK 8 会启动报错
五, 常见问题
1 . 并发模式失败 (concurrent mode failure)
发生在 CMS GC 运行期间, 详情参考:
JVM 调优 -- GC 长时间停顿问题及解决方法 http://www.importnew.com/22886.html
GC 的悲观策略
2. 提升失败 (promotion failed)
发生在 Minor GC 期间
参考资料
铁锚 https://me.csdn.net/renfufei : 快速解读 GC 日志
Geek-Yan https://me.csdn.net/bmwopwer1 : JVM 学习笔记 (四) CMS GC 日志详解
来源: https://juejin.im/post/5c80b0f451882532cd57b541