JVM GC работает очень странно

Question

После попытки множества различных настроек JVM GC и проведения большого тестирования, когда у меня были проблемы с длинными крупными GC-паузами, я сейчас тестирую G1GC JVM GC. Помимо этого, я также собираю данные с монитором производительности, и только приложения, которые работают (помимо системных служб, ...), - это сервер GlassFish с моим приложением. Я не нашел ничего странного в протоколе мониторинга производительности (использование процессора составляет около 5-10%, и оно становится немного выше, когда происходит GC, память составляет около 60%, ...). Это теперь пятый день тестирования, и я заметил следующее:

До второй крупный (смешанный) GC не произошло все было хорошо (второстепенный GC было около 20мс долго, производительность GC был 160000M/с, ...) , Второй крупный GC занял около 2 секунд (длинные - первые заняли 150 мс, но не критические), и после этого младший GC намного дольше, чем раньше (см. Серые линии на изображении, которые представляют продолжительность младшего (молодого) GC) и производительность GC составляет всего 12000 М/с и все еще падает. Мне интересно, почему это происходит после второго основного GC, даже никаких других приложений не работает, а использование ЦП/памяти такое же, как раньше. Я не знаю, что здесь происходит. У меня также есть еще один вопрос: я выполняю те же тесты на разных ПК, у которых меньше оперативной памяти и более старых процессоров, а производительность GC составляет около 5000 М/с (младший GC составляет около 50-100 мс), что я считаю нормальным из-за худшего процессора и меньше оперативной памяти. Странно то, что основной GC еще не состоялся после 3 дней работы, и старое поколение растет намного медленнее, чем здесь, даже настройки одинаковы. Почему растет намного медленнее (здесь около 150 МБ за два дня, на втором ПК 80 МБ за три дня)? Спасибо за все ваши ответы, я не знаю, почему GC работает так ненормально (сначала она работает нормально, а затем ухудшается производительность).

EDIT: here является лог-файл полный GC, который был импортирован в GCViewer, а также детали события статистика из GCViewer:

Вход на 3-й основной GC:

2015-06-08T08:09:13.123+0200: 572815.533: [GC concurrent-root-region-scan-start] 
2015-06-08T08:09:13.139+0200: 572815.560: [GC concurrent-root-region-scan-end, 0.0271771 secs] 
2015-06-08T08:09:13.139+0200: 572815.560: [GC concurrent-mark-start] 
2015-06-08T08:09:16.302+0200: 572818.721: [GC concurrent-mark-end, 3.1612900 secs] 
2015-06-08T08:09:16.318+0200: 572818.729: [GC remark 572818.729: [Finalize Marking, 0.0002590 secs] 572818.729: [GC ref-proc, 0.4479462 secs] 572819.177: [Unloading, 3.2004912 secs], 3.6499382 secs] 
[Times: user=0.20 sys=0.08, real=3.64 secs] 

Опять же, реальная время было намного выше, чем пользователь + sys, фаза разгрузки заняла более 3 секунд.

Answer 1

Не могу дать вам подтвержденное объяснение без глубокого погружения в проблему, но давайте попробуем.

Вы, скорее всего, прочитали документацию G1 GC oracle и знаете, что этот сборщик был создан для приложений с огромной кучей. Он был разработан для уменьшения длительных пауз во время крупных сборщиков мусора.

В вашем примере мы видим, что незначительные GC-паузы увеличиваются сразу после завершения основного GC. Я не знаю внутренней механики G1, но интуиция говорит мне, что второй крупный GC был внутренним «сигналом» для G1, чтобы анализировать его производительность (достигает ли он целей пропускной способности/приостанавливает цели). Поэтому мне кажется, что после этого анализа G1 решил изменить свои внутренние параметры. Бьюсь об заклад, что длительная незначительная пауза GC указывает на то, что G1 увеличивает пространство для молодых поколений.

Почему он это сделал? Ну, большее молодое поколение уменьшит скорость продвижения до старшего поколения. Таким образом, пространство старого поколения будет заполнено медленнее. Скорее всего, G1 попытался предотвратить следующую серьезную паузу GC, которая будет длинной, как предыдущая (2 секунды).

Опять же, я не могу гарантировать, что все работает так, как я сказал без глубокого анализа, но я стараюсь дать вам указания.

Как насчет вашей «медленной» машины, которая работала 3 дня без серьезной паузы GC - это действительно сложно сказать, не зная конфигурации GC и того, как работает ваше приложение. Держу пари, что загрузка приложения была ниже.

Answer 2

Поскольку вы, похоже, беспокоитесь о временах паузы, я не вижу никаких целей времени паузы в ваших флагах JVM.

Вы можете установить время паузы времени через MaxGCMinorPauseMillis (только для несовершеннолетних) и MaxGCPauseMillis (в целом).

Это просто цели, сборщик может не встретить их по разным причинам. По умолчанию GC разрешено записывать только 1% вашего процессорного времени на GCing. Поэтому, если не удается выполнить свои цели, вы можете попробовать установить GCTimeRatio=19, чтобы предоставить ему 5% времени (обмен пропускной способностью на паузу).

---

Самая длинная пауза в журналах, кажется, это одна:

2015-06-05T09:14:51.909+0200: 317539.613: [GC remark 317539.613: [Finalize Marking, 0.0003625 secs] 317539.613: [GC ref-proc, 0.9890475 secs] 317540.602: [Unloading, 0.9739555 secs], 1.9643775 secs] 

Вы можете попробовать низведение контрольного времени обработки с -XX:+ParallelRefProcEnabled