Demo
without evacuation (partially stw)
1.416: [GC pause (young) (initial-mark), 0.62417980 secs] // initial mark phase…....2.042: [GC concurrent-root-region-scan-start] // concurrent scan phase start2.067: [GC concurrent-root-region-scan-end, 0.0251507] // concurrent scan phase end2.068: [GC concurrent-mark-start] // concurrent mark phase start3.198: [GC concurrent-mark-reset-for-overflow] // well, some awkward exception occurred and would be self-adjusted soon4.053: [GC concurrent-mark-end, 1.9849672 sec] // concurrent mark phase end4.055: [GC remark 4.055: [GC ref-proc, 0.0000254 secs], 0.0030184 secs] // remark phase done, stw[Times: user=0.00 sys=0.00, real=0.00 secs] 4.088: [GC cleanup 117M->106M(138M), 0.0015198 secs] // cleanup phase done, stw[Times: user=0.00 sys=0.00, real=0.00 secs]4.090: [GC concurrent-cleanup-start] // concurrently free up regions that is empty, start4.091: [GC concurrent-cleanup-end, 0.0002721] // concurrently free up regions that is empty, end |
with evacuation (completely stw)
0.522: [GC pause (young), 0.15877971 secs] // 这是一次ygc// 开始时间点0.522，stw持续时间0.15877971[Parallel Time: 157.1 ms] // 本次ygc的并行时间157.1ms[GC Worker Start (ms): 522.1 522.2 522.2 522.2 // 4个GCWorker的启动时间Avg: 522.2, Min: 522.1, Max: 522.2, Diff: 0.1] // 平均值，最小值，最大值，最大最小差[Ext Root Scanning (ms): 1.6 1.5 1.6 1.9 // 4个GCWorker扫描根的时长Avg: 1.7, Min: 1.5, Max: 1.9, Diff: 0.4] // 平均值，最小值，最大值，最大最小差[Update RS (ms): 38.7 38.8 50.6 37.3 // 4个GCWorkrer更新RS的时长Avg: 41.3, Min: 37.3, Max: 50.6, Diff: 13.3] // 平均值，最小值，最大值，最大最小差[Processed Buffers : 2 2 3 2 // 4个GCWorker更新的RS数量Sum: 9, Avg: 2, Min: 2, Max: 3, Diff: 1] // 总数，平均值，最小值，最大值，最大最小差[Scan RS (ms): 9.9 9.7 0.0 9.7 // 4个GCWorker扫描RS的时长Avg: 7.3, Min: 0.0, Max: 9.9, Diff: 9.9] // 平均值，最小值，最大值，最大最小差[Object Copy (ms): 106.7 106.8 104.6 107.9 // 4个GCWorker复制存活对象的时长Avg: 106.5, Min: 104.6, Max: 107.9, Diff: 3.3] // 平均值，最小值，最大值，最大最小差[Termination (ms): 0.0 0.0 0.0 0.0 // 4个GCWorker的终止时长Avg: 0.0, Min: 0.0, Max: 0.0, Diff: 0.0] // 平均值，最小值，最大值，最大最小差[Termination Attempts : 1 4 4 6 // 4个GCWorker的尝试终止次数Sum: 15, Avg: 3, Min: 1, Max: 6, Diff: 5] // 总数，平均值，最小值，最大值，最大最小差[GC Worker End (ms): 679.1 679.1 679.1 679.1 // 4个GCWorker的停止时间Avg: 679.1, Min: 679.1, Max: 679.1, Diff: 0.1] // 平均值，最小值，最大值，最大最小差[GC Worker (ms): 156.9 157.0 156.9 156.9 // 4个GCWorker的存活时间Avg: 156.9, Min: 156.9, Max: 157.0, Diff: 0.1] // 平均值，最小值，最大值，最大最小差[GC Worker Other (ms): 0.3 0.3 0.3 0.3 // 4个GCWorker花费在其他杂事上的时间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)] // 回收效果// Eden从12M回收到0B，容量从12M减少到10M// Survivors从0B增加到2048K// 堆从13M减少到9739K，容量保持不变[Times: user=0.59 sys=0.02, real=0.16 secs] |
参考资料
权威参考
https://blogs.oracle.com/poonam/understanding-g1-gc-logs |
近期评论