Краткая форма: сборщик мусора CMS, по-видимому, не может собирать постоянно увеличивающееся количество мусора; в итоге наша JVM заполняется, и приложение перестает отвечать на запросы. Принудительный сбор GC с помощью внешнего инструмента (JConsole или jmap -histo:live) очищает его один раз.
ОБНОВЛЕНИЕ: проблема связана с плагином JTop для JConsole; если мы не запустим JConsole или не запустим его без плагина JTop, поведение исчезнет.
(Технические примечания: мы запускаем 32-разрядную версию Sun JDK 1.6.0_07 на платформе Linux 2.6.9. Обновление версии JDK на самом деле не вариант, если только это не является главной причиной. Кроме того, наша Система не подключена к машине, доступной через Интернет, поэтому снимки экрана JConsole и т. д. не подходят.)
В настоящее время мы используем нашу JVM со следующими флагами:
-server -Xms3072m -Xmx3072m -XX:NewSize=512m -XX:MaxNewSize=512m
-XX:+UseConcMarkSweepGC -XX:+UseParNewGC -XX:+CMSParallelRemarkEnabled
-XX:CMSInitiatingOccupancyFraction=70
-verbose:gc -XX:+PrintGCDetails -XX:+PrintGCTimeStamps
-XX:+DisableExplicitGC
Наблюдая за графиком памяти в JConsole, существует полный GC, который запускается каждые ~ 15 минут или около того в течение первых нескольких часов жизни нашего приложения; после каждого полного GC все больше и больше памяти все еще используется. Через несколько часов система переходит в устойчивое состояние, когда в CMS старого поколения примерно 2 ГБ используемой памяти.
Звучит как классическая утечка памяти, за исключением того, что если мы используем какой-либо инструмент, который заставляет полный GC (нажать кнопку «собрать мусор» в JConsole или запустить jmap -histo:live и т. Д.), Старый ген внезапно падает до ~ 500 МБ, и наше приложение снова становится отзывчивым в течение следующих нескольких часов (в течение этого времени продолжается та же самая схема - после каждого полного GC все больше и больше старого поколения будет заполнено).
Одна вещь, на которую следует обратить внимание: в JConsole указанный счетчик GC ConcurrentMarkSweep останется равным 0, пока мы не принудительно настроим GC с помощью jconsole / jmap / и т. Д.
Используя jmap -histo и jmap -histo:live последовательно, я могу определить, что явно не собранные объекты состоят из:
- несколько миллионов
HashMap с и массивы HashMap$Entry (в соотношении 1: 1)
- несколько миллионов
Vector с и массивов объектов (соотношение 1: 1 и примерно столько же, сколько число хэш-карт)
- несколько миллионов
HashSet, Hashtable и com.sun.jmx.remote.util.OrderClassLoader с, а также массивы Hashtable$Entry (примерно столько же, сколько у каждого; примерно вдвое меньше, чем хэш-карты и векторы)
Ниже приведены некоторые выдержки из вывода ГХ; моя интерпретация, по-видимому, заключается в том, что CMS GC прерывается, не переходя к GC «останови мир». Я неправильно истолковываю этот вывод? Есть ли что-то, что могло бы вызвать это?
Во время нормальной работы выходные блоки CMS GC выглядят примерно так:
36301.827: [GC [1 CMS-initial-mark: 1856321K(2621330K)] 1879456K(3093312K), 1.7634200 secs] [Times: user=0.17 sys=0.00, real=0.18 secs]
36303.638: [CMS-concurrent-mark-start]
36314.903: [CMS-concurrent-mark: 7.804/11.264 secs] [Times: user=2.13 sys=0.06, real=1.13 secs]
36314.903: [CMS-concurrent-preclean-start]
36314.963: [CMS-concurrent-preclean: 0.037/0.060 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
36314.963: [CMS-concurrent-abortable-preclean-start]
36315.195: [GC 36315.195: [ParNew: 428092K->40832K(471872K), 1.1705760 secs] 2284414K->1897153K(3093312K), 1.1710560 secs] [Times: user=0.13 sys=0.02, real=0.12 secs]
CMS: abort preclean due to time 36320.059: [CMS-concurrent-abortable-preclean: 0.844/5.095 secs] [Times: user=0.74 sys=0.05, real=0.51 secs]
36320.062: [GC[YG occupancy: 146166 K (471872 K)]36320.062: [Rescan (parallel), 1.54078550 secs]36321.603: [weak refs processing, 0.0042640 secs] [1 CMS-remark: 1856321K(2621440K)] 2002488K(3093312K), 1.5456150 secs] [Times: user=0.18 sys=0.03, real=0.15 secs]
36321.608: [CMS-concurrent-sweep-start]
36324.650: [CMS-concurrent-sweep: 2.686/3.042 secs] [Times: uesr=0.66 sys=0.02, real=0.30 secs]
36324.651: [CMS-concurrent-reset-start]
36324.700: [CMS-concurrent-reset: 0.050/0.050 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
и все; следующая строка будет следующей ParNew GC.
Когда мы запускаем сборщик мусора, используя jmap -histo: live, мы вместо этого получаем:
48004.088: [CMS-concurrent-mark: 8.012/8.647 secs] [Times: user=1.15 sys=0.02, real=0.87 secs]
(concurrent mode interrupted)
, за которыми следуют ~ 125 строк в форме ниже: (некоторые GeneratedMethodAccessor, некоторые GeneratedSerializationConstructorAccessor, некоторые GeneratedConstructorAccessor и т. Д.)
[Unloading class sun.reflect.GeneratedMethodAccessor3]
с последующим:
: 1911295K->562232K(2621440K), 15.6886180 secs] 2366440K->562232K(3093312K), [CMS Perm: 52729K->51864K(65536K)], 15.6892270 secs] [Times: user=1.55 sys=0.01, real=1.57 secs]
Заранее спасибо!