G1GC не автоматически настраивает NewSize (длительное время GC)

Мое приложение - G1GC с объемом памяти 45 ГБ. Я вижу длинные времена GC. В ходе расследования я обнаружил, что только 5% кучи для молодого поколения, которая очень часто пополняется, приводит к частым сборам. Более того, хотя большая часть кучи пуста, GC не корректирует "NewSize", и он постоянен на уровне 5%, а большая часть кучи зарезервирована (но не используется) для "Заготовленной генерации". Документация G1GC предполагает, что NewSize корректируется автоматически во время каждой коллекции GC.

https://docs.oracle.com/javase/9/gctuning/garbage-first-garbage-collector.htm

Вопрос:-

  1. Значения по умолчанию для "G1MaxNewSizePercent" и G1NewSizePercent составляют 60% и 5% соответственно, почему GC не регулирует размер автоматически и почему он застрял на 5%. http://www.oracle.com/technetwork/articles/java/g1gc-1984535.html
  2. Нужно ли делать что-то особенное для GC, чтобы начать автоматическую настройку?
  3. Почему большая часть кучи была зарезервирована для штатного поколения на первом месте?

Ниже приведен снимок GCViewer

GC зритель

Флаги 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 LOG снимок

     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)
Источник

1 ответ

Решение

Вы проводите большую часть времени в обработке ссылок. Почти все ваше время GC.

[Ref Proc: 1180,2 мс].

Этап обработки ссылок включает обработку любых мягких / слабых / окончательных / фантомных /JNI-ссылок, обнаруженных эталонным процессором STW.

Память Eden(Young Gen) определяется эвристикой, собранной коллектором G1 на каждом GC. Он настраивает Young Gen в соответствии с историей GC так, чтобы максимальное время паузы соответствовало вашему целевому времени паузы. Если целевое время паузы короткое, память eden может быть короткой.

Если ничего не установлено, целевое время паузы по умолчанию составляет 200 мс. Я полагаю, потому что ваше время Ref Proc очень велико, G1 сохраняет размер вашего региона eden маленьким, чтобы дать вам максимально возможное время паузы.

Вы должны исследовать, какие ссылки находятся в куче, и посмотреть, нормально ли это для вашего приложения для создания этих многочисленных ссылок. Исправьте это, и ваша память Eden должна увеличиться автоматически.

Источник
Другие вопросы по тегам