G1GC 不自动调整 NewSize（长 GC 时间）
G1GC not auto adjusting NewSize (Long GC times)
我的应用程序是 G1GC，内存大小为 45GB。我看到很长的 GC 时间。在调查时，我发现只有 5% 的年轻代堆被频繁填满，导致频繁回收。此外，尽管大部分堆是空的，但 GC 并未调整 "NewSize"，它始终保持在 5%，并且大部分堆已保留（但未使用）用于 "Tenured Generation"。 G1GC 文档建议在每次 GC 收集期间自动调整 NewSize。
问题：-
- "G1MaxNewSizePercent" 和 G1NewSizePercent 的默认值分别是 60% 和 5%，为什么 GC 没有自动调整大小并且卡在 5%。 http://www.oracle.com/technetwork/articles/java/g1gc-1984535.html
- 我需要做一些特殊的事情让 GC 开始自动调整吗？
- 为什么大部分堆首先被保留给老一代？
以下是 GCViewer 快照
JVM 标志
sudo -u ./jcmd [PID] VM.flags
-XX:+AlwaysPreTouch
-XX:CICompilerCount=15
-XX:ConcGCThreads=6
-XX:G1HeapRegionSize=16777216
-XX:GCLogFileSize=10485760
-XX:+HeapDumpOnOutOfMemoryError
-XX:InitialHeapSize=48318382080
-XX:MarkStackSize=4194304
-XX:MaxHeapSize=48318382080
-XX:MaxNewSize=28991029248
-XX:MinHeapDeltaBytes=16777216
-XX:NumberOfGCLogFiles=5
-XX:-OmitStackTraceInFastThrow
-XX:OnOutOfMemoryError=/bin/kill -9 %p
-XX:+PrintGC -XX:+PrintGCApplicationStoppedTime
-XX:+PrintGCDateStamps
-XX:+PrintGCDetails
-XX:+PrintGCTimeStamps
-XX:+PrintTenuringDistribution
-XX:+UseG1GC
-XX:+UseGCLogFileRotation
GC 日志快照
2018-02-26T21:44:51.808+0000: 3964500.472: Total time for which application threads were stopped: 1.6367601 seconds, Stopping threads took: 0.0013929 seconds
2018-02-26T21:45:30.402+0000: 3964539.066: [GC pause (G1 Evacuation Pause) (young)
Desired survivor size 150994944 bytes, new threshold 15 (max 15)
- age 1: 9990048 bytes, 9990048 total
- age 2: 3134528 bytes, 13124576 total
- age 3: 3096528 bytes, 16221104 total
- age 4: 3214512 bytes, 19435616 total
- age 5: 1927232 bytes, 21362848 total
- age 6: 1268760 bytes, 22631608 total
- age 7: 717648 bytes, 23349256 total
- age 8: 439232 bytes, 23788488 total
- age 9: 246680 bytes, 24035168 total
- age 10: 167256 bytes, 24202424 total
- age 11: 49928 bytes, 24252352 total
- age 12: 54232 bytes, 24306584 total
- age 13: 58920 bytes, 24365504 total
- age 14: 56704 bytes, 24422208 total
- age 15: 43744 bytes, 24465952 total
, 1.5579128 secs]
[Parallel Time: 34.2 ms, GC Workers: 25]
[GC Worker Start (ms): Min: 3964539071.6, Avg: 3964539071.9, Max: 3964539072.2, Diff: 0.6]
[Ext Root Scanning (ms): Min: 9.4, Avg: 11.8, Max: 14.3, Diff: 4.9, Sum: 294.7]
[Update RS (ms): Min: 6.1, Avg: 9.8, Max: 19.2, Diff: 13.1, Sum: 245.1]
[Processed Buffers: Min: 14, Avg: 162.4, Max: 668, Diff: 654, Sum: 4059]
[Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.3]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Object Copy (ms): Min: 2.3, Avg: 9.4, Max: 11.7, Diff: 9.4, Sum: 235.3]
[Termination (ms): Min: 1.0, Avg: 2.4, Max: 4.3, Diff: 3.3, Sum: 60.0]
[Termination Attempts: Min: 78, Avg: 230.8, Max: 303, Diff: 225, Sum: 5769]
[GC Worker Other (ms): Min: 0.1, Avg: 0.1, Max: 0.3, Diff: 0.2, Sum: 3.6]
[GC Worker Total (ms): Min: 33.2, Avg: 33.6, Max: 33.9, Diff: 0.7, Sum: 839.0]
[GC Worker End (ms): Min: 3964539105.5, Avg: 3964539105.5, Max: 3964539105.6, Diff: 0.1]
[Code Root Fixup: 0.1 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.7 ms]
[Other: 1522.9 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 1510.4 ms]
[Ref Enq: 0.1 ms]
[Redirty Cards: 0.4 ms]
[Humongous Register: 0.1 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 0.5 ms]
[Eden: 2256.0M(2256.0M)->0.0B(2256.0M) Survivors: 48.0M->48.0M Heap: 5703.0M(45.0G)->3449.3M(45.0G)]
[Times: user=1.62 sys=0.34, real=1.56 secs]
2018-02-26T21:45:31.963+0000: 3964540.627: Total time for which application threads were stopped: 1.5935495 seconds, Stopping threads took: 0.0057849 seconds
2018-02-26T21:45:40.547+0000: 3964549.211: Total time for which application threads were stopped: 0.0743828 seconds, Stopping threads took: 0.0024422 seconds
2018-02-26T21:45:51.083+0000: 3964559.748: Total time for which application threads were stopped: 0.0173656 seconds, Stopping threads took: 0.0011296 seconds
2018-02-26T21:46:06.646+0000: 3964575.310: [GC pause (G1 Evacuation Pause) (young)
Desired survivor size 150994944 bytes, new threshold 15 (max 15)
- age 1: 10282952 bytes, 10282952 total
- age 2: 3420512 bytes, 13703464 total
- age 3: 2663240 bytes, 16366704 total
- age 4: 2506952 bytes, 18873656 total
- age 5: 1215280 bytes, 20088936 total
- age 6: 555136 bytes, 20644072 total
- age 7: 542128 bytes, 21186200 total
- age 8: 336520 bytes, 21522720 total
- age 9: 173096 bytes, 21695816 total
- age 10: 117656 bytes, 21813472 total
- age 11: 44280 bytes, 21857752 total
- age 12: 45728 bytes, 21903480 total
- age 13: 53928 bytes, 21957408 total
- age 14: 58128 bytes, 22015536 total
- age 15: 56704 bytes, 22072240 total
, 1.2324057 secs]
[Parallel Time: 39.1 ms, GC Workers: 25]
[GC Worker Start (ms): Min: 3964575316.2, Avg: 3964575317.5, Max: 3964575318.7, Diff: 2.4]
[Ext Root Scanning (ms): Min: 9.0, Avg: 12.4, Max: 16.1, Diff: 7.0, Sum: 311.0]
[Update RS (ms): Min: 2.1, Avg: 8.2, Max: 16.4, Diff: 14.3, Sum: 206.0]
[Processed Buffers: Min: 24, Avg: 149.3, Max: 246, Diff: 222, Sum: 3732]
[Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.4]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[Object Copy (ms): Min: 6.9, Avg: 12.5, Max: 15.5, Diff: 8.6, Sum: 311.5]
[Termination (ms): Min: 2.6, Avg: 3.9, Max: 4.7, Diff: 2.1, Sum: 96.9]
[Termination Attempts: Min: 179, Avg: 384.9, Max: 448, Diff: 269, Sum: 9622]
[GC Worker Other (ms): Min: 0.0, Avg: 0.5, Max: 0.7, Diff: 0.7, Sum: 12.4]
[GC Worker Total (ms): Min: 36.3, Avg: 37.5, Max: 38.7, Diff: 2.4, Sum: 938.3]
[GC Worker End (ms): Min: 3964575354.9, Avg: 3964575355.0, Max: 3964575355.1, Diff: 0.1]
[Code Root Fixup: 0.1 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.6 ms]
[Other: 1192.6 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 1180.2 ms]
[Ref Enq: 0.1 ms]
[Redirty Cards: 0.4 ms]
[Humongous Register: 1.8 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 0.3 ms]
[Eden: 2256.0M(2256.0M)->0.0B(2256.0M) Survivors: 48.0M->48.0M Heap: 5705.3M(45.0G)->3439.2M(45.0G)]
[Times: user=1.86 sys=0.00, real=1.23 secs]
2018-02-26T21:46:07.880+0000: 3964576.545: Total time for which application threads were stopped: 1.2492396 seconds, Stopping threads took: 0.0013324 seconds
2018-02-26T21:46:41.430+0000: 3964610.095: Total time for which application threads were stopped: 0.0331942 seconds, Stopping threads took: 0.0043586 seconds
2018-02-26T21:46:44.246+0000: 3964612.910: [GC pause (G1 Evacuation Pause) (young)
您大部分时间都花在参考文献处理上。几乎所有的 GC 时间。
[参考过程：1180.2 毫秒]。
引用处理阶段涉及处理任何由 STW 引用处理器发现的 soft/weak/final/phantom/JNI 引用。
Eden(Young Gen) 内存由 G1 收集器在每次 GC 上收集的 Heuristics 确定。它根据 GC 历史调整 Young Gen，使最大暂停时间与您的目标暂停时间相匹配。如果你的目标暂停时间很短，伊甸园内存可以很短。
如果不设置，目标暂停时间默认为200ms。我猜是因为您的 Ref Proc 时间太大，G1 使您的伊甸园区域大小保持较小，以便为您提供最佳的暂停时间。
您应该调查堆上有哪些引用，看看您的应用程序产生这么多引用是否正常。解决这个问题，你的 Eden 内存应该会自动增加。
我的应用程序是 G1GC，内存大小为 45GB。我看到很长的 GC 时间。在调查时，我发现只有 5% 的年轻代堆被频繁填满，导致频繁回收。此外，尽管大部分堆是空的，但 GC 并未调整 "NewSize"，它始终保持在 5%，并且大部分堆已保留（但未使用）用于 "Tenured Generation"。 G1GC 文档建议在每次 GC 收集期间自动调整 NewSize。
问题：-
- "G1MaxNewSizePercent" 和 G1NewSizePercent 的默认值分别是 60% 和 5%，为什么 GC 没有自动调整大小并且卡在 5%。 http://www.oracle.com/technetwork/articles/java/g1gc-1984535.html
- 我需要做一些特殊的事情让 GC 开始自动调整吗？
- 为什么大部分堆首先被保留给老一代？
以下是 GCViewer 快照
JVM 标志
sudo -u ./jcmd [PID] VM.flags
-XX:+AlwaysPreTouch
-XX:CICompilerCount=15
-XX:ConcGCThreads=6
-XX:G1HeapRegionSize=16777216
-XX:GCLogFileSize=10485760
-XX:+HeapDumpOnOutOfMemoryError
-XX:InitialHeapSize=48318382080
-XX:MarkStackSize=4194304
-XX:MaxHeapSize=48318382080
-XX:MaxNewSize=28991029248
-XX:MinHeapDeltaBytes=16777216
-XX:NumberOfGCLogFiles=5
-XX:-OmitStackTraceInFastThrow
-XX:OnOutOfMemoryError=/bin/kill -9 %p
-XX:+PrintGC -XX:+PrintGCApplicationStoppedTime
-XX:+PrintGCDateStamps
-XX:+PrintGCDetails
-XX:+PrintGCTimeStamps
-XX:+PrintTenuringDistribution
-XX:+UseG1GC
-XX:+UseGCLogFileRotation
GC 日志快照
2018-02-26T21:44:51.808+0000: 3964500.472: Total time for which application threads were stopped: 1.6367601 seconds, Stopping threads took: 0.0013929 seconds
2018-02-26T21:45:30.402+0000: 3964539.066: [GC pause (G1 Evacuation Pause) (young)
Desired survivor size 150994944 bytes, new threshold 15 (max 15)
- age 1: 9990048 bytes, 9990048 total
- age 2: 3134528 bytes, 13124576 total
- age 3: 3096528 bytes, 16221104 total
- age 4: 3214512 bytes, 19435616 total
- age 5: 1927232 bytes, 21362848 total
- age 6: 1268760 bytes, 22631608 total
- age 7: 717648 bytes, 23349256 total
- age 8: 439232 bytes, 23788488 total
- age 9: 246680 bytes, 24035168 total
- age 10: 167256 bytes, 24202424 total
- age 11: 49928 bytes, 24252352 total
- age 12: 54232 bytes, 24306584 total
- age 13: 58920 bytes, 24365504 total
- age 14: 56704 bytes, 24422208 total
- age 15: 43744 bytes, 24465952 total
, 1.5579128 secs]
[Parallel Time: 34.2 ms, GC Workers: 25]
[GC Worker Start (ms): Min: 3964539071.6, Avg: 3964539071.9, Max: 3964539072.2, Diff: 0.6]
[Ext Root Scanning (ms): Min: 9.4, Avg: 11.8, Max: 14.3, Diff: 4.9, Sum: 294.7]
[Update RS (ms): Min: 6.1, Avg: 9.8, Max: 19.2, Diff: 13.1, Sum: 245.1]
[Processed Buffers: Min: 14, Avg: 162.4, Max: 668, Diff: 654, Sum: 4059]
[Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.3]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Object Copy (ms): Min: 2.3, Avg: 9.4, Max: 11.7, Diff: 9.4, Sum: 235.3]
[Termination (ms): Min: 1.0, Avg: 2.4, Max: 4.3, Diff: 3.3, Sum: 60.0]
[Termination Attempts: Min: 78, Avg: 230.8, Max: 303, Diff: 225, Sum: 5769]
[GC Worker Other (ms): Min: 0.1, Avg: 0.1, Max: 0.3, Diff: 0.2, Sum: 3.6]
[GC Worker Total (ms): Min: 33.2, Avg: 33.6, Max: 33.9, Diff: 0.7, Sum: 839.0]
[GC Worker End (ms): Min: 3964539105.5, Avg: 3964539105.5, Max: 3964539105.6, Diff: 0.1]
[Code Root Fixup: 0.1 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.7 ms]
[Other: 1522.9 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 1510.4 ms]
[Ref Enq: 0.1 ms]
[Redirty Cards: 0.4 ms]
[Humongous Register: 0.1 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 0.5 ms]
[Eden: 2256.0M(2256.0M)->0.0B(2256.0M) Survivors: 48.0M->48.0M Heap: 5703.0M(45.0G)->3449.3M(45.0G)]
[Times: user=1.62 sys=0.34, real=1.56 secs]
2018-02-26T21:45:31.963+0000: 3964540.627: Total time for which application threads were stopped: 1.5935495 seconds, Stopping threads took: 0.0057849 seconds
2018-02-26T21:45:40.547+0000: 3964549.211: Total time for which application threads were stopped: 0.0743828 seconds, Stopping threads took: 0.0024422 seconds
2018-02-26T21:45:51.083+0000: 3964559.748: Total time for which application threads were stopped: 0.0173656 seconds, Stopping threads took: 0.0011296 seconds
2018-02-26T21:46:06.646+0000: 3964575.310: [GC pause (G1 Evacuation Pause) (young)
Desired survivor size 150994944 bytes, new threshold 15 (max 15)
- age 1: 10282952 bytes, 10282952 total
- age 2: 3420512 bytes, 13703464 total
- age 3: 2663240 bytes, 16366704 total
- age 4: 2506952 bytes, 18873656 total
- age 5: 1215280 bytes, 20088936 total
- age 6: 555136 bytes, 20644072 total
- age 7: 542128 bytes, 21186200 total
- age 8: 336520 bytes, 21522720 total
- age 9: 173096 bytes, 21695816 total
- age 10: 117656 bytes, 21813472 total
- age 11: 44280 bytes, 21857752 total
- age 12: 45728 bytes, 21903480 total
- age 13: 53928 bytes, 21957408 total
- age 14: 58128 bytes, 22015536 total
- age 15: 56704 bytes, 22072240 total
, 1.2324057 secs]
[Parallel Time: 39.1 ms, GC Workers: 25]
[GC Worker Start (ms): Min: 3964575316.2, Avg: 3964575317.5, Max: 3964575318.7, Diff: 2.4]
[Ext Root Scanning (ms): Min: 9.0, Avg: 12.4, Max: 16.1, Diff: 7.0, Sum: 311.0]
[Update RS (ms): Min: 2.1, Avg: 8.2, Max: 16.4, Diff: 14.3, Sum: 206.0]
[Processed Buffers: Min: 24, Avg: 149.3, Max: 246, Diff: 222, Sum: 3732]
[Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.4]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[Object Copy (ms): Min: 6.9, Avg: 12.5, Max: 15.5, Diff: 8.6, Sum: 311.5]
[Termination (ms): Min: 2.6, Avg: 3.9, Max: 4.7, Diff: 2.1, Sum: 96.9]
[Termination Attempts: Min: 179, Avg: 384.9, Max: 448, Diff: 269, Sum: 9622]
[GC Worker Other (ms): Min: 0.0, Avg: 0.5, Max: 0.7, Diff: 0.7, Sum: 12.4]
[GC Worker Total (ms): Min: 36.3, Avg: 37.5, Max: 38.7, Diff: 2.4, Sum: 938.3]
[GC Worker End (ms): Min: 3964575354.9, Avg: 3964575355.0, Max: 3964575355.1, Diff: 0.1]
[Code Root Fixup: 0.1 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.6 ms]
[Other: 1192.6 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 1180.2 ms]
[Ref Enq: 0.1 ms]
[Redirty Cards: 0.4 ms]
[Humongous Register: 1.8 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 0.3 ms]
[Eden: 2256.0M(2256.0M)->0.0B(2256.0M) Survivors: 48.0M->48.0M Heap: 5705.3M(45.0G)->3439.2M(45.0G)]
[Times: user=1.86 sys=0.00, real=1.23 secs]
2018-02-26T21:46:07.880+0000: 3964576.545: Total time for which application threads were stopped: 1.2492396 seconds, Stopping threads took: 0.0013324 seconds
2018-02-26T21:46:41.430+0000: 3964610.095: Total time for which application threads were stopped: 0.0331942 seconds, Stopping threads took: 0.0043586 seconds
2018-02-26T21:46:44.246+0000: 3964612.910: [GC pause (G1 Evacuation Pause) (young)
您大部分时间都花在参考文献处理上。几乎所有的 GC 时间。
[参考过程：1180.2 毫秒]。
引用处理阶段涉及处理任何由 STW 引用处理器发现的 soft/weak/final/phantom/JNI 引用。
Eden(Young Gen) 内存由 G1 收集器在每次 GC 上收集的 Heuristics 确定。它根据 GC 历史调整 Young Gen，使最大暂停时间与您的目标暂停时间相匹配。如果你的目标暂停时间很短，伊甸园内存可以很短。
如果不设置，目标暂停时间默认为200ms。我猜是因为您的 Ref Proc 时间太大，G1 使您的伊甸园区域大小保持较小，以便为您提供最佳的暂停时间。
您应该调查堆上有哪些引用，看看您的应用程序产生这么多引用是否正常。解决这个问题，你的 Eden 内存应该会自动增加。