5

我有一个每秒约 100-1000 个请求的实时 Web 应用程序。我使用 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
4

3 回答 3

1

主要问题是：您提到的“FullGC”计数器计数了什么。

1.) CMS 是一个 Full-collection，因为它收集了年轻代和年老代。

2.) Each run of the CMS will include two stop-the-world phases (Initial Mark and Remark) while all other work is done concurrently. CMS does not try to prevent stop-the-world-phases, it just treis to kepp them as short as possible.

3.) When the VM runs out of memory while a concurrent phase of CMS is active it will fall back to the normal Mark-Sweep-Compact-algorithm which will result in a long stop-the-world pause.

Inspecting your GC-logs I don't see any hint that 3.) is happening. When inspecting the jstat-log you can see that the FGC-counter increases on "CMS Initial Mark" and "CMS Final Remark", so it just seems to count the two stop-the-world-phases that are a normal part of a CMS-collection.

于 2013-08-19T14:14:47.343 回答
1

CMS DOES use FULL GCs.

All garbage collectors do either a minor GC or a Full GC. Minor GCs will collect the young generation and FullGCs will collect the young, the old and the perm gen.

On CMS all that you get is a throughput collector for the Old Generation, this means that this collector will try to avoid big stop the world pauses.It has different phases like you can see on your logs, I am not going into details of CMS phases but you do need to know that when your old generation is not able to allocate a tenured object, a Full collection is guaranteed to take place. Thus CMS does perform FULLGCs.

As of your jstat log doubt, FullGC on CMS will always increase the FULLGC metric on a 2 increment yet only one FULLGC took place. (I had read this on the official jstat documentation some time back but couldn't find it just now but once I had the same doubt as you did and I have personally verified this on multiple JVMs and sites).

于 2013-09-04T05:59:00.443 回答
0

尝试按照 JVM 参数获取详细的 GC 日志，我们可以进一步调查

-XX:+PrintPromotionFailure To get more details about promotion failures
-XX:PrintFLSStatistics=1  To get more details about young and old generation statistics
于 2013-08-19T10:02:48.077 回答