Нечастые длинные GC паузы с G1GC

Question

Я испытываю нечастые длительные паузы GC с алгоритмом G1GC - более 30 секунд в течение месяца. Как только это произойдет, я перезапущу свою службу, и эта задержка больше не повторится в течение следующего 1 месяца.

Я прилагаю журнал GC.

2016-06-15T02:30:17.407-0400: 1702455.276: Total time for which application threads were stopped: 0.2900480 seconds
2016-06-15T02:30:25.509-0400: 1702463.378: Total time for which application threads were stopped: 0.0018900 seconds
2016-06-15T02:30:29.817-0400: 1702467.686: [GC pause (young)
Desired survivor size 7340032 bytes, new threshold 15 (max 15)
- age   1:    1903912 bytes,    1903912 total
- age   2:     641440 bytes,    2545352 total
- age   3:     455856 bytes,    3001208 total
- age   4:     563544 bytes,    3564752 total
- age   5:    1873368 bytes,    5438120 total
- age   6:     326024 bytes,    5764144 total
- age   7:     299144 bytes,    6063288 total
- age   8:     304632 bytes,    6367920 total
- age   9:     273160 bytes,    6641080 total
- age  10:     309152 bytes,    6950232 total
- age  11:     156824 bytes,    7107056 total
- age  12:     135064 bytes,    7242120 total
, 0.1199490 secs]
   [Parallel Time: 118.2 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 1702467686.7, Avg: 1702467686.8, Max: 1702467686.9, Diff: 0.2]
      [Ext Root Scanning (ms): Min: 18.4, Avg: 20.2, Max: 24.6, Diff: 6.2, Sum: 80.7]
      [Update RS (ms): Min: 75.5, Avg: 79.5, Max: 80.8, Diff: 5.3, Sum: 317.8]
         [Processed Buffers: Min: 52, Avg: 61.0, Max: 70, Diff: 18, Sum: 244]
      [Scan RS (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.3]
      [Object Copy (ms): Min: 17.7, Avg: 18.1, Max: 18.6, Diff: 0.8, Sum: 72.3]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [GC Worker Other (ms): Min: 0.1, Avg: 0.1, Max: 0.1, Diff: 0.0, Sum: 0.4]
      [GC Worker Total (ms): Min: 117.8, Avg: 117.9, Max: 118.0, Diff: 0.2, Sum: 471.6]
      [GC Worker End (ms): Min: 1702467804.7, Avg: 1702467804.7, Max: 1702467804.7, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Clear CT: 0.2 ms]
   [Other: 1.6 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.3 ms]
      [Ref Enq: 0.0 ms]
      [Free CSet: 0.4 ms]
   [Eden: 100.0M(100.0M)->0.0B(100.0M) Survivors: 9216.0K->9216.0K Heap: 2164.6M(2198.0M)->2065.5M(2198.0M)]
 [Times: user=0.48 sys=0.00, real=37.62 secs]
2016-06-15T02:31:07.438-0400: 1702505.307: Total time for which application threads were stopped: 37.6223210 seconds

2016-06-15T02:31:07.443-0400: 1702505.312: Total time for which application threads were stopped: 0.0034690 seconds
2016-06-15T02:31:07.446-0400: 1702505.315: Total time for which application threads were stopped: 0.0018140 seconds
2016-06-15T02:31:07.451-0400: 1702505.320: Total time for which application threads were stopped: 0.0020130 seconds
2016-06-15T02:31:07.453-0400: 1702505.322: Total time for which application threads were stopped: 0.0015850 seconds

Я использую ниже флаги G1GC:

-server -d64 -verbose:gc -Xms2g -Xmx4g -XX:+UseG1GC 
-XX:MaxGCPauseMillis=1500 -XX:G1HeapRegionSize=2 
-XX:+PrintFlagsFinal -XX:ParallelGCThreads=4 -XX:ConcGCThreads=2 
-XX:PermSize=64m -XX:MaxPermSize=256m -XX:+DisableExplicitGC 
-XX:+PrintGCDateStamps -XX:+DoEscapeAnalysis -XX:+PrintTenuringDistribution 
-XX:+PrintGCTimeStamps -XX:+PrintGCDetails 
-XX:+PrintGCApplicationStoppedTime -XX:+HeapDumpOnOutOfMemoryError 
-XX:HeapDumpPath=$PP_HOME -XX:+UseCompressedOops -XX:+AggressiveOpts"

Конфигурация машины:

Red Hat Enterprise Linux Server release 5.11 
Dual core CPU
java version "1.7.0_45"
Java(TM) SE Runtime Environment (build 1.7.0_45-b18)
Java HotSpot(TM) 64-Bit Server VM (build 24.45-b08, mixed mode)

Как мы можем найти причину для длинных GC из приведенных выше утверждений?

Answer 1

Обновите до последней версии Java 8 - вам не следует использовать G1 с Java 7, потому что он не был готов к работе в то время. Шансы очень хорошие, вы попали в исправленную ошибку. Да, есть способы получить OpenJDK 8 на RHEL 5. Да, ваше приложение значительно увеличится в скорости.

Также это:

-XX: MaxGCPauseMillis = 1500

и это:

-Xms2g -Xmx4g

Можно предположить, что вы не работаете в среде с большой кучей и малой задержкой, для которой предназначена G1. С такой старой JRE вам может быть лучше использовать значение по умолчанию (ParallelGC) и, возможно, настроить несколько параметров, чтобы сократить время паузы (пробег может отличаться). Или CMS, которая была более зрелой, и с настройкой может быть достаточно стабильной.

И ради всего святого, если ваше приложение достаточно критично, чтобы 30-секундная пауза GC каждый месяц была проблемой, то вы, вероятно, можете позволить себе систему с RHEL 7 и более, чем двухъядерные.

Answer 2

Реальное время здесь составляет 37 секунд, тогда как время пользователя составляет 0,48 секунды, а время ядра — 0 секунд. То есть всем потокам GC потребовалось 37 секунд, чтобы использовать 0,48 секунды процессорного времени. IOW, потоки GC сильно испытывают недостаток ресурсов ЦП. Шумный сосед?