Promotion Failure with CMS
Florian Binder
java at java4.info
Wed Sep 26 03:29:44 PDT 2012
Hi Saroj,
no every object is promoted separately. But if you have some large
arrays you need some large chunks for them. So in your case you do not
need 2gb of contiguous free space but a lot of contiguous 200kb to 30mb
chunks.
With -XX:PrintFLSStatistics=1 you get some interesting information about
the FreeChunks which includes the MaxChunkSize as well.
Flo
Am 26.09.2012 07:55, schrieb roz dev:
> 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
> <mailto: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
> <mailto: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 <tel:24.09.2012%2022>: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 <tel:2292042936> bytes, 2292042936
>> <tel: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 <tel:2398571736> bytes, 2398571736
>> <tel: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 <tel:2186166456> bytes, 2186166456
>> <tel: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 <tel:2073140800> bytes, 2073140800
>> <tel: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 <tel:2398660792> bytes, 2398660792
>> <tel: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 list
>> hotspot-gc-use at openjdk.java.net <mailto:hotspot-gc-use at openjdk.java.net>
>> http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use
>
>
> _______________________________________________
> hotspot-gc-use mailing list
> hotspot-gc-use at openjdk.java.net
> <mailto: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/20120926/dfed6c71/attachment-0001.html
More information about the hotspot-gc-use
mailing list