本篇文章主要介绍在-XX:+PrintGCDetails选项的情况下G1 GC log打印的信息。(注:本文假设读者对G1算法的基本原理已经有所了解)

下面是一段G1垃圾收集器相关的log信息

0.522: [GC pause (young), 0.15877971 secs]
[Parallel Time: 157.1 ms]
[GC Worker Start (ms): 522.1 522.2 522.2 522.2
Avg: 522.2, Min: 522.1, Max: 522.2, Diff: 0.1]
[Ext Root Scanning (ms): 1.6 1.5 1.6 1.9
Avg: 1.7, Min: 1.5, Max: 1.9, Diff: 0.4]
[Update RS (ms): 38.7 38.8 50.6 37.3
Avg: 41.3, Min: 37.3, Max: 50.6, Diff: 13.3]
[Processed Buffers : 2 2 3 2
Sum: 9, Avg: 2, Min: 2, Max: 3, Diff: 1]
[Scan RS (ms): 9.9 9.7 0.0 9.7
Avg: 7.3, Min: 0.0, Max: 9.9, Diff: 9.9]
[Object Copy (ms): 106.7 106.8 104.6 107.9
Avg: 106.5, Min: 104.6, Max: 107.9, Diff: 3.3]
[Termination (ms): 0.0 0.0 0.0 0.0
Avg: 0.0, Min: 0.0, Max: 0.0, Diff: 0.0]
[Termination Attempts : 1 4 4 6
Sum: 15, Avg: 3, Min: 1, Max: 6, Diff: 5]
[GC Worker End (ms): 679.1 679.1 679.1 679.1
Avg: 679.1, Min: 679.1, Max: 679.1, Diff: 0.1]
[GC Worker (ms): 156.9 157.0 156.9 156.9
Avg: 156.9, Min: 156.9, Max: 157.0, Diff: 0.1]
[GC Worker Other (ms): 0.3 0.3 0.3 0.3
Avg: 0.3, Min: 0.3, Max: 0.3, Diff: 0.0]
[Clear CT: 0.1 ms]
[Other: 1.5 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 0.3 ms]
[Ref Enq: 0.0 ms]
[Free CSet: 0.3 ms]
[Eden: 12M(12M)->0B(10M) Survivors: 0B->2048K Heap: 13M(64M)->9739K(64M)]
[Times: user=0.59 sys=0.02, real=0.16 secs] 上面日志是一段G1垃圾收集器的“整理暂停”阶段的日志,在这个阶段仍然存活的Java对象会从现在所在的regions拷贝到新的regions。
这是一个stop-the-world行为,所有的应用程序线程会在一个合适的安全点停下。 下面我们来看看日志中每行信息的具体意思, 0.522: [GC pause (young), 0.15877971 secs]
该次整理暂停阶段发生在应用程序启动0.522秒后,涉及整理的regions是young区(如果括号里面的内容是mixed,则会同时涉及到young区和old区),这个过程耗时0.15秒 [Parallel Time: 157.1 ms]
GC工作线程在整个阶段花费的时间 [GC Worker Start (ms): 522.1 522.2 522.2 522.2
Avg: 522.2, Min: 522.1, Max: 522.2, Diff: 0.1]
GC工作线程开始工作的时间点,单位是ms [Ext Root Scanning (ms): 1.6 1.5 1.6 1.9
Avg: 1.7, Min: 1.5, Max: 1.9, Diff: 0.4]
扫描扩展根节点花费的时间,单位ms [Update RS (ms): 38.7 38.8 50.6 37.3
Avg: 41.3, Min: 37.3, Max: 50.6, Diff: 13.3]
GC工作线程更新Remembered Set花费的时间,Remembered Set标记了heap region存储了哪些java对象 [Processed Buffers : 2 2 3 2
Sum: 9, Avg: 2, Min: 2, Max: 3, Diff: 1]
GC工作线程扫描Remembered Set的数量 [Scan RS (ms): 9.9 9.7 0.0 9.7
Avg: 7.3, Min: 0.0, Max: 9.9, Diff: 9.9]
GC工作线程花费在Remembered Set扫描上面的时间 [Object Copy (ms): 106.7 106.8 104.6 107.9
Avg: 106.5, Min: 104.6, Max: 107.9, Diff: 3.3]
对象拷贝花费的时间 [GC Worker End (ms): 679.1 679.1 679.1 679.1
Avg: 679.1, Min: 679.1, Max: 679.1, Diff: 0.1]
GC工作线程完成操作的时间节点 [Eden: 12M(12M)->0B(13M) Survivors: 0B->2048K Heap: 14M(64M)->9739K(64M)]
本行给出了GC处理后,各个内存区域容量的变化,从上面的日志可以看到Eden区的内存已经全部被回收,而且被G1算法设定的目标值变大
[Times: user=0.59 sys=0.02, real=0.16 secs]
该行记录GC阶段花费的各个角度的时间统计,如果real time与JVM给出的GC耗时相差较大,则表明有其他的服务在消耗机器的资源 像CMS算法一样,G1算法也会有并发标记的处理过程,
1.416: [GC pause (young) (initial-mark), 0.62417980 secs]
…....
2.042: [GC concurrent-root-region-scan-start]
2.067: [GC concurrent-root-region-scan-end, 0.0251507]
2.068: [GC concurrent-mark-start]
3.198: [GC concurrent-mark-reset-for-overflow]
4.053: [GC concurrent-mark-end, 1.9849672 sec]
4.055: [GC remark 4.055: [GC ref-proc, 0.0000254 secs], 0.0030184 secs](注:remark阶段是stop-the-world的)
[Times: user=0.00 sys=0.00, real=0.00 secs]
4.088: [GC cleanup 117M->106M(138M), 0.0015198 secs]
[Times: user=0.00 sys=0.00, real=0.00 secs]
4.090: [GC concurrent-cleanup-start]
4.091: [GC concurrent-cleanup-end, 0.0002721]

04-06 01:29