FullGC происходит каждый раз, когда CMS работает

Question

У меня есть веб-приложение в реальном времени со 100-1000 запросами в секунду. Я использую CMS GC и каждый раз, когда CMS начинает работать, счетчик FGC увеличивается на 2. Почему FullGC происходит каждый раз? Я имею в виду, что CMS должны работать без FullGC. Или это нормальное поведение? Мои варианты JMV:

-Xms6g 
-Xmx6g 
-XX:PermSize=512m 
-XX:MaxPermSize=512m 
-XX:+UseParNewGC 
-XX:+UseConcMarkSweepGC 
-XX:+UseCMSInitiatingOccupancyOnly 
-XX:CMSInitiatingOccupancyFraction=70 
-XX:+CMSClassUnloadingEnabled 
-XX:+UseLargePages 
-XX:LargePageSizeInBytes=2m 
-verbose:gc 
-Xloggc:gc.log 
-XX:+PrintGCDetails 
-XX:+PrintGCDateStamps 
-Dsun.rmi.dgc.client.gcInterval=3600000 
-Dsun.rmi.dgc.server.gcInterval=3600000 

Здесь вы gc.log:

2013-08-19T10:21:33.072+0600: 123570.236: [GC 123570.237: [ParNew: 427534K->35446K(440896K), 0.1872440 secs] 4482285K->4091194K(6242496K), 0.1877660 secs] [Times: user=0.51 sys=0.01, real=0.19 secs] 
2013-08-19T10:21:34.026+0600: 123571.191: [GC 123571.191: [ParNew: 427382K->34355K(440896K), 0.1993550 secs] 4483130K->4090615K(6242496K), 0.1998720 secs] [Times: user=0.53 sys=0.00, real=0.20 secs] 
2013-08-19T10:21:34.724+0600: 123571.889: [GC 123571.889: [ParNew: 426291K->38786K(440896K), 0.2229880 secs] 4482551K->4095384K(6242496K), 0.2235130 secs] [Times: user=0.53 sys=0.00, real=0.23 secs] 
2013-08-19T10:21:35.579+0600: 123572.744: [GC 123572.744: [ParNew: 430722K->34694K(440896K), 0.1812580 secs] 4487320K->4091801K(6242496K), 0.1817630 secs] [Times: user=0.49 sys=0.00, real=0.18 secs] 
2013-08-19T10:21:36.429+0600: 123573.594: [GC 123573.594: [ParNew: 426630K->34091K(440896K), 0.1752240 secs] 4483737K->4092028K(6242496K), 0.1757390 secs] [Times: user=0.48 sys=0.00, real=0.17 secs] 
2013-08-19T10:21:37.221+0600: 123574.386: [GC 123574.386: [ParNew: 426027K->36411K(440896K), 0.2047550 secs] 4483964K->4095856K(6242496K), 0.2052280 secs] [Times: user=0.50 sys=0.00, real=0.21 secs] 
2013-08-19T10:21:38.059+0600: 123575.223: [GC 123575.223: [ParNew: 428347K->40113K(440896K), 0.1892000 secs] 4487792K->4100213K(6242496K), 0.1896180 secs] [Times: user=0.51 sys=0.01, real=0.19 secs] 
2013-08-19T10:21:38.593+0600: 123575.757: [GC 123575.757: [ParNew: 432049K->39917K(440896K), 0.2193730 secs] 4492149K->4101831K(6242496K), 0.2198480 secs] [Times: user=0.50 sys=0.00, real=0.22 secs] 
2013-08-19T10:21:38.817+0600: 123575.981: [GC [1 CMS-initial-mark: 4061914K(5801600K)] 4102165K(6242496K), 0.0901990 secs] [Times: user=0.09 sys=0.00, real=0.09 secs] 
2013-08-19T10:21:38.908+0600: 123576.072: [CMS-concurrent-mark-start] 
2013-08-19T10:21:39.305+0600: 123576.469: [CMS-concurrent-mark: 0.397/0.397 secs] [Times: user=4.16 sys=0.44, real=0.39 secs] 
2013-08-19T10:21:39.305+0600: 123576.469: [CMS-concurrent-preclean-start] 
2013-08-19T10:21:39.335+0600: 123576.499: [GC 123576.499: [ParNew: 431853K->39752K(440896K), 0.2246840 secs] 4493767K->4102434K(6242496K), 0.2251970 secs] [Times: user=0.54 sys=0.00, real=0.23 secs] 
2013-08-19T10:21:39.576+0600: 123576.741: [CMS-concurrent-preclean: 0.039/0.271 secs] [Times: user=0.75 sys=0.05, real=0.27 secs] 
2013-08-19T10:21:39.576+0600: 123576.741: [CMS-concurrent-abortable-preclean-start] 
2013-08-19T10:21:40.193+0600: 123577.357: [GC 123577.358: [ParNew: 431688K->39319K(440896K), 0.2158020 secs] 4494370K->4102833K(6242496K), 0.2162640 secs] [Times: user=0.53 sys=0.00, real=0.22 secs] 
2013-08-19T10:21:40.474+0600: 123577.638: [CMS-concurrent-abortable-preclean: 0.673/0.898 secs] [Times: user=3.19 sys=0.77, real=0.90 secs] 
2013-08-19T10:21:40.479+0600: 123577.643: [GC[YG occupancy: 202771 K (440896 K)]123577.643: [Rescan (parallel) , 0.0455840 secs]123577.689: [weak refs processing, 2.2041640 secs]123579.893: [class unloading, 0.0445080 secs]123579.938: [scrub symbol & string tables, 0.0187100 secs] [1 CMS-remark: 4063513K(5801600K)] 4266284K(6242496K), 2.3260510 secs] [Times: user=3.24 sys=0.00, real=2.32 secs] 
2013-08-19T10:21:42.806+0600: 123579.970: [CMS-concurrent-sweep-start] 
2013-08-19T10:21:42.914+0600: 123580.079: [GC 123580.079: [ParNew: 431328K->45397K(440896K), 0.0902990 secs] 4494842K->4109425K(6242496K), 0.0908150 secs] [Times: user=0.50 sys=0.00, real=0.09 secs] 
2013-08-19T10:21:43.012+0600: 123580.176: [GC 123580.176: [ParNew: 45767K->4894K(440896K), 0.1271260 secs] 4109795K->4114786K(6242496K), 0.1275320 secs] [Times: user=0.75 sys=0.04, real=0.13 secs] 
2013-08-19T10:21:43.286+0600: 123580.451: [GC 123580.451: [ParNew: 396847K->48960K(440896K), 0.2152650 secs] 4506739K->4161825K(6242496K), 0.2157500 secs] [Times: user=0.59 sys=0.00, real=0.22 secs] 
2013-08-19T10:21:43.509+0600: 123580.673: [GC 123580.674: [ParNew: 49831K->8172K(440896K), 0.0639450 secs] 4162696K->4159717K(6242496K), 0.0643790 secs] [Times: user=0.48 sys=0.00, real=0.06 secs] 
2013-08-19T10:21:43.726+0600: 123580.890: [GC 123580.890: [ParNew: 400108K->48960K(440896K), 0.1256470 secs] 4551616K->4203961K(6242496K), 0.1261110 secs] [Times: user=0.50 sys=0.00, real=0.13 secs] 
2013-08-19T10:21:43.999+0600: 123581.164: [GC 123581.164: [ParNew: 440896K->48960K(440896K), 0.1631010 secs] 4565558K->4184975K(6242496K), 0.1635960 secs] [Times: user=0.58 sys=0.01, real=0.16 secs] 
2013-08-19T10:21:44.715+0600: 123581.880: [GC 123581.880: [ParNew: 440896K->39265K(440896K), 0.2020150 secs] 4374009K->3975902K(6242496K), 0.2025700 secs] [Times: user=0.53 sys=0.00, real=0.21 secs] 
2013-08-19T10:21:44.924+0600: 123582.088: [GC 123582.088: [ParNew: 39857K->1876K(440896K), 0.0546600 secs] 3976335K->3973247K(6242496K), 0.0550670 secs] [Times: user=0.46 sys=0.02, real=0.06 secs] 
2013-08-19T10:21:45.207+0600: 123582.371: [GC 123582.371: [ParNew: 393812K->42887K(440896K), 0.2367970 secs] 4280052K->3929127K(6242496K), 0.2372620 secs] [Times: user=0.57 sys=0.00, real=0.24 secs] 
2013-08-19T10:21:46.048+0600: 123583.212: [GC 123583.213: [ParNew: 434823K->33908K(440896K), 0.1922750 secs] 4081263K->3683497K(6242496K), 0.1927880 secs] [Times: user=0.54 sys=0.00, real=0.19 secs] 

Вот jstat войти:

70.86 0.00 63.36 69.93 29.29 7110 1077.048 42 112.603 1189.651 unknown GCCause  No GC 
    0.00 69.63 84.75 69.95 29.29 7111 1077.223 42 112.603 1189.826 unknown GCCause  No GC 
74.37 20.57 100.00 69.98 29.29 7113 1077.428 42 112.603 1190.031 unknown GCCause  Allocation Failure 
    S0  S1  E  O  P  YGC  YGCT FGC FGCT  GCT LGCC     GCC 
81.53 0.00 80.03 70.01 29.29 7114 1077.837 43 112.693 1190.530 CMS Initial Mark  No GC 
    0.00 81.19 92.05 70.03 29.29 7115 1078.061 43 112.693 1190.754 unknown GCCause  No GC 
80.31 0.00 41.70 70.04 29.29 7116 1078.277 44 112.693 1190.970 No GC    CMS Final Remark 
80.31 0.00 41.70 70.04 29.29 7116 1078.277 44 112.693 1190.970 No GC    CMS Final Remark 
10.00 92.72 0.09 70.85 29.30 7118 1078.368 44 115.019 1193.386 No GC    GCLocker Initiated GC 
    S0  S1  E  O  P  YGC  YGCT FGC FGCT  GCT LGCC     GCC 
86.43 100.00 100.00 71.26 29.30 7122 1078.900 44 115.019 1193.918 unknown GCCause  Allocation Failure 
    3.83 0.00 96.82 67.37 29.30 7124 1079.319 44 115.019 1194.338 GCLocker Initiated GC No GC 
10.70 87.60 100.00 62.91 29.30 7126 1079.556 44 115.019 1194.575 unknown GCCause  Allocation Failure 
69.26 46.82 100.00 58.81 29.30 7127 1079.748 44 115.019 1194.767 unknown GCCause  Allocation Failure 
    0.00 2.97 0.00 54.59 29.30 7129 1080.196 44 115.019 1195.215 GCLocker Initiated GC No GC 
    S0  S1  E  O  P  YGC  YGCT FGC FGCT  GCT LGCC     GCC 
77.12 0.00 72.64 46.93 29.30 7130 1080.391 44 115.019 1195.410 unknown GCCause  No GC 
    1.21 0.00 92.31 40.78 29.30 7132 1080.656 44 115.019 1195.675 GCLocker Initiated GC No GC 
70.43 0.00 0.14 33.51 29.30 7134 1080.874 44 115.019 1195.893 unknown GCCause  No GC 
    0.00 62.56 33.67 25.89 29.30 7135 1080.974 44 115.019 1195.992 unknown GCCause  No GC 
71.90 0.00 85.91 23.61 29.30 7136 1081.153 44 115.019 1196.172 unknown GCCause  No GC 
    S0  S1  E  O  P  YGC  YGCT FGC FGCT  GCT LGCC     GCC 
35.00 87.41 100.00 23.66 29.30 7138 1081.349 44 115.019 1196.368 unknown GCCause  Allocation Failure 
    0.00 79.22 68.07 23.69 29.30 7139 1081.671 44 115.019 1196.690 unknown GCCause  No GC 
87.27 0.00 93.23 23.70 29.30 7140 1081.878 44 115.019 1196.897 unknown GCCause  No GC 
    0.00 65.85 68.58 23.73 29.30 7141 1082.028 44 115.019 1197.047 unknown GCCause  No GC 
37.82 0.00 22.79 23.75 29.30 7142 1082.097 44 115.019 1197.116 unknown GCCause  No GC 
    S0  S1  E  O  P  YGC  YGCT FGC FGCT  GCT LGCC     GCC 
    0.00 65.38 91.55 23.75 29.30 7143 1082.223 44 115.019 1197.242 unknown GCCause  No GC 
    5.66 97.48 100.00 23.80 29.30 7146 1082.490 44 115.019 1197.509 unknown GCCause  Allocation Failure 
91.30 0.00 93.29 24.44 29.30 7148 1082.807 44 115.019 1197.826 unknown GCCause  No GC 
64.91 76.26 100.00 24.48 29.30 7150 1082.925 44 115.019 1197.944 unknown GCCause  Allocation Failure 
    0.00 75.64 43.14 24.51 29.30 7151 1083.267 44 115.019 1198.286 unknown GCCause  No GC 

Answer 1

Главный вопрос: что подсчитано «FullGC» -колонтеру, о котором вы упомянули.

1.) CMS - это полная коллекция в том смысле, что она собирает как молодое, так и старое поколение.

2.) Каждый запуск CMS будет включать в себя две фазы «стоп-мир» (начальный знак и примечание), в то время как всякая другая работа выполняется одновременно. CMS не пытается предотвратить фазу stop-the-world-phase, это просто трек, чтобы сделать их как можно короче.

3.) Когда у VM закончится память, когда активна параллельная фаза CMS, она вернется к нормальному алгоритму Mark-Sweep-Compact, что приведет к паузе паузы в паузе.

Проверка ваших GC-журналов. Я не вижу никаких намеков на то, что 3.). При проверке jstat-log вы можете видеть, что счетчик FGC увеличивается на «Начальный знак CMS» и «Заключительное замечание CMS», поэтому просто кажется, что считаются две фазы stop-the-world, которые являются нормальной частью CMS-коллекция.

Answer 2

Попробуйте следующие параметры виртуальной машины Java, чтобы получить журналы подробный GC, и мы можем исследовать это дополнительно

-XX:+PrintPromotionFailure To get more details about promotion failures 
-XX:PrintFLSStatistics=1 To get more details about young and old generation statistics 

Answer 3

CMS использует ПОЛНЫЕ GC.

Все сборщики мусора выполняют либо небольшие GC, либо GC. Незначительные GC собирают молодое поколение, и FullGCs соберут молодых, старых и перманентных.

На CMS все, что вы получаете, является сборщиком пропускной способности для старого поколения, это означает, что этот коллекционер попытается избежать большой остановки в мире. Это разные фазы, как вы можете видеть на своих журналах, я не собираюсь в деталях на этапах CMS, но вам нужно знать, что, когда ваше старое поколение не может выделить объект, наделенный полномочиями, гарантируется полная коллекция. Таким образом, CMS выполняет FULLGC.

По вашему сомнению jstat log, FullGC на CMS всегда будет увеличивать метрику FULLGC с шагом 2, но только один FULLGC. (Я прочитал это в официальной документации jstat некоторое время назад, но не смог найти его только сейчас, но как только у меня возникли такие же сомнения, как и вы, и я лично проверил это на нескольких JVM и сайтах).