G1日志
Young Collection日志
1 | 2016-09-29T16:58:43.298+0800: 84662.983: [GC pause (G1 Evacuation Pause) (young) |
GC pause (G1 Evacuation Pause) (young) - 表示此时GC暂停是YGC。
Parallel Time与GC Workers – 并行阶段总的停顿时间和GC工作线程数量。紧跟着的几行显示并行阶段的执行任务。
GC Worker Start与GC Worker End – 各个工作线程(workers)启动和结束的时间戳(Timestamp)的统计值
External Root Scanning - 扫描外部根花费的时间统计值
Update RS - 更新Remembered Set。
Scan RS - 扫描CSet中的region的Remembered Sets，查找指向Collection Set的references。
Code Root Scanning – 扫描code root set查找指向CSet的引用。
Object copy – 每个独立的线程在拷贝和转移对象时所消耗的时间.
Termination time - 结束时间，当worker线程完成了自己那部分对象的复制和扫描任务,就进入终止协议(termination protocol)。它会查找未完成的工作(looks for work to steal), 一旦它完成就会再进入终止协议。终止尝试记录(Termination attempt counts)所有查找工作的尝试次数(attempts to steal work).
GC worker other – 每个GC线程中不能归属到之前列出的阶段任务（usual task）的其他时间。
GC Worker Total -每个独立的 GC worker 线程消耗的时间，包含“usual” and “unusual”任务的执行时间。并行任务完成之后将开始串行任务，该阶段主GC线程updates code roots with the new location of evacuated objects and also purges the code root set table. clear CT phase (which is carried out in parallel with the help of parallel worker threads) clears the card table marks。
[Code Root Fixup: 0.1 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 1.1 ms]
Choose CSet – 确定要进行垃圾回收的region集合时消耗的时间. 通常很小,在必须选择 old 区时会稍微长一点点。
Ref Proc -处理GC前面阶段产生的sofe、weak等引用所使用的时间
Ref Enq -将soft, weak, 等引用放置到待处理列表(pending list)花费的时间.
Free CSet -释放刚被垃圾收集的 heap区所消耗的时间,包括对应的remembered sets。
concurrent mark 日志
1 | 2016-10-10T17:14:28.807+0800: 12.742: [GC pause (Metadata GC Threshold) (young) (initial-mark) |
GC pause (Metadata GC Threshold) (young) (initial-mark) — 显示本次GC暂停是由于Metadata空间不足引发初始标记阶段。除了Metadata GC Threshold触发并发标记，还可能会有G1 Humongous Allocation、G1 Evacuation Pause（主要是该原因触发），以上两者本质上貌似还是occupancy higher than threshold。initial-mark实质上是一次YGC，有STW，暂停时间为real=0.20 secs。
concurrent-root-region-scan — 并发根扫描阶段。
concurrent-mark — 并发标记阶段。
remark — 重新标记阶段，会有STW，暂停时间为real=0. 02 secs。
cleanup — 清除阶段，会有STW，暂停时间为real=0. 00 secs（因为显示的值是保留了两位小数后的值，real值可能很小）。清除阶段显示会将260M空间清理，于是紧接着会有额外的concurrent-cleanup阶段。倘若没有空间清理，concurrent-cleanup就不会存在。
Mixed GC日志
在分析MixedGC前，先看下配置的JVM参数：
1 | -Xms96g |
堆空间是96G,每个region大小32M，那么G1会划分出3072个region，G1OldCSetRegionThresholdPercent限制每次能进入CSet的old region容量最大为5%的堆空间，即4915.2M，合计153.6个old region，四舍五入为154。
接下来分析日志。
在每次并发标记阶段会紧接着一次YGC，来决定是否触发Mixed GC。
1 | 2016-10-11T08:26:26.848+0800: 54730.783: [GC pause (G1 Evacuation Pause) (young) |
从第四行可以看出，这次YGC后发现并发标记阶段选出的可以进行垃圾回收的old region数量有1509个，可回收空间占47.51 %，大于能容忍浪费的5%，于是需要开始 mixed GC。
1 | 2016-10-11T08:26:34.619+0800: 54738.554: [GC pause (G1 Evacuation Pause) (mixed) |
第一行显示这次疏散暂停的类型—混合GC，紧接着的几行中显示开始筛选CSet，predicted base time是预测花费时间，依据添加到CSet的young和old region时间。
可以发现本次CSet筛选了154个old region到CSet中，这个数值就是之前计算出的最大能加入到CSet的数量（G1会尝试一次将最大数量的region加入CSet，根据暂停时间来调整下次进入CSet的old region数量）。
第七行显示这次Mixed GC后，还剩1355个candidate old region（1509-154），可回收空间占42.50%，于是G1决定将继续Mixed GC（continue mixed GCs）。垃圾收集时间0.0325863 secs，在目标停顿100ms以内，G1认为154个old region回收将是可行的数量，于是会在下一次的Mixed GC也选择这个数量的old region进入CSet。
倘若超过了目标停顿时间，Mixed GC可能会在下次回收阶段只筛选95个old region。为什么是95个？因为开始MixedGC前的那次YGC，发现有1509个候选old region，设置的G1MixedGCCountTarget为16，那么每次进入CSet的old region数量最小必须是95（1509/16 = 94.31）。如果只筛选95个old region后暂停时间又小于目标停顿时间，G1又会适当的添加进入CSet的old region数量，来得到一个理想的old region数量。
1 | 2016-10-11T08:27:04.339+0800: 54768.274: [GC pause (G1 Evacuation Pause) (mixed) |
这是期间的某一次Mixed GC日志，这一次只选择了95个old regions进入CSet，注意上次Mixed GC后还剩893 candidate old regions，并且上次Mixed GC暂停时间是0.0841628 secs，尚不清除为什么只选择了95个。但是这里关注的是added expensive regions to CSet，当进入CSet的candidate old region数量没超出最小数量阈值95时，G1会尝试回收expensive region，expensive region表示存活对象的占用空间超过G1MixedGCLiveThresholdPercent的区域，G1不会将该region标注为candidate old regions以供Mixed GC使用，因为这类region的存活率高，疏散代价较高。
1 | 2016-10-11T08:27:55.749+0800: 54819.684: [GC pause (G1 Evacuation Pause) (mixed) |
这次MixedGC后，可回收空间是4.99 %，低于阈值5.00 %，G1将决定不再继续Mixed GC。