G1垃圾回收日志分析

编程入门行业动态更新时间:2024-10-28 00:16:26

G1<a href=https://www.elefans.com/category/jswz/34/1770876.html style= 垃圾回收日志分析"/>

G1垃圾回收日志分析

标准 gc 日志

使用G1垃圾回收器最难的地方是读懂回收日志。G1回收虽然也是分代的，但是打印出来的日志却不像其他回收器那样明显。所以需要好好配置JVM参数才行。先看下面一段日志，这段日志是通过配置好的JVM参数输出的，分隔明确，很容易分辨出每次回收过程。

 # 每次回收以 花括号开始 # invocations=2302 代表第2302次回收
{Heap before GC invocations=2302 (full 0):garbage-first heap   total 32768K, used 30719K [0x00000007be000000, 0x00000007be100100, 0x00000007c0000000)region size 1024K, 18 young (18432K), 0 survivors (0K)Metaspace       used 7722K, capacity 7936K, committed 8064K, reserved 1056768Kclass space    used 1013K, capacity 1068K, committed 1152K, reserved 1048576K# 代表是一次 yong GC ,原因是: 疏散停顿（Evacuation Pause）是将活着的对象从一个区域（young or young + old）拷贝到另一个区域的阶段。
2020-10-09T20:13:01.203-0800: 22.971: [GC pause (G1 Evacuation Pause) (young) (to-space exhausted), 0.0062834 secs]# 4 个线程回收[Parallel Time: 0.9 ms, GC Workers: 4][GC Worker Start (ms): Min: 22970.7, Avg: 22970.8, Max: 22971.0, Diff: 0.3][Ext Root Scanning (ms): Min: 0.0, Avg: 0.2, Max: 0.2, Diff: 0.2, Sum: 0.6][Update RS (ms): Min: 0.5, Avg: 0.6, Max: 0.6, Diff: 0.1, Sum: 2.4][Processed Buffers: Min: 4, Avg: 7.5, Max: 10, Diff: 6, Sum: 30][Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0][Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0][Object Copy (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0][Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.1][Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4][GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0][GC Worker Total (ms): Min: 0.6, Avg: 0.8, Max: 0.9, Diff: 0.3, Sum: 3.2][GC Worker End (ms): Min: 22971.6, Avg: 22971.6, Max: 22971.6, Diff: 0.0][Code Root Fixup: 0.0 ms][Code Root Purge: 0.0 ms][Clear CT: 0.0 ms][Other: 5.3 ms][Evacuation Failure: 5.0 ms][Choose CSet: 0.0 ms][Ref Proc: 0.2 ms][Ref Enq: 0.0 ms][Redirty Cards: 0.0 ms][Humongous Register: 0.0 ms][Humongous Reclaim: 0.0 ms][Free CSet: 0.0 ms]# 这一行比较简单，不再解释[Eden: 18.0M(18.0M)->0.0B(16.0M) Survivors: 0.0B->0.0B Heap: 30.0M(32.0M)->10.7M(32.0M)]
Heap after GC invocations=2303 (full 0):garbage-first heap   total 32768K, used 10994K [0x00000007be000000, 0x00000007be100100, 0x00000007c0000000)region size 1024K, 0 young (0K), 0 survivors (0K)Metaspace       used 7722K, capacity 7936K, committed 8064K, reserved 1056768Kclass space    used 1013K, capacity 1068K, committed 1152K, reserved 1048576K
}# 回收结束标志，各阶段耗时[Times: user=0.01 sys=0.00, real=0.00 secs] # 下面是一段mix gc ，以一个yong gc 开始，开始的原因是大对象分配失败 （G1 Humongous Allocation）
{Heap before GC invocations=2303 (full 0):garbage-first heap   total 32768K, used 20906K [0x00000007be000000, 0x00000007be100100, 0x00000007c0000000)region size 1024K, 9 young (9216K), 0 survivors (0K)Metaspace       used 7722K, capacity 7936K, committed 8064K, reserved 1056768Kclass space    used 1013K, capacity 1068K, committed 1152K, reserved 1048576K# 初始标记 + yong gc
2020-10-09T20:13:01.212-0800: 22.980: [GC pause (G1 Humongous Allocation) (young) (initial-mark), 0.0008588 secs][Parallel Time: 0.7 ms, GC Workers: 4][GC Worker Start (ms): Min: 22980.2, Avg: 22980.2, Max: 22980.2, Diff: 0.0][Ext Root Scanning (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.3, Sum: 0.9][Update RS (ms): Min: 0.2, Avg: 0.3, Max: 0.3, Diff: 0.1, Sum: 1.0][Processed Buffers: Min: 3, Avg: 4.5, Max: 5, Diff: 2, Sum: 18][Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0][Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0][Object Copy (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0][Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.2][Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4][GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.2][GC Worker Total (ms): Min: 0.6, Avg: 0.6, Max: 0.6, Diff: 0.1, Sum: 2.3][GC Worker End (ms): Min: 22980.8, Avg: 22980.8, Max: 22980.8, Diff: 0.0][Code Root Fixup: 0.0 ms][Code Root Purge: 0.0 ms][Clear CT: 0.0 ms][Other: 0.2 ms][Choose CSet: 0.0 ms][Ref Proc: 0.1 ms][Ref Enq: 0.0 ms][Redirty Cards: 0.0 ms][Humongous Register: 0.0 ms][Humongous Reclaim: 0.0 ms][Free CSet: 0.0 ms][Eden: 9216.0K(16.0M)->0.0B(15.0M) Survivors: 0.0B->1024.0K Heap: 21.4M(32.0M)->10.7M(32.0M)]
Heap after GC invocations=2304 (full 0):garbage-first heap   total 32768K, used 10996K [0x00000007be000000, 0x00000007be100100, 0x00000007c0000000)region size 1024K, 1 young (1024K), 1 survivors (1024K)Metaspace       used 7722K, capacity 7936K, committed 8064K, reserved 1056768Kclass space    used 1013K, capacity 1068K, committed 1152K, reserved 1048576K
}[Times: user=0.00 sys=0.00, real=0.00 secs] # 扫描根节点
2020-10-09T20:13:01.213-0800: 22.981: [GC concurrent-root-region-scan-start]
2020-10-09T20:13:01.213-0800: 22.981: [GC concurrent-root-region-scan-end, 0.0000529 secs]
# 并发标记
2020-10-09T20:13:01.213-0800: 22.981: [GC concurrent-mark-start]
2020-10-09T20:13:01.215-0800: 22.983: [GC concurrent-mark-end, 0.0018968 secs]
# 重新标记
2020-10-09T20:13:01.215-0800: 22.983: [GC remark 2020-10-09T20:13:01.215-0800: 22.983: [Finalize Marking, 0.0000987 secs] 2020-10-09T20:13:01.215-0800: 22.983: [GC ref-proc, 0.0000624 secs] 2020-10-09T20:13:01.216-0800: 22.983: [Unloading, 0.0018305 secs], 0.0021155 secs][Times: user=0.01 sys=0.00, real=0.00 secs] # 并发清除
2020-10-09T20:13:01.218-0800: 22.985: [GC cleanup 20M->12M(32M), 0.0003173 secs][Times: user=0.00 sys=0.00, real=0.00 secs] 
2020-10-09T20:13:01.218-0800: 22.986: [GC concurrent-cleanup-start]
2020-10-09T20:13:01.218-0800: 22.986: [GC concurrent-cleanup-end, 0.0000095 secs]
# 再来一次yong gc
{Heap before GC invocations=2305 (full 0):garbage-first heap   total 32768K, used 22697K [0x00000007be000000, 0x00000007be100100, 0x00000007c0000000)region size 1024K, 16 young (16384K), 1 survivors (1024K)Metaspace       used 7712K, capacity 7918K, committed 8064K, reserved 1056768Kclass space    used 1010K, capacity 1061K, committed 1152K, reserved 1048576K
2020-10-09T20:13:01.220-0800: 22.988: [GC pause (G1 Evacuation Pause) (young), 0.0012414 secs][Parallel Time: 1.0 ms, GC Workers: 4][GC Worker Start (ms): Min: 22988.0, Avg: 22988.0, Max: 22988.1, Diff: 0.0][Ext Root Scanning (ms): Min: 0.1, Avg: 0.1, Max: 0.2, Diff: 0.0, Sum: 0.6][Update RS (ms): Min: 0.6, Avg: 0.7, Max: 0.7, Diff: 0.1, Sum: 2.7][Processed Buffers: Min: 8, Avg: 8.8, Max: 9, Diff: 1, Sum: 35][Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0][Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0][Object Copy (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0][Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.3][Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4][GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0][GC Worker Total (ms): Min: 0.9, Avg: 0.9, Max: 0.9, Diff: 0.1, Sum: 3.6][GC Worker End (ms): Min: 22988.9, Avg: 22988.9, Max: 22989.0, Diff: 0.0][Code Root Fixup: 0.0 ms][Code Root Purge: 0.0 ms][Clear CT: 0.1 ms][Other: 0.2 ms][Choose CSet: 0.0 ms][Ref Proc: 0.1 ms][Ref Enq: 0.0 ms][Redirty Cards: 0.0 ms][Humongous Register: 0.0 ms][Humongous Reclaim: 0.0 ms][Free CSet: 0.0 ms][Eden: 15.0M(15.0M)->0.0B(3072.0K) Survivors: 1024.0K->1024.0K Heap: 22.2M(32.0M)->5214.5K(32.0M)]
Heap after GC invocations=2306 (full 0):garbage-first heap   total 32768K, used 5214K [0x00000007be000000, 0x00000007be100100, 0x00000007c0000000)region size 1024K, 1 young (1024K), 1 survivors (1024K)Metaspace       used 7712K, capacity 7918K, committed 8064K, reserved 1056768Kclass space    used 1010K, capacity 1061K, committed 1152K, reserved 1048576K
}[Times: user=0.00 sys=0.00, real=0.00 secs] 
# 然后是mix gc
{Heap before GC invocations=2306 (full 0):garbage-first heap   total 32768K, used 8286K [0x00000007be000000, 0x00000007be100100, 0x00000007c0000000)region size 1024K, 4 young (4096K), 1 survivors (1024K)Metaspace       used 7712K, capacity 7918K, committed 8064K, reserved 1056768Kclass space    used 1010K, capacity 1061K, committed 1152K, reserved 1048576K
2020-10-09T20:13:01.223-0800: 22.991: [GC pause (G1 Evacuation Pause) (mixed), 0.0009352 secs][Parallel Time: 0.6 ms, GC Workers: 4][GC Worker Start (ms): Min: 22990.7, Avg: 22990.7, Max: 22990.8, Diff: 0.1][Ext Root Scanning (ms): Min: 0.1, Avg: 0.2, Max: 0.3, Diff: 0.1, Sum: 0.8][Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0][Processed Buffers: Min: 0, Avg: 0.2, Max: 1, Diff: 1, Sum: 1][Scan RS (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.2][Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.2, Diff: 0.2, Sum: 0.2][Object Copy (ms): Min: 0.1, Avg: 0.3, Max: 0.4, Diff: 0.3, Sum: 1.1][Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0][Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4][GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0][GC Worker Total (ms): Min: 0.5, Avg: 0.6, Max: 0.6, Diff: 0.1, Sum: 2.3][GC Worker End (ms): Min: 22991.3, Avg: 22991.3, Max: 22991.3, Diff: 0.0][Code Root Fixup: 0.0 ms][Code Root Purge: 0.0 ms][Clear CT: 0.0 ms][Other: 0.2 ms][Choose CSet: 0.0 ms][Ref Proc: 0.1 ms][Ref Enq: 0.0 ms][Redirty Cards: 0.0 ms][Humongous Register: 0.0 ms][Humongous Reclaim: 0.0 ms][Free CSet: 0.0 ms][Eden: 3072.0K(3072.0K)->0.0B(18.0M) Survivors: 1024.0K->1024.0K Heap: 8286.5K(32.0M)->4441.5K(32.0M)]
Heap after GC invocations=2307 (full 0):garbage-first heap   total 32768K, used 4441K [0x00000007be000000, 0x00000007be100100, 0x00000007c0000000)region size 1024K, 1 young (1024K), 1 survivors (1024K)Metaspace       used 7712K, capacity 7918K, committed 8064K, reserved 1056768Kclass space    used 1010K, capacity 1061K, committed 1152K, reserved 1048576K
}[Times: user=0.00 sys=0.00, real=0.00 secs]

观察上面的gc日志可以总结出以下几点

mix gc 开始的标志是 initial-mark ，每次要从一次yong gc开始
mix gc 中间可能还夹杂着 yong gc （除了开始的那一次）
[Times: user=0.01 sys=0.00, real=0.00 secs] 字样代表的时长并不每个阶段都有。
4 上面的JVM参数是

-XX:+PrintHeapAtGC  # 每次gc前后输出堆信息，对分隔G1的gc过程很有用
-XX:+PrintGCDetails  
-XX:+UseG1GC 
-Xmx32m 
-Xloggc:gc.log  # gc日志输出到指定文本
-XX:+PrintGCDateStamps

详细GC日志

上面的日志基本上已经够用了，如果想更精细一点可以加上 -XX:+PrintAdaptiveSizePolicy 打印内存调节的过程。然后日志如下所示
对于普通的yong gc ，日志如下：

{Heap before GC invocations=823 (full 0):garbage-first heap   total 32768K, used 26794K [0x00000007be000000, 0x00000007be100100, 0x00000007c0000000)region size 1024K, 19 young (19456K), 1 survivors (1024K)Metaspace       used 11630K, capacity 11998K, committed 12160K, reserved 1060864Kclass space    used 1511K, capacity 1588K, committed 1664K, reserved 1048576K# 根据现有的内存状态，预测要回收15.62 ms, 目标是停顿小于 200ms,还有184.38的调整空间。根据这个可以适当调整堆栈比例。
2020-10-09T20:09:58.017-0800: 24.625: [GC pause (G1 Evacuation Pause) (young) 24.625: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 0, predicted base time: 15.62 ms, remaining time: 184.38 ms, target pause time: 200.00 ms]24.625: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 18 regions, survivors: 1 regions, predicted young region time: 0.03 ms]24.625: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 18 regions, survivors: 1 regions, old: 0 regions, predicted pause time: 15.65 ms, target pause time: 200.00 ms]# gc消耗的时间太长了，说明内存不够用了，可以尝试扩容24.648: [G1Ergonomics (Heap Sizing) attempt heap expansion, reason: recent GC overhead higher than threshold after GC, recent GC overhead: 39.83 %, threshold: 10.00 %, uncommitted: 0 bytes, calculated expansion amount: 0 bytes (20.00 %)]
, 0.0230167 secs][Parallel Time: 11.5 ms, GC Workers: 4][GC Worker Start (ms): Min: 24624.8, Avg: 24625.5, Max: 24626.2, Diff: 1.4][Ext Root Scanning (ms): Min: 0.0, Avg: 0.2, Max: 0.8, Diff: 0.8, Sum: 0.8][Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0][Processed Buffers: Min: 0, Avg: 0.2, Max: 1, Diff: 1, Sum: 1][Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0][Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0][Object Copy (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0][Termination (ms): Min: 0.0, Avg: 3.0, Max: 10.7, Diff: 10.7, Sum: 12.0][Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4][GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0][GC Worker Total (ms): Min: 0.0, Avg: 3.2, Max: 10.7, Diff: 10.7, Sum: 12.9][GC Worker End (ms): Min: 24626.2, Avg: 24628.7, Max: 24636.2, Diff: 10.0][Code Root Fixup: 0.0 ms][Code Root Purge: 0.0 ms][Clear CT: 0.0 ms][Other: 11.5 ms][Choose CSet: 0.0 ms][Ref Proc: 11.4 ms][Ref Enq: 0.0 ms][Redirty Cards: 0.0 ms][Humongous Register: 0.0 ms][Humongous Reclaim: 0.0 ms][Free CSet: 0.0 ms][Eden: 18.0M(18.0M)->0.0B(18.0M) Survivors: 1024.0K->1024.0K Heap: 26.2M(32.0M)->6315.7K(32.0M)]
Heap after GC invocations=824 (full 0):garbage-first heap   total 32768K, used 6315K [0x00000007be000000, 0x00000007be100100, 0x00000007c0000000)region size 1024K, 1 young (1024K), 1 survivors (1024K)Metaspace       used 11630K, capacity 11998K, committed 12160K, reserved 1060864Kclass space    used 1511K, capacity 1588K, committed 1664K, reserved 1048576K
}[Times: user=0.00 sys=0.00, real=0.03 secs]

对于普通的yong gc日志就是上面这样一个接一个。但是mix gc完全不一样，开始的时候回打印gc开始的原因，结束的时候会打印gc结束的原因。

# 触发了concurrent cycle。开始concurrent cycle有2个条件：
# 申请H-OBJ（申请的内存大于Region的一半）
# 堆占用率达到45%。
# 这里的原因是堆占用率达到45%24.658: [G1Ergonomics (Concurrent Cycles) request concurrent cycle initiation, reason: occupancy higher than threshold, occupancy: 12582912 bytes, allocation request: 3549488 bytes, threshold: 15099480 bytes (45.00 %), source: concurrent humongous allocation]24.658: [G1Ergonomics (Concurrent Cycles) request concurrent cycle initiation, reason: requested by GC cause, GC cause: G1 Humongous Allocation]# 一个yong gc开始，标志 initial-mark
{Heap before GC invocations=824 (full 0):garbage-first heap   total 32768K, used 25048K [0x00000007be000000, 0x00000007be100100, 0x00000007c0000000)region size 1024K, 17 young (17408K), 1 survivors (1024K)Metaspace       used 11630K, capacity 11998K, committed 12160K, reserved 1060864Kclass space    used 1511K, capacity 1588K, committed 1664K, reserved 1048576K24.658: [G1Ergonomics (Concurrent Cycles) initiate concurrent cycle, reason: concurrent cycle initiation requested]
2020-10-09T20:09:58.050-0800: 24.658: [GC pause (G1 Humongous Allocation) (young) (initial-mark) 24.658: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 0, predicted base time: 17.61 ms, remaining time: 182.39 ms, target pause time: 200.00 ms]24.658: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 16 regions, survivors: 1 regions, predicted young region time: 0.03 ms]24.658: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 16 regions, survivors: 1 regions, old: 0 regions, predicted pause time: 17.64 ms, target pause time: 200.00 ms]24.681: [G1Ergonomics (Heap Sizing) attempt heap expansion, reason: recent GC overhead higher than threshold after GC, recent GC overhead: 44.10 %, threshold: 10.00 %, uncommitted: 0 bytes, calculated expansion amount: 0 bytes (20.00 %)]
, 0.0231035 secs][Parallel Time: 11.7 ms, GC Workers: 4][GC Worker Start (ms): Min: 24658.3, Avg: 24658.5, Max: 24658.7, Diff: 0.4][Ext Root Scanning (ms): Min: 0.0, Avg: 0.8, Max: 1.4, Diff: 1.3, Sum: 3.1][Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0][Processed Buffers: Min: 0, Avg: 0.2, Max: 1, Diff: 1, Sum: 1][Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0][Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0][Object Copy (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.1][Termination (ms): Min: 0.0, Avg: 3.0, Max: 10.9, Diff: 10.9, Sum: 12.0][Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4][GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0][GC Worker Total (ms): Min: 1.1, Avg: 3.8, Max: 11.6, Diff: 10.6, Sum: 15.3][GC Worker End (ms): Min: 24659.8, Avg: 24662.4, Max: 24669.9, Diff: 10.1][Code Root Fixup: 0.0 ms][Code Root Purge: 0.0 ms][Clear CT: 0.0 ms][Other: 11.3 ms][Choose CSet: 0.0 ms][Ref Proc: 11.2 ms][Ref Enq: 0.0 ms][Redirty Cards: 0.0 ms][Humongous Register: 0.0 ms][Humongous Reclaim: 0.0 ms][Free CSet: 0.0 ms][Eden: 16.0M(18.0M)->0.0B(18.0M) Survivors: 1024.0K->1024.0K Heap: 25.5M(32.0M)->3625.0K(32.0M)]
Heap after GC invocations=825 (full 0):garbage-first heap   total 32768K, used 3625K [0x00000007be000000, 0x00000007be100100, 0x00000007c0000000)region size 1024K, 1 young (1024K), 1 survivors (1024K)Metaspace       used 11630K, capacity 11998K, committed 12160K, reserved 1060864Kclass space    used 1511K, capacity 1588K, committed 1664K, reserved 1048576K
}[Times: user=0.01 sys=0.00, real=0.02 secs] 2020-10-09T20:09:58.074-0800: 24.682: [GC concurrent-root-region-scan-start]
2020-10-09T20:09:58.075-0800: 24.683: [GC concurrent-root-region-scan-end, 0.0008813 secs]
2020-10-09T20:09:58.075-0800: 24.683: [GC concurrent-mark-start]
2020-10-09T20:09:58.084-0800: 24.692: [GC concurrent-mark-end, 0.0091770 secs]
2020-10-09T20:09:58.084-0800: 24.692: [GC remark 2020-10-09T20:09:58.084-0800: 24.692: [Finalize Marking, 0.0018289 secs] 2020-10-09T20:09:58.086-0800: 24.694: [GC ref-proc, 0.0001201 secs] 2020-10-09T20:09:58.086-0800: 24.694: [Unloading, 0.0022931 secs], 0.0045892 secs][Times: user=0.01 sys=0.00, real=0.00 secs] 
2020-10-09T20:09:58.089-0800: 24.697: [GC cleanup 15M->15M(32M), 0.0002603 secs][Times: user=0.00 sys=0.00, real=0.00 secs] 
{Heap before GC invocations=826 (full 0):garbage-first heap   total 32768K, used 27824K [0x00000007be000000, 0x00000007be100100, 0x00000007c0000000)region size 1024K, 19 young (19456K), 1 survivors (1024K)Metaspace       used 11630K, capacity 11998K, committed 12160K, reserved 1060864Kclass space    used 1511K, capacity 1588K, committed 1664K, reserved 1048576K# 再来一次yong gc 
2020-10-09T20:09:58.095-0800: 24.703: [GC pause (G1 Evacuation Pause) (young) 24.703: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 3, predicted base time: 18.84 ms, remaining time: 181.16 ms, target pause time: 200.00 ms]24.703: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 18 regions, survivors: 1 regions, predicted young region time: 0.03 ms]24.703: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 18 regions, survivors: 1 regions, old: 0 regions, predicted pause time: 18.87 ms, target pause time: 200.00 ms]24.707: [G1Ergonomics (Heap Sizing) attempt heap expansion, reason: recent GC overhead higher than threshold after GC, recent GC overhead: 50.01 %, threshold: 10.00 %, uncommitted: 0 bytes, calculated expansion amount: 0 bytes (20.00 %)]# 正常可回收的对象不超过5%，停止 mixed 回收。24.707: [G1Ergonomics (Mixed GCs) do not start mixed GCs, reason: reclaimable percentage not over threshold, candidate old regions: 3 regions, reclaimable: 1661096 bytes (4.95 %), threshold: 5.00 %]
, 0.0043467 secs][Parallel Time: 1.5 ms, GC Workers: 4][GC Worker Start (ms): Min: 24702.6, Avg: 24703.3, Max: 24704.0, Diff: 1.4][Ext Root Scanning (ms): Min: 0.0, Avg: 0.7, Max: 1.4, Diff: 1.4, Sum: 2.9][Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0][Processed Buffers: Min: 0, Avg: 0.5, Max: 1, Diff: 1, Sum: 2][Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0][Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0][Object Copy (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1][Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.2][Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4][GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0][GC Worker Total (ms): Min: 0.0, Avg: 0.8, Max: 1.5, Diff: 1.5, Sum: 3.2][GC Worker End (ms): Min: 24704.0, Avg: 24704.1, Max: 24704.1, Diff: 0.0][Code Root Fixup: 0.0 ms][Code Root Purge: 0.0 ms][Clear CT: 0.0 ms][Other: 2.8 ms][Choose CSet: 0.0 ms][Ref Proc: 2.7 ms][Ref Enq: 0.0 ms][Redirty Cards: 0.0 ms][Humongous Register: 0.0 ms][Humongous Reclaim: 0.0 ms][Free CSet: 0.0 ms][Eden: 18.0M(18.0M)->0.0B(18.0M) Survivors: 1024.0K->1024.0K Heap: 27.2M(32.0M)->5925.8K(32.0M)]
Heap after GC invocations=827 (full 0):garbage-first heap   total 32768K, used 5925K [0x00000007be000000, 0x00000007be100100, 0x00000007c0000000)region size 1024K, 1 young (1024K), 1 survivors (1024K)Metaspace       used 11630K, capacity 11998K, committed 12160K, reserved 1060864Kclass space    used 1511K, capacity 1588K, committed 1664K, reserved 1048576K
}[Times: user=0.01 sys=0.00, real=0.00 secs]

什么时候发生Mixed GC?
-XX:G1HeapWastePercent
通过-XX:G1HeapWastePercent指定触发Mixed GC的堆垃圾占比，默认值5%，也就是在全局标记结束后能够统计出所有Cset内可被回收的垃圾占整对的比例值，如果超过5%，那么就会触发之后的多轮Mixed GC，如果不超过，那么会在之后的某次Young GC中重新执行全局并发标记。可以尝试适当的调高此阈值，能够适当的降低Mixed GC的频率。

由一些参数控制，另外也控制着哪些老年代Region会被选入CSet（收集集合）。
G1HeapWastePercent：在global concurrent marking结束之后，我们可以知道old gen regions中有多少空间要被回收，在每次YGC之后和再次发生Mixed GC之前，会检查垃圾占比是否达到此参数，只有达到了，下次才会发生Mixed GC。
G1MixedGCLiveThresholdPercent：old generation region中的存活对象的占比，只有在此参数之下，才会被选入CSet。
G1MixedGCCountTarget：一次global concurrent marking之后，最多执行Mixed GC的次数。
G1OldCSetRegionThresholdPercent：一次Mixed GC中能被选入CSet的最多old generation region数量。

什么样的region会纳入cSet
通过-XX:G1MixedGCLiveThresholdPercent指定被纳入Cset的Region的存活空间占比阈值，不同版本默认值不同，有65%和85%。在全局并发标记阶段，如果一个Region的存活对象的空间占比低于此值，则会被纳入Cset。此值直接影响到Mixed GC选择回收的区域，当发现GC时间较长时，可以尝试调低此阈值，尽量优先选择回收垃圾占比高的Region，但此举也可能导致垃圾回收的不够彻底，最终触发Full GC。但是纳入的region还是有上限的，由G1MixedGCCountTarget控制，默认不超过全部Region的10%。
什么时候触发全局标记
通过-XX:InitiatingHeapOccupancyPercent指定触发全局并发标记的老年代使用占比，默认值45%，也就是老年代占堆的比例超过45%。如果Mixed GC周期结束后老年代使用率还是超过45%,那么会再次触发全局并发标记过程，这样就会导致频繁的老年代GC，影响应用吞吐量。同时老年代空间不大，Mixed GC回收的空间肯定是偏少的。可以适当调高IHOP的值，当然如果此值太高，很容易导致年轻代晋升失败而触发Full GC，所以需要多次调整测试。
一次全局标记后可以多次mix回收
通过-XX:G1MixedGCCountTarget指定一个周期内触发Mixed GC最大次数，默认值8。一次全局并发标记后，最多接着8次Mixed GC，把全局并发标记阶段生成的Cset里的Region拆分为最多8部分，然后在每轮Mixed GC里收集一部分。这个值要和上一个参数配合使用，8*10%=80%，应该来说会大于每次标记阶段的Cset集合了。一般此参数也不需额外调整。

参考：

更多推荐

G1垃圾回收日志分析

本文发布于:2023-07-03 16:27:19，感谢您对本站的认可！

本文链接:https://www.elefans.com/category/jswz/34/1008938.html