[prev in list] [next in list] [prev in thread] [next in thread] 

List:       openjdk-hotspot-gc-use
Subject:    Long GC pause time
From:       y.s.ramakrishna () oracle ! com (Y !  S !  Ramakrishna)
Date:       2010-08-31 23:57:36
Message-ID: 4C7D96F0.1060600 () oracle ! com
[Download RAW message or body]

oh, and -XX:+PrintReferenceGC to get more detail on
what kind of Reference objects are causing the issue.

-- ramki

On 08/31/10 15:27, Y. S. Ramakrishna wrote:
> Noam, also please provision and use the survivor spaces to age
> objects and reduce pressure on CMS. The premature
> promotion and subsequent death is probably exacerbating the
> proliferating Ref object deaths (if i may be permitted an
> oxymoron) in the old gen.
> 
> -- ramki
> 
> On 08/31/10 11:28, Jon Masamitsu wrote:
>> Try -XX+ParallelRefProcEnabled
>>
>> Your spending much of the pause time doing Reference processing
>>
>> 89.867: [GC[YG occupancy: 420 K (274752 K)]89.867: [Rescan (parallel) , 
>> 0.0242770 secs]89.892: [weak refs processing, 1.3860230 secs] [1 
>> CMS-remark: 4198190K(6635136K)] 4198611K(6909888K), 1.4164670 secs] 
>> [Times: user=1.68 sys=0.01, real=1.41 secs]
>>
>> (see the "[weak refs processing, 1.3860230 secs]") so doing it in 
>> parallel might
>> help.  ParallelRefProcEnabled isn't always a win so it's not "on" by 
>> default.
>>
>> You might also try -XX:+CMSScavengeBeforeRemark.  That's a just a guess.
>> Sometimes doing a minor collection before the remark helps.
>>
>> On 08/31/10 08:22, noam katzowicz wrote:
>>> Hello.
>>>  
>>> We are running JBoss AS over RH5, using java 6u21, with the following 
>>> GC params:
>>>  
>>> -Xms6750m -Xmx6750m
>>> -XX:+UseConcMarkSweepGC
>>> -XX:SurvivorRatio=128
>>> -XX:MaxTenuringThreshold=0
>>> -XX:+UseCompressedOops
>>> -XX:CMSInitiatingOccupancyFraction=60
>>> -Dsun.rmi.dgc.client.gcInterval=3600000
>>> -Dsun.rmi.dgc.server.gcInterval=3600000
>>> -XX:+PrintGCTimeStamps -XX:+PrintGCDetails -XX:+PrintTenuringDistribution
>>>  
>>> We are experiencing relatively long GC pause time of over 1 second.
>>> Our application allocates hundreds of MBs per second. We?ve tried 
>>> different generation sizes but the above was the best we came up with. 
>>> Your help is appreciated.
>>>  
>>>
>>> Desired survivor size 1081344 bytes, new threshold 0 (max 0)
>>> : 272640K->0K(274752K), 0.0596370 secs] 4422502K->4173928K(6909888K), 
>>> 0.0606730 secs] [Times: user=0.44 sys=0.03, real=0.06 secs]
>>> 89.486: [CMS-concurrent-preclean: 1.308/1.649 secs] [Times: user=10.32 
>>> sys=2.30, real=1.65 secs]
>>> 89.487: [CMS-concurrent-abortable-preclean-start]
>>> 89.804: [GC 89.804: [ParNew
>>> Desired survivor size 1081344 bytes, new threshold 0 (max 0)
>>> : 272640K->0K(274752K), 0.0603670 secs] 4446568K->4198190K(6909888K), 
>>> 0.0614310 secs] [Times: user=0.48 sys=0.03, real=0.07 secs]
>>> 89.866: [CMS-concurrent-abortable-preclean: 0.293/0.379 secs] [Times: 
>>> user=2.42 sys=0.54, real=0.38 secs]
>>> 89.867: [GC[YG occupancy: 420 K (274752 K)]89.867: [Rescan (parallel) 
>>> , 0.0242770 secs]89.892: [weak refs processing, 1.3860230 secs] [1 
>>> CMS-remark: 4198190K(6635136K)] 4198611K(6909888K), 1.4164670 secs] 
>>> [Times: user=1.68 sys=0.01, real=1.41 secs]
>>> 91.284: [CMS-concurrent-sweep-start]
>>> 91.590: [GC 91.591: [ParNew
>>> Desired survivor size 1081344 bytes, new threshold 0 (max 0)
>>> : 272640K->0K(274752K), 0.0675550 secs] 4371287K->4128966K(6909888K), 
>>> 0.0683470 secs] [Times: user=0.56 sys=0.01, real=0.07 secs]
>>> 91.860: [GC 91.860: [ParNew
>>> Desired survivor size 1081344 bytes, new threshold 0 (max 0)
>>> : 272640K->0K(274752K), 0.0604320 secs] 4308368K->4053829K(6909888K), 
>>> 0.0612020 secs] [Times: user=0.41 sys=0.01, real=0.06 secs]
>>> 92.786: [GC 92.787: [ParNew
>>> Desired survivor size 1081344 bytes, new threshold 0 (max 0)
>>> : 272640K->0K(274752K), 0.1028730 secs] 3964957K->3753351K(6909888K), 
>>> 0.1038490 secs] [Times: user=0.80 sys=0.02, real=0.10 secs]
>>> 93.106: [GC 93.107: [ParNew
>>> Desired survivor size 1081344 bytes, new threshold 0 (max 0)
>>> : 272640K->0K(274752K), 0.0487000 secs] 3949085K->3699496K(6909888K), 
>>> 0.0494470 secs] [Times: user=0.32 sys=0.01, real=0.05 secs]
>>> 93.371: [GC 93.371: [ParNew
>>> Desired survivor size 1081344 bytes, new threshold 0 (max 0)
>>> : 272640K->0K(274752K), 0.0430620 secs] 3905862K->3652769K(6909888K), 
>>> 0.0438800 secs] [Times: user=0.33 sys=0.01, real=0.05 secs]
>>> 94.637: [GC 94.638: [ParNew
>>> Desired survivor size 1081344 bytes, new threshold 0 (max 0)
>>> : 272640K->0K(274752K), 0.0564930 secs] 3416325K->3164258K(6909888K), 
>>> 0.0575000 secs] [Times: user=0.44 sys=0.02, real=0.06 secs]
>>> 94.863: [CMS-concurrent-sweep: 3.107/3.578 secs] [Times: user=16.85 
>>> sys=3.23, real=3.58 secs]
>>> 94.863: [CMS-concurrent-reset-start]
>>> 94.878: [CMS-concurrent-reset: 0.015/0.015 secs] [Times: user=0.03 
>>> sys=0.01, real=0.02 secs]
>>> 95.981: [GC 95.981: [ParNew
>>> Desired survivor size 1081344 bytes, new threshold 0 (max 0)
>>> : 272640K->0K(274752K), 0.0514980 secs] 3405940K->3152334K(6909888K), 
>>> 0.0524610 secs] [Times: user=0.44 sys=0.01, real=0.05 secs]
>>> 100.179: [GC 100.180: [ParNew
>>> Desired survivor size 1081344 bytes, new threshold 0 (max 0)
>>> : 272640K->0K(274752K), 0.0676510 secs] 3424974K->3178150K(6909888K), 
>>> 0.0686240 secs] [Times: user=0.58 sys=0.00, real=0.07 secs]
>>> 100.909: [GC 100.909: [ParNew
>>> Desired survivor size 1081344 bytes, new threshold 0 (max 0)
>>> : 272640K->0K(274752K), 0.0707060 secs] 3450790K->3202638K(6909888K), 
>>> 0.0717030 secs] [Times: user=0.55 sys=0.01, real=0.07 secs]
>>> 101.613: [GC 101.613: [ParNew
>>> Desired survivor size 1081344 bytes, new threshold 0 (max 0)
>>> : 272636K->0K(274752K), 0.0667270 secs] 3475274K->3224061K(6909888K), 
>>> 0.0678240 secs] [Times: user=0.50 sys=0.01, real=0.07 secs]
>>> 102.072: [GC 102.073: [ParNew
>>> Desired survivor size 1081344 bytes, new threshold 0 (max 0)
>>> : 272635K->0K(274752K), 0.0590350 secs] 3496696K->3241246K(6909888K), 
>>> 0.0601190 secs] [Times: user=0.44 sys=0.00, real=0.06 secs]
>>> 102.756: [GC 102.756: [ParNew
>>> Desired survivor size 1081344 bytes, new threshold 0 (max 0)
>>> : 272613K->0K(274752K), 0.0630060 secs] 3513860K->3262602K(6909888K), 
>>> 0.0640320 secs] [Times: user=0.49 sys=0.00, real=0.07 secs]
>>> 103.452: [GC 103.453: [ParNew
>>> Desired survivor size 1081344 bytes, new threshold 0 (max 0)
>>> : 272640K->0K(274752K), 0.0533390 secs] 3535242K->3280184K(6909888K), 
>>> 0.0543760 secs] [Times: user=0.41 sys=0.01, real=0.06 secs]
>>> 104.462: [GC 104.462: [ParNew
>>> Desired survivor size 1081344 bytes, new threshold 0 (max 0)
>>> : 272640K->0K(274752K), 0.0729890 secs] 3552824K->3299003K(6909888K), 
>>> 0.0740260 secs] [Times: user=0.48 sys=0.01, real=0.07 secs]
>>> 106.274: [GC 106.274: [ParNew
>>> Desired survivor size 1081344 bytes, new threshold 0 (max 0)
>>> : 272640K->0K(274752K), 0.0609880 secs] 3571643K->3314370K(6909888K), 
>>> 0.0619510 secs] [Times: user=0.41 sys=0.00, real=0.06 secs]
>>> 108.154: [GC 108.155: [ParNew
>>> Desired survivor size 1081344 bytes, new threshold 0 (max 0)
>>> : 272640K->0K(274752K), 0.1251050 secs] 3587010K->3343996K(6909888K), 
>>> 0.1261630 secs] [Times: user=0.71 sys=0.02, real=0.13 secs]
>>> 108.882: [GC 108.883: [ParNew
>>> Desired survivor size 1081344 bytes, new threshold 0 (max 0)
>>> : 272640K->0K(274752K), 0.0952060 secs] 3616636K->3369490K(6909888K), 
>>> 0.0962930 secs] [Times: user=0.64 sys=0.01, real=0.10 secs]
>>> 109.482: [GC 109.482: [ParNew
>>> Desired survivor size 1081344 bytes, new threshold 0 (max 0)
>>> : 272936K->0K(274752K), 0.0791270 secs] 3642426K->3392040K(6909888K), 
>>> 0.0800830 secs] [Times: user=0.53 sys=0.01, real=0.08 secs]
>>> 109.948: [GC 109.949: [ParNew
>>> Desired survivor size 1081344 bytes, new threshold 0 (max 0)
>>> : 273038K->0K(274752K), 0.0835410 secs] 3665079K->3417813K(6909888K), 
>>> 0.0845680 secs] [Times: user=0.57 sys=0.00, real=0.08 secs]
>>> 110.035: [GC 110.035: [ParNew
>>> Desired survivor size 1081344 bytes, new threshold 0 (max 0)
>>> : 64K->0K(274752K), 0.0088490 secs] 3417877K->3417828K(6909888K), 
>>> 0.0093860 secs] [Times: user=0.09 sys=0.00, real=0.01 secs]
>>> 110.484: [GC 110.485: [ParNew
>>> Desired survivor size 1081344 bytes, new threshold 0 (max 0)
>>> : 272640K->0K(274752K), 0.0880810 secs] 3690468K->3443727K(6909888K), 
>>> 0.0890560 secs] [Times: user=0.59 sys=0.00, real=0.09 secs]
>>> 110.910: [GC 110.910: [ParNew
>>> Desired survivor size 1081344 bytes, new threshold 0 (max 0)
>>> : 272640K->0K(274752K), 0.0860790 secs] 3716367K->3475451K(6909888K), 
>>> 0.0870070 secs] [Times: user=0.58 sys=0.02, real=0.08 secs]
>>> 111.276: [GC 111.277: [ParNew
>>> Desired survivor size 1081344 bytes, new threshold 0 (max 0)
>>> : 272639K->0K(274752K), 0.0772230 secs] 3748091K->3503686K(6909888K), 
>>> 0.0782780 secs] [Times: user=0.47 sys=0.02, real=0.08 secs]
>>> 111.658: [GC 111.659: [ParNew
>>> Desired survivor size 1081344 bytes, new threshold 0 (max 0)
>>> : 272640K->0K(274752K), 0.0754700 secs] 3776326K->3532682K(6909888K), 
>>> 0.0763440 secs] [Times: user=0.54 sys=0.01, real=0.07 secs]
>>> 112.068: [GC 112.068: [ParNew
>>> Desired survivor size 1081344 bytes, new threshold 0 (max 0)
>>> : 272640K->0K(274752K), 0.0705680 secs] 3805322K->3559619K(6909888K), 
>>> 0.0714610 secs] [Times: user=0.47 sys=0.02, real=0.07 secs]
>>> 112.497: [GC 112.498: [ParNew
>>> Desired survivor size 1081344 bytes, new threshold 0 (max 0)
>>> : 272640K->0K(274752K), 0.0779750 secs] 3832259K->3589461K(6909888K), 
>>> 0.0788830 secs] [Times: user=0.50 sys=0.01, real=0.08 secs]
>>> 112.911: [GC 112.911: [ParNew
>>> Desired survivor size 1081344 bytes, new threshold 0 (max 0)
>>> : 272640K->0K(274752K), 0.0728900 secs] 3862101K->3616744K(6909888K), 
>>> 0.0738560 secs] [Times: user=0.52 sys=0.00, real=0.07 secs]
>>> 113.362: [GC 113.363: [ParNew
>>> Desired survivor size 1081344 bytes, new threshold 0 (max 0)
>>> : 272640K->0K(274752K), 0.0609030 secs] 3889384K->3638477K(6909888K), 
>>> 0.0619050 secs] [Times: user=0.44 sys=0.01, real=0.06 secs]
>>> 113.829: [GC 113.829: [ParNew
>>> Desired survivor size 1081344 bytes, new threshold 0 (max 0)
>>> : 272614K->0K(274752K), 0.0641940 secs] 3911091K->3659305K(6909888K), 
>>> 0.0653490 secs] [Times: user=0.48 sys=0.01, real=0.06 secs]
>>> 114.311: [GC 114.311: [ParNew
>>> Desired survivor size 1081344 bytes, new threshold 0 (max 0)
>>> : 272640K->0K(274752K), 0.0618170 secs] 3931945K->3681619K(6909888K), 
>>> 0.0626970 secs] [Times: user=0.50 sys=0.01, real=0.06 secs]
>>> 114.841: [GC 114.842: [ParNew
>>> Desired survivor size 1081344 bytes, new threshold 0 (max 0)
>>> : 272640K->0K(274752K), 0.0670890 secs] 3954259K->3711036K(6909888K), 
>>> 0.0680540 secs] [Times: user=0.52 sys=0.02, real=0.07 secs]
>>> 115.356: [GC 115.357: [ParNew
>>> Desired survivor size 1081344 bytes, new threshold 0 (max 0)
>>> : 272640K->0K(274752K), 0.0623700 secs] 3983676K->3737945K(6909888K), 
>>> 0.0633630 secs] [Times: user=0.49 sys=0.00, real=0.07 secs]
>>> 115.829: [GC 115.830: [ParNew
>>> Desired survivor size 1081344 bytes, new threshold 0 (max 0)
>>> : 272640K->0K(274752K), 0.0665900 secs] 4010585K->3766876K(6909888K), 
>>> 0.0676240 secs] [Times: user=0.51 sys=0.01, real=0.06 secs]
>>> 116.271: [GC 116.271: [ParNew
>>> Desired survivor size 1081344 bytes, new threshold 0 (max 0)
>>> : 272630K->0K(274752K), 0.0594280 secs] 4039506K->3796861K(6909888K), 
>>> 0.0603620 secs] [Times: user=0.46 sys=0.02, real=0.06 secs]
>>> 116.716: [GC 116.717: [ParNew
>>> Desired survivor size 1081344 bytes, new threshold 0 (max 0)
>>> : 272640K->0K(274752K), 0.0724150 secs] 4069501K->3825191K(6909888K), 
>>> 0.0733430 secs] [Times: user=0.52 sys=0.01, real=0.08 secs]
>>> 117.145: [GC 117.146: [ParNew
>>> Desired survivor size 1081344 bytes, new threshold 0 (max 0)
>>> : 272640K->0K(274752K), 0.0664990 secs] 4097831K->3853057K(6909888K), 
>>> 0.0675760 secs] [Times: user=0.48 sys=0.00, real=0.07 secs]
>>> 117.543: [GC 117.545: [ParNew
>>> Desired survivor size 1081344 bytes, new threshold 0 (max 0)
>>> : 272640K->0K(274752K), 0.0650350 secs] 4125697K->3880562K(6909888K), 
>>> 0.0673450 secs] [Times: user=0.49 sys=0.01, real=0.07 secs]
>>> 117.956: [GC 117.956: [ParNew
>>> Desired survivor size 1081344 bytes, new threshold 0 (max 0)
>>> : 272640K->0K(274752K), 0.0664410 secs] 4153202K->3907935K(6909888K), 
>>> 0.0673980 secs] [Times: user=0.49 sys=0.02, real=0.07 secs]
>>> 118.385: [GC 118.386: [ParNew
>>> Desired survivor size 1081344 bytes, new threshold 0 (max 0)
>>> : 272631K->0K(274752K), 0.0655070 secs] 4180566K->3934925K(6909888K), 
>>> 0.0664120 secs] [Times: user=0.50 sys=0.01, real=0.07 secs]
>>> 118.826: [GC 118.827: [ParNew
>>> Desired survivor size 1081344 bytes, new threshold 0 (max 0)
>>> : 272608K->0K(274752K), 0.0605390 secs] 4207533K->3964211K(6909888K), 
>>> 0.0616050 secs] [Times: user=0.50 sys=0.02, real=0.06 secs]
>>> 119.233: [GC 119.234: [ParNew
>>> Desired survivor size 1081344 bytes, new threshold 0 (max 0)
>>> : 272640K->0K(274752K), 0.0656870 secs] 4236851K->3991065K(6909888K), 
>>> 0.0666900 secs] [Times: user=0.50 sys=0.02, real=0.07 secs]
>>> 119.301: [GC [1 CMS-initial-mark: 3991065K(6635136K)] 
>>> 3991071K(6909888K), 0.0091650 secs] [Times: user=0.01 sys=0.00, 
>>> real=0.01 secs]
>>> 119.311: [CMS-concurrent-mark-start]
>>> 119.699: [GC 119.699: [ParNew
>>> Desired survivor size 1081344 bytes, new threshold 0 (max 0)
>>> : 272640K->0K(274752K), 0.0647090 secs] 4263705K->4019961K(6909888K), 
>>> 0.0656290 secs] [Times: user=0.53 sys=0.01, real=0.06 secs]
>>> 120.081: [GC 120.082: [ParNew
>>> Desired survivor size 1081344 bytes, new threshold 0 (max 0)
>>> : 272640K->0K(274752K), 0.0641110 secs] 4292601K->4048334K(6909888K), 
>>> 0.0649070 secs] [Times: user=0.50 sys=0.01, real=0.06 secs]
>>> 120.538: [GC 120.539: [ParNew
>>> Desired survivor size 1081344 bytes, new threshold 0 (max 0)
>>> : 272640K->0K(274752K), 0.0677200 secs] 4320974K->4075491K(6909888K), 
>>> 0.0687990 secs] [Times: user=0.49 sys=0.03, real=0.07 secs]
>>> 120.621: [CMS-concurrent-mark: 1.076/1.310 secs] [Times: user=10.66 
>>> sys=1.73, real=1.31 secs]
>>> 120.621: [CMS-concurrent-preclean-start]
>>> 120.942: [GC 120.943: [ParNew
>>> Desired survivor size 1081344 bytes, new threshold 0 (max 0)
>>> : 272640K->0K(274752K), 0.0736770 secs] 4348131K->4104969K(6909888K), 
>>> 0.0747430 secs] [Times: user=0.51 sys=0.03, real=0.07 secs]
>>> 121.337: [GC 121.338: [ParNew
>>> Desired survivor size 1081344 bytes, new threshold 0 (max 0)
>>> : 272640K->0K(274752K), 0.0569980 secs] 4377609K->4126623K(6909888K), 
>>> 0.0579070 secs] [Times: user=0.48 sys=0.03, real=0.06 secs]
>>> 121.766: [GC 121.767: [ParNew
>>> Desired survivor size 1081344 bytes, new threshold 0 (max 0)
>>> : 272615K->0K(274752K), 0.0590140 secs] 4399238K->4148770K(6909888K), 
>>> 0.0599510 secs] [Times: user=0.44 sys=0.03, real=0.06 secs]
>>> 122.174: [GC 122.175: [ParNew
>>> Desired survivor size 1081344 bytes, new threshold 0 (max 0)
>>> : 272640K->0K(274752K), 0.0531420 secs] 4421410K->4167895K(6909888K), 
>>> 0.0540310 secs] [Times: user=0.45 sys=0.03, real=0.05 secs]
>>> 122.257: [CMS-concurrent-preclean: 1.306/1.636 secs] [Times: 
>>> user=10.25 sys=2.21, real=1.63 secs]
>>> 122.257: [CMS-concurrent-abortable-preclean-start]
>>> 122.631: [GC 122.631: [ParNew
>>> Desired survivor size 1081344 bytes, new threshold 0 (max 0)
>>> : 272640K->0K(274752K), 0.0528220 secs] 4440535K->4187654K(6909888K), 
>>> 0.0537160 secs] [Times: user=0.46 sys=0.02, real=0.05 secs]
>>> 122.696: [CMS-concurrent-abortable-preclean: 0.355/0.439 secs] [Times: 
>>> user=2.50 sys=0.52, real=0.44 secs]
>>> 122.698: [GC[YG occupancy: 7874 K (274752 K)]122.698: [Rescan 
>>> (parallel) , 0.0253430 secs]122.723: [weak refs processing, 1.1038100 
>>> secs] [1 CMS-remark: 4187654K(6635136K)] 4195529K(6909888K), 1.1357970 
>>> secs] [Times: user=1.42 sys=0.01, real=1.14 secs]
>>> 123.834: [CMS-concurrent-sweep-start]
>>> 124.060: [GC 124.061: [ParNew
>>> Desired survivor size 1081344 bytes, new threshold 0 (max 0)
>>> : 272640K->0K(274752K), 0.0690300 secs] 4399395K->4167257K(6909888K), 
>>> 0.0698010 secs] [Times: user=0.52 sys=0.02, real=0.07 secs]
>>>  
>>> ------------------------------------------------------------------------
>>>
>>> _______________________________________________
>>> hotspot-gc-use mailing list
>>> 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
>> http://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

[prev in list] [next in list] [prev in thread] [next in thread]