G1提供了两种GC模式，Young GC和Mixed GC，两种都是完全Stop The World的。
* Young GC：选定所有年轻代里的Region。通过控制年轻代的region个数，即年轻代内存大小，来控制young GC的时间开销。
* Mixed GC：选定所有年轻代里的Region，外加根据global concurrent marking统计得出收集收益高的若干老年代Region。在用户指定的开销目标范围内尽可能选择收益高的老年代Region。
内容来源于:
young gc
{Heap before GC invocations=12 (full 1):
garbage-first heap total 3145728K, used 336645K (0x0000000700000000, 0x00000007c0000000, 0x00000007c0000000)
// 表示使用了G1垃圾收集器，total heap 3145728K，使用了336645K。
region size 1024K, 172 young (176128K), 13 survivors (13312K)
// Region大小为1M，青年代占用了172个（共176128K），幸存区占用了13个（共13312K）。
Metaspace used 29944K, capacity 30196K, committed 30464K, reserved 1077248K
// java 8的新特性，去掉永久区，添加了元数据区，这块不是本文重点，不再赘述。需要注意的是，之所以有committed和reserved，是因为没有设置MetaspaceSize=MaxMetaspaceSize。
class space used 3391K, capacity 3480K, committed 3584K, reserved 1048576K
2014-11-14T17:57:23.654+0800: 27.884: [GC pause (G1 Evacuation Pause) (young)
# GC原因，新生代minor GC
Desired survivor size 11534336 bytes, new threshold 15 (max 15)
- age 1: 5011600 bytes, 5011600 total
27.884: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 1461, predicted base time: 35.25 ms, remaining time: 64.75 ms, target pause time: 100.00 ms]
// 发生minor GC和full GC时，所有相关region都是要回收的。而发生并发GC时，会根据目标停顿时间动态选择部分垃圾对并多的Region回收，这一步就是选择Region。_pending_cards是关于RSet的Card Table。predicted base time是预测的扫描card table时间。
27.884: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 159 regions, survivors: 13 regions, predicted young region time: 44.09 ms]
// 这一步是添加Region到collection set，新生代一共159个Region，13个幸存区Region，这也和之前的（172 young (176128K), 13 survivors (13312K)）吻合。预计收集时间是44.09 ms。
27.884: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 159 regions, survivors: 13 regions, old: 0 regions, predicted pause time: 79.34 ms, target pause time: 100.00 ms]
// 这一步是对上面两步的总结。预计总收集时间79.34ms。
, 0.0158389 secs]
[Parallel Time: 8.1 ms, GC Workers: 4]
// 由于收集过程是多线程并行（并发）进行，这里是4个>线程，总共耗时8.1ms（wall clock time）
[GC Worker Start (ms): Min: 27884.5, Avg: 27884.5, Max: 27884.5, Diff: 0.1]
收集线程开>始的时间，使用的是相对时间，Min是最早开始时间，Avg是平均开始时间，Max是最晚开始时间，Diff是Max-Min（此处的0.1貌似有问题）
[Ext Root Scanning (ms): Min: 0.4, Avg: 0.8, Max: 1.2, Diff: 0.8, Sum: 3.1]
// 扫描Roots花费的时间，Sum表示total cpu time，下同。
[Update RS (ms): Min: 0.0, Avg: 0.3, Max: 0.6, Diff: 0.6, Sum: 1.4]
// Update RS (ms)是每个线程花费在更新Remembered Set上的时间。
[Processed Buffers: Min: 0, Avg: 2.8, Max: 5, Diff: 5, Sum: 11]
[Scan RS (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.3]
// 扫描CS中的region对应>的RSet，因为RSet是points-into，所以这样实现避免了扫描old generadion region，但是会产生float garbage。
[Code Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.6]
// 扫描code root耗时。code root指的是经过JIT编译后的代码里，引用了heap中的对象。引用关系保存在RSet中。
[Object Copy (ms): Min: 4.9, Avg: 5.1, Max: 5.2, Diff: 0.3, Sum: 20.4]
// 拷贝活的对象到新region的耗时。
[Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0
// 线程结束，在结束前，它会检查其他线程是否还有未扫描完的引用，如果有，则”偷”过来，完成后再申请结束，这个时>间是线程之前互相同步所花费的时间。
[GC Worker Other (ms): Min: 0.0, Avg: 0.4, Max: 1.3, Diff: 1.3, Sum: 1.4]
// 花费在其他工作上（未列出）的时间。
[GC Worker Total (ms): Min: 6.4, Avg: 6.8, Max: 7.8, Diff: 1.4, Sum: 27.2]
// 每个线程花费的时间和。
[GC Worker End (ms): Min: 27891.0, Avg: 27891.3, Max: 27892.3, Diff: 1.3]
// 每个线程结束的时间。
[Code Root Fixup: 0.5 ms]
// 用来将code root修正到正确的evacuate之后的对象位置所花费的时间
。
[Code Root Migration: 1.3 ms]
// 更新code root 引用的耗时，code root中的引用因为对象的evacuation而需要更新。
[Code Root Purge: 0.0 ms]
// 清除code root的耗时，code root中的引用已经失效，不再指向Region中的对象，所以需要被清除。
[Clear CT: 0.2 ms]
// 清除card table的耗时。
[Other: 5.8 ms]
// 其他事项共耗时5.8ms，其他事项包括选择CSet，处理已用对象，引用入ReferenceQueues，释放CSet中的region到free list。
[Choose CSet: 0.0 ms]
[Ref Proc: 5.0 ms]
[Ref Enq: 0.1 ms]
[Redirty Cards: 0.0 ms]
[Free CSet: 0.2 ms]
[Eden: 159.0M(159.0M)->0.0B(301.0M) Survivors: 13.0M->11.0M Heap: 328.8M(3072.0M)->167.3M(3072.0M)]
// 新生代清空了，下次扩容到301MB。
Heap after GC invocations=13 (full 1):
garbage-first heap total 3145728K, used 171269K [0x0000000700000000, 0x00000007c0000000, 0x00000007c0000000)
region size 1024K, 11 young (11264K), 11 survivors (11264K)
Metaspace used 29944K, capacity 30196K, committed 30464K, reserved 1077248K
class space used 3391K, capacity 3480K, committed 3584K, reserved 1048576K
}
[Times: user=0.05 sys=0.01, real=0.02 secs]
global concurrent marking
66955.252: [G1Ergonomics (Concurrent Cycles) request concurrent cycle initiation, reason: occupancy higher than threshold, occupancy: 1449132032 bytes, allocation request: 579608 bytes, threshold: 1449
551430 bytes (45.00 %), source: concurrent humongous allocation]
2014-12-10T11:13:09.532+0800: 66955.252: Application time: 2.5750418 seconds
66955.259: [G1Ergonomics (Concurrent Cycles) request concurrent cycle initiation, reason: requested by GC cause, GC cause: G1 Humongous Allocation]
// 发生global concurrent marking的原因是：humongous allocation
//上面提过在巨大对象分配之前，会检测到old generation 使用占比是否超过了 initiating heap occupancy percent（45%）
//因为 1449132032(used)+ 579608(allocation request:) > 1449551430(threshold)，所以触发了本次global concurrent marking。
{Heap before GC invocations=1874 (full 4):
garbage-first heap total 3145728K, used 1281786K [0x0000000700000000, 0x00000007c0000000, 0x00000007c0000000)
region size 1024K, 171 young (175104K), 27 survivors (27648K)
Metaspace used 116681K, capacity 137645K, committed 137984K, reserved 1171456K
class space used 13082K, capacity 16290K, committed 16384K, reserved 1048576K
66955.259: [G1Ergonomics (Concurrent Cycles) initiate concurrent cycle, reason: concurrent cycle initiation requested]
2014-12-10T11:13:09.539+0800: 66955.259: [GC pause (G1 Humongous Allocation) (young) (initial-mark)
// initial mark往往伴随着一次YGC，在日志中也有体现：GC pause (G1 Humongous Allocation) (young) (initial-mark)。
…….
66955.317: [GC concurrent-root-region-scan-start]
66955.318: Total time for which application threads were stopped: 0.0655753 seconds
66955.330: Application time: 0.0127071 seconds
66955.335: Total time for which application threads were stopped: 0.0043882 seconds
66955.346: [GC concurrent-root-region-scan-end, 0.0281351 secs]
66955.346: [GC concurrent-mark-start]
66955.365: Application time: 0.0306801 seconds
66955.371: Total time for which application threads were stopped: 0.0061326 seconds
66955.933: [GC concurrent-mark-end, 0.5871129 secs]
66955.933: Application time: 0.5613792 seconds
66955.935: [GC remark 66955.936: [GC ref-proc, 0.0235275 secs], 0.0320865 secs]
eal=0.03 secs]
66955.968: Total time for which application threads were stopped: 0.0350098 seconds
66955.968: Application time: 0.0001691 seconds
66955.970: [GC cleanup 1178M->632M(3072M), 0.0060632 secs]
eal=0.01 secs]
66955.977: Total time for which application threads were stopped: 0.0088462 seconds
66955.977: [GC concurrent-cleanup-start]
66955.979: [GC concurrent-cleanup-end, 0.0024743 secs
Leave a Reply