时间戳

首页 > 解决方案 > Java 垃圾收集延迟

java - Java 垃圾收集延迟

问题描述

背景： 我们使用 Open JDK 11 在 6 核 linux 主机上运行 Spring Batch Java 应用程序，我们在主机上运行多个应用程序实例。

GC Config 如下图 -XX:+UseG1GC -Xms3G -Xmx3G -Xlog:gc*=debug -Xloggc:/applogs/api_as_m01/gc01.log -XX:+PrintGCDetails -XX:ParallelGCThreads=16 -XX:+DisableExplicitGC

问题： GC 模式似乎不可预测，在大多数情况下，即使内存没有被使用并准备好进行 GC，它也会等待内存使用率达到 >85% 来启动 GC，这在我们拍摄内存快照时由外部 GC 触发器确认. 目前尚不清楚为什么它会等待 >85% 的内存使用，即使最终发生 GC，应用程序也不会出现 OOM，即使没有任何干预。它在一整天内运行 GC 两次或三次。

什么可能导致这种延迟，我们如何确保 GC 正常运行以保持内存使用正常？

GC 日志：

    [0.820s][info][gc,heap] Heap region size: 1M
[0.852s][info][gc     ] Using G1
[0.852s][info][gc,heap,coops] Heap address: 0x0000000700000000, size: 3072 MB, Compressed Oops mode: Zero based, Oop shift amount: 3
[2.149s][info][gc,start     ] GC(0) Pause Young (Normal) (G1 Evacuation Pause)
[2.150s][info][gc,task      ] GC(0) Using 6 workers of 6 for evacuation
[2.158s][info][gc,phases    ] GC(0)   Pre Evacuate Collection Set: 0.2ms
[2.158s][info][gc,phases    ] GC(0)   Evacuate Collection Set: 6.3ms
[2.158s][info][gc,phases    ] GC(0)   Post Evacuate Collection Set: 1.4ms
[2.159s][info][gc,phases    ] GC(0)   Other: 1.3ms
[2.159s][info][gc,heap      ] GC(0) Eden regions: 153->0(147)
[2.159s][info][gc,heap      ] GC(0) Survivor regions: 0->6(20)
[2.159s][info][gc,heap      ] GC(0) Old regions: 0->0
[2.159s][info][gc,heap      ] GC(0) Humongous regions: 2->0
[2.159s][info][gc,metaspace ] GC(0) Metaspace: 15725K->15725K(1064960K)
[2.159s][info][gc           ] GC(0) Pause Young (Normal) (G1 Evacuation Pause) 155M->5M(3072M) 9.642ms
[2.159s][info][gc,cpu       ] GC(0) User=0.03s Sys=0.00s Real=0.01s
[2.596s][info][gc,start     ] GC(1) Pause Young (Concurrent Start) (Metadata GC Threshold)
[2.596s][info][gc,task      ] GC(1) Using 6 workers of 6 for evacuation
[2.604s][info][gc,phases    ] GC(1)   Pre Evacuate Collection Set: 0.1ms
[2.604s][info][gc,phases    ] GC(1)   Evacuate Collection Set: 6.0ms
[2.604s][info][gc,phases    ] GC(1)   Post Evacuate Collection Set: 1.0ms
[2.605s][info][gc,phases    ] GC(1)   Other: 0.9ms
[2.605s][info][gc,heap      ] GC(1) Eden regions: 80->0(146)
[2.605s][info][gc,heap      ] GC(1) Survivor regions: 6->7(20)
[2.605s][info][gc,heap      ] GC(1) Old regions: 0->0
[2.605s][info][gc,heap      ] GC(1) Humongous regions: 0->0
[2.605s][info][gc,metaspace ] GC(1) Metaspace: 20745K->20745K(1069056K)
[2.605s][info][gc           ] GC(1) Pause Young (Concurrent Start) (Metadata GC Threshold) 85M->7M(3072M) 8.561ms
[2.605s][info][gc,cpu       ] GC(1) User=0.02s Sys=0.01s Real=0.01s
[2.605s][info][gc           ] GC(2) Concurrent Cycle
[2.605s][info][gc,marking   ] GC(2) Concurrent Clear Claimed Marks
[2.605s][info][gc,marking   ] GC(2) Concurrent Clear Claimed Marks 0.026ms
[2.605s][info][gc,marking   ] GC(2) Concurrent Scan Root Regions
[2.607s][info][gc,marking   ] GC(2) Concurrent Scan Root Regions 1.881ms
[2.607s][info][gc,marking   ] GC(2) Concurrent Mark (2.607s)
[2.607s][info][gc,marking   ] GC(2) Concurrent Mark From Roots
[2.607s][info][gc,task      ] GC(2) Using 2 workers of 2 for marking
[2.609s][info][gc,marking   ] GC(2) Concurrent Mark From Roots 2.184ms
[2.609s][info][gc,marking   ] GC(2) Concurrent Preclean
[2.609s][info][gc,marking   ] GC(2) Concurrent Preclean 0.197ms
[2.609s][info][gc,marking   ] GC(2) Concurrent Mark (2.607s, 2.609s) 2.417ms
[2.609s][info][gc,start     ] GC(2) Pause Remark
[2.612s][info][gc,stringtable] GC(2) Cleaned string and symbol table, strings: 9132 processed, 0 removed, symbols: 69213 processed, 643 removed
[2.612s][info][gc            ] GC(2) Pause Remark 8M->8M(3072M) 3.027ms
[2.612s][info][gc,cpu        ] GC(2) User=0.01s Sys=0.00s Real=0.00s
[2.612s][info][gc,marking    ] GC(2) Concurrent Rebuild Remembered Sets
[2.613s][info][gc,marking    ] GC(2) Concurrent Rebuild Remembered Sets 0.185ms
[2.613s][info][gc,start      ] GC(2) Pause Cleanup
[2.613s][info][gc            ] GC(2) Pause Cleanup 8M->8M(3072M) 0.511ms
[2.613s][info][gc,cpu        ] GC(2) User=0.00s Sys=0.00s Real=0.00s
[2.613s][info][gc,marking    ] GC(2) Concurrent Cleanup for Next Mark
[2.619s][info][gc,marking    ] GC(2) Concurrent Cleanup for Next Mark 6.174ms
[2.620s][info][gc            ] GC(2) Concurrent Cycle 14.778ms
[3.208s][info][gc,start      ] GC(3) Pause Young (Normal) (G1 Evacuation Pause)
[3.208s][info][gc,task       ] GC(3) Using 6 workers of 6 for evacuation
[3.217s][info][gc,phases     ] GC(3)   Pre Evacuate Collection Set: 0.3ms
[3.217s][info][gc,phases     ] GC(3)   Evacuate Collection Set: 6.3ms
[3.217s][info][gc,phases     ] GC(3)   Post Evacuate Collection Set: 1.4ms
[3.218s][info][gc,phases     ] GC(3)   Other: 0.8ms
[3.218s][info][gc,heap       ] GC(3) Eden regions: 146->0(157)
[3.218s][info][gc,heap       ] GC(3) Survivor regions: 7->9(20)
[3.218s][info][gc,heap       ] GC(3) Old regions: 0->0
[3.218s][info][gc,heap       ] GC(3) Humongous regions: 0->0
[3.218s][info][gc,metaspace  ] GC(3) Metaspace: 27168K->27168K(1073152K)
[3.218s][info][gc            ] GC(3) Pause Young (Normal) (G1 Evacuation Pause) 153M->8M(3072M) 9.920ms
[3.218s][info][gc,cpu        ] GC(3) User=0.03s Sys=0.00s Real=0.01s
[3.848s][info][gc,start      ] GC(4) Pause Young (Normal) (G1 Evacuation Pause)
[3.848s][info][gc,task       ] GC(4) Using 6 workers of 6 for evacuation
[3.858s][info][gc,phases     ] GC(4)   Pre Evacuate Collection Set: 0.1ms
[3.858s][info][gc,phases     ] GC(4)   Evacuate Collection Set: 8.4ms
[3.859s][info][gc,phases     ] GC(4)   Post Evacuate Collection Set: 1.3ms
[3.859s][info][gc,phases     ] GC(4)   Other: 0.7ms
[3.859s][info][gc,heap       ] GC(4) Eden regions: 157->0(170)
[3.859s][info][gc,heap       ] GC(4) Survivor regions: 9->11(21)
[3.859s][info][gc,heap       ] GC(4) Old regions: 0->0
[3.859s][info][gc,heap       ] GC(4) Humongous regions: 0->0
[3.859s][info][gc,metaspace  ] GC(4) Metaspace: 31520K->31520K(1077248K)
[3.859s][info][gc            ] GC(4) Pause Young (Normal) (G1 Evacuation Pause) 165M->10M(3072M) 11.289ms
[3.859s][info][gc,cpu        ] GC(4) User=0.06s Sys=0.00s Real=0.01s
[4.299s][info][gc,start      ] GC(5) Pause Young (Normal) (G1 Evacuation Pause)
[4.299s][info][gc,task       ] GC(5) Using 6 workers of 6 for evacuation
[4.309s][info][gc,phases     ] GC(5)   Pre Evacuate Collection Set: 0.1ms
[4.309s][info][gc,phases     ] GC(5)   Evacuate Collection Set: 7.5ms
[4.309s][info][gc,phases     ] GC(5)   Post Evacuate Collection Set: 1.5ms
[4.309s][info][gc,phases     ] GC(5)   Other: 0.8ms
[4.310s][info][gc,heap       ] GC(5) Eden regions: 170->0(195)
[4.310s][info][gc,heap       ] GC(5) Survivor regions: 11->12(23)
[4.310s][info][gc,heap       ] GC(5) Old regions: 0->0
[4.310s][info][gc,heap       ] GC(5) Humongous regions: 0->0
[4.310s][info][gc,metaspace  ] GC(5) Metaspace: 32118K->32118K(1079296K)
[4.310s][info][gc            ] GC(5) Pause Young (Normal) (G1 Evacuation Pause) 180M->12M(3072M) 10.921ms
[4.310s][info][gc,cpu        ] GC(5) User=0.05s Sys=0.01s Real=0.01s
[5.014s][info][gc,start      ] GC(6) Pause Young (Normal) (G1 Evacuation Pause)
[5.014s][info][gc,task       ] GC(6) Using 6 workers of 6 for evacuation
[5.030s][info][gc,phases     ] GC(6)   Pre Evacuate Collection Set: 0.2ms
[5.031s][info][gc,phases     ] GC(6)   Evacuate Collection Set: 14.0ms
[5.031s][info][gc,phases     ] GC(6)   Post Evacuate Collection Set: 1.4ms
[5.031s][info][gc,phases     ] GC(6)   Other: 0.7ms
[5.031s][info][gc,heap       ] GC(6) Eden regions: 195->0(269)
[5.031s][info][gc,heap       ] GC(6) Survivor regions: 12->14(26)
[5.031s][info][gc,heap       ] GC(6) Old regions: 0->0
[5.031s][info][gc,heap       ] GC(6) Humongous regions: 0->0
[5.031s][info][gc,metaspace  ] GC(6) Metaspace: 33683K->33683K(1079296K)
[5.031s][info][gc            ] GC(6) Pause Young (Normal) (G1 Evacuation Pause) 207M->13M(3072M) 16.989ms
[5.031s][info][gc,cpu        ] GC(6) User=0.06s Sys=0.00s Real=0.01s
[5.415s][info][gc,start      ] GC(7) Pause Young (Concurrent Start) (Metadata GC Threshold)
[5.416s][info][gc,task       ] GC(7) Using 6 workers of 6 for evacuation
[5.436s][info][gc,phases     ] GC(7)   Pre Evacuate Collection Set: 0.3ms
[5.436s][info][gc,phases     ] GC(7)   Evacuate Collection Set: 18.2ms
[5.437s][info][gc,phases     ] GC(7)   Post Evacuate Collection Set: 1.6ms
[5.437s][info][gc,phases     ] GC(7)   Other: 1.0ms
[5.437s][info][gc,heap       ] GC(7) Eden regions: 43->0(274)
[5.438s][info][gc,heap       ] GC(7) Survivor regions: 14->13(36)
[5.438s][info][gc,heap       ] GC(7) Old regions: 0->0
[5.438s][info][gc,heap       ] GC(7) Humongous regions: 0->0
[5.438s][info][gc,metaspace  ] GC(7) Metaspace: 35053K->35053K(1081344K)
[5.438s][info][gc            ] GC(7) Pause Young (Concurrent Start) (Metadata GC Threshold) 56M->12M(3072M) 22.239ms
[5.438s][info][gc,cpu        ] GC(7) User=0.05s Sys=0.00s Real=0.02s
[5.438s][info][gc            ] GC(8) Concurrent Cycle
[5.438s][info][gc,marking    ] GC(8) Concurrent Clear Claimed Marks
[5.438s][info][gc,marking    ] GC(8) Concurrent Clear Claimed Marks 0.037ms
[5.438s][info][gc,marking    ] GC(8) Concurrent Scan Root Regions
[5.443s][info][gc,marking    ] GC(8) Concurrent Scan Root Regions 4.721ms
[5.443s][info][gc,marking    ] GC(8) Concurrent Mark (5.443s)
[5.443s][info][gc,marking    ] GC(8) Concurrent Mark From Roots
[5.443s][info][gc,task       ] GC(8) Using 2 workers of 2 for marking
[5.445s][info][gc,marking    ] GC(8) Concurrent Mark From Roots 2.352ms
[5.445s][info][gc,marking    ] GC(8) Concurrent Preclean
[5.445s][info][gc,marking    ] GC(8) Concurrent Preclean 0.183ms
[5.445s][info][gc,marking    ] GC(8) Concurrent Mark (5.443s, 5.445s) 2.563ms
[5.446s][info][gc,start      ] GC(8) Pause Remark
[5.450s][info][gc,stringtable] GC(8) Cleaned string and symbol table, strings: 15971 processed, 0 removed, symbols: 114522 processed, 1048 removed
[5.451s][info][gc            ] GC(8) Pause Remark 13M->13M(3072M) 5.120ms
[5.451s][info][gc,cpu        ] GC(8) User=0.02s Sys=0.00s Real=0.00s
[5.451s][info][gc,marking    ] GC(8) Concurrent Rebuild Remembered Sets
[5.451s][info][gc,marking    ] GC(8) Concurrent Rebuild Remembered Sets 0.210ms
[5.451s][info][gc,start      ] GC(8) Pause Cleanup
[5.452s][info][gc            ] GC(8) Pause Cleanup 13M->13M(3072M) 0.787ms
[5.452s][info][gc,cpu        ] GC(8) User=0.00s Sys=0.00s Real=0.00s
[5.452s][info][gc,marking    ] GC(8) Concurrent Cleanup for Next Mark
[5.459s][info][gc,marking    ] GC(8) Concurrent Cleanup for Next Mark 7.293ms
[5.460s][info][gc            ] GC(8) Concurrent Cycle 21.721ms
[7.673s][info][gc,start      ] GC(9) Pause Young (Normal) (G1 Evacuation Pause)
[7.673s][info][gc,task       ] GC(9) Using 6 workers of 6 for evacuation
[7.701s][info][gc,phases     ] GC(9)   Pre Evacuate Collection Set: 0.1ms
[7.701s][info][gc,phases     ] GC(9)   Evacuate Collection Set: 24.5ms
[7.701s][info][gc,phases     ] GC(9)   Post Evacuate Collection Set: 2.6ms
[7.702s][info][gc,phases     ] GC(9)   Other: 0.8ms
[7.702s][info][gc,heap       ] GC(9) Eden regions: 274->0(416)
[7.702s][info][gc,heap       ] GC(9) Survivor regions: 13->20(36)
[7.702s][info][gc,heap       ] GC(9) Old regions: 0->0
[7.702s][info][gc,heap       ] GC(9) Humongous regions: 0->0
[7.702s][info][gc,metaspace  ] GC(9) Metaspace: 50170K->50170K(1093632K)
[7.702s][info][gc            ] GC(9) Pause Young (Normal) (G1 Evacuation Pause) 286M->19M(3072M) 28.946ms
[7.702s][info][gc,cpu        ] GC(9) User=0.14s Sys=0.01s Real=0.03s
[9.122s][info][gc,start      ] GC(10) Pause Young (Concurrent Start) (Metadata GC Threshold)
[9.122s][info][gc,task       ] GC(10) Using 6 workers of 6 for evacuation
[9.149s][info][gc,phases     ] GC(10)   Pre Evacuate Collection Set: 0.2ms
[9.149s][info][gc,phases     ] GC(10)   Evacuate Collection Set: 23.6ms
[9.150s][info][gc,phases     ] GC(10)   Post Evacuate Collection Set: 2.4ms
[9.150s][info][gc,phases     ] GC(10)   Other: 0.9ms
[9.150s][info][gc,heap       ] GC(10) Eden regions: 383->0(1822)
[9.150s][info][gc,heap       ] GC(10) Survivor regions: 20->21(55)
[9.150s][info][gc,heap       ] GC(10) Old regions: 0->0
[9.150s][info][gc,heap       ] GC(10) Humongous regions: 116->0
[9.150s][info][gc,metaspace  ] GC(10) Metaspace: 58602K->58602K(1101824K)
[9.150s][info][gc            ] GC(10) Pause Young (Concurrent Start) (Metadata GC Threshold) 518M->21M(3072M) 27.755ms
[9.150s][info][gc,cpu        ] GC(10) User=0.06s Sys=0.01s Real=0.03s
[9.150s][info][gc            ] GC(11) Concurrent Cycle
[9.150s][info][gc,marking    ] GC(11) Concurrent Clear Claimed Marks
[9.150s][info][gc,marking    ] GC(11) Concurrent Clear Claimed Marks 0.063ms
[9.150s][info][gc,marking    ] GC(11) Concurrent Scan Root Regions
[9.158s][info][gc,marking    ] GC(11) Concurrent Scan Root Regions 7.274ms
[9.158s][info][gc,marking    ] GC(11) Concurrent Mark (9.158s)
[9.158s][info][gc,marking    ] GC(11) Concurrent Mark From Roots
[9.158s][info][gc,task       ] GC(11) Using 2 workers of 2 for marking
[9.160s][info][gc,marking    ] GC(11) Concurrent Mark From Roots 2.116ms
[9.160s][info][gc,marking    ] GC(11) Concurrent Preclean
[9.160s][info][gc,marking    ] GC(11) Concurrent Preclean 0.183ms
[9.160s][info][gc,marking    ] GC(11) Concurrent Mark (9.158s, 9.160s) 2.344ms
[9.160s][info][gc,start      ] GC(11) Pause Remark
[9.168s][info][gc,stringtable] GC(11) Cleaned string and symbol table, strings: 28616 processed, 0 removed, symbols: 186406 processed, 144 removed
[9.169s][info][gc            ] GC(11) Pause Remark 22M->22M(3072M) 8.840ms
[9.169s][info][gc,cpu        ] GC(11) User=0.03s Sys=0.00s Real=0.01s
[9.169s][info][gc,marking    ] GC(11) Concurrent Rebuild Remembered Sets
[9.169s][info][gc,marking    ] GC(11) Concurrent Rebuild Remembered Sets 0.165ms
[9.169s][info][gc,start      ] GC(11) Pause Cleanup
[9.170s][info][gc            ] GC(11) Pause Cleanup 22M->22M(3072M) 0.494ms
[9.170s][info][gc,cpu        ] GC(11) User=0.00s Sys=0.00s Real=0.00s
[9.170s][info][gc,marking    ] GC(11) Concurrent Cleanup for Next Mark
[9.173s][info][gc,marking    ] GC(11) Concurrent Cleanup for Next Mark 3.106ms
[9.173s][info][gc            ] GC(11) Concurrent Cycle 22.854ms
[18.224s][info][gc,start      ] GC(12) Pause Young (Concurrent Start) (Metadata GC Threshold)
[18.224s][info][gc,task       ] GC(12) Using 6 workers of 6 for evacuation
[18.270s][info][gc,phases     ] GC(12)   Pre Evacuate Collection Set: 0.3ms
[18.270s][info][gc,phases     ] GC(12)   Evacuate Collection Set: 39.4ms
[18.270s][info][gc,phases     ] GC(12)   Post Evacuate Collection Set: 4.6ms
[18.271s][info][gc,phases     ] GC(12)   Other: 1.4ms
[18.271s][info][gc,heap       ] GC(12) Eden regions: 1245->0(1278)
[18.271s][info][gc,heap       ] GC(12) Survivor regions: 21->39(231)
[18.271s][info][gc,heap       ] GC(12) Old regions: 0->0
[18.271s][info][gc,heap       ] GC(12) Humongous regions: 116->0
[18.271s][info][gc,metaspace  ] GC(12) Metaspace: 98134K->98134K(1136640K)
[18.271s][info][gc            ] GC(12) Pause Young (Concurrent Start) (Metadata GC Threshold) 1382M->38M(3072M) 46.731ms
[18.271s][info][gc,cpu        ] GC(12) User=0.13s Sys=0.01s Real=0.04s
[18.271s][info][gc            ] GC(13) Concurrent Cycle
[18.271s][info][gc,marking    ] GC(13) Concurrent Clear Claimed Marks
[18.271s][info][gc,marking    ] GC(13) Concurrent Clear Claimed Marks 0.148ms
[18.271s][info][gc,marking    ] GC(13) Concurrent Scan Root Regions
[18.283s][info][gc,marking    ] GC(13) Concurrent Scan Root Regions 11.947ms
[18.283s][info][gc,marking    ] GC(13) Concurrent Mark (18.283s)
[18.283s][info][gc,marking    ] GC(13) Concurrent Mark From Roots
[18.283s][info][gc,task       ] GC(13) Using 2 workers of 2 for marking
[18.285s][info][gc,marking    ] GC(13) Concurrent Mark From Roots 2.302ms
[18.285s][info][gc,marking    ] GC(13) Concurrent Preclean
[18.286s][info][gc,marking    ] GC(13) Concurrent Preclean 0.209ms
[18.286s][info][gc,marking    ] GC(13) Concurrent Mark (18.283s, 18.286s) 2.545ms
[18.286s][info][gc,start      ] GC(13) Pause Remark
[18.295s][info][gc,stringtable] GC(13) Cleaned string and symbol table, strings: 46621 processed, 0 removed, symbols: 284121 processed, 119 removed
[18.296s][info][gc            ] GC(13) Pause Remark 41M->41M(3072M) 10.091ms
[18.296s][info][gc,cpu        ] GC(13) User=0.04s Sys=0.00s Real=0.01s
[18.296s][info][gc,marking    ] GC(13) Concurrent Rebuild Remembered Sets
[18.296s][info][gc,marking    ] GC(13) Concurrent Rebuild Remembered Sets 0.224ms
[18.297s][info][gc,start      ] GC(13) Pause Cleanup
[18.297s][info][gc            ] GC(13) Pause Cleanup 41M->41M(3072M) 0.568ms
[18.297s][info][gc,cpu        ] GC(13) User=0.00s Sys=0.00s Real=0.00s
[18.297s][info][gc,marking    ] GC(13) Concurrent Cleanup for Next Mark
[18.300s][info][gc,marking    ] GC(13) Concurrent Cleanup for Next Mark 3.352ms
[18.301s][info][gc            ] GC(13) Concurrent Cycle 29.641ms
[11176.588s][info][gc,start      ] GC(14) Pause Young (Normal) (G1 Evacuation Pause)
[11176.588s][info][gc,task       ] GC(14) Using 6 workers of 6 for evacuation
[11176.645s][info][gc,phases     ] GC(14)   Pre Evacuate Collection Set: 0.3ms
[11176.645s][info][gc,phases     ] GC(14)   Evacuate Collection Set: 45.1ms
[11176.645s][info][gc,phases     ] GC(14)   Post Evacuate Collection Set: 10.5ms
[11176.646s][info][gc,phases     ] GC(14)   Other: 1.0ms
[11176.646s][info][gc,heap       ] GC(14) Eden regions: 1278->0(1767)
[11176.646s][info][gc,heap       ] GC(14) Survivor regions: 39->76(165)
[11176.646s][info][gc,heap       ] GC(14) Old regions: 0->0
[11176.646s][info][gc,heap       ] GC(14) Humongous regions: 23->17
[11176.646s][info][gc,metaspace  ] GC(14) Metaspace: 127295K->127295K(1163264K)
[11176.646s][info][gc            ] GC(14) Pause Young (Normal) (G1 Evacuation Pause) 1339M->93M(3072M) 58.169ms
[11176.646s][info][gc,cpu        ] GC(14) User=0.26s Sys=0.01s Real=0.06s
[49900.836s][info][gc,start      ] GC(15) Pause Young (Normal) (G1 Evacuation Pause)
[49900.836s][info][gc,task       ] GC(15) Using 6 workers of 6 for evacuation
[49900.900s][info][gc,phases     ] GC(15)   Pre Evacuate Collection Set: 0.2ms
[49900.900s][info][gc,phases     ] GC(15)   Evacuate Collection Set: 37.7ms
[49900.900s][info][gc,phases     ] GC(15)   Post Evacuate Collection Set: 25.1ms
[49900.901s][info][gc,phases     ] GC(15)   Other: 1.1ms
[49900.901s][info][gc,heap       ] GC(15) Eden regions: 1767->0(1076)
[49900.901s][info][gc,heap       ] GC(15) Survivor regions: 76->141(231)
[49900.901s][info][gc,heap       ] GC(15) Old regions: 0->0
[49900.901s][info][gc,heap       ] GC(15) Humongous regions: 104->34
[49900.901s][info][gc,metaspace  ] GC(15) Metaspace: 134079K->134079K(1169408K)
[49900.901s][info][gc            ] GC(15) Pause Young (Normal) (G1 Evacuation Pause) 1947M->174M(3072M) 65.156ms
[49900.901s][info][gc,cpu        ] GC(15) User=0.31s Sys=0.04s Real=0.06s
[65074.992s][info][gc,start      ] GC(16) Pause Young (Normal) (G1 Evacuation Pause)
[65074.992s][info][gc,task       ] GC(16) Using 6 workers of 6 for evacuation
[65075.066s][info][gc,phases     ] GC(16)   Pre Evacuate Collection Set: 0.3ms
[65075.066s][info][gc,phases     ] GC(16)   Evacuate Collection Set: 63.7ms
[65075.066s][info][gc,phases     ] GC(16)   Post Evacuate Collection Set: 9.0ms
[65075.067s][info][gc,phases     ] GC(16)   Other: 0.8ms
[65075.067s][info][gc,heap       ] GC(16) Eden regions: 1076->0(903)
[65075.067s][info][gc,heap       ] GC(16) Survivor regions: 141->87(153)
[65075.067s][info][gc,heap       ] GC(16) Old regions: 0->44
[65075.067s][info][gc,heap       ] GC(16) Humongous regions: 294->68
[65075.067s][info][gc,metaspace  ] GC(16) Metaspace: 138622K->138622K(1173504K)
[65075.067s][info][gc            ] GC(16) Pause Young (Normal) (G1 Evacuation Pause) 1510M->198M(3072M) 74.434ms
[65075.067s][info][gc,cpu        ] GC(16) User=0.38s Sys=0.00s Real=0.08s
[65075.750s][info][gc,start      ] GC(17) Pause Young (Normal) (G1 Evacuation Pause)
[65075.750s][info][gc,task       ] GC(17) Using 6 workers of 6 for evacuation
[65075.782s][info][gc,phases     ] GC(17)   Pre Evacuate Collection Set: 0.2ms
[65075.782s][info][gc,phases     ] GC(17)   Evacuate Collection Set: 30.7ms
[65075.783s][info][gc,phases     ] GC(17)   Post Evacuate Collection Set: 1.3ms
[65075.783s][info][gc,phases     ] GC(17)   Other: 0.6ms
[65075.783s][info][gc,heap       ] GC(17) Eden regions: 80->0(1823)
[65075.783s][info][gc,heap       ] GC(17) Survivor regions: 87->20(21)
[65075.783s][info][gc,heap       ] GC(17) Old regions: 44->100
[65075.783s][info][gc,heap       ] GC(17) Humongous regions: 90->79
[65075.783s][info][gc,metaspace  ] GC(17) Metaspace: 138725K->138725K(1173504K)
[65075.783s][info][gc            ] GC(17) Pause Young (Normal) (G1 Evacuation Pause) 300M->198M(3072M) 33.338ms
[65075.783s][info][gc,cpu        ] GC(17) User=0.19s Sys=0.00s Real=0.03s
[65891.537s][info][gc,start      ] GC(18) Pause Young (Normal) (G1 Evacuation Pause)
[65891.537s][info][gc,task       ] GC(18) Using 6 workers of 6 for evacuation
[65891.569s][info][gc,phases     ] GC(18)   Pre Evacuate Collection Set: 0.3ms
[65891.570s][info][gc,phases     ] GC(18)   Evacuate Collection Set: 28.8ms
[65891.570s][info][gc,phases     ] GC(18)   Post Evacuate Collection Set: 2.3ms
[65891.570s][info][gc,phases     ] GC(18)   Other: 0.8ms
[65891.571s][info][gc,heap       ] GC(18) Eden regions: 133->0(133)
[65891.571s][info][gc,heap       ] GC(18) Survivor regions: 20->20(20)
[65891.571s][info][gc,heap       ] GC(18) Old regions: 100->120
[65891.571s][info][gc,heap       ] GC(18) Humongous regions: 169->70
[65891.571s][info][gc,metaspace  ] GC(18) Metaspace: 138856K->138856K(1173504K)
[65891.571s][info][gc            ] GC(18) Pause Young (Normal) (G1 Evacuation Pause) 421M->210M(3072M) 33.338ms
[65891.571s][info][gc,cpu        ] GC(18) User=0.16s Sys=0.00s Real=0.03s
[65907.915s][info][gc,start      ] GC(19) Pause Young (Normal) (G1 Evacuation Pause)
[65907.915s][info][gc,task       ] GC(19) Using 6 workers of 6 for evacuation
[65907.941s][info][gc,phases     ] GC(19)   Pre Evacuate Collection Set: 2.4ms
[65907.941s][info][gc,phases     ] GC(19)   Evacuate Collection Set: 22.0ms
[65907.942s][info][gc,phases     ] GC(19)   Post Evacuate Collection Set: 1.9ms
[65907.942s][info][gc,phases     ] GC(19)   Other: 0.6ms
[65907.942s][info][gc,heap       ] GC(19) Eden regions: 133->0(134)
[65907.942s][info][gc,heap       ] GC(19) Survivor regions: 20->19(20)
[65907.942s][info][gc,heap       ] GC(19) Old regions: 120->140
[65907.942s][info][gc,heap       ] GC(19) Humongous regions: 205->70
[65907.942s][info][gc,metaspace  ] GC(19) Metaspace: 139061K->139061K(1173504K)
[65907.942s][info][gc            ] GC(19) Pause Young (Normal) (G1 Evacuation Pause) 478M->228M(3072M) 27.818ms
[65907.942s][info][gc,cpu        ] GC(19) User=0.14s Sys=0.00s Real=0.02s
[65908.189s][info][gc,start      ] GC(20) Pause Young (Normal) (G1 Evacuation Pause)
[65908.189s][info][gc,task       ] GC(20) Using 6 workers of 6 for evacuation
[65908.207s][info][gc,phases     ] GC(20)   Pre Evacuate Collection Set: 0.2ms
[65908.207s][info][gc,phases     ] GC(20)   Evacuate Collection Set: 15.3ms
[65908.207s][info][gc,phases     ] GC(20)   Post Evacuate Collection Set: 1.1ms
[65908.208s][info][gc,phases     ] GC(20)   Other: 0.7ms
[65908.208s][info][gc,heap       ] GC(20) Eden regions: 134->0(177)
[65908.208s][info][gc,heap       ] GC(20) Survivor regions: 19->15(20)
[65908.208s][info][gc,heap       ] GC(20) Old regions: 140->159
[65908.208s][info][gc,heap       ] GC(20) Humongous regions: 70->70
[65908.208s][info][gc,metaspace  ] GC(20) Metaspace: 139064K->139064K(1173504K)
[65908.208s][info][gc            ] GC(20) Pause Young (Normal) (G1 Evacuation Pause) 362M->243M(3072M) 18.382ms
[65908.208s][info][gc,cpu        ] GC(20) User=0.09s Sys=0.00s Real=0.02s
[65908.521s][info][gc,start      ] GC(21) Pause Young (Normal) (G1 Evacuation Pause)
[65908.521s][info][gc,task       ] GC(21) Using 6 workers of 6 for evacuation
[65908.543s][info][gc,phases     ] GC(21)   Pre Evacuate Collection Set: 0.1ms
[65908.543s][info][gc,phases     ] GC(21)   Evacuate Collection Set: 20.7ms
[65908.543s][info][gc,phases     ] GC(21)   Post Evacuate Collection Set: 0.9ms
[65908.544s][info][gc,phases     ] GC(21)   Other: 0.4ms
[65908.544s][info][gc,heap       ] GC(21) Eden regions: 177->0(651)
[65908.544s][info][gc,heap       ] GC(21) Survivor regions: 15->18(24)
[65908.544s][info][gc,heap       ] GC(21) Old regions: 159->173
[65908.544s][info][gc,heap       ] GC(21) Humongous regions: 71->71
[65908.544s][info][gc,metaspace  ] GC(21) Metaspace: 139064K->139064K(1173504K)
[65908.544s][info][gc            ] GC(21) Pause Young (Normal) (G1 Evacuation Pause) 421M->260M(3072M) 22.693ms
[65908.544s][info][gc,cpu        ] GC(21) User=0.12s Sys=0.00s Real=0.03s
[65909.154s][info][gc,start      ] GC(22) Pause Young (Normal) (G1 Evacuation Pause)
[65909.154s][info][gc,task       ] GC(22) Using 6 workers of 6 for evacuation
[65909.176s][info][gc,phases     ] GC(22)   Pre Evacuate Collection Set: 0.2ms
[65909.176s][info][gc,phases     ] GC(22)   Evacuate Collection Set: 19.3ms
[65909.176s][info][gc,phases     ] GC(22)   Post Evacuate Collection Set: 1.6ms
[65909.176s][info][gc,phases     ] GC(22)   Other: 0.8ms
[65909.176s][info][gc,heap       ] GC(22) Eden regions: 205->0(1500)
[65909.177s][info][gc,heap       ] GC(22) Survivor regions: 18->14(28)
[65909.177s][info][gc,heap       ] GC(22) Old regions: 173->190
[65909.177s][info][gc,heap       ] GC(22) Humongous regions: 95->83
[65909.177s][info][gc,metaspace  ] GC(22) Metaspace: 139090K->139090K(1173504K)
[65909.177s][info][gc            ] GC(22) Pause Young (Normal) (G1 Evacuation Pause) 489M->287M(3072M) 22.912ms
[65909.177s][info][gc,cpu        ] GC(22) User=0.10s Sys=0.00s Real=0.02s
[65912.334s][info][gc,start      ] GC(23) Pause Young (Normal) (G1 Evacuation Pause)
[65912.334s][info][gc,task       ] GC(23) Using 6 workers of 6 for evacuation
[65912.355s][info][gc,phases     ] GC(23)   Pre Evacuate Collection Set: 0.2ms
[65912.355s][info][gc,phases     ] GC(23)   Evacuate Collection Set: 18.6ms
[65912.355s][info][gc,phases     ] GC(23)   Post Evacuate Collection Set: 1.4ms
[65912.356s][info][gc,phases     ] GC(23)   Other: 0.6ms
[65912.356s][info][gc,heap       ] GC(23) Eden regions: 139->0(943)
[65912.356s][info][gc,heap       ] GC(23) Survivor regions: 14->11(20)
[65912.356s][info][gc,heap       ] GC(23) Old regions: 190->204
[65912.356s][info][gc,heap       ] GC(23) Humongous regions: 139->77
[65912.356s][info][gc,metaspace  ] GC(23) Metaspace: 139133K->139133K(1173504K)
[65912.356s][info][gc            ] GC(23) Pause Young (Normal) (G1 Evacuation Pause) 482M->291M(3072M) 21.372ms
[65912.356s][info][gc,cpu        ] GC(23) User=0.11s Sys=0.00s Real=0.02s

标签： javagarbage-collection

解决方案

当您说收集模式看起来“不可预测”时，您可能描述的是 G1 GC 用于收集堆空间的不同区域（伊甸园、年轻、旧等）的可用空间的多重收集方法，这些区域使用不同的该收集发生时的条件。您在收集发生之前看到的“延迟”是您的应用程序的正常堆使用情况，直到达到一个或多个触发收集的条件。

从文档：

G1 是一个分代的、增量的、并行的、主要是并发的、stop-the-world 和撤离垃圾收集器，它监视每个 stop-the-world 暂停中的暂停时间目标

从这里的文档：https ://docs.oracle.com/javase/9​​/gctuning/garbage-first-garbage-collector.htm#JSGCT-GUID-0394E76A-1A8F-425E-A0D0-B48A3DC82B42

虽然所有收集器都是可配置的，但您需要知道自己在做什么，否则随机调整会使事情变得更糟。

如果您正在寻找可预测的收集时间，您可以查看其他具有不同特征的收集器。但是，如果您没有遇到 OOM 并且暂停时间是可以接受的，我认为您应该评估您是否有问题。

如果您正在寻找有关调优的建议，那么指定您希望实现的 GC 目标会有所帮助？一旦你定义了这些，你就可以专注于你需要调整哪些 GC 选项。

推荐阅读