barbitoff programmer`s blog

Здесь я публикую заметки из программерской жизни: грабли, на которые мне случилось наступить, проблемы, для которых было найдено элегантное (или не очень) решение, а также все, с чем мне пришлось столкнуться и чем хотелось бы поделиться =)
PS Если хотите меня поблагодарить - на странице есть 3 места, чтобы это сделать =)

понедельник, 6 апреля 2015 г.

Постоянные беспричинные Full GC

Проблема

Есть сервер приложений, на котором крутится несколько достаточно сложных Java-приложений, использующих множество различных фреймворков. Под определенной нагрузкой сервер начинает очень сильно тормозить, отклик на http-запросы падает с долей секунды до нескольких десятков секунд.
Было включено расширенное логирование сборщика мусора ключами:
-Xloggc:\some\path\to\gc.log -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCDateStamps
Настройки памяти следующие:
-Xms3072m -Xmx3072m -XX:MaxPermSize=512m
Соотношение young- / tenored-разделов в хипе - по-умолчанию (т.е. параметры -XX:NewSize / -XX:MaxNewSize / -XX:NewRatio не используются) , сборщики также используются по-умолчанию.
В итоге в gc.log появилась интересная информация:
...
51222.509: [GC [PSYoungGen: 6003K->128K(995648K)] 418005K->412130K(3092800K), 0.0124632 secs] [Times: user=0.02 sys=0.00, real=0.02 secs]

51222.522: [Full GC (System) [PSYoungGen: 128K->0K(995648K)] [PSOldGen: 412002K->412004K(2097152K)] 412130K->412004K(3092800K) [PSPermGen: 160113K->160113K(160640K)], 1.8001088 secs] [Times: user=1.79 sys=0.00, real=1.79 secs]

51224.324: [GC [PSYoungGen: 106K->96K(992448K)] 412110K->412100K(3089600K), 0.0097823 secs] [Times: user=0.06 sys=0.00, real=0.02 secs]

51224.334: [Full GC (System) [PSYoungGen: 96K->0K(992448K)] [PSOldGen: 412004K->412004K(2097152K)] 412100K->412004K(3089600K) [PSPermGen: 160113K->160113K(160640K)], 1.7753052 secs] [Times: user=1.78 sys=0.00, real=1.78 secs]

51226.115: [GC [PSYoungGen: 9595K->128K(1001792K)] 421600K->412132K(3098944K), 0.0120281 secs] [Times: user=0.05 sys=0.00, real=0.02 secs]

51226.128: [Full GC (System) [PSYoungGen: 128K->0K(1001792K)] [PSOldGen: 412004K->409356K(2097152K)] 412132K->409356K(3098944K) [PSPermGen: 160113K->160113K(160576K)], 1.7348557 secs] [Times: user=1.73 sys=0.00, real=1.73 secs]

51227.942: [GC [PSYoungGen: 20781K->6387K(998784K)] 430137K->415744K(3095936K), 0.0125255 secs] [Times: user=0.06 sys=0.00, real=0.02 secs]

51227.955: [Full GC (System) [PSYoungGen: 6387K->0K(998784K)] [PSOldGen: 409356K->415263K(2097152K)] 415744K->415263K(3095936K) [PSPermGen: 160120K->160120K(160576K)], 1.7130215 secs] [Times: user=1.72 sys=0.00, real=1.72 secs]
...
Т.е. видим следующую ситуацию: примерно раз в 2 секунды срабатывает сначала обычный GC, а вслед за ним - Full GC. Причем объективных причин сборки мусора нет: на момент начала работы GC в young generation свободно около 98-99% процентов памяти, в old generation - около 75%, в permament geneartion - 70% (от максимальных 512m). 

Решение

Сказать по правде, ситуация поставила в ступор. Благо, достаточно быстро нагуглилась схожая проблема: http://basisondemand.com/as_java/how_we_resolved_the_issue_of_frequent_full_gc_that_was_running_every_03_seconds_verbose_systemgc. Там парни предположили, что причина такого поведения - явные вызовы System.gc() где-то в коде. Благо, этот вызов можно игнорировать, если установить следующий ключ:
-XX:+DisableExplicitGC
В моем случае это решение также сработало.

ЗЫ Кстати, вот хорошая статейка по сборке мусора в Java: http://www.oracle.com/technetwork/java/javase/gc-tuning-6-140523.html.

Комментариев нет:

Отправить комментарий