JVM GC 相关的参数
-XX:+PrintGC 输出 GC 日志-XX:+PrintGCDetails 输出 GC 的详细日志-XX:+PrintGCTimeStamps 输出 GC 的时间戳(以基准时间的形式)-XX:+PrintGCDateStamps 输出 GC 的时间戳(以日期的形式,如 2013-05-04T21:53:59.234+0800)-XX:+PrintHeapAtGC 在进行 GC 的前后打印出堆的信息-Xloggc:D:/gc.log 日志文件的输出路径示例
比如在某个应用中,配置:
-XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:D:/gc.log启动后打印如下 GC 日志:YongGC
2019-04-18T14:52:06.790+0800: 2.653: [GC (Allocation Failure) [PSYoungGen: 33280K->5113K(38400K)] 33280K->5848K(125952K), 0.0095764 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]含义:2019-04-18T14:52:06.790+0800(当前时间戳): 2.653(应用启动基准时间): [GC (Allocation Failure) [PSYoungGen(表示 Young GC): 33280K(年轻代回收前大小)->5113K(年轻代回收后大小)(38400K(年轻代总大小))] 33280K(整个堆回收前大小)->5848K(整个堆回收后大小)(125952K(堆总大小)), 0.0095764(耗时) secs] [Times: user=0.00(用户耗时) sys=0.00(系统耗时), real=0.01(实际耗时) secs] Full GC
2019-04-18T14:52:15.359+0800: 11.222: [Full GC (Metadata GC Threshold) [PSYoungGen: 6129K->0K(143360K)] [ParOldGen: 13088K->13236K(55808K)] 19218K->13236K(199168K), [Metaspace: 20856K->20856K(1069056K)], 0.1216713 secs] [Times: user=0.44 sys=0.02, real=0.12 secs]含义:2019-04-18T14:52:15.359+0800(当前时间戳): 11.222(应用启动基准时间): [Full GC (Metadata GC Threshold) [PSYoungGen: 6129K(年轻代回收前大小)->0K(年轻代回收后大小)(143360K(年轻代总大小))] [ParOldGen: 13088K(老年代回收前大小)->13236K(老年代回收后大小)(55808K(老年代总大小))] 19218K(整个堆回收前大小)->13236K(整个堆回收后大小)(199168K(堆总大小)), [Metaspace: 20856K(持久代回收前大小)->20856K(持久代回收后大小)(1069056K(持久代总大小))], 0.1216713(耗时) secs] [Times: user=0.44(用户耗时) sys=0.02(系统耗时), real=0.12(实际耗时) secs
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]
(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]
并发重置所用结束,所用的时间。