Promotion Failure with CMS

Mon Sep 24 13:50:08 PDT 2012

Hi All

I am using Java 6 Update 23 with 72GB Heap.

I am getting Promotion Failure with CMS.

2012-09-19T15:27:10.923-0400: 1205700.121: [GC 1205700.121: [ParNew
(promotion failed)
Desired survivor size 1234796544 bytes, new threshold 1 (max 4)
- age ? 1: 2421521448 bytes, 2421521448 total
: 21705536K->21705536K(21705536K), 4.5292200 secs]1205704.650: [CMS:
37054811K->18221426K(50919424K), 32.5634240 secs]
53545404K->18221426K(72624960K),
[CMS Perm : 46723K->45384K(77956K)], 37.0928130 secs] [Times: user=57.92
sys=0.02, real=37.09 secs]?

I am trying to understand this log line?

?[CMS: 37054811K->18221426K(50919424K), 32.5634240 secs]

Does it mean that CMS took 32 sec of wall time.

And,?I see the perm gen is also being collected even though max Perm Gen
size is 128 MB.?
Why is that happening?

Another question is: How should I deal with Promotion Failure?

My JVM args are

-server -Xms73278m -Xmx73278m ?-XX:MaxPermSize=128m?
-XX:+UseConcMarkSweepGC -XX:+UseParNewGC
-XX:CMSInitiatingOccupancyFraction=65?
-XX:+DisableExplicitGC -XX:NewSize=23552m -XX:MaxNewSize=23552m?
-XX:+PrintGCDateStamps -XX:+PrintSafepointStatistics
-XX:+UseCMSInitiatingOccupancyOnly?
-XX:+CMSParallelRemarkEnabled -XX:+ParallelRefProcEnabled
-XX:+CMSClassUnloadingEnabled?
-XX:+CMSPermGenSweepingEnabled -XX:CMSInitiatingPermOccupancyFraction=68?
-XX:+UseCMSInitiatingOccupancyOnly -verbosegc?
-XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps
-XX:+PrintTenuringDistribution?
-XX:+HeapDumpOnOutOfMemoryError
-XX:HeapDumpPath=/opt/gid/tomcat/srv/solrSlaveTcSrv/logs

Full logs are?

2012-09-19T15:01:27.245-0400: 1204156.443: [GC [1 CMS-initial-mark:
34896031K(50919424K)] 37340642K(72624960K), 0.4650020 secs] [Times:
user=0.46 sys=0.00, real=0.47 secs]?
2012-09-19T15:01:27.710-0400: 1204156.908: [CMS-concurrent-mark-start]
2012-09-19T15:01:29.852-0400: 1204159.050: [CMS-concurrent-mark:
2.140/2.142 secs] [Times: user=12.73 sys=0.14, real=2.14 secs]?
2012-09-19T15:01:29.852-0400: 1204159.050: [CMS-concurrent-preclean-start]
2012-09-19T15:01:30.046-0400: 1204159.245: [CMS-concurrent-preclean:
0.192/0.194 secs] [Times: user=0.19 sys=0.00, real=0.19 secs]?
2012-09-19T15:01:30.046-0400: 1204159.245:
[CMS-concurrent-abortable-preclean-start]
?CMS: abort preclean due to time 2012-09-19T15:01:35.234-0400: 1204164.433:
[CMS-concurrent-abortable-preclean: 5.026/5.188 secs] [Times: user=6.93
sys=0.01, real=5.19 secs]?
2012-09-19T15:01:35.235-0400: 1204164.433: [GC[YG occupancy: 3499130 K
(21705536 K)]1204164.433: [Rescan (parallel) , 0.2566170 secs]1204164.690:
[weak refs processing, 0.3779280 secs] [1 CMS-remark: 34896031K(50919424K)]
38395161K(72624960K), 0.6379830 secs] [Times: user=10.99 sys=0.01,
real=0.64 secs]?
2012-09-19T15:01:35.873-0400: 1204165.071: [CMS-concurrent-sweep-start]
2012-09-19T15:02:09.680-0400: 1204198.878: [CMS-concurrent-sweep:
33.805/33.807 secs] [Times: user=40.49 sys=0.12, real=33.80 secs]?
2012-09-19T15:02:09.680-0400: 1204198.878: [CMS-concurrent-reset-start]
2012-09-19T15:02:09.790-0400: 1204198.988: [CMS-concurrent-reset:
0.110/0.110 secs] [Times: user=0.11 sys=0.00, real=0.11 secs]?
2012-09-19T15:07:54.896-0400: 1204544.094: [GC 1204544.094: [ParNew
Desired survivor size 1234796544 bytes, new threshold 1 (max 4)
- age ? 1: 2350102440 bytes, 2350102440 total
: 21705536K->2411712K(21705536K), 1.2991600 secs]
39356156K->23512228K(72624960K), 1.2992650 secs] [Times: user=16.03
sys=0.01, real=1.30 secs]?
2012-09-19T15:15:09.066-0400: 1204978.265: [GC 1204978.265: [ParNew
Desired survivor size 1234796544 bytes, new threshold 1 (max 4)
- age ? 1: 2427844296 bytes, 2427844296 total
: 21705536K->2411712K(21705536K), 1.6306700 secs]
42806052K->29854665K(72624960K), 1.6307870 secs] [Times: user=22.58
sys=0.05, real=1.63 secs]?
2012-09-19T15:20:51.315-0400: 1205320.513: [GC 1205320.513: [ParNew
Desired survivor size 1234796544 bytes, new threshold 1 (max 4)
- age ? 1: 2292042936 bytes, 2292042936 total
: 21705536K->2411712K(21705536K), 1.5484080 secs]
49148489K->34251580K(72624960K), 1.5485200 secs] [Times: user=21.24
sys=0.04, real=1.55 secs]?
2012-09-19T15:27:10.923-0400: 1205700.121: [GC 1205700.121: [ParNew
(promotion failed)
Desired survivor size 1234796544 bytes, new threshold 1 (max 4)
- age ? 1: 2421521448 bytes, 2421521448 total
: 21705536K->21705536K(21705536K), 4.5292200 secs]1205704.650: [CMS:
37054811K->18221426K(50919424K), 32.5634240 secs]
53545404K->18221426K(72624960K),
[CMS Perm : 46723K->45384K(77956K)], 37.0928130 secs] [Times: user=57.92
sys=0.02, real=37.09 secs]?
2012-09-19T15:35:38.721-0400: 1206207.920: [GC 1206207.920: [ParNew
Desired survivor size 1234796544 bytes, new threshold 1 (max 4)
- age ? 1: 2410186856 bytes, 2410186856 total
: 19293824K->2411712K(21705536K), 0.6405050 secs]
37515250K->22899742K(72624960K), 0.6406260 secs] [Times: user=11.15
sys=0.02, real=0.64 secs]?
2012-09-19T15:36:23.120-0400: 1206252.318: [GC 1206252.319: [ParNew
Desired survivor size 1234796544 bytes, new threshold 1 (max 4)
- age ? 1: 2398571736 bytes, 2398571736 total
: 21705536K->2411712K(21705536K), 1.2799480 secs]
42193566K->26210207K(72624960K), 1.2800840 secs] [Times: user=18.69
sys=0.05, real=1.28 secs]?
2012-09-19T15:42:05.249-0400: 1206594.447: [GC 1206594.447: [ParNew
Desired survivor size 1234796544 bytes, new threshold 1 (max 4)
- age ? 1: 2387771616 bytes, 2387771616 total
: 21705536K->2411712K(21705536K), 1.6001020 secs]
45504031K->32137231K(72624960K), 1.6002430 secs] [Times: user=21.98
sys=0.05, real=1.60 secs]?
2012-09-19T15:48:22.748-0400: 1206971.946: [GC 1206971.946: [ParNew
Desired survivor size 1234796544 bytes, new threshold 1 (max 4)
- age ? 1: 2186166456 bytes, 2186166456 total
: 21705536K->2411712K(21705536K), 1.0172150 secs]
51431055K->35601035K(72624960K), 1.0173520 secs] [Times: user=14.43
sys=0.01, real=1.02 secs]?
2012-09-19T15:48:23.766-0400: 1206972.964: [GC [1 CMS-initial-mark:
33189323K(50919424K)] 35624491K(72624960K), 0.4248680 secs] [Times:
user=0.42 sys=0.00, real=0.42 secs]?
2012-09-19T15:48:24.191-0400: 1206973.389: [CMS-concurrent-mark-start]
2012-09-19T15:48:26.114-0400: 1206975.312: [CMS-concurrent-mark:
1.922/1.923 secs] [Times: user=10.17 sys=0.00, real=1.92 secs]?
2012-09-19T15:48:26.114-0400: 1206975.312: [CMS-concurrent-preclean-start]
2012-09-19T15:48:26.276-0400: 1206975.475: [CMS-concurrent-preclean:
0.161/0.163 secs] [Times: user=0.16 sys=0.00, real=0.17 secs]?
2012-09-19T15:48:26.276-0400: 1206975.475:
[CMS-concurrent-abortable-preclean-start]
?CMS: abort preclean due to time 2012-09-19T15:48:31.387-0400: 1206980.586:
[CMS-concurrent-abortable-preclean: 4.582/5.111 secs] [Times: user=5.02
sys=0.01, real=5.11 secs]?
2012-09-19T15:48:31.388-0400: 1206980.586: [GC[YG occupancy: 2751488 K
(21705536 K)]1206980.586: [Rescan (parallel) , 0.1391430 secs]1206980.725:
[weak refs processing, 0.2528810 secs] [1 CMS-remark: 33189323K(50919424K)]
35940812K(72624960K), 0.3932910 secs] [Times: user=6.48 sys=0.02, real=0.39
secs]?
2012-09-19T15:48:31.781-0400: 1206980.980: [CMS-concurrent-sweep-start]
2012-09-19T15:48:50.677-0400: 1206999.875: [CMS-concurrent-sweep:
18.894/18.896 secs] [Times: user=22.16 sys=0.04, real=18.89 secs]?
2012-09-19T15:48:50.677-0400: 1206999.875: [CMS-concurrent-reset-start]
2012-09-19T15:48:50.787-0400: 1206999.986: [CMS-concurrent-reset:
0.110/0.110 secs] [Times: user=0.11 sys=0.00, real=0.11 secs]?
2012-09-19T15:50:46.472-0400: 1207115.670: [GC 1207115.671: [ParNew
Desired survivor size 1234796544 bytes, new threshold 1 (max 4)
- age ? 1: 2460495072 bytes, 2460495072 total
: 21705536K->2411712K(21705536K), 1.5029900 secs]
38573074K->22241303K(72624960K), 1.5031370 secs] [Times: user=21.39
sys=0.01, real=1.51 secs]?
2012-09-19T15:52:31.997-0400: 1207221.195: [GC 1207221.195: [ParNew
Desired survivor size 1234796544 bytes, new threshold 1 (max 4)
- age ? 1: 2383579648 bytes, 2383579648 total
: 21705536K->2411712K(21705536K), 1.5506250 secs]
41535127K->25853570K(72624960K), 1.5507680 secs] [Times: user=19.89
sys=0.03, real=1.55 secs]?
2012-09-19T15:57:11.344-0400: 1207500.543: [GC 1207500.543: [ParNew
Desired survivor size 1234796544 bytes, new threshold 1 (max 4)
- age ? 1: 2418667680 bytes, 2418667680 total
: 21705536K->2411712K(21705536K), 1.0315930 secs]
45147394K->30233927K(72624960K), 1.0317280 secs] [Times: user=16.29
sys=0.02, real=1.04 secs]?
2012-09-19T16:03:18.945-0400: 1207868.144: [GC 1207868.144: [ParNew
Desired survivor size 1234796544 bytes, new threshold 1 (max 4)
- age ? 1: 2073140800 bytes, 2073140800 total
: 21705536K->2411712K(21705536K), 0.9741820 secs]
49527751K->33922371K(72624960K), 0.9743210 secs] [Times: user=14.52
sys=0.03, real=0.98 secs]?
2012-09-19T16:05:52.719-0400: 1208021.918: [GC 1208021.918: [ParNew
Desired survivor size 1234796544 bytes, new threshold 1 (max 4)
- age ? 1: 2398660792 bytes, 2398660792 total
: 21705536K->2411712K(21705536K), 1.2001310 secs]
53216195K->36484638K(72624960K), 1.2002770 secs] [Times: user=18.38
sys=0.01, real=1.20 secs]?
2012-09-19T16:05:53.920-0400: 1208023.118: [GC [1 CMS-initial-mark:
34072926K(50919424K)] 36624798K(72624960K), 1.8306890 secs] [Times:
user=1.83 sys=0.00, real=1.83 secs]?
2012-09-19T16:05:55.751-0400: 1208024.949: [CMS-concurrent-mark-start]
2012-09-19T16:05:57.927-0400: 1208027.125: [CMS-concurrent-mark:
2.174/2.176 secs] [Times: user=14.51 sys=0.02, real=2.17 secs]?
2012-09-19T16:05:57.927-0400: 1208027.125: [CMS-concurrent-preclean-start]
2012-09-19T16:05:58.165-0400: 1208027.363: [CMS-concurrent-preclean:
0.234/0.238 secs] [Times: user=0.47 sys=0.00, real=0.24 secs]?
2012-09-19T16:05:58.165-0400: 1208027.363:
[CMS-concurrent-abortable-preclean-start]
?CMS: abort preclean due to time 2012-09-19T16:06:03.630-0400: 1208032.828:
[CMS-concurrent-abortable-preclean: 5.403/5.465 secs] [Times: user=14.12
sys=0.09, real=5.47 secs]?
2012-09-19T16:06:03.630-0400: 1208032.829: [GC[YG occupancy: 6072639 K
(21705536 K)]1208032.829: [Rescan (parallel) , 0.8860860 secs]1208033.715:
[weak refs processing, 0.3105550 secs] [1 CMS-remark: 34072926K(50919424K)]
40145566K(72624960K), 1.2026100 secs] [Times: user=19.96 sys=0.06,
real=1.20 secs]?
2012-09-19T16:06:04.833-0400: 1208034.031: [CMS-concurrent-sweep-start]
2012-09-19T16:06:19.800-0400: 1208048.999: [CMS-concurrent-sweep:
14.966/14.967 secs] [Times: user=35.33 sys=0.08, real=14.96 secs]?
2012-09-19T16:06:19.800-0400: 1208048.999: [CMS-concurrent-reset-start]
2012-09-19T16:06:19.943-0400: 1208049.141: [CMS-concurrent-reset:
0.142/0.143 secs] [Times: user=0.37 sys=0.00, real=0.15 secs]?
2012-09-19T16:07:21.398-0400: 1208110.596: [GC 1208110.596: [ParNew
Desired survivor size 1234796544 bytes, new threshold 1 (max 4)
- age ? 1: 2387743168 bytes, 2387743168 total
: 21705536K->2411712K(21705536K), 1.8267340 secs]
42297347K->26739701K(72624960K), 1.8268780 secs] [Times: user=21.04
sys=0.02, real=1.83 secs]?
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20120924/dc8176c5/attachment.html 