promotion failed

[Jon Masamitsu]

Ken,

A promotion failure is often a sign that  the  CMS
collection did not start soon enough.  In your case
based on the -XX:CMSInitiatingOccupancyFraction=70
flag, it looks like the CMS collection would have started
soon and that was a little too late.  There is probably a
fair amount of fragmentation in the CMS generation
at the point of the promotion failure since it looks like
there is 100m free in the CMS generation and from
the log fragment you sent, it looks like the promotion
rate is very low.

If most of the data in you application is short lived,
try increasing the MaxTenuringThreshold to see
if you can keep more of it in the young gen until it
dies.

A smaller CMSInitiatingOccupancyFraction will
help as will a larger heap, but if fragmentation
is your real problem, then those will only delay
the promotion failure.

If it's fragementation, take a look at

http://blogs.sun.com/jonthecollector/entry/when_the_sum_of_the

for some suggestions.

Jon



Ken-- at newsgroupstats.hk wrote On 07/18/08 09:43,:

>Hi Jon,
>
>uptime is 346136 (96 hours)
>
>first Big GC occur at 227781 second (63th hour)
>
>2nd Big GC occur at 311815 second (86th hour)
>
>Total count of promotion failed = 2
>
>Regards,
>Ken
>
>
>
>Jon Masamitsu wrote:
>  
>
>>Ken,
>>
>>How often do your promotion failures occur?
>>
>>Jon
>>
>>Ken-- at newsgroupstats.hk wrote On 07/18/08 05:21,:
>>
>>    
>>
>>>Dear All,
>>>
>>>please advise any more tuning for avoiding promotion failed
>>>
>>>VM Options:
>>>"C:\Program Files\Java\jdk1.6.0_04\bin\java" -server -verbose:gc
>>>-XX:+PrintGCDetails -Xloggc:gc.log -showversion -Xms4G -Xmx4G
>>>-XX:NewSize=512M -XX:PermSize=64M -XX:MaxPermSize=64M
>>>-XX:+CMSClassUnloadingEnabled -XX:+DisableExplicitGC
>>>      
>>>
>-XX:+UseConcMarkSweepGC
>  
>
>>>-XX:+UseParNewGC -XX:SurvivorRatio=6 -XX:CMSInitiatingOccupancyFraction=70
>>>-XX:TargetSurvivorRatio=90 -XX:+HandlePromotionFailure
>>>-Dcom.sun.management.jmxremote.port=7191
>>>-Dcom.sun.management.jmxremote.authenticate=false
>>>-Dcom.sun.management.jmxremote.ssl=false
>>>
>>>GC Log:
>>>227734.958: [GC 227734.958: [ParNew: 458751K->65536K(458752K), 0.4883967
>>>secs] 2975829K->2611470K(4128768K), 0.4885529 secs] [Times: user=1.42
>>>sys=0.20, real=0.48 secs] 
>>>227781.363: [GC 227781.363: [ParNew (promotion failed):
>>>458752K->458751K(458752K), 1.1739277 secs]
>>>227782.544: [CMS: 2566464K->903491K(3670016K), 14.2218888 secs]
>>>3004686K->903491K(4128768K), 15.4022930 secs] [Times: user=16.16 sys=0.70,
>>>real=15.39 secs] 
>>>227796.767: [GC [1 CMS-initial-mark: 903491K(3670016K)] 910269K(4128768K),
>>>0.0014926 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] 
>>>227796.769: [CMS-concurrent-mark-start]
>>>227799.448: [GC 227799.449: [ParNew: 393216K->21851K(458752K), 0.0851390
>>>secs] 1296707K->925343K(4128768K), 0.0853620 secs] [Times: user=0.86
>>>sys=0.00, real=0.09 secs] 
>>>227799.536: [CMS-concurrent-mark: 2.670/2.767 secs] [Times: user=9.72
>>>sys=0.03, real=2.77 secs] 
>>>227799.536: [CMS-concurrent-preclean-start]
>>>227800.624: [GC 227800.624: [ParNew: 415067K->11565K(458752K), 0.0345770
>>>secs] 1318559K->915056K(4128768K), 0.0347455 secs] [Times: user=0.27
>>>sys=0.06, real=0.05 secs] 
>>>227800.684: [CMS-concurrent-preclean: 0.995/1.148 secs] [Times: user=4.38
>>>sys=0.23, real=1.14 secs] 
>>>227800.684: [CMS-concurrent-abortable-preclean-start]
>>>227801.270: [CMS-concurrent-abortable-preclean: 0.475/0.587 secs] [Times:
>>>user=2.22 sys=0.09, real=0.59 secs] 
>>>227801.273: [GC[YG occupancy: 240407 K (458752 K)]227801.273: [Rescan
>>>(parallel) , 0.0092978 secs]227801.282: [weak refs processing, 0.0002179
>>>secs]227801.283: [class unloading, 0.0082907 secs]227801.291: [scrub
>>>      
>>>
>symbol
>  
>
>>>& string tables, 0.0066056 secs] [1 CMS-remark: 903491K(3670016K)]
>>>1143898K(4128768K), 0.0275619 secs] [Times: user=0.03 sys=0.00, real=0.03
>>>secs] 
>>>227801.302: [CMS-concurrent-sweep-start]
>>>227803.075: [CMS-concurrent-sweep: 1.773/1.773 secs] [Times: user=4.19
>>>sys=0.03, real=1.77 secs] 
>>>227803.075: [CMS-concurrent-reset-start]
>>>227803.103: [CMS-concurrent-reset: 0.028/0.028 secs] [Times: user=0.06
>>>sys=0.00, real=0.03 secs] 
>>>227816.785: [GC 227816.786: [ParNew: 404776K->25694K(458752K), 0.2086003
>>>secs] 1188297K->809215K(4128768K), 0.2087517 secs] [Times: user=1.13
>>>sys=0.19, real=0.20 secs] 
>>>
>>>Regards,
>>>Ken
>>>
>>>
>>>
>>> 
>>>
>>>      
>>>
>>
>>    
>>
>
>  
>