G1垃圾回收日志分析
2024-05-11 16:03:38
标准 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集合了。一般此参数也不需额外调整。
参考：https://zhuanlan.zhihu.com/p/181305087
G1垃圾回收日志分析相关推荐
- 万字长文教你看懂java G1垃圾回收日志
文章目录 一.如何在idea打印G1日志 二.G1基础参数 三.G1新生代收集 1. 四个关键信息 2. 列出了新生代收集中并行收集的详细过程 3.列出了新生代GC中的一些任务: 4.包含一些扩展功能 ...
- 想知道垃圾回收暂停的过程中发生了什么吗？查查垃圾回收日志就知道了！
\ 关键点 \ 垃圾回收日志中包括着一些关键性能指标: \ 要做一次正确的垃圾回收分析需要收集许多数据,所以好的工具是非常必要的: \ 除了垃圾回收之外还有很多事件都可能会让应用程序暂停: \ 让你的 ...
- Java垃圾回收日志解析
1.开启垃圾回收日志 在运行一个java程序时可以在命令行中加入相应的JVM垃圾回收参数,获取程序运行时详细的垃圾回收日志信息.以下是一些大概的参数: -XX:+PrintGC与-verbose:gc ...
- 一篇文章教你弄懂java CMS垃圾回收日志
文章目录 一.CMS垃圾回收器介绍 二.CMS JVM运行参数 三.CMS收集器运行过程 1.初始标记(CMS initial mark) 2.并发标记(CMS concurrent mark) 3. ...
- G1垃圾回收算法概述
垃圾回收都是基于分区进行的.G1在实现垃圾回收时一共提供了3种回收的方法,分别是新生代回收(称为Young GC, YGC),混合回收(称为Mixed GC),全回收(称为Full GC, FGC). ...
- idea本地跑如何看gc日志_不可思议，竟然还有人不会查看GC垃圾回收日志？
日志的重要性,不需要过多强调了.通过日志,我们可以发现程序可能有内存(泄露)问题.本文从案例出发,具体介绍这些日志信息,以期帮助大家更好地了解垃圾回收的运行情况. 还是先上图,看看本文的主要内容: 我 ...
- 什么是G1垃圾回收算法
转载自 什么是G1垃圾回收算法 为解决CMS算法产生空间碎片和其它一系列的问题缺陷,HotSpot提供了另外一种垃圾回收策略,G1(Garbage First)算法,通过参数 -XX:+UseG1GC ...
- Android中垃圾回收日志信息
原因 GC_CONCURRENTfreed 178K, 41% free 3673K/6151K, external 0K/0K, paused 2ms+2ms GC_EXPLICITfreed 6K ...
- android 通知垃圾回收,Android中垃圾回收日志信息
原因 GC_CONCURRENTfreed 178K, 41% free 3673K/6151K, external 0K/0K, paused 2ms+2ms GC_EXPLICITfreed 6K ...
最新文章
- Spring3.3 整合 Hibernate3、MyBatis3.2 配置多数据源/动态切换数据源 方法
- 【Qt】错误GL/gl.h: No such file or directory的解决方法（以及cannot find -lGL解决方法）
- Tornado多进程启动的2种方法
- valid parentheses java_Valid Parentheses Java
- web 后台返回json格式数据的方式（status 406）
- Windows系统 notepad命令详解，Windows系统打开记事本
- Create umbraco website-On the road of umbraco (1)
- ASP.NET对IIS中的虚拟目录进行操作
- 【用jersey构建REST服务】系列文章
- Origin2018-小白安装
- 扫地机器人扫水泥地板有用吗_拖地机器人好用吗—拖地机器人的优点介绍
- 教你m4a怎么转换成mp3
- arange函数——numpy模块
- 光速入门Docker 和 Kubernetes，一起学~
- 如何把EAN13码外观设置和code128码一样
- Photon网络中Player中存取数据
- 神经风格迁移综述论文分享(neural style transfer review)
- 饭桌的威力，辛酸的父母。
- 微信小程序云开发上传word文档到云存储器
- java 获取字符串最后的数字