G1 GC - чрезвычайно длительное время завершения

Question

G1 GC иногда проводит много времени в фазе завершения. Как вы можете видеть, в то время как GC среднее время работы 442,9, завершение - 327,3. Это высокопроизводительное приложение с низкой задержкой, которое обрабатывает много сообщений. Данные обработки событий должны быть собраны yong gc. Обычно обработка события занимает не более 150 мс.

HW: x24 Intel (R) Xeon (R) CPU E5-2620 v3 @ 2,40 ГГц, 32 ГБ памяти, 8 ГБ памяти бесплатно Параметры JVM: -server -XX:+UseG1GC -XX:MaxGCPauseMillis=60 -XX:ParallelGCThreads=24 -Xmx12g -Xms12g -Xss256k Linux 2.6.32-696.6.3.el6.x86_64 Java-версия "1.8.0_102"

Обычно G1 устанавливает новый размер на 7 Гб, пауза молодого GC - 50 мс, время завершения - всего 6 мс, интервал между коллекциями - 3 с.

Если приложение генерирует много долгоживущих объектов, то пауза молодого возраста может увеличиться, что также приводит к уменьшению размера молодого GC. Но в этом случае время завершения остается неизменным. И мне интересно, почему время завершения может увеличиться так драматично.

Обратите внимание также на большое системное время для этой паузы. Обычно системное время для паузы GC составляет 0-10 мс. Для этого это 1 сек.

2017-08-23T13:21:37.690-0400: 1509.022: [GC pause (G1 Evacuation Pause) (young), 0.4474119 secs]
   [Parallel Time: 443.2 ms, GC Workers: 24]
      [GC Worker Start (ms): Min: 1509022.9, Avg: 1509023.0, Max: 1509023.4, Diff: 0.4]
      [Ext Root Scanning (ms): Min: 2.1, Avg: 22.5, Max: 90.4, Diff: 88.3, Sum: 539.7]
      [Update RS (ms): Min: 0.0, Avg: 2.2, Max: 5.0, Diff: 5.0, Sum: 54.0]
         [Processed Buffers: Min: 0, Avg: 24.7, Max: 67, Diff: 67, Sum: 592]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.7]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 26.1, Avg: 106.1, Max: 435.6, Diff: 409.6, Sum: 2545.3]
      [Termination (ms): Min: 0.0, Avg: 312.0, Max: 327.3, Diff: 327.3, Sum: 7488.6]
         [Termination Attempts: Min: 1, Avg: 1.5, Max: 4, Diff: 3, Sum: 36]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.0, Sum: 0.6]
      [GC Worker Total (ms): Min: 442.5, Avg: 442.9, Max: 443.0, Diff: 0.5, Sum: 10628.9]
      [GC Worker End (ms): Min: 1509465.9, Avg: 1509465.9, Max: 1509465.9, Diff: 0.1]
   [Code Root Fixup: 0.4 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.3 ms]
   [Other: 3.6 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 1.5 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.4 ms]
      [Humongous Register: 0.2 ms]
      [Humongous Reclaim: 0.1 ms]
      [Free CSet: 0.3 ms]
   [Eden: 476.0M(476.0M)->0.0B(556.0M) Survivors: 136.0M->56.0M Heap: 4480.6M(12.0G)->4016.3M(12.0G)]
 [Times: user=4.23 sys=1.08, real=0.45 secs]

Answer 1

У меня есть предложение. Иногда, когда в системе выполняются другие процессы, они сталкиваются с вашими работниками Java GC.

[Копия объекта (мс): мин: 26,1, среднее значение: 106,1, макс: 435,6, разница: 409,6, сумма: 2545,3] [Ext Root Scanning (мс): мин: 2,1, среднее значение: 22,5, макс: 90,4, разница: 88,3, Сумма: 539,7]

Из вышеприведенных журналов видно, что работники ГК выполняют непропорциональный объем работы. Это означает, что большинство потоков GC заканчивают рано, и некоторые из них все еще работают. Когда это происходит, завершенные темы пытаются украсть работу у других. Это отражается на времени прекращения. В результате время прекращения является не причиной, а просто побочным эффектом.

[Завершение (мс): Мин: 0,0, Ср.: 312,0, Макс: 327,3, Разница: 327,3, Сумма: 7488,6]

У вас 24-ядерный компьютер и 24 рабочих потока GC. Если существуют другие процессы или действия системы, для которых требуются ресурсы ЦП, есть вероятность, что некоторые из рабочих GC запланированы поздно из-за конфликта.

Стоит попытаться уменьшить количество тем до 18 и дать ему шанс.

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