Tomcat full GC каждые 2 минуты в течение первых 5 часов работы приложения

Question

У нас есть кластер серверов Tomcat, который используется на очень большом веб-сайте. Мы заметили, что в течение первых 5-6 часов после перезагрузки приложения Full GC будет запускаться каждые 2 минуты, останавливая приложение на 5-20 секунд. Через 5-6 часов полный сборщик мусора больше не будет работать, пока кот не будет перезапущен. Уровень трафика не является фактором, который мы пройдем в наши часы пик без проблем.

Все серверы являются двухъядерными и имеют 32 ГБ ОЗУ с процессором Centos 5. Наши java-опции используются ежедневно, но вот настройки, которые соответствуют образцу журнала GC ниже:

-server -Xmx27g -Xms27g  -XX:+DisableExplicitGC -XX:+UseConcMarkSweepGC -XX:+PrintTenuringDistribution  -Dsun.rmi.dgc.client.gcInterval=900000 -Dsun.rmi.dgc.server.gcInterval=900000 -XX:NewSize=8g -XX:SurvivorRatio=16 -verbose:gc -XX:+PrintGCTimeStamps -XX:+PrintGCDetails

Регистрация образцов вскоре после перезагрузки приложения

191.955: [Full GC 191.958: [CMS: 1815877K->1158107K(19922944K), 3.0376720 secs] 3118102K->1158107K(27845568K), [CMS Perm : 83787K->46767K(83960K)], 3.0415080 secs] [Times: user=2.95 sys=0.10, real=3.04 secs]

215.501: [GC 215.504: [ParNew
Desired survivor size 238583808 bytes, new threshold 15 (max 15)
- age   1:   50457968 bytes,   50457968 total
: 7456799K->111048K(7922624K), 0.0617110 secs] 8614906K->1269155K(27845568K), 0.0661400 secs] [Times: user=0.68 sys=0.00, real=0.07 secs]

215.577: [GC 215.579: [ParNew
Desired survivor size 238583808 bytes, new threshold 15 (max 15)
- age   1:      66288 bytes,      66288 total
- age   2:   50219144 bytes,   50285432 total
: 114868K->66525K(7922624K), 0.0381810 secs] 1272975K->1224632K(27845568K), 0.0413630 secs] [Times: user=0.46 sys=0.00, real=0.04 secs]

236.177: [GC 236.180: [ParNew
Desired survivor size 238583808 bytes, new threshold 15 (max 15)
- age   1:   45071064 bytes,   45071064 total
- age   2:      26112 bytes,   45097176 total
- age   3:   34785960 bytes,   79883136 total
: 7523165K->110355K(7922624K), 0.0921350 secs] 8681272K->1268462K(27845568K), 0.0969290 secs] [Times: user=0.95 sys=0.01, real=0.10 secs]

...

316.456: [GC 316.459: [ParNew
Desired survivor size 238583808 bytes, new threshold 15 (max 15)
- age   1:   41430416 bytes,   41430416 total
- age   3:   22728376 bytes,   64158792 total
- age   5:   19599960 bytes,   83758752 total
- age   6:   21847616 bytes,  105606368 total
- age   7:   27667592 bytes,  133273960 total
- age   8:      10904 bytes,  133284864 total
- age   9:   31824256 bytes,  165109120 total
: 7650333K->215213K(7922624K), 0.1332630 secs] 8808440K->1373320K(27845568K), 0.1380590 secs] [Times: user=1.45 sys=0.01, real=0.14 secs]

338.851: [GC 338.854: [ParNew
Desired survivor size 238583808 bytes, new threshold 15 (max 15)
- age   1:   40678840 bytes,   40678840 total
- age   2:   27075936 bytes,   67754776 total
- age   4:   20399720 bytes,   88154496 total
- age   6:   19271008 bytes,  107425504 total
- age   7:   21655032 bytes,  129080536 total
- age   8:   27118800 bytes,  156199336 total
- age   9:      10904 bytes,  156210240 total
- age  10:   31747808 bytes,  187958048 total
: 7671853K->285541K(7922624K), 0.1456470 secs] 8829960K->1443648K(27845568K), 0.1503540 secs] [Times: user=1.62 sys=0.01, real=0.15 secs]

343.376: [Full GC 343.378: [CMS: 1158107K->1312570K(19922944K), 3.4129290 secs] 2884580K->1312570K(27845568K), [CMS Perm : 83964K->47203K(83968K)], 3.4168600 secs] [Times: user=3.87 sys=0.02, real=3.41 secs]

**Last Full GC**

20517.892: [GC 20517.898: [ParNew
Desired survivor size 238583808 bytes, new threshold 15 (max 15)
- age   1:   33948208 bytes,   33948208 total
- age   2:      88280 bytes,   34036488 total
- age   3:   19872472 bytes,   53908960 total
- age   4:   16072608 bytes,   69981568 total
- age   5:   15718712 bytes,   85700280 total
- age   6:   15771016 bytes,  101471296 total
- age   7:   16895976 bytes,  118367272 total
- age   8:   24233728 bytes,  142601000 total
: 7618727K->200950K(7922624K), 0.1728420 secs] 16794482K->9376705K(27845568K), 0.1822350 secs] [Times: user=2.21 sys=0.01, real=0.18 secs]

20526.469: [Full GC 20526.475: [CMS: 9175755K->9210800K(19922944K), 33.1161300 secs] 13632232K->9210800K(27845568K), [CMS Perm : 83967K->53332K(83968K)], 33.1254170 secs] [Times: user=33.12 sys=0.02, real=33.12 secs]


**Log samples after Full GC no longer runs**

74412.335: [GC 74412.340: [ParNew
Desired survivor size 238583808 bytes, new threshold 11 (max 15)
- age   1:   43614032 bytes,   43614032 total
- age   2:   41194144 bytes,   84808176 total
- age   3:   27392888 bytes,  112201064 total
- age   5:   22753896 bytes,  134954960 total
- age   7:   24439608 bytes,  159394568 total
- age   8:   24015704 bytes,  183410272 total
- age   9:   24080848 bytes,  207491120 total
- age  10:   24715800 bytes,  232206920 total
- age  11:   21844024 bytes,  254050944 total
: 7813778K->312911K(7922624K), 0.3329150 secs] 24426351K->16967791K(27845568K), 0.3416730 secs] [Times: user=3.69 sys=0.02, real=0.35 secs]

74445.007: [GC 74445.012: [ParNew
Desired survivor size 238583808 bytes, new threshold 11 (max 15)
- age   1:   42690688 bytes,   42690688 total
- age   2:   37055848 bytes,   79746536 total
- age   3:   37107464 bytes,  116854000 total
- age   4:   26223088 bytes,  143077088 total
- age   6:   22478672 bytes,  165555760 total
- age   8:   24259744 bytes,  189815504 total
- age   9:   23862672 bytes,  213678176 total
- age  10:   23911864 bytes,  237590040 total
- age  11:   24496888 bytes,  262086928 total
: 7769547K->344030K(7922624K), 0.3088470 secs] 24424428K->17021685K(27845568K), 0.3175830 secs] [Times: user=3.57 sys=0.01, real=0.32 secs]

74475.169: [GC 74475.175: [ParNew
Desired survivor size 238583808 bytes, new threshold 10 (max 15)
- age   1:   42011656 bytes,   42011656 total
- age   2:   33147608 bytes,   75159264 total
- age   3:   32391640 bytes,  107550904 total
- age   4:   36516584 bytes,  144067488 total
- age   5:   25940856 bytes,  170008344 total
- age   7:   22037464 bytes,  192045808 total
- age   9:   24130040 bytes,  216175848 total
- age  10:   23724672 bytes,  239900520 total
- age  11:   23329640 bytes,  263230160 total
: 7803184K->331046K(7922624K), 0.3091600 secs] 24480839K->17033619K(27845568K), 0.3179630 secs] [Times: user=3.56 sys=0.01, real=0.32 secs]

Если мы не перезапустим этот сервер на следующей неделе, он будет работать нормально.

Любая помощь будет принята с благодарностью.

РЕДАКТИРОВАТЬ: проблема будет отображаться только в случае повторного развертывания файла WAR. Самостоятельный перезапуск tomcat не вызывает этой проблемы.

Answer 1

Я бы попытался подключиться к одному из экземпляров с jvisualvm с установленным плагином VisualGC. Это покажет вам начальное распределение памяти для каждого пула в JVM и как оно меняется со временем. Существует также сэмплер памяти и профилировщик, который может быть полезен для определения состояния памяти в данный момент времени.

Также я не уверен, как вы пришли к параметрам JVM, которые вы используете (27Gb? Вы храните какой-то тип в кеше памяти в процессе?), Но я обычно начинаю с минимума, а затем настраиваю его только после выявления проблемы (например, для небольшого нового пула и т. д.). Просто попробуйте запустить что-то вроде:

-Xmx.. -verbose:gc -XX:+PrintGCTimeStamps -XX:+PrintGCDetails -XX:+PrintTenuringDistribution -Xloggc:/tmp/gc.log -XX:+HeapDumpOnOutOfMemoryError

На вашем объеме памяти java должен запускаться в режиме 'сервера' автоматически, и обычно он довольно хорош при динамическом выделении необходимых пулов памяти, если есть достаточно памяти.

Answer 2

Теория о том, что может происходить здесь, может исходить из статистики вашего ehcache.

Важно понимать, когда сборщик CMS запускает полный сборщик мусора.Следующее является верным [ Ссылка ]

В отличие от других сборщиков, сборщик CMS не запускает сборку старого поколения, когда старое поколение заполняется.Вместо этого он пытается запустить сбор достаточно рано, чтобы завершить его до того, как это произойдет

По сути, коллектор CMS принимает решение, когда запускать сборщик мусора на основе предыдущих уровней и как быстро он заполняется.,Это делает это, чтобы уменьшить время паузы в будущем.

Таким образом, когда вы видите все эти полные коллекции на ранних этапах после запуска приложения, JVM может определить, что для нее выделено много памяти.поэтому он часто запускает GC, чтобы защитить себя от достижения точки, в которой может произойти ошибка OOM.Если вы посмотрите на статистику ваших сборщиков мусора, первая полная коллекция начинается, когда израсходовано всего 1,8 ГБ из 27 ГБ, оставшихся в куче.Последнее происходит при 9,2 ГБ из 27 ГБ.

В этот момент, когда полные ГХ останавливают коллектор, определил, что он не находится под нагрузкой, и что распределение памяти несколько выровнялось.Возможно ли это через 5-6 часов, когда кеши приложений полностью заполнены и не выделяют гораздо больше памяти для своих нужд.Вы можете создать инструмент для просмотра статистики по попаданиям, промахам, размеру кэша с течением времени и таким образом отслеживать их размеры.В какой-то момент, когда они перестают расти, вы можете увидеть, соответствуют ли они времени остановки вашего GC.Лично я использовал только инструменты собственного производства, но вы можете попробовать что-то вроде инструмента EHCache Monitor , доступного на их сайте.

Кроме того, вы запускали журналы GC через любой инструмент, такой как Инструменты IBM Diagnostic или MAT для определения пропускной способности, которую ваше приложение получает за это время.С CMS коллектором не все паузы являются остановкой, поэтому некоторые паузы могут быть быстрее, чем вы думаете