ZGC初体验

时间:2024-03-16 21:49:18


JDK11发布了,ZGC的相关描述很诱人,体验了一下。
一共测试了三次,分别使用JDK8和JDK11。使用JMeter做压力测试,比较G1和ZGC的差别。

JDK8下的G1

JAVA_OPTS=" -Xms2g -Xmx2g -Xmn1400m -XX:+UseG1GC -XX:InitiatingHeapOccupancyPercent=60 "
JAVA_OPTS="$JAVA_OPTS -XX:MaxGCPauseMillis=50 -XX:+PrintGCDetails -verbose:gc   -Xloggc:./g1-gc.log"

大约测试了半个小时,使用visualvm_142查看CPU和内存使用情况:
ZGC初体验

GC情况:
ZGC初体验

可见,G1的性能还是不错的。
一共收集467次。一共耗时2405毫秒,平均每次5.15毫秒。

JDK11下的ZGC(2G内存)

JAVA_OPTS=" -server -Xms2g -Xmx2g -XX:ConcGCThreads=4 -XX:+UnlockExperimentalVMOptions -XX:+UseZGC "
JAVA_OPTS="$JAVA_OPTS    -Xlog:gc*:file=gis-gc.txt "

同样使用2G内存,测试半小时。

visualvm_142不支持ZGC,所以,使用JDK11自带的jconsole查看:
ZGC初体验

一共972次收集,耗时1373毫秒。平均每次1.41毫秒。

JDK11的ZGC(8G内存)

据Oracle的宣传,ZGC特别适合大内存的情况。
于是,增大内存配置,继续测试半小时。

JAVA_OPTS=" -server -Xms8g -Xmx8g -XX:ConcGCThreads=4 -XX:+UnlockExperimentalVMOptions -XX:+UseZGC "
JAVA_OPTS="$JAVA_OPTS    -Xlog:gc*:file=gis-gc.txt "

jconsole输出如下:
ZGC初体验

813次收集,耗时1113毫秒。平均每次1.37毫秒。

测试比较失败,因为虽然配置了8G内存,但是,实际使用的内存很少超过1.5G。
以后试试怎么提升程序使用的内存量。

可以看出来,ZGC的性能相比G1还是提高很多的
JDK8下的G1和JDK11下的ZGC,CPU利用率基本没差别。

下面贴一段ZGC的收集日志:

[1131.279s][info][gc,start    ] GC(502) Garbage Collection (Proactive)
[1131.280s][info][gc,phases   ] GC(502) Pause Mark Start 0.719ms
[1131.314s][info][gc,phases   ] GC(502) Concurrent Mark 34.151ms
[1131.315s][info][gc,phases   ] GC(502) Pause Mark End 0.066ms
[1131.315s][info][gc,phases   ] GC(502) Concurrent Process Non-Strong References 0.564ms
[1131.315s][info][gc,phases   ] GC(502) Concurrent Reset Relocation Set 0.008ms
[1131.315s][info][gc,phases   ] GC(502) Concurrent Destroy Detached Pages 0.001ms
[1131.317s][info][gc,phases   ] GC(502) Concurrent Select Relocation Set 1.367ms
[1131.317s][info][gc,phases   ] GC(502) Concurrent Prepare Relocation Set 0.030ms
[1131.317s][info][gc,phases   ] GC(502) Pause Relocate Start 0.565ms
[1131.319s][info][gc,phases   ] GC(502) Concurrent Relocate 1.343ms
[1131.319s][info][gc,load     ] GC(502) Load: 6.96/7.15/7.00
[1131.319s][info][gc,mmu      ] GC(502) MMU: 2ms/25.6%, 5ms/70.2%, 10ms/85.1%, 20ms/92.1%, 50ms/95.8%, 100ms/97.5%
[1131.319s][info][gc,marking  ] GC(502) Mark: 4 stripe(s), 3 proactive flush(es), 1 terminate flush(es), 0 completion(s), 0 continuation(s) 
[1131.319s][info][gc,reloc    ] GC(502) Relocation: Successful, 7M relocated
[1131.319s][info][gc,nmethod  ] GC(502) NMethods: 5130 registered, 1910 unregistered
[1131.319s][info][gc,metaspace] GC(502) Metaspace: 59M used, 59M capacity, 59M committed, 60M reserved
[1131.319s][info][gc,ref      ] GC(502) Soft: 6431 encountered, 0 discovered, 0 enqueued
[1131.319s][info][gc,ref      ] GC(502) Weak: 4778 encountered, 538 discovered, 0 enqueued
[1131.319s][info][gc,ref      ] GC(502) Final: 32 encountered, 7 discovered, 0 enqueued
[1131.319s][info][gc,ref      ] GC(502) Phantom: 306 encountered, 238 discovered, 0 enqueued
[1131.319s][info][gc,heap     ] GC(502)                Mark Start          Mark End        Relocate Start      Relocate End           High               Low         
[1131.319s][info][gc,heap     ] GC(502)  Capacity:     8192M (100%)       8192M (100%)       8192M (100%)       8192M (100%)       8192M (100%)       8192M (100%)   
[1131.319s][info][gc,heap     ] GC(502)   Reserve:       42M (1%)           42M (1%)           42M (1%)           42M (1%)           42M (1%)           42M (1%)     
[1131.319s][info][gc,heap     ] GC(502)      Free:     7116M (87%)        7102M (87%)        7974M (97%)        8026M (98%)        8026M (98%)        7100M (87%)    
[1131.319s][info][gc,heap     ] GC(502)      Used:     1034M (13%)        1048M (13%)         176M (2%)          124M (2%)         1050M (13%)         124M (2%)     
[1131.319s][info][gc,heap     ] GC(502)      Live:         -                59M (1%)           59M (1%)           59M (1%)             -                  -          
[1131.319s][info][gc,heap     ] GC(502) Allocated:         -                14M (0%)           18M (0%)           32M (0%)             -                  -          
[1131.319s][info][gc,heap     ] GC(502)   Garbage:         -               974M (12%)          98M (1%)           44M (1%)             -                  -          
[1131.319s][info][gc,heap     ] GC(502) Reclaimed:         -                  -               876M (11%)         930M (11%)            -                  -          
[1131.319s][info][gc          ] GC(502) Garbage Collection (Proactive) 1034M(13%)->124M(2%)

还有GC统计信息

[1130.680s][info][gc,stats    ] === Garbage Collection Statistics =======================================================================================================================
[1130.681s][info][gc,stats    ]                                                              Last 10s              Last 10m              Last 10h                Total
[1130.681s][info][gc,stats    ]                                                              Avg / Max             Avg / Max             Avg / Max             Avg / Max
[1130.681s][info][gc,stats    ]   Collector: Garbage Collection Cycle                     37.112 / 39.642       39.446 / 79.870       38.985 / 108.249      38.985 / 108.249     ms
[1130.681s][info][gc,stats    ]  Contention: Mark Segment Reset Contention                     0 / 0                 0 / 4                 0 / 4                 0 / 4           ops/s
[1130.681s][info][gc,stats    ]  Contention: Mark SeqNum Reset Contention                      0 / 0                 0 / 0                 0 / 0                 0 / 0           ops/s
[1130.681s][info][gc,stats    ]  Contention: Relocation Contention                             0 / 0                 0 / 15                1 / 397               1 / 397         ops/s
[1130.681s][info][gc,stats    ]    Critical: Allocation Stall                              0.000 / 0.000         0.000 / 0.000         0.000 / 0.000         0.000 / 0.000       ms
[1130.681s][info][gc,stats    ]    Critical: Allocation Stall                                  0 / 0                 0 / 0                 0 / 0                 0 / 0           ops/s
[1130.681s][info][gc,stats    ]    Critical: GC Locker Stall                               0.000 / 0.000         0.000 / 0.000         0.000 / 0.000         0.000 / 0.000       ms
[1130.681s][info][gc,stats    ]    Critical: GC Locker Stall                                   0 / 0                 0 / 0                 0 / 0                 0 / 0           ops/s
[1130.681s][info][gc,stats    ]      Memory: Allocation Rate                                 489 / 526             538 / 618             532 / 618             532 / 618         MB/s
[1130.681s][info][gc,stats    ]      Memory: Heap Used After Mark                           1084 / 1150           1320 / 2916           1310 / 3724           1310 / 3724        MB
[1130.681s][info][gc,stats    ]      Memory: Heap Used After Relocation                      121 / 124             121 / 180             119 / 180             119 / 180         MB
[1130.681s][info][gc,stats    ]      Memory: Heap Used Before Mark                          1069 / 1134           1303 / 2898           1294 / 3694           1294 / 3694        MB
[1130.681s][info][gc,stats    ]      Memory: Heap Used Before Relocation                     178 / 210             184 / 260             183 / 750             183 / 750         MB
[1130.681s][info][gc,stats    ]      Memory: Out Of Memory                                     0 / 0                 0 / 0                 0 / 0                 0 / 0           ops/s
[1130.681s][info][gc,stats    ]      Memory: Page Cache Flush                                  0 / 0                 0 / 0                 0 / 0                 0 / 0           MB/s
[1130.681s][info][gc,stats    ]      Memory: Page Cache Hit L1                               246 / 257             270 / 285             265 / 288             265 / 288         ops/s
[1130.681s][info][gc,stats    ]      Memory: Page Cache Hit L2                                 0 / 0                 0 / 0                 0 / 0                 0 / 0           ops/s
[1130.681s][info][gc,stats    ]      Memory: Page Cache Miss                                   0 / 0                 0 / 0                 1 / 255               1 / 255         ops/s
[1130.681s][info][gc,stats    ]      Memory: Undo Object Allocation Failed                     0 / 0                 0 / 0                 0 / 1                 0 / 1           ops/s
[1130.681s][info][gc,stats    ]      Memory: Undo Object Allocation Succeeded                  0 / 0                 0 / 15                1 / 397               1 / 397         ops/s
[1130.681s][info][gc,stats    ]      Memory: Undo Page Allocation                              0 / 1                 0 / 2                 0 / 3                 0 / 3           ops/s
[1130.681s][info][gc,stats    ]       Phase: Concurrent Destroy Detached Pages             0.001 / 0.001         0.001 / 0.001         0.001 / 0.019         0.001 / 0.019       ms
[1130.681s][info][gc,stats    ]       Phase: Concurrent Mark                              31.185 / 33.047       32.399 / 69.008       31.824 / 69.008       31.824 / 69.008      ms
[1130.681s][info][gc,stats    ]       Phase: Concurrent Mark Continue                      0.000 / 0.000         0.000 / 0.000         0.000 / 0.000         0.000 / 0.000       ms
[1130.681s][info][gc,stats    ]       Phase: Concurrent Prepare Relocation Set             0.032 / 0.037         0.042 / 0.244         0.061 / 7.368         0.061 / 7.368       ms
[1130.681s][info][gc,stats    ]       Phase: Concurrent Process Non-Strong References      0.640 / 0.821         0.729 / 2.334         0.741 / 4.196         0.741 / 4.196       ms
[1130.681s][info][gc,stats    ]       Phase: Concurrent Relocate                           1.812 / 2.377         2.302 / 6.325         2.393 / 31.625        2.393 / 31.625      ms
[1130.681s][info][gc,stats    ]       Phase: Concurrent Reset Relocation Set               0.008 / 0.009         0.012 / 0.351         0.014 / 1.204         0.014 / 1.204       ms
[1130.681s][info][gc,stats    ]       Phase: Concurrent Select Relocation Set              1.395 / 1.570         1.533 / 2.617         1.541 / 4.508         1.541 / 4.508       ms
[1130.681s][info][gc,stats    ]       Phase: Pause Mark End                                0.077 / 0.087         0.076 / 0.148         0.077 / 0.616         0.077 / 0.616       ms
[1130.681s][info][gc,stats    ]       Phase: Pause Mark Start                              0.697 / 0.747         0.692 / 1.219         0.713 / 1.219         0.713 / 1.219       ms
[1130.681s][info][gc,stats    ]       Phase: Pause Relocate Start                          0.603 / 0.699         0.578 / 0.699         0.607 / 1.488         0.607 / 1.488       ms
[1130.681s][info][gc,stats    ]    Subphase: Concurrent Mark                              30.755 / 33.018       31.715 / 68.387       31.037 / 68.387       31.037 / 68.387      ms
[1130.681s][info][gc,stats    ]    Subphase: Concurrent Mark Idle                          1.062 / 1.115         1.103 / 2.300         1.107 / 12.119        1.107 / 12.119      ms
[1130.681s][info][gc,stats    ]    Subphase: Concurrent Mark Try Flush                     0.044 / 0.090         0.174 / 14.243        0.165 / 14.243        0.165 / 14.243      ms
[1130.681s][info][gc,stats    ]    Subphase: Concurrent Mark Try Terminate                 0.645 / 1.116         0.731 / 2.302         0.737 / 12.129        0.737 / 12.129      ms
[1130.681s][info][gc,stats    ]    Subphase: Concurrent References Enqueue                 0.000 / 0.000         0.000 / 0.022         0.000 / 0.022         0.000 / 0.022       ms
[1130.681s][info][gc,stats    ]    Subphase: Concurrent References Process                 0.094 / 0.192         0.126 / 1.273         0.121 / 1.273         0.121 / 1.273       ms
[1130.681s][info][gc,stats    ]    Subphase: Concurrent Weak Roots                         0.440 / 0.705         0.434 / 2.049         0.446 / 3.622         0.446 / 3.622       ms
[1130.681s][info][gc,stats    ]    Subphase: Concurrent Weak Roots JNIWeakHandles          0.000 / 0.000         0.000 / 0.000         0.000 / 0.000         0.000 / 0.000       ms
[1130.681s][info][gc,stats    ]    Subphase: Concurrent Weak Roots StringTable             0.429 / 0.674         0.446 / 2.030         0.457 / 3.620         0.457 / 3.620       ms
[1130.681s][info][gc,stats    ]    Subphase: Concurrent Weak Roots VMWeakHandles           0.034 / 0.145         0.052 / 1.025         0.054 / 1.128         0.054 / 1.128       ms
[1130.681s][info][gc,stats    ]    Subphase: Pause Mark Try Complete                       0.000 / 0.000         0.001 / 0.003         0.001 / 0.003         0.001 / 0.003       ms
[1130.681s][info][gc,stats    ]    Subphase: Pause Remap TLABS                             0.001 / 0.002         0.001 / 0.012         0.001 / 0.012         0.001 / 0.012       ms
[1130.681s][info][gc,stats    ]    Subphase: Pause Retire TLABS                            0.010 / 0.018         0.010 / 0.043         0.010 / 0.043         0.010 / 0.043       ms
[1130.681s][info][gc,stats    ]    Subphase: Pause Roots                                   0.375 / 0.642         0.362 / 1.119         0.376 / 1.354         0.376 / 1.354       ms
[1130.681s][info][gc,stats    ]    Subphase: Pause Roots ClassLoaderDataGraph              0.101 / 0.595         0.090 / 0.689         0.091 / 1.336         0.091 / 1.336       ms
[1130.681s][info][gc,stats    ]    Subphase: Pause Roots CodeCache                         0.415 / 0.520         0.401 / 0.980         0.423 / 0.980         0.423 / 0.980       ms
[1130.681s][info][gc,stats    ]    Subphase: Pause Roots JNIHandles                        0.001 / 0.002         0.001 / 0.013         0.001 / 0.052         0.001 / 0.052       ms
[1130.681s][info][gc,stats    ]    Subphase: Pause Roots JNIWeakHandles                    0.000 / 0.000         0.000 / 0.000         0.000 / 0.000         0.000 / 0.000       ms
[1130.681s][info][gc,stats    ]    Subphase: Pause Roots JRFWeak                           0.000 / 0.000         0.000 / 0.000         0.000 / 0.000         0.000 / 0.000       ms
[1130.681s][info][gc,stats    ]    Subphase: Pause Roots JVMTIExport                       0.000 / 0.001         0.000 / 0.013         0.000 / 0.013         0.000 / 0.013       ms
[1130.681s][info][gc,stats    ]    Subphase: Pause Roots JVMTIWeakExport                   0.000 / 0.001         0.000 / 0.001         0.000 / 0.001         0.000 / 0.001       ms
[1130.681s][info][gc,stats    ]    Subphase: Pause Roots Management                        0.001 / 0.002         0.001 / 0.003         0.001 / 0.008         0.001 / 0.008       ms
[1130.681s][info][gc,stats    ]    Subphase: Pause Roots ObjectSynchronizer                0.000 / 0.000         0.000 / 0.000         0.000 / 0.016         0.000 / 0.016       ms
[1130.681s][info][gc,stats    ]    Subphase: Pause Roots Setup                             0.042 / 0.087         0.040 / 0.138         0.040 / 0.138         0.040 / 0.138       ms
[1130.681s][info][gc,stats    ]    Subphase: Pause Roots StringTable                       0.000 / 0.000         0.000 / 0.000         0.000 / 0.000         0.000 / 0.000       ms
[1130.681s][info][gc,stats    ]    Subphase: Pause Roots SystemDictionary                  0.008 / 0.010         0.008 / 0.081         0.008 / 0.081         0.008 / 0.081       ms
[1130.681s][info][gc,stats    ]    Subphase: Pause Roots Teardown                          0.001 / 0.003         0.001 / 0.003         0.001 / 0.015         0.001 / 0.015       ms
[1130.681s][info][gc,stats    ]    Subphase: Pause Roots Threads                           0.041 / 0.078         0.044 / 0.171         0.046 / 0.621         0.046 / 0.621       ms
[1130.681s][info][gc,stats    ]    Subphase: Pause Roots Universe                          0.002 / 0.003         0.003 / 0.527         0.003 / 0.527         0.003 / 0.527       ms
[1130.681s][info][gc,stats    ]    Subphase: Pause Roots VMWeakHandles                     0.000 / 0.000         0.000 / 0.000         0.000 / 0.000         0.000 / 0.000       ms
[1130.681s][info][gc,stats    ]    Subphase: Pause Weak Roots                              0.000 / 0.001         0.000 / 0.004         0.000 / 0.011         0.000 / 0.011       ms
[1130.681s][info][gc,stats    ]    Subphase: Pause Weak Roots JFRWeak                      0.000 / 0.000         0.000 / 0.004         0.000 / 0.004         0.000 / 0.004       ms
[1130.681s][info][gc,stats    ]    Subphase: Pause Weak Roots JNIWeakHandles               0.000 / 0.000         0.000 / 0.000         0.000 / 0.000         0.000 / 0.000       ms
[1130.681s][info][gc,stats    ]    Subphase: Pause Weak Roots JVMTIWeakExport              0.000 / 0.000         0.000 / 0.001         0.000 / 0.011         0.000 / 0.011       ms
[1130.681s][info][gc,stats    ]    Subphase: Pause Weak Roots Setup                        0.000 / 0.000         0.000 / 0.001         0.000 / 0.001         0.000 / 0.001       ms
[1130.681s][info][gc,stats    ]    Subphase: Pause Weak Roots StringTable                  0.000 / 0.000         0.000 / 0.000         0.000 / 0.000         0.000 / 0.000       ms
[1130.681s][info][gc,stats    ]    Subphase: Pause Weak Roots SymbolTable                  0.000 / 0.000         0.000 / 0.000         0.000 / 0.000         0.000 / 0.000       ms
[1130.681s][info][gc,stats    ]    Subphase: Pause Weak Roots Teardown                     0.001 / 0.001         0.001 / 0.001         0.001 / 0.001         0.001 / 0.001       ms
[1130.681s][info][gc,stats    ]    Subphase: Pause Weak Roots VMWeakHandles                0.000 / 0.000         0.000 / 0.000         0.000 / 0.000         0.000 / 0.000       ms
[1130.681s][info][gc,stats    ]      System: Java Threads                                     33 / 33               33 / 33               33 / 37               33 / 37          threads
[1130.681s][info][gc,stats    ] =========================================================================================================================================================