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

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

https://docs.oracle.com/javase/9/gctuning/garbage-first-garbage-collector.htm#JSGCT-GUID-C268549C-7D95-499C-9B24-A6670B44E49C

Вопрос:-

  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

Снимок журнала сборщика мусора

     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)

java jvm garbage-collection heap-memory g1gc
person maneet    schedule 27.02.2018    source источник

Ответы (1)


arrow_upward
1
arrow_downward

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

[Ref Proc: 1180,2 мс] .

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

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

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

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

person Laxman Prabhu    schedule 27.02.2018
comment
Вы должны попробовать JDK 11. У нас была такая же проблема со ссылками, и проблема полностью исчезла с JDK 11. - person cocorossello; 15.10.2018