Сборка мусора в CMS занимает слишком много времени

Один из наших клиентов сталкивается с серьезными проблемами с производительностью, которые, по-видимому, вызваны длительными запусками мусора, и я не знаю, что с этим делать...

Версия Java: 1.7.0_67 Аргументы JVM: -Xms10240m -Xmx16386m -XX:NewSize=2048m -XX:MaxPermSize=150m -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:+PrintGCDetails ...

Дополнительная информация

Приложение - это наш серверный сервер для веб-приложения. Сервер подключается к базе данных SQL и нескольким системам ERP. Эти данные затем обрабатываются и отправляются веб-клиентам. Этот клиент, в частности, имеет около 50 пользователей по всему миру, которые получают доступ к данным через этот единственный сервер.

  • ОС: Windows Server 2008 R2 Datacenter + SP1
  • Процессор: Xeon E5-2660 (4 ядра + HT)
  • Оперативная память: 32 ГБ

Что я пробовал до сих пор

  • увеличенные Xmx и Xms (читайте, что Xms должен быть одинаковым или, по крайней мере, близким к Xmx для лучшей производительности)
  • возиться с размером молодого поколения (соотношение 1, 2, 3)
  • увеличение PermGeneration
  • пробовал разные варианты GC

Вот некоторые части журнала gc. Вы можете ясно видеть, что длительность gc увеличивается с течением времени и достигает пика примерно через 17 секунд.

Что может вызвать эти проблемы? Есть ли какие-нибудь аргументы JVM, с которыми можно возиться?

Обновление / 25.03.2016

После запуска VisualVM кажется, что я обнаружил одну из проблем: Young Generation теперь установлен на 4 ГБ - соотношение между Eden и Survivor, по-видимому, далеко... Eden = 3,5 ГБ, а Survivor = 0,5 ГБ. все время генерируется много новых объектов (что мне придется исследовать дальше), Eden заполняется более чем 0,5 ГБ (больше, например, от 1 до 2 ГБ). Оставшийся в живых не может удержать его, и поэтому срабатывает Major GC.

Новые возникающие вопросы:

  1. Мои предположения неверны?
  2. Я думаю, что мои следующие шаги должны быть вручную установить коэффициент выживаемости. Любые предложения, основанные на моем случае?
  3. Нужно ли отключать AdaptiveSizePolicy? (-XX:-UseAdaptiveSizePolicy)
  4. Почему в журнале GC причина указана как "System.gc()", а в коде определенно нет ручного GC, запускаемого вручную (декомпилировали все классы и проверили):

2016-03-25T04:59:55.726+0100: 14992.418: [Full GC (System.gc())2016-03-25T04:59:55.726+0100: 14992.418: [CMS: 265708K->265749K(6291456K), 1.1520720 secs] 507160K->265749K(10066368K), [CMS Perm : 54875K->54875K(91504K)], 1.1523255 secs] [Times: user=1.14 sys=0.00, real=1.14 secs]

Старые бревна / 24.03.2016

Первые несколько журналов после запуска:

12.434: [GC12.434: [ParNew: 1677824K->100069K(1887488K), 0.0983359 secs] 1677824K->100069K(10276096K), 0.0985257 secs] [Times: user=0.31 sys=0.02, real=0.11 secs] 
16.293: [GC16.293: [ParNew: 1777893K->209664K(1887488K), 0.1933143 secs] 1777893K->212290K(10276096K), 0.1934443 secs] [Times: user=0.50 sys=0.02, real=0.19 secs] 
19.994: [Full GC19.994: [CMS: 2626K->172662K(8388608K), 0.6312313 secs] 1521173K->172662K(10276096K), [CMS Perm : 24831K->24825K(24896K)], 0.6314259 secs] [Times: user=0.70 sys=0.06, real=0.64 secs] 
261.411: [Full GC261.411: [CMS: 172662K->27686K(8388608K), 0.2232379 secs] 876118K->27686K(10276096K), [CMS Perm : 30913K->30911K(41376K)], 0.2234464 secs] [Times: user=0.22 sys=0.00, real=0.22 secs] 
441.716: [Full GC441.716: [CMS: 27686K->24604K(8388608K), 0.1768511 secs] 500368K->24604K(10276096K), [CMS Perm : 30937K->30936K(51520K)], 0.1770344 secs] [Times: user=0.17 sys=0.00, real=0.17 secs]

Некоторое время спустя:

20235.044: [Full GC20235.044: [CMS: 195484K->248016K(8388608K), 1.0221468 secs] 798601K->248016K(10276096K), [CMS Perm : 52564K->52564K(87480K)], 1.0223571 secs] [Times: user=1.00 sys=0.02, real=1.01 secs] 
20431.860: [Full GC20431.860: [CMS: 248016K->404539K(8388608K), 1.6120188 secs] 1385622K->404539K(10276096K), [CMS Perm : 54537K->54536K(87672K)], 1.6122663 secs] [Times: user=1.58 sys=0.03, real=1.61 secs] 
20655.867: [Full GC20655.867: [CMS: 404539K->323692K(8388608K), 1.4389098 secs] 958490K->323692K(10276096K), [CMS Perm : 54655K->54652K(90896K)], 1.4391006 secs] [Times: user=1.43 sys=0.00, real=1.43 secs] 
20956.441: [Full GC20956.441: [CMS: 323692K->378663K(8388608K), 1.4717112 secs] 1233969K->378663K(10276096K), [CMS Perm : 54713K->54713K(91092K)], 1.4719180 secs] [Times: user=1.47 sys=0.00, real=1.47 secs] 
21149.053: [Full GC21149.053: [CMS: 378663K->284427K(8388608K), 1.1860728 secs] 717555K->284427K(10276096K), [CMS Perm : 54828K->54828K(91284K)], 1.1862890 secs] [Times: user=1.19 sys=0.00, real=1.19 secs] 
21438.332: [Full GC21438.332: [CMS: 284427K->519857K(8388608K), 2.0659280 secs] 1676708K->519857K(10276096K), [CMS Perm : 62993K->62984K(91476K)], 2.0662088 secs] [Times: user=2.03 sys=0.03, real=2.06 secs] 
21738.902: [Full GC21738.903: [CMS: 519857K->470206K(8388608K), 1.9628709 secs] 1590878K->470206K(10276096K), [CMS Perm : 63230K->63229K(104976K)], 1.9631042 secs] [Times: user=1.95 sys=0.00, real=1.95 secs] 
21922.221: [Full GC21922.221: [CMS: 470206K->448817K(8388608K), 1.7216487 secs] 1127397K->448817K(10276096K), [CMS Perm : 63269K->63269K(105384K)], 1.7218965 secs] [Times: user=1.72 sys=0.00, real=1.72 secs] 
22161.837: [Full GC22161.837: [CMS: 448817K->435548K(8388608K), 1.7168703 secs] 943145K->435548K(10276096K), [CMS Perm : 63298K->63298K(105576K)], 1.7170921 secs] [Times: user=1.72 sys=0.00, real=1.72 secs] 
22402.100: [Full GC22402.100: [CMS: 435548K->613005K(8388608K), 2.3503697 secs] 1841133K->613005K(10276096K), [CMS Perm : 65977K->65976K(105576K)], 2.3506446 secs] [Times: user=2.29 sys=0.05, real=2.34 secs] 
22642.893: [Full GC22642.893: [CMS: 613005K->621214K(8388608K), 2.3825301 secs] 1710749K->621214K(10276096K), [CMS Perm : 66925K->66924K(109964K)], 2.3827835 secs] [Times: user=2.37 sys=0.00, real=2.37 secs] 
22883.148: [Full GC22883.148: [CMS: 621214K->600821K(8388608K), 2.4086658 secs] 1523224K->600821K(10276096K), [CMS Perm : 67550K->67550K(111544K)], 2.4089147 secs] [Times: user=2.40 sys=0.00, real=2.40 secs]

На пике длительности gc:

51603.282: [Full GC51603.282: [CMS: 4940385K->4859068K(8388608K), 16.6679541 secs] 5987385K->4859068K(10276096K), [CMS Perm : 114750K->114750K(153600K)], 16.6684484 secs] [Times: user=16.66 sys=0.00, real=16.66 secs] 
51813.482: [Full GC51813.482: [CMS: 4859068K->4900085K(8388608K), 16.4928686 secs] 6116576K->4900085K(10276096K), [CMS Perm : 114750K->114750K(153600K)], 16.4933047 secs] [Times: user=16.49 sys=0.00, real=16.49 secs] 
52026.148: [Full GC52026.148: [CMS: 4900085K->4896483K(8388608K), 16.8907197 secs] 6090675K->4896483K(10276096K), [CMS Perm : 114755K->114755K(153600K)], 16.8911947 secs] [Times: user=16.88 sys=0.00, real=16.89 secs] 
52223.160: [Full GC52223.160: [CMS: 4896483K->5031826K(8388608K), 17.1507980 secs] 6559062K->5031826K(10276096K), [CMS Perm : 114763K->114763K(153600K)], 17.1513112 secs] [Times: user=17.16 sys=0.00, real=17.16 secs] 
52425.802: [Full GC52425.802: [CMS: 5031826K->5016422K(8388608K), 17.8492606 secs] 6444936K->5016422K(10276096K), [CMS Perm : 114811K->114811K(153600K)], 17.8497294 secs] [Times: user=17.85 sys=0.00, real=17.85 secs] 
52628.857: [Full GC52628.858: [CMS: 5016422K->5077701K(8388608K), 17.9003775 secs] 6606932K->5077701K(10276096K), [CMS Perm : 114812K->114812K(153600K)], 17.9027559 secs] [Times: user=17.88 sys=0.02, real=17.89 secs] 
52747.442: [GC52747.443: [ParNew: 1677824K->209664K(1887488K), 1.3771078 secs] 6755525K->5530527K(10350324K), 1.3774630 secs] [Times: user=1.64 sys=0.08, real=1.37 secs] 
52833.644: [Full GC52833.644: [CMS: 5320863K->4956574K(8462836K), 17.7157636 secs] 6575478K->4956574K(10350324K), [CMS Perm : 114826K->114826K(153600K)], 17.7162266 secs] [Times: user=17.74 sys=0.00, real=17.72 secs] 
53058.481: [Full GC53058.482: [CMS: 4956574K->5002967K(8462836K), 17.9367047 secs] 6626713K->5002967K(10350324K), [CMS Perm : 114835K->114835K(153600K)], 17.9371138 secs] [Times: user=17.92 sys=0.00, real=17.92 secs]

Полный журнал: http://pastebin.ca/3409912

Источник

3 ответа

Утечка памяти может вызвать эту паузу. Когда система прогрелась, вы можете сделать снимок кучи (дампа кучи) и проанализировать его с помощью такого инструмента, как Eclipse Memory Analyzer. Вы можете присоединиться к запущенному процессу с помощью jvisualvm и попытаться проанализировать / проанализировать использование памяти. Наиболее эффективным решением является оптимизация алгоритма.

Источник

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

Я подозреваю, что ваши пространства Survivor недостаточно велики, так что, когда пространство Eden очищается, у выживших не хватает места, и это вызывает полный сборщик мусора, однопоточный.

Источник

Что может вызвать эти проблемы?

добавлять -XX:+PrintGCCause чтобы увидеть, что вызывает полный сборщик мусора.

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