標準 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回收的空間肯定是偏少的?？梢赃m當調高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垃圾回收日志分析的全部內容，希望文章能夠幫你解決所遇到的問題。

如果覺得生活随笔網站內容還不錯，歡迎將生活随笔推薦給好友。