理解G1垃圾收集器日志
发表这个文章的目的是为了解释使用了G1垃圾收集器的一些跟踪和诊断选项而生成出来的垃圾收集日志的意义。我们来看一下使用一个提供最详细的信息级别的生产环境选项PrintGCDetails生成的输出日志。同时，我们也会看一下启用的两个诊断选项 -XX:+UnlockDiagnosticVMOptions 、 -XX:G1PrintRegionLivenessInfo 的输出信息，它们会打印出在标记周期末尾每个区域的活跃对象使用了总空间、占用大小和 -XX:+G1PrintHeapRegions 提供在堆的区域上的最详尽的分配和释放的信息。
我们会看到在JDK 1.7.0_04下使用了这些选项生成的日志
Option -XX:+PrintGCDetails
这有一个使用了 PrintGCDetail 选项的G1垃圾收集器生成的样例日志。
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收集)日志，活跃对象从一个区域集(年轻代或年轻代+年老代)被复制到另一个区域集。它是一个stop-the-world活动，所以有应用线程在这个时间内、在安全点上都会被停止。
这个暂停由几个被在日志条目里以缩进方式标示出的子任务组成。这是为疏散暂停打印出的最顶一行。
0.522: [GC pause (young), 0.15877971 secs]
这是最顶层的信息，它告诉我们这是一个从进程启动后0.522秒开始的一个疏散暂停，在这时年轻代所有的区域被疏散，如Eden和Survivor。这次收集用了0.15877971秒完成的。
疏散暂停也可以是混合的，这个案例中被选中的区域集包括所有的年轻代区域和一个年老代区域。
1.730: [GC pause (mixed), 0.32714353 secs]
让我们看一下在这次疏散暂停中所有的子任务是如何执行的。
[Parallel Time: 157.1 ms]
并行时间是所有并行GC工作线程所花费的总时间。下面几行和在这次总的并行时间里的这些工作线程执行的并行任务相一致。在这个案例里是157.1ms。。
[GC Worker Start (ms): 522.1 522.2 522.2 522.2
Avg: 522.2, Min: 522.1, Max: 522.2, Diff: 0.1]
第一行告诉我们每一个工作者线程的以毫秒为单位的启动时间。这些启动时间遵守以工作线程的id为顺序的排序规则 - thread 0 启动于522.1ms、thread 1 启动于522.2ms、从进程启动开始算起。第二行告诉我们所有工作线程的平均、最小、最大和差异时间。
[Ext Root Scanning (ms): 1.6 1.5 1.6 1.9
Avg: 1.7, Min: 1.5, Max: 1.9, Diff: 0.4]
这告诉我们每一个扫描根(全局、寄存器、线程栈、虚拟机数据结构)的工作线程花费的时间。这里，thread 0 用了1.6ms执行根扫描任务，thread 1 用了1.5ms。第二行，清晰的给出了所有工作线程的平均、最小、最大和差异时间。
[Update RS (ms): 38.7 38.8 50.6 37.3
Avg: 41.3, Min: 37.3, Max: 50.6, Diff: 13.3]
Update RS 告诉我们每一个线程更新Remembered Sets花费的时间。Remembered Sets是保存到堆中的区域的跟踪引用。设值方法线程持续改变对象图，自此引指向一个特定的区域。我们保存这些改变的跟踪信息到叫作Update Buffers的更新缓存中。Update RS 子任务不能并发的处理更新缓存，更新一致所有区域的Remembered Sets。
[Processed Buffers : 2 2 3 2
Sum: 9, Avg: 2, Min: 2, Max: 3, Diff: 1]
这告诉我们每一个线程处理的Update Buffers(上面提到的)的数量。
[Scan RS (ms): 9.9 9.7 0.0 9.7
Avg: 7.3, Min: 0.0, Max: 9.9, Diff: 9.9]
这是每一个工作线程扫描Remembered Sets花费的时间。一个区域的Remembered Sets包含指向这个区域的引用的相符合的卡片。这个阶段扫描这些卡片寻找指向所有这些区域的Collection Set的引用。
[Object Copy (ms): 106.7 106.8 104.6 107.9
Avg: 106.5, Min: 104.6, Max: 107.9, Diff: 3.3]
这些是每一个工作线程把Collection Sets的区域里的活跃对象复制到另一个区域里花费时间。
[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]
为Collection Set选择区域所花费的时间。
[Ref Proc: 0.3 ms]
花费在处理引用对象上的时间。
[Ref Enq: 0.0 ms]
引用入队到ReferenceQueues花费的时间。
[Free CSet: 0.3 ms]
释放Collection Set数据结构花费的时间。
[Eden: 12M(12M)->0B(13M) Survivors: 0B->2048K Heap: 14M(64M)->9739K(64M)]
这行告诉我们疏散暂停时堆空间的大小变化的详细信息。这显示了Eden占用了12M，在收集前它的容量也是12M。收集之后，它的容量降到了0，自所有对象从Eden区疏散/晋升后。它的目标大小增长到了13M。新Eden区的13M容量不是在这个时候提供的。这个值是Eden的目标大小。如有要求，区域才会被添加到Eden，当已添加的区域已达到目标大小(译者注:也就是新Eden区目标容量满了)，我们启动下一次收集。
类似地，收集之后Survivor从0字节增长到2048K，堆空间总占有量和总容量分别是14M和64M回收之前，回收之后分别变为9739K和64M。
除了疏散暂停，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]
[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]
标记周期的第一阶段是初始标记，从根上直接可达的对象都被标记，这个阶段背负着一个完整的疏散暂停。
2.042: [GC concurrent-root-region-scan-start]
这表示并发阶段的开始，开始扫描从初始标记阶段的幸存者直接可达的根区集合。
2.067: [GC concurrent-root-region-scan-end, 0.0251507]
并发根区扫描阶段的结束，它持续了0.0251507秒。
2.068: [GC concurrent-mark-start]
从进程启动开始2.068秒后并发标记启动。
3.198: [GC concurrent-mark-reset-for-overflow]
这表示全局标记栈已经满了，发生了栈溢出。并发标记检测到这个溢出然后重置了这个数据结构以重新启动标记。
4.053: [GC concurrent-mark-end, 1.9849672 sec]
并发标记阶段的结束，它持续了1.9849672秒。
4.055: [GC remark 4.055: [GC ref-proc, 0.0000254 secs], 0.0030184 secs]
这个是stop-the-world的重新标记阶段。它完成了从上一个阶段的标记工作(SATB buffers processing)的剩余部分。在这个案例中，这个阶段用了0.0030184秒，0.0000254秒花在了引用处理上。
4.088: [GC cleanup 117M->106M(138M), 0.0015198 secs]
清理阶段也是一个stop-the-world阶段。它遍历所以区域的标记信息，计算每个区域的活跃数据信息，重置标记数据结构，根据gc-efficiency(gc效率)对区域进行排序。在这个例子中，总堆大小是138M，计算活跃数据之后，发现总活跃数据大小从117M降到了106M。
4.090: [GC concurrent-cleanup-start]
并发清理阶段开始，它释放被发现为空的区域(不包含任何的活跃数据的区域)，在上一个stop-the-world阶段期间。
4.091: [GC concurrent-cleanup-end, 0.0002721]
并发清理阶段清理空的区域用时0.0002721秒。
Option -XX:G1PrintRegionLivenessInfo
现在，让我们看一下使用G1PrintRegionLivenessInfo参数生成的输出日志。这是一个诊断选项，使用-XX:+UnlockDisgnositicVMOptions参数才能启用。G1PrintRegionLivenessInfo打印在并发标记周期的清理阶段每个区的活跃数据信息。
26.896: [GC cleanup ### PHASE Post-Marking @ 26.896 ### HEAP committed: 0x02e00000-0x0fe00000 reserved: 0x02e00000-0x12e00000 region-size: 1048576
并发标记周期的清理阶段，开始于进程启动之后26.896秒。这个活跃数据信息在标记阶段被打印出来了。已提交的G1堆范围从0x02e00000到0x0fe00000，Java虚拟机保留的总的堆从0x02e00000到0x12e00000。G1堆中的每一个区大小是1048576字节。
### type address-range used prev-live next-live gc-eff ### (bytes) (bytes) (bytes) (bytes/ms)
这是输出信息的头部，它告诉我们关于区域的类型、区域的寻址范围、区域的已用空间、相对于之前标记周期的区域的活跃数据、相对于当前标记周期的区域的活跃数据和那个区域的GC效率。
### FREE 0x02e00000-0x02f00000 0 0 0 0.0
这是一个空闲区域
### OLD 0x02f00000-0x03000000 1048576 1038592 1038592 0.0
年老代区域寻址范围从0x02f00000到0x03000000。区域总已使用的空间是1048576字节。按照标记周期活跃数据是1038592字节，相对当前标记周期的活跃数据也是1038592字节。GC效率计算结果为0。
### EDEN 0x03400000-0x03500000 20992 20992 20992 0.0
这是一个Eden区域。
### HUMS 0x0ae00000-0x0af00000 1048576 1048576 1048576 0.0
### HUMC 0x0af00000-0x0b000000 1048576 1048576 1048576 0.0
### HUMC 0x0b000000-0x0b100000 1048576 1048576 1048576 0.0
### HUMC 0x0b100000-0x0b200000 1048576 1048576 1048576 0.0
### HUMC 0x0b200000-0x0b300000 1048576 1048576 1048576 0.0
### HUMC 0x0b300000-0x0b400000 1048576 1048576 1048576 0.0
### HUMC 0x0b400000-0x0b500000 1001480 1001480 1001480 0.0
这些是为了存储大对象的叫作Humongous Regions的连续区域集。HUMS (Humongous starts)表示Humongous Regions集的开始，HUMC (Humongous continues)表示Humongous Regions集的随后的区域。
### SURV 0x09300000-0x09400000 16384 16384 16384 0.0
这是一个Survivor区域。
### SUMMARY capacity: 208.00 MB used: 150.16 MB / 72.19 % prev-live: 149.78 MB / 72.01 % next-live: 142.82 MB / 68.66 %
最后，打印出一个总结，列出了容量、已用空间、并发标记完成之后生命力的变化。在这个案例中，G1的堆大小是208M，总已用空间是150.16M占总堆大小的72.19%、之前标记的活跃数据是149.78M占总堆大小的72.01%、依据并发标记活跃数据是142.82M占总堆大小的68.66%。
Option -XX:+G1PrintHeapRegions
G1PrintHeapRegions选项记录当和区域相关一些事件，比如当区域被提交、分配、或者回收。
COMMIT/UNCOMMIT events
G1HR COMMIT [0x6e900000,0x6ea00000]
G1HR COMMIT [0x6ea00000,0x6eb00000]
这表示堆被初始化或者扩展，这个区域(从0x6eb00000到0x6ec00000)被刷新提交。COMMIT 事件总是按顺序生成。比如下一个COMMIT 事件总会是未提交区域的低地址。
G1HR UNCOMMIT [0x72700000,0x72800000]
G1HR UNCOMMIT [0x72600000,0x72700000]
和COMMIT相反。堆空间在一次Full GC后收缩了，区域被反提交。像COMMIT、UNCOMMIT这样的事件都是按顺序生成的。比如下一次UNCOMMIT事件总会是已提交区域的高地址。
GC Cycle events
G1HR #StartGC 7
G1HR CSET 0x6e900000
G1HR REUSE 0x70500000
G1HR ALLOC(Old) 0x6f800000
G1HR RETIRE 0x6f800000 0x6f821b20
G1HR #EndGC 7
这显示了一个疏散暂停的开始和结束。这个事件之后跟着一个GC计数器跟踪疏散暂停和Full GCs。这里显示这是进程启动后的第7次GC。
G1HR #StartFullGC 17
G1HR UNCOMMIT [0x6ed00000,0x6ee00000]
G1HR POST-COMPACTION(Old) 0x6e800000 0x6e854f58
G1HR #EndFullGC 17
显示Full GC的开始和结束。这个事件和上面的一样跟着一个同样的GC计数器。这是进程启动后的第17次GC。
ALLOC events
G1HR ALLOC(Eden) 0x6e800000
底部从0x6e800000开始的区域被用于分配。在这个例子中这个区域被设值方法分配为Eden区。
G1HR ALLOC(StartsH) 0x6ec00000 0x6ed00000
G1HR ALLOC(ContinuesH) 0x6ed00000 0x6e000000
被用来给Humongous object分配的区域。这个对象跨越了两个区域。
G1HR ALLOC(SingleH) 0x6f900000 0x6f9eb010
单个区域被用来Humongous object对象的分配。
G1HR COMMIT [0x6ee00000,0x6ef00000]
G1HR COMMIT [0x6ef00000,0x6f000000]
G1HR COMMIT [0x6f000000,0x6f100000]
G1HR COMMIT [0x6f100000,0x6f200000]
G1HR ALLOC(StartsH) 0x6ee00000 0x6ef00000
G1HR ALLOC(ContinuesH) 0x6ef00000 0x6f000000
G1HR ALLOC(ContinuesH) 0x6f000000 0x6f100000
G1HR ALLOC(ContinuesH) 0x6f100000 0x6f102010
这里，堆空间中空闲的已提交区域可能不满足Humongous object分配请求。所以堆空间需要扩展。因此新的区域会被提交，为Humongous object分配空间。
G1HR ALLOC(Old) 0x6f800000
GC期间年老代被用于分配的开始区域
G1HR ALLOC(Survivor) 0x6fa00000
GC期被用来复制老对象的区域
注意Eden和Humongous ALLOC事件在GC边界之外生成，Survivor ALLOC事件在GC边界之内生成。
Other Events
G1HR RETIRE 0x6e800000 0x6e87bd98
收回、停止使用从0x6e800000到0x6e87bd98的空间分配。
注意大部分区域是满的当他们被收回，我们忽略这个事件来减少输出量。当同一类型的另一个区域被分配或者我们达到了GC的开始、结束(取决于区域)，一个区域才被收回。所以对Eden区域有(举例)：
- ALLOC(Eden) Foo
- ALLOC(Eden) Bar
- StartGC
第二点，Foo已经被收回，它曾经是满的。第三点，Bar被收回，它曾经是满的。如果当它们被收回时都不是满的，我们会有一个RETIRE 事件。
- ALLOC(Eden) Foo
- RETIRE Foo top
- ALLOC(Eden) Bar
- StartGC
G1HR CSET 0x6e900000
区域(底部：0x6e900000)被选择为Collection Set。这个区域可能之前已经被选为Collection Set(当它被分配时)。然而，我们为在CSet里的所有的区域生成CSET事件来确保没有关于哪些区域是CSet的一部分的困惑。
G1HR POST-COMPACTION(Old) 0x6e800000 0x6e839858
在全量压缩之后为每一个堆中非空的区域生成一个POST-COMPACTION 事件。一个全量的压缩操作四处移动对象，所以我们不知道堆(哪些区域被写入，哪些区域被清空)的结果形状是什么样子的。为了处理这个，我们为每个非空的区域生成一个POST-COMPACTION事件附带这些区域的类型信息(old/humongous)和堆空间的边界。所以我们应该不会有eden和survivors。
POST-COMPACTION事件生成时会附带Full GC 边界。
G1HR CLEANUP 0x6f400000
G1HR CLEANUP 0x6f300000
G1HR CLEANUP 0x6f200000
这些区域在并发的重新标记阶段之后被发现是空的，稍候会马上被回收掉。
G1HR #StartGC 5
G1HR CSET 0x6f400000
G1HR CSET 0x6e900000
G1HR REUSE 0x6f800000
GC结束时我们收回了我们分配的年老代区域。他们不是满的，下一次GC期我们继续分配它。这就是REUSE的意义。在上面的例子中，0x6f800000 应该已经是在上一次GC期间的ALLOC(Old)事件的最后一个区域，应该在上一次GC结束前被收回。
G1HR ALLOC-FORCE(Eden) 0x6f800000
一个特殊的ALLOC事件，指出我们已经达到指定类型区域(这里是Eden)期望的最大值。但是我们决定再分配一个。当我们扩展年轻代时，当前它只被用于Eden区域，因为我们不能执行一个GC因为GC-Locker是激活的。
G1HR EVAC-FAILURE 0x6f800000
在GC期间，因为堆空间是满的，我们从给出的区域疏散一个对象失败了。没有剩余空间来复制这个对象。这个事件被生成附带GC边界，为疏散对象失败的每个区域都生成一次。
When Heap Regions are reclaimed ?
非常值得谈论一下在G1堆中的堆区域什么时候被回收。
- CSet里的所有区域(出现在CSet事件里的区域)在GC结束时被回收。 EVAC-FAILURE事件的区域除外。
- CLEANUP 事件 的所有区域都会被回收。
- Full GC之后，一些区域(我们从那移出对象的那些区域)会被回收。但是没有被显示的显示出来，代替的是被留下来的、以POST-COMPACTION事件打印出来的堆里的非空区域。
其它
教程源地址：Understanding G1 GC Logs
有翻译不对或者不清楚的地方，敬请各位大神指正
注意：尊重劳动成果，转载请注明出处，谢谢！ 理解G1垃圾收集器日志