Fork me on GitHub

G1日志

Young GC日志

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
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
class space used 3391K, capacity 3480K, committed 3584K, reserved 1048576K
//java 8的新特性,去掉永久区,添加了元数据区,这块不是本文重点,不再赘述。需要注意的是,之所以有committed和reserved,是因为没有设置MetaspaceSize=MaxMetaspaceSize。
[GC pause (G1 Evacuation Pause) (young)
//GC原因,新生代minor GC。
[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时间。
[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。
[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。
[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] [Processed Buffers: Min: 0, Avg: 2.8, Max: 5, Diff: 5, Sum: 11]
//Update RS (ms)是每个线程花费在更新Remembered Set上的时间。
[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]
[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]
//其他事项共耗时5.8ms,其他事项包括选择CSet,处理已用对象,引用入ReferenceQueues,释放CSet中的region到free list。
[Eden: 159.0M(159.0M)->0.0B(301.0M) Survivors: 13.0M->11.0M Heap: 328.8M(3072.0M)->167.3M(3072.0M)]
//新生代清空了,下次扩容到301MB。

global concurrent marking 日志

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
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]
{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)
…….
2014-12-10T11:13:09.597+0800: 66955.317: [GC concurrent-root-region-scan-start]
2014-12-10T11:13:09.597+0800: 66955.318: Total time for which application threads were stopped: 0.0655753 seconds
2014-12-10T11:13:09.610+0800: 66955.330: Application time: 0.0127071 seconds
2014-12-10T11:13:09.614+0800: 66955.335: Total time for which application threads were stopped: 0.0043882 seconds
2014-12-10T11:13:09.625+0800: 66955.346: [GC concurrent-root-region-scan-end, 0.0281351 secs]
2014-12-10T11:13:09.625+0800: 66955.346: [GC concurrent-mark-start]
2014-12-10T11:13:09.645+0800: 66955.365: Application time: 0.0306801 seconds
2014-12-10T11:13:09.651+0800: 66955.371: Total time for which application threads were stopped: 0.0061326 seconds
2014-12-10T11:13:10.212+0800: 66955.933: [GC concurrent-mark-end, 0.5871129 secs]
2014-12-10T11:13:10.212+0800: 66955.933: Application time: 0.5613792 seconds
2014-12-10T11:13:10.215+0800: 66955.935: [GC remark 66955.936: [GC ref-proc, 0.0235275 secs], 0.0320865 secs]
[Times: user=0.05 sys=0.00, real=0.03 secs]
2014-12-10T11:13:10.247+0800: 66955.968: Total time for which application threads were stopped: 0.0350098 seconds
2014-12-10T11:13:10.248+0800: 66955.968: Application time: 0.0001691 seconds
2014-12-10T11:13:10.250+0800: 66955.970: [GC cleanup 1178M->632M(3072M), 0.0060632 secs]
[Times: user=0.02 sys=0.00, real=0.01 secs]
2014-12-10T11:13:10.256+0800: 66955.977: Total time for which application threads were stopped: 0.0088462 seconds
2014-12-10T11:13:10.257+0800: 66955.977: [GC concurrent-cleanup-start]
2014-12-10T11:13:10.259+0800: 66955.979: [GC concurrent-cleanup-end, 0.0024743 secs

  这次发生global concurrent marking的原因是:humongous allocation,上面提过在巨大对象分配之前,会检测到old generation 使用占比是否超过了 initiating heap occupancy percent(45%),因为
1449132032(used)+ 579608(allocation request:) > 1449551430(threshold),所以触发了本次global concurrent marking。对于具体执行过程,上面的表格已经详细讲解了。值得注意的是上文中所说的initial mark往往伴随着一次YGC,在日志中也有体现:GC pause (G1 Humongous Allocation) (young) (initial-mark)。

-----------------本文结束,感谢您的阅读-----------------