Promotion Failure with CMS

Tue Sep 25 22:55:55 PDT 2012

Hi Flo

I have a follow up question.

Is Promotion failure caused by un-availability of contiguous free space in
old gen for whole of young gen? If my young gen has 2 GB of live data set
which contains of objects of different sizes like 200kb to 30 mb,and
promotion failure happens -is it because GC is trying to fit in all 2gb in
contiguous space in old gen?

Thanks
Saroj

On Tue, Sep 25, 2012 at 3:25, roz dev <rozdev29 at gmail.com> wrote:

> Hi Flo
>
> Thanks for your inputs. We are using Solr 4 for doing sorting for lots of
> searches and Solr is creating lots of arrays, behind the scene to do the
> sorting.
>
> This is causing our memory consumption to be higher than usual. We are
> planning to change the young gen to be 5 gb and see what happens.
>
> We will keep you all posted.
>
> Thanks
> Saroj
>
>
> On Tue, Sep 25, 2012 at 3:16 AM, Florian Binder <java at java4.info> wrote:
>
>>  Hi Roz,
>>
>> you have a very large new generation. This results in a lot of objects
>> being promoted in each minor collection. In your cases it tries to promote
>> about 2gb of data to the 48gb old generation with about 16gb of free space.
>> Probably due to fragmentation this can't be done. Do you have large objects
>> (arrays) in your application?
>> Have you already tried to reduce your new generation? Maybe 2gb are
>> enough? This would result in less data for promotion and more space for the
>> old generation which reduces fragmentation problems.
>>
>> Since there has been a bug resulting in (more) fragmentation you should
>> update to >= 6u25 (see [1]).
>>
>> Promotion failures always result in a full (stw) collection, which took
>> in your case 32 seconds.
>>
>>
>> [1]: http://bugs.sun.com/view_bug.do?bug_id=6999988
>>
>> Regards,
>> Flo
>>
>>
>>
>> Am 24.09.2012 22:50, schrieb roz dev:
>>
>>
>> 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]?
>>
>>
>>
>>
>> _______________________________________________
>> hotspot-gc-use mailing listhotspot-gc-use at openjdk.java.nethttp://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use
>>
>>
>>
>> _______________________________________________
>> hotspot-gc-use mailing list
>> hotspot-gc-use at openjdk.java.net
>> http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use
>>
>>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20120925/ca32c86e/attachment-0001.html 