Почему Java G1 gc тратит так много времени на сканирование RS?

В настоящее время я оцениваю сборщик мусора G1 и его производительность для нашего приложения. Глядя на gc-log, я заметил, что у многих коллекций очень длинные фазы "Scan RS":

7968.869: [GC pause (mixed), 10.27831700 secs]
   [Parallel Time: 10080.8 ms]
   (...)
      [Scan RS (ms):  4030.4  4034.1  4032.0  4032.0
       Avg: 4032.1, Min: 4030.4, Max: 4034.1, Diff:   3.7]
      [Object Copy (ms):  6038.5  6033.3  6036.7  6037.1
       Avg: 6036.4, Min: 6033.3, Max: 6038.5, Diff:   5.2]
   (...)
    [Eden: 19680M(19680M)->0B(20512M) Survivors: 2688M->2624M Heap:
     75331M(111904M)->51633M(115744M)]
 [Times: user=40.49 sys=0.02, real=10.28 secs]

Все удаленные записи в строках журнала показывают время выполнения в однозначных мс.

Я думаю, что большую часть времени следует уделять копированию, верно? В чем может быть причина того, что Scan RS занимает так много времени? Есть идеи, как настроить G1-настройки? JVM была начата с

-Xms40960M -Xmx128G -XX:+UseG1GC -verbose:gc -XX:+PrintGCDetails -Xloggc:gc.log

Редактировать: О, я забыл... Я использую Java 7u25

Обновление: я заметил две другие странные вещи:

16187.740: [GC concurrent-mark-start]
16203.934: [GC pause (young), 2.89871800 secs]
(...)
16218.455: [GC pause (young), 4.61375100 secs]
(...)
16237.441: [GC pause (young), 4.46131800 secs]
(...)
16257.785: [GC pause (young), 4.73922600 secs]
(...)
16275.417: [GC pause (young), 3.87863400 secs]
(...)
16291.505: [GC pause (young), 3.72626400 secs]
(...)
16307.824: [GC pause (young), 3.72921700 secs]
(...)
16325.851: [GC pause (young), 3.91060700 secs]
(...)
16354.600: [GC pause (young), 5.61306000 secs]
(...)
16393.069: [GC pause (young), 17.50453200 secs]
(...)
16414.590: [GC concurrent-mark-end, 226.8497670 sec]

Параллельный прогон GC продолжается, пока выполняются параллельные прогоны. Я не уверен, что это так, но мне это кажется неправильным. Правда, это крайний пример, но я вижу такое поведение по всему журналу.

Другое дело, что мой процесс JVM вырос до 160g. Учитывая размер кучи 128g, это довольно большие накладные расходы. Это следовало ожидать, или G1 утечка памяти? Есть идеи, как это выяснить?

PS: я не совсем уверен, должен ли я задавать новые вопросы для обновлений... если кто-то из вас думает, что это будет полезно, скажите мне;)

Обновление 2: я думаю, что у G1 действительно может быть утечка памяти: http://printfdebugger.tumblr.com/post/19142660766/how-i-learned-to-love-cms-and-had-my-heart-broken-by-g1 Поскольку сейчас это соглашение, я не собираюсь тратить больше времени на игру с этим. То, что я еще не пробовал, - это настройка размера региона (-XX:G1HeapRegionSize) и снижение занятости кучи (-XX:InitiatingHeapOccupancyPercent).

Источник

1 ответ

Посмотрим.

1 - Первые подсказки

Похоже, что ваш GC был настроен на использование 4 потоков (или у вас есть 4 виртуальных ЦП, но это вряд ли учитывая размер кучи). Это довольно мало для кучи 128 ГБ, я ожидал большего.

События GC, кажется, происходят с интервалом в 25 с. Однако в предоставленной вами выдержке из журнала не указано количество обработанных регионов.

=> Вы случайно указали время паузы для G1GC (-XX:MaxGCPauseMillis=N)

2 - длительное время сканирования RSet

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

Итак, у нас есть еще один вопрос:

=> Сколько регионов было обработано во время этой конкретной коллекции (т.е. насколько велик CSet)

3 - длительное время копирования объекта

Время копирования, как следует из названия, - это время, затрачиваемое каждым рабочим потоком на копирование живых объектов из областей в наборе сбора в другие регионы.

Такое длительное время копирования может указывать на то, что было обработано много регионов, и что вы можете уменьшить это число. Можно также предложить обмен, но это маловероятно, учитывая ваши пользовательские / реальные значения в конце журнала.

4 - что теперь делать

Вы должны проверить в журнале GC количество регионов, которые были обработаны. Соотнесите это число с размером региона и определите объем памяти, который был отсканирован.

Затем вы можете установить меньшее время паузы (например, до 500 мс, используя -XX:MaxGCPauseMillis=500). Это будет

  • увеличить количество событий GC,
  • уменьшить количество свободной памяти за цикл GC
  • уменьшить паузы STW во время YGC

Надеюсь, это поможет!

Источники:

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