ZGC源码分析（6）- 日志分析

2019-01-15 本文已影响0人躺在石头上吐泡泡

根据ZGC运行的情况，截取部分关键的日志信息。分析如下：

ZGC初始化信息

这一部分主要是ZGC初始化的状态。从日志我们看出JVM的版本，是否支持NUMA，大爷内存等。还有CPU的数目为8，GC工作线程数位5，并发工作线程数为1。整个堆空间15279MB（接近15GB，实际上我设置了15GB的堆空间，这里有效地为14.9GB），预分配的内存为256M

[2018-12-17T14:15:10.878+0800][59454][gc,init] Initializing The Z Garbage Collector
[2018-12-17T14:15:10.878+0800][59454][gc,init] Version: 11.0.1+13-LTS (release)
[2018-12-17T14:15:10.878+0800][59454][gc,init] NUMA Support: Disabled
[2018-12-17T14:15:10.878+0800][59454][gc,init] CPUs: 8 total, 8 available
[2018-12-17T14:15:10.878+0800][59454][gc,init] Memory: 15279M
[2018-12-17T14:15:10.878+0800][59454][gc,init] Large Page Support: Disabled
[2018-12-17T14:15:10.878+0800][59454][gc,init] Workers: 5 parallel, 1 concurrent
[2018-12-17T14:15:10.879+0800][59454][gc,init] Heap backed by file: /memfd:java_heap
[2018-12-17T14:15:10.879+0800][59454][gc,init] Available space on backing filesystem: N/A
[2018-12-17T14:15:10.928+0800][59454][gc,init] Pre-touching: Disabled
[2018-12-17T14:15:10.928+0800][59454][gc,init] Pre-mapping: 256M
[2018-12-17T14:15:10.935+0800][59454][gc,init] Runtime Workers: 5 parallel
[2018-12-17T14:15:10.935+0800][59454][gc ] Using The Z Garbage Collector

GC触发

GC第一次触发是满足预热规则出发的。在日志中我么能看到warmup的字样。

[2018-12-17T14:15:11.166+0800][59461][gc,start] GC(0) Garbage Collection (Warmup)
[2018-12-17T14:15:11.169+0800][59468][gc,phases] GC(0) Pause Mark Start 0.332ms
[2018-12-17T14:15:11.208+0800][59461][gc,phases] GC(0) Concurrent Mark 38.999ms
[2018-12-17T14:15:11.213+0800][59468][gc,phases] GC(0) Pause Mark End 0.111ms
[2018-12-17T14:15:11.213+0800][59461][gc,phases] GC(0) Concurrent Process Non-Strong References 0.191ms
[2018-12-17T14:15:11.213+0800][59461][gc,phases] GC(0) Concurrent Reset Relocation Set 0.001ms
[2018-12-17T14:15:11.215+0800][59461][gc,phases] GC(0) Concurrent Destroy Detached Pages 1.222ms
[2018-12-17T14:15:11.217+0800][59461][gc,phases] GC(0) Concurrent Select Relocation Set 1.929ms
[2018-12-17T14:15:11.217+0800][59461][gc,phases] GC(0) Concurrent Prepare Relocation Set 0.329ms
[2018-12-17T14:15:11.218+0800][59468][gc,phases] GC(0) Pause Relocate Start 0.499ms
[2018-12-17T14:15:11.245+0800][59461][gc,phases] GC(0) Concurrent Relocate 26.737ms
[2018-12-17T14:15:11.245+0800][59461][gc,load ] GC(0) Load: 0.75/0.80/0.90
[2018-12-17T14:15:11.245+0800][59461][gc,mmu ] GC(0) MMU: 2ms/75.0%, 5ms/90.0%, 10ms/93.9%, 20ms/96.9%, 50ms/98.1%, 100ms/99.1%
[2018-12-17T14:15:11.245+0800][59461][gc,marking] GC(0) Mark: 1 stripe(s), 1 proactive flush(es), 1 terminate flush(es), 0 completion(s), 0 continuation(s)
[2018-12-17T14:15:11.245+0800][59461][gc,reloc ] GC(0) Relocation: Successful, 24M relocated
[2018-12-17T14:15:11.245+0800][59461][gc,nmethod] GC(0) NMethods: 38 registered, 0 unregistered
[2018-12-17T14:15:11.245+0800][59461][gc,metaspace] GC(0) Metaspace: 4M used, 4M capacity, 5M committed, 8M reserved
[2018-12-17T14:15:11.245+0800][59461][gc,ref ] GC(0) Soft: 106 encountered, 0 discovered, 0 enqueued
[2018-12-17T14:15:11.245+0800][59461][gc,ref ] GC(0) Weak: 215 encountered, 184 discovered, 46 enqueued
[2018-12-17T14:15:11.245+0800][59461][gc,ref ] GC(0) Final: 0 encountered, 0 discovered, 0 enqueued
[2018-12-17T14:15:11.245+0800][59461][gc,ref ] GC(0) Phantom: 2 encountered, 2 discovered, 1 enqueued
[2018-12-17T14:15:11.246+0800][59461][gc,heap ] GC(0) Mark Start Mark End Relocate Start Relocate End High Low
[2018-12-17T14:15:11.246+0800][59461][gc,heap ] GC(0) Capacity: 298M (29%) 386M (38%) 396M (39%) 450M (44%) 450M (44%) 298M (29%)
[2018-12-17T14:15:11.246+0800][59461][gc,heap ] GC(0) Reserve: 42M (4%) 42M (4%) 42M (4%) 42M (4%) 42M (4%) 42M (4%)
[2018-12-17T14:15:11.246+0800][59461][gc,heap ] GC(0) Free: 728M (71%) 638M (62%) 788M (77%) 644M (63%) 788M (77%) 616M (60%)
[2018-12-17T14:15:11.246+0800][59461][gc,heap ] GC(0) Used: 254M (25%) 344M (34%) 194M (19%) 338M (33%) 366M (36%) 194M (19%)
[2018-12-17T14:15:11.246+0800][59461][gc,heap ] GC(0) Live: - 43M (4%) 43M (4%) 43M (4%) - -
[2018-12-17T14:15:11.246+0800][59461][gc,heap ] GC(0) Allocated: - 90M (9%) 100M (10%) 314M (31%) - -
[2018-12-17T14:15:11.246+0800][59461][gc,heap ] GC(0) Garbage: - 210M (21%) 50M (5%) 14M (1%) - -
[2018-12-17T14:15:11.246+0800][59461][gc,heap ] GC(0) Reclaimed: - - 160M (16%) 196M (19%) - -
[2018-12-17T14:15:11.246+0800][59461][gc ] GC(0) Garbage Collection (Warmup) 254M(25%)->338M(33%)

GC触发是满足分配速率规则，我们可以看到Allocation Rate

[2018-12-17T14:15:11.495+0800][59461][gc ] GC(3) Garbage Collection (Allocation Rate) 130M(13%)->62M(6%)
[2018-12-17T14:15:11.566+0800][59461][gc,start ] GC(4) Garbage Collection (Allocation Rate)

GC触发是满足周期收集规则，我们可以看到Proactive

[2018-12-17T10:32:30.556+0800][45833][gc,start ] GC(7) Garbage Collection (Proactive)

Zstat输出的统计

[2018-12-17T14:15:20.966+0800][59462][gc,stats [2018-12-17T14:15:20.966+0800][59462][gc,stats ] [2018-12-17T14:15:20.966+0800][59462][gc,stats ] [2018-12-17T14:15:20.966+0800][59462][gc,stats [2018-12-17T14:15:20.966+0800][59462][gc,stats [2018-12-17T14:15:20.966+0800][59462][gc,stats [2018-12-17T14:15:20.966+0800][59462][gc,stats [2018-12-17T14:15:20.966+0800][59462][gc,stats [2018-12-17T14:15:20.966+0800][59462][gc,stats [2018-12-17T14:15:20.966+0800][59462][gc,stats [2018-12-17T14:15:20.966+0800][59462][gc,stats [2018-12-17T14:15:20.966+0800][59462][gc,stats ] [2018-12-17T14:15:20.966+0800][59462][gc,stats ] [2018-12-17T14:15:20.966+0800][59462][gc,stats ] [2018-12-17T14:15:20.966+0800][59462][gc,stats ] [2018-12-17T14:15:20.966+0800][59462][gc,stats ] [2018-12-17T14:15:20.966+0800][59462][gc,stats ] [2018-12-17T14:15:20.966+0800][59462][gc,stats ] [2018-12-17T14:15:20.966+0800][59462][gc,stats ] [2018-12-17T14:15:20.966+0800][59462][gc,stats ] [2018-12-17T14:15:20.966+0800][59462][gc,stats ] [2018-12-17T14:15:20.966+0800][59462][gc,stats ] [2018-12-17T14:15:20.966+0800][59462][gc,stats ] [2018-12-17T14:15:20.966+0800][59462][gc,stats ] [2018-12-17T14:15:20.966+0800][59462][gc,stats ] [2018-12-17T14:15:20.966+0800][59462][gc,stats ] [2018-12-17T14:15:20.966+0800][59462][gc,stats ] [2018-12-17T14:15:20.966+0800][59462][gc,stats ] [2018-12-17T14:15:20.966+0800][59462][gc,stats ] [2018-12-17T14:15:20.966+0800][59462][gc,stats ] [2018-12-17T14:15:20.966+0800][59462][gc,stats ] [2018-12-17T14:15:20.966+0800][59462][gc,stats ] [2018-12-17T14:15:20.966+0800][59462][gc,stats ] [2018-12-17T14:15:20.966+0800][59462][gc,stats ] [2018-12-17T14:15:20.966+0800][59462][gc,stats ] [2018-12-17T14:15:20.966+0800][59462][gc,stats [2018-12-17T14:15:20.967+0800][59462][gc,stats [2018-12-17T14:15:20.967+0800][59462][gc,stats [2018-12-17T14:15:20.967+0800][59462][gc,stats [2018-12-17T14:15:20.967+0800][59462][gc,stats [2018-12-17T14:15:20.967+0800][59462][gc,stats [2018-12-17T14:15:20.967+0800][59462][gc,stats [2018-12-17T14:15:20.967+0800][59462][gc,stats [2018-12-17T14:15:20.967+0800][59468][gc,phases [2018-12-17T14:15:20.967+0800][59462][gc,stats [2018-12-17T14:15:20.967+0800][59462][gc,stats [2018-12-17T14:15:20.967+0800][59462][gc,stats [2018-12-17T14:15:20.967+0800][59462][gc,stats [2018-12-17T14:15:20.967+0800][59462][gc,stats [2018-12-17T14:15:20.967+0800][59462][gc,stats [2018-12-17T14:15:20.967+0800][59462][gc,stats [2018-12-17T14:15:20.967+0800][59462][gc,stats [2018-12-17T14:15:20.967+0800][59462][gc,stats [2018-12-17T14:15:20.967+0800][59462][gc,stats [2018-12-17T14:15:20.967+0800][59462][gc,stats [2018-12-17T14:15:20.967+0800][59462][gc,stats [2018-12-17T14:15:20.967+0800][59462][gc,stats [2018-12-17T14:15:20.967+0800][59462][gc,stats [2018-12-17T14:15:20.967+0800][59462][gc,stats [2018-12-17T14:15:20.967+0800][59462][gc,stats [2018-12-17T14:15:20.967+0800][59462][gc,stats [2018-12-17T14:15:20.967+0800][59462][gc,stats [2018-12-17T14:15:20.967+0800][59462][gc,stats [2018-12-17T14:15:20.967+0800][59462][gc,stats [2018-12-17T14:15:20.967+0800][59462][gc,stats [2018-12-17T14:15:20.967+0800][59462][gc,stats [2018-12-17T14:15:20.967+0800][59462][gc,stats [2018-12-17T14:15:20.967+0800][59462][gc,stats [2018-12-17T14:15:20.967+0800][59462][gc,stats [2018-12-17T14:15:20.967+0800][59462][gc,stats [2018-12-17T14:15:20.967+0800][59462][gc,stats [2018-12-17T14:15:20.967+0800][59462][gc,stats [2018-12-17T14:15:20.967+0800][59462][gc,stats [2018-12-17T14:15:20.967+0800][59462][gc,stats [2018-12-17T14:15:20.967+0800][59462][gc,stats [2018-12-17T14:15:20.967+0800][59462][gc,stats ] [2018-12-17T14:15:20.967+0800][59462][gc,stats ] === Garbage Collection Statistics =======================================================================================================================
Last 10s Last 10m Last 10h Total
Avg / Max Avg / Max Avg / Max Avg / Max
] Collector: Garbage Collection Cycle 154.948 / 345.168 154.948 / 345.168 154.948 / 345.168 154.948 / 345.168 ms
] Contention: Mark Segment Reset Contention 2 / 9 2 / 9 2 / 9 2 / 9 ops/s
] Contention: Mark SeqNum Reset Contention 0 / 2 0 / 2 0 / 2 0 / 2 ops/s
] Contention: Relocation Contention 0 / 5 0 / 5 0 / 5 0 / 5 ops/s
] Critical: Allocation Stall 128.845 / 308.257 128.845 / 308.257 128.845 / 308.257 128.845 / 308.257 ms
] Critical: Allocation Stall 3 / 6 3 / 6 3 / 6 3 / 6 ops/s
] Critical: GC Locker Stall 0.000 / 0.000 0.000 / 0.000 0.000 / 0.000 0.000 / 0.000 ms
] Critical: GC Locker Stall 0 / 0 0 / 0 0 / 0 0 / 0 ops/s
Memory: Allocation Rate 1927 / 3098 1927 / 3098 1927 / 3098 1927 / 3098 MB/s
Memory: Heap Used After Mark 832 / 982 832 / 982 832 / 982 832 / 982 MB
Memory: Heap Used After Relocation 540 / 982 540 / 982 540 / 982 540 / 982 MB
Memory: Heap Used Before Mark 690 / 982 690 / 982 690 / 982 690 / 982 MB
Memory: Heap Used Before Relocation 505 / 982 505 / 982 505 / 982 505 / 982 MB
Memory: Out Of Memory 0 / 0 0 / 0 0 / 0 0 / 0 ops/s
Memory: Page Cache Flush 287 / 516 287 / 516 287 / 516 287 / 516 MB/s
Memory: Page Cache Hit L1 172 / 303 172 / 303 172 / 303 172 / 303 ops/s
Memory: Page Cache Hit L2 0 / 0 0 / 0 0 / 0 0 / 0 ops/s
Memory: Page Cache Miss 34 / 102 34 / 102 34 / 102 34 / 102 ops/s
Memory: Undo Object Allocation Failed 0 / 0 0 / 0 0 / 0 0 / 0 ops/s
Memory: Undo Object Allocation Succeeded 0 / 5 0 / 5 0 / 5 0 / 5 ops/s
Memory: Undo Page Allocation 2 / 6 2 / 6 2 / 6 2 / 6 ops/s
Phase: Concurrent Destroy Detached Pages 0.073 / 1.222 0.073 / 1.222 0.073 / 1.222 0.073 / 1.222 ms
Phase: Concurrent Mark 142.312 / 310.943 142.312 / 310.943 142.312 / 310.943 142.312 / 310.943 ms
Phase: Concurrent Mark Continue 0.000 / 0.000 0.000 / 0.000 0.000 / 0.000 0.000 / 0.000 ms
Phase: Concurrent Prepare Relocation Set 0.172 / 1.081 0.172 / 1.081 0.172 / 1.081 0.172 / 1.081 ms
Phase: Concurrent Process Non-Strong References 0.135 / 0.264 0.135 / 0.264 0.135 / 0.264 0.135 / 0.264 ms
Phase: Concurrent Relocate 7.653 / 43.869 7.653 / 43.869 7.653 / 43.869 7.653 / 43.869 ms
Phase: Concurrent Reset Relocation Set 0.020 / 0.221 0.020 / 0.221 0.020 / 0.221 0.020 / 0.221 ms
Phase: Concurrent Select Relocation Set 1.728 / 5.198 1.728 / 5.198 1.728 / 5.198 1.728 / 5.198 ms
Phase: Pause Mark End 0.082 / 0.127 0.082 / 0.127 0.082 / 0.127 0.082 / 0.127 ms
Phase: Pause Mark Start 0.107 / 0.332 0.107 / 0.332 0.107 / 0.332 0.107 / 0.332 ms
Phase: Pause Relocate Start 0.164 / 1.865 0.164 / 1.865 0.164 / 1.865 0.164 / 1.865 ms
] Subphase: Concurrent Mark 142.913 / 310.887 142.913 / 310.887 142.913 / 310.887 142.913 / 310.887 ms
] Subphase: Concurrent Mark Idle 1.070 / 3.907 1.070 / 3.907 1.070 / 3.907 1.070 / 3.907 ms
] Subphase: Concurrent Mark Try Flush 0.230 / 4.609 0.230 / 4.609 0.230 / 4.609 0.230 / 4.609 ms
] Subphase: Concurrent Mark Try Terminate 1.061 / 4.611 1.061 / 4.611 1.061 / 4.611 1.061 / 4.611 ms
] Subphase: Concurrent References Enqueue 0.001 / 0.008 0.001 / 0.008 0.001 / 0.008 0.001 / 0.008 ms
] Subphase: Concurrent References Process 0.044 / 0.084 0.044 / 0.084 0.044 / 0.084 0.044 / 0.084 ms
] Subphase: Concurrent Weak Roots 0.033 / 0.148 0.033 / 0.148 0.033 / 0.148 0.033 / 0.148 ms
] Subphase: Concurrent Weak Roots JNIWeakHandles 0.000 / 0.000 0.000 / 0.000 0.000 / 0.000 0.000 / 0.000 ms
] GC(52) Pause Mark Start 0.080ms
] Subphase: Concurrent Weak Roots StringTable 0.032 / 0.131 0.032 / 0.131 0.032 / 0.131 0.032 / 0.131 ms
] Subphase: Concurrent Weak Roots VMWeakHandles 0.005 / 0.016 0.005 / 0.016 0.005 / 0.016 0.005 / 0.016 ms
] Subphase: Pause Mark Try Complete 0.001 / 0.001 0.001 / 0.001 0.001 / 0.001 0.001 / 0.001 ms
] Subphase: Pause Remap TLABS 0.001 / 0.009 0.001 / 0.009 0.001 / 0.009 0.001 / 0.009 ms
] Subphase: Pause Retire TLABS 0.007 / 0.025 0.007 / 0.025 0.007 / 0.025 0.007 / 0.025 ms
] Subphase: Pause Roots 0.034 / 1.742 0.034 / 1.742 0.034 / 1.742 0.034 / 1.742 ms
] Subphase: Pause Roots ClassLoaderDataGraph 0.022 / 1.570 0.022 / 1.570 0.022 / 1.570 0.022 / 1.570 ms
] Subphase: Pause Roots CodeCache 0.022 / 1.742 0.022 / 1.742 0.022 / 1.742 0.022 / 1.742 ms
] Subphase: Pause Roots JNIHandles 0.008 / 0.952 0.008 / 0.952 0.008 / 0.952 0.008 / 0.952 ms
] Subphase: Pause Roots JNIWeakHandles 0.000 / 0.000 0.000 / 0.000 0.000 / 0.000 0.000 / 0.000 ms
] Subphase: Pause Roots JRFWeak 0.000 / 0.000 0.000 / 0.000 0.000 / 0.000 0.000 / 0.000 ms
] Subphase: Pause Roots JVMTIExport 0.001 / 0.003 0.001 / 0.003 0.001 / 0.003 0.001 / 0.003 ms
] Subphase: Pause Roots JVMTIWeakExport 0.001 / 0.001 0.001 / 0.001 0.001 / 0.001 0.001 / 0.001 ms
] Subphase: Pause Roots Management 0.002 / 0.023 0.002 / 0.023 0.002 / 0.023 0.002 / 0.023 ms
] Subphase: Pause Roots ObjectSynchronizer 0.000 / 0.001 0.000 / 0.001 0.000 / 0.001 0.000 / 0.001 ms
] Subphase: Pause Roots Setup 0.002 / 0.012 0.002 / 0.012 0.002 / 0.012 0.002 / 0.012 ms
] Subphase: Pause Roots StringTable 0.000 / 0.000 0.000 / 0.000 0.000 / 0.000 0.000 / 0.000 ms
] Subphase: Pause Roots SystemDictionary 0.011 / 0.664 0.011 / 0.664 0.011 / 0.664 0.011 / 0.664 ms
] Subphase: Pause Roots Teardown 0.001 / 0.017 0.001 / 0.017 0.001 / 0.017 0.001 / 0.017 ms
] Subphase: Pause Roots Threads 0.010 / 0.168 0.010 / 0.168 0.010 / 0.168 0.010 / 0.168 ms
] Subphase: Pause Roots Universe 0.006 / 0.348 0.006 / 0.348 0.006 / 0.348 0.006 / 0.348 ms
] Subphase: Pause Roots VMWeakHandles 0.000 / 0.000 0.000 / 0.000 0.000 / 0.000 0.000 / 0.000 ms
] Subphase: Pause Weak Roots 0.001 / 0.005 0.001 / 0.005 0.001 / 0.005 0.001 / 0.005 ms
] Subphase: Pause Weak Roots JFRWeak 0.001 / 0.002 0.001 / 0.002 0.001 / 0.002 0.001 / 0.002 ms
] Subphase: Pause Weak Roots JNIWeakHandles 0.000 / 0.000 0.000 / 0.000 0.000 / 0.000 0.000 / 0.000 ms
] Subphase: Pause Weak Roots JVMTIWeakExport 0.001 / 0.003 0.001 / 0.003 0.001 / 0.003 0.001 / 0.003 ms
] Subphase: Pause Weak Roots Setup 0.000 / 0.001 0.000 / 0.001 0.000 / 0.001 0.000 / 0.001 ms
] Subphase: Pause Weak Roots StringTable 0.000 / 0.000 0.000 / 0.000 0.000 / 0.000 0.000 / 0.000 ms
] Subphase: Pause Weak Roots SymbolTable 0.000 / 0.000 0.000 / 0.000 0.000 / 0.000 0.000 / 0.000 ms
] Subphase: Pause Weak Roots Teardown 0.001 / 0.003 0.001 / 0.003 0.001 / 0.003 0.001 / 0.003 ms
] Subphase: Pause Weak Roots VMWeakHandles 0.000 / 0.000 0.000 / 0.000 0.000 / 0.000 0.000 / 0.000 ms
System: Java Threads 9 / 10 9 / 10 9 / 10 9 / 10 threads
] =========================================================================================================================================================