Java-GC работает, но не восстанавливает ничего

В течение последних нескольких дней мы видим, что JVM на наших серверах переходит в состояние, когда они тратят 100% процессорного времени в GC OldGen, когда:

а. Они не нужны, потому что в куче осталось много места и

В. Они ничего не исправляют.

Я знаю, что они находятся в GC, просматривая трассировку стека и сопоставляя ThreadID в ProcessExplorer с теми, что находятся в дампе стека. Каждый поток GC занимает около 4% CPU.

Серверы работают с 16 гигабайтами (32-гигабайтная оперативная память) и имеют 8 ядер. Время обновления обычно составляет около 30 дней, при этом перезагрузки требуются только из-за требований исправления MS, но в настоящее время они сбой на отметке 20 дней.

Вот график продолжительности, шкала времени = 19 дней. http://i45.tinypic.com/257qalu.png

Вот зум на хвосте этого графика http://i48.tinypic.com/2duiccw.png

Как вы можете видеть, продолжительность резко возрастает.

Ниже приведен график использования кучи после GC. http://i48.tinypic.com/znna4h.png

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

У меня есть кучи кучи для каждого сервера, и ничто не выделяется как проблематичное. Есть несколько магазинов ehCache, я вижу наш код приложения, т.е. Просто "нормальный материал"

Самое большое изменение, которое мы внесли ~ 20 дней назад, заключалось в том, чтобы внедрить патч поставщика, который изменил внутренний кеш из неограниченного hashmap, который использовал жесткие ссылки (и очевидную утечку памяти) на тот, который состоял из мягких ссылок, и мне интересно, это причина, т.е. почему-то есть огромные накладные расходы при управлении этими мягкими ссылками после точки?

Есть ли у кого-нибудь идеи относительно того, где искать дальше, или кто-то может подтвердить мою мягкую справочную теорию?

Вот мой jvm.args:

java.args = -server -Xms16000m -Xmx16000m -Dsun.io.useCanonCaches = false -XX: MaxPermSize = 350m -Xloggc: e:/gcLogs/eRGCLogs.txt -verbose: gc -XX: + PrintGCDetails -XX: + PrintGCTimeStamps -XX: + PrintGCDateStamps -XX: + UseParallelGC -XX: + UseParallelOldGC -Dnet.sf.ehcache.sizeof.filter = D:/jo3/java_ehCacheOpenSource/sizeOfExclusions.config -Xbatch -Dcoldfusion.rootDir = {application.home}/../-Dcoldfusion.libPath = {application.home}/../lib -Dcoldfusion.classPath = {application.home}/../lib/updates, { application.home}/../Lib, {application.home}/../шлюз/Library/, {application.home}/../Wwwroot/WEB-INF/Flex/банки, {application.home}/../wwwroot/WEB-INF/cfform/jars,d:/jo3/java,d:/JO3/java_ehCacheOpenSource/,D:/jo3/java_ehCacheMonitorProbe

Мы находимся на Coldfusion, который похож на массивную структуру, которая находится поверх Java.

Версия JVM: 1.6.0_29

Как и требовалось, "нормальные" журналы GC выглядят следующим образом:

2013-03-19T22: 11: 36.670 + 1100: 1288665.702: [GC [PSYoungGen: 4695800K- > 471119K (4722112K)] 9301727K- > 5077046K (15644800K), 0.3584434 secs] [Times: user = 5.01 sys = 0.00, real = 0,36 с] [3]: [3]: [0]: [0] [0]: [ 0,38 с] 2013-03-19T22: 17: 46.749 + 1100: 1289035.760: [GC [PSYoungGen: 4654489K- > 517299K (4673792K)] 9260416K- > 5123227K (15596480K), 0.4130828 secs] [Times: user = 5.80 sys = 0.00, real = 0,41 сек] 2013-03-19T22: 21: 08.762 + 1100: 1289237.763: [GC [PSYoungGen: 4673779K- > 522660K (4738880K)] 9279707K- > 5143831K (15661568K), 0.4005516 secs] [Times: user = 5.97 sys = 0.00, real = 0,40 сек] 2013 г. - 23: 42,683 + 1100: 1289391,675: [GC [PSYoungGen: 4582628K- > 530998K (4590976K)] 9203799K- > 5186242K (15513664K), 0,4317352 сек.] [Время: пользователь = 6.24 sys = 0,00, real = 0,43 с] [3]: [12]: [] [] [[ 0,39 с] 2013-03-19T22: 27: 44.076 + 1100: 1289633.055: [GC [PSYoungGen: 2602730K- > 447527K (4732864K)] 7291358K- > 5208743K (15655552K), 0,3725317 secs] [Times: user = 5.80 sys = 0.00, real = 0,37 с] 2013-03-19T22: 27: 44,448 + 1100: 1289633.428: [Полный GC (система) [PSYoungGen: 447527K- > 0K (4732864K)] [ParOldGen: 4761215K- > 4628296K (10922688K)] 5208743K- > 4628296K (15655552K) [ PSPermGen: 352378K- > 352287K (352832K)], 4.2955639 secs] [Times: user = 57.70 sys = 0.06, real = 4.30 secs] 2013-03-19T22: 30: 37,950 + 1100: 1289806.920: [GC [PSYoungGen: 4004416K- > 70948K (4690432K)] 8632712K- > 4699245K (15613120K), 0,1062227 secs] [Times: user = 0.76 sys = 0.00, real = 0.11 сек] [00015040K], 0,13347919 сек.] [Время: пользователь = 1.03 sys = 0,00, real = 0,13 с] 2013-03-19T22: 36: 32.120 + 1100: 1290161.070: [GC [PSYoungGen: 4092343K- > 147318K (4712320K)] 8720640K- > 4775615K (15635008K), 0,1593523 secs] [Times: user = 1.58 sys = 0.00, real = 0,16 с] 2

Когда мы находимся в режиме сбоя, журналы GC выглядят так:

2013-03-22T10: 03: 47.619 + 1100: 1504185.901: [GC [PSYoungGen: 0K- > 0K (5452736K)] 4413907K- > 4413907K (16375424K), 0.0114248 secs] [Время: пользователь = 0,16 sys = 0,00, real = 0,01 с] 2013-03-22T10: 03: 47.631 + 1100: 1504185.912: [Полный GC [PSYoungGen: 0K- > 0K (5452736K)] [ParOldGen: 4413907K- > 4412613K (10922688K)] 4413907K- > 4412613K (16375424K) [PSPermGen: 358399K → 358278K (358400K)], 5.4435442 secs] [Times: user = 73.74 sys = 0.14, real = 5.44 secs] [0]: 53.145 + 1100: 1504191.426: [GC [PSYoungGen: 269219K- > 7734K (5449088K)] 4681833K- > 4422114K (16371776K), 0.0298728 secs] [Times: user = 0.34 sys = 0.00, real = 0,03 сек] 2013-03-22T10: 03: 53.175 + 1100: 1504191.456: [Полный GC [PSYoungGen: 7734K- > 0K (5449088K)] [ParOldGen: 4414379K- > 4415189K (10922688K)] 4422114K- > 4415189K (16371776K) [PSPermGen: 358399K → 358371K (358400K)], 2.6033684 secs] [Times: user = 36.33 sys = 0.00, real = 2.60 secs] (16374016K), 0,0133588 сек.] [Времена: пользователь = 0,16 сис = 0,00, реальный = 0,6 s = 0,006, 0,01 сек] 2013-03-22T10: 03: 55.802 + 1100: 1504194.082: [Полный GC [PSYoungGen: 826K- > 0K (5451328K)] [ParOldGen: 4415189K- > 4415348K (10922688K)] 4416015K- > 4415348K (16374016K) [PSPermGen: 358399K → 358389K (358400K)], 2.7156884 secs] [Times: user = 38.11 sys = 0.00, real = 2.71 secs] 2

Ответ 1

Как уже упоминалось в комментариях, нехватка места в PermGen, скорее всего, будет вашей причиной. Это может быть вызвано чрезмерным интернированием строк во всем коде, что может привести к "взрыву" PermGen - также загрузка многих классов (обычно через фреймворки, которые делают это для вас в фоновом режиме) также может вызвать это.

Кроме того, как упоминалось в одном из комментариев, использование коллекции CMS (Concurrent Mark и Sweep) может уменьшить ваши GC Stop the World, если проблема связана с емкостью старого поколения. Он также может улучшить вашу производительность за счет сокращения латентности, которая хороша независимо от текущей проблемы.

Кроме того, если вы публикуете фрагменты журнала GC, которые могут быть полезны для указания в правильном направлении.

Об инструменте jstat вы можете использовать его следующим образом, чтобы получить полезную информацию:

jstat -gcutil <pid> <interval>

Обычно я использую интервал 1000 мс. -gcutil дает вам GC Utilization (в%) - так что вы можете увидеть, приближается ли какое-либо поколение на 100%.

Вы также можете использовать jstat -gc <pid> ... и получить точную емкость своего старого поколения.

EDIT: после просмотра журналов GC

В соответствии с вашими журналами GC он подтверждает исходную предпосылку, что ваш PermGen заполняется. В диапазоне времени между 10:03:47 и 10:03:55 Я вижу, что PermGen постоянно достигает максимума, а GC как-то удаляет около 10-100 КБ данных:

См. ниже:

2013-03-22T10:03:47.631+1100: 1504185.912: [Full GC [... [PSPermGen: 358399K->358278K(358400K)]...
2013-03-22T10:03:53.175+1100: 1504191.456: [Full GC [... [PSPermGen: 358399K->358371K(358400K)]...
2013-03-22T10:03:55.802+1100: 1504194.082: [Full GC [... [PSPermGen: 358399K->358389K(358400K)]...

Если вы посмотрите на старые и молодые поколения, вы увидите, что они оба не достигли своего максимума, OldGen потребляет 4 ГБ из 10 ГБ - так что это не причина.

Из собранных вами данных я не могу сказать, соответствует ли скорость, на которую заполняется PermGen, время выполнения процесса - это означает, что PermGen должен залить день, а не 20 дней. Поэтому трудно сказать, что такое определенное решение, но вот несколько рекомендаций:

Изучите свой код, чтобы убедиться, что вы не злоупотребляете методом String intern() - если вы используете его слишком широко в коде без уважительной причины, это может быть вашей основной причиной.
Проверьте фреймворки, которые вы используете, если они динамически генерируют классы - это также будет использовать пространство PermGen, но в определенной степени.
Если вы можете, выполните еженедельный перезапуск процессов, чтобы предотвратить это время простоя.
Рассмотрите возможность увеличения пространства PermGen, но отслеживайте его с увеличением, это может просто увеличить ваш 20-дневный период, но не решить проблему. PermGen должен оставаться довольно статичным после того, как процесс был достаточно продолжительным.
Выполнение поиска в Google со строкой Coldfusion PermGen вызвало множество обращений, которые сообщают о проблемах, - попробуйте следовать им, чтобы сфокусировать вас на своем исследовании.