Причина внезапной длительной паузы в GC

Question

Я запускаю приложение в течение одного дня, используя тестовую партию в цикле.Одна тестовая партия выполняется в течение 4 часов, и я запускаю ту же тестовую партию для 30 циклов, и в итоге она работает ровно в течение одного дня, и внезапно в конце дня на 20 секунд наблюдается резкий скачок.

Я уже настроил GC и вижу прикрепленную картинку,

Внезапно к концу дня я увидел шипв паузе GC

1) Почему в GC произошел внезапный всплеск?ПРИМЕЧАНИЕ. Я выполняю один и тот же тест в цикле, и каждый тест выполняется в течение 4 часов, и внезапно в 10-м цикле возникает скачок?
2) Каковы могут быть его возможности и как его отслеживать?

Соответствующая часть журнала ГХ:

{Heap before GC invocations=5451 (full 0):
 garbage-first heap   total 8388608K, used 4872081K [0x00000005c0000000, 0x00000005c0404000, 0x00000007c0000000)
  region size 4096K, 614 young (2514944K), 19 survivors (77824K)
 Metaspace       used 38562K, capacity 39526K, committed 39888K, reserved 1085440K
  class space    used 4096K, capacity 4277K, committed 4352K, reserved 1048576K
2018-05-22T16:36:06.323+0000: 85842.817: [GC pause (G1 Evacuation Pause) (young)
Desired survivor size 161480704 bytes, new threshold 15 (max 15)
- age   1:    4507344 bytes,    4507344 total
- age   2:   16799960 bytes,   21307304 total
- age   3:   15901408 bytes,   37208712 total
- age   4:   16061376 bytes,   53270088 total
, 20.3599018 secs]
   [Parallel Time: 16841.9 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 85846284.8, Avg: 85846414.4, Max: 85846458.0, Diff: 173.2]
      [Ext Root Scanning (ms): Min: 787.2, Avg: 1628.6, Max: 2662.7, Diff: 1875.5, Sum: 13029.0]
      [Update RS (ms): Min: 13521.3, Avg: 14190.0, Max: 14460.0, Diff: 938.7, Sum: 113520.2]
         [Processed Buffers: Min: 11, Avg: 27.8, Max: 50, Diff: 39, Sum: 222]
      [Scan RS (ms): Min: 165.8, Avg: 291.7, Max: 401.5, Diff: 235.7, Sum: 2333.4]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.7]
      [Object Copy (ms): Min: 78.1, Avg: 279.5, Max: 1353.4, Diff: 1275.3, Sum: 2235.6]
      [Termination (ms): Min: 0.0, Avg: 3.8, Max: 5.0, Diff: 5.0, Sum: 30.6]
         [Termination Attempts: Min: 1, Avg: 5.1, Max: 15, Diff: 14, Sum: 41]
      [GC Worker Other (ms): Min: 0.0, Avg: 317.6, Max: 1258.0, Diff: 1258.0, Sum: 2541.0]
      [GC Worker Total (ms): Min: 16667.6, Avg: 16711.3, Max: 16841.3, Diff: 173.7, Sum: 133690.5]
      [GC Worker End (ms): Min: 85863125.6, Avg: 85863125.8, Max: 85863126.2, Diff: 0.6]
   [Code Root Fixup: 1.2 ms]
   [Code Root Purge: 0.0 ms]
   [String Dedup Fixup: 5.9 ms, GC Workers: 8]
      [Queue Fixup (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Table Fixup (ms): Min: 0.0, Avg: 1.6, Max: 5.9, Diff: 5.9, Sum: 12.6]
   [Clear CT: 1.1 ms]
   [Other: 3509.7 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 30.7 ms]
      [Ref Enq: 2.4 ms]
      [Redirty Cards: 4.0 ms]
      [Humongous Register: 2339.6 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 3.5 ms]
   [Eden: 2380.0M(2380.0M)->0.0B(720.0M) Survivors: 76.0M->96.0M Heap: 4757.9M(8192.0M)->2395.9M(8192.0M)]
Heap after GC invocations=5452 (full 0):
 garbage-first heap   total 8388608K, used 2453393K [0x00000005c0000000, 0x00000005c0404000, 0x00000007c0000000)
  region size 4096K, 24 young (98304K), 24 survivors (98304K)
 Metaspace       used 38562K, capacity 39526K, committed 39888K, reserved 1085440K
  class space    used 4096K, capacity 4277K, committed 4352K, reserved 1048576K
}
 [Times: user=33.60 sys=5.40, real=20.36 secs] 
2018-05-22T16:36:26.684+0000: 85863.177: Total time for which application threads were stopped: 23.3452204 seconds, Stopping threads took: 1.5114697 seconds
2018-05-22T16:36:26.685+0000: 85863.179: [GC concurrent-string-deduplication, 6912.0B->64.0B(6848.0B), avg 88.1%, 0.0000411 secs]

Полные журналы ГХ здесь

Конфигурация ГХ:

-XX:+UseG1GC
-XX:ParallelGCThreads=8
-XX:+ExplicitGCInvokesConcurrent
-XX:+ParallelRefProcEnabled
-XX:+UseStringDeduplication
-XX:+UnlockExperimentalVMOptions
-XX:G1NewSizePercent=10
-XX:G1MaxNewSizePercent=30
-XX:MaxGCPauseMillis=400

Java версия - 8

Answer 1

У меня есть маленький вопрос, сколько ядер или виртуальных процессоров у вас есть на этой машине?

Извините, я не понял, что у вас 8 ядер, но мне не хватает значения Xms и Xmx., но я полагаю, что вы используете одно и то же значение, чтобы избежать изменения размера.

Исходя из моего опыта, я бы предпочел использовать параллельный сборщик мусора на вашем месте.Есть ли у вас особые причины для использования GC1?

Я имею в виду, я бы использовал GC1, если бы у меня была машина с большими возможностями, чем у вас, я говорю о количестве ядер и куче, которую вы должны выделить,В соответствии с Oracle :

Сборщик мусора в первую очередь (G1) - это сборщик мусора серверного типа, предназначенный для многопроцессорных машин с большим объемом памяти.

Более того, я не могу видеть конфигурацию для числа параллельных потоков, используемых параллельными фазами, поэтому я могу представить, что для тех фаз, которые вы используете 2 потока, согласно этой информации для Java 9 .К сожалению, я не смог найти значение по умолчанию для Java 8.

Максимальное количество потоков, используемых для одновременной работы.По умолчанию это значение равно -XX: ParallelGCThreads, деленное на 4

. Таким образом, я думаю, что только с двумя потоками для параллельной фазы существует больше плавающего мусора, который должен обрабатываться во время обновлениязапомненные наборы (обновление RS) и, возможно, это объясняет, почему этот этап занимает много времени.

С учетом количества ядер, которые есть у машины, и памяти, используемой вашей JVM, я бы порекомендовал вам попробовать параллельный коллектор сэти флаги, чтобы увидеть, сможете ли вы избежать этой длинной паузы

-XX:+UseParallelGC -Xms8192M -Xmx8192M -Xmn3072M -XX:SurvivorRatio=3 -Xss1024K -XX:MetaspaceSize=1024M -XX:MaxMetaspaceSize=1024M -XX:TargetSurvivorRatio=90 -XX:ParallelGCThreads=8 -XX:+AlwaysPreTouch -XX:+ParallelRefProcEnabled -XX:-UseAdaptiveSizePolicy -XX:+DisableExplicitGC -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/some/path/ -verbose:gc -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps -XX:+PrintGCDetails -Xloggc:/some/path/gc.log -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=10 -XX:GCLogFileSize=10M

И последнее, но не менее важное: помните, что с G1GC вы должны избегать полных сборщиков мусора в максимально возможной степени, поскольку они выполняются с использованием только одного потока, как вы можете видеть здесь

Третий тип коллекций, с которыми вы можете столкнуться, и тот, от которого мы работаем, это Full GC.В G1 Full GC представляет собой однопоточную паузу Stop The World (STW), которая эвакуирует и уплотняет все регионы.Есть три важных элемента информации, которые вы можете получить из журналов Full GC

Я думаю, что это будет улучшено в Java 10

С уважением,

RCC