Long GC pause time

noam katzowicz noam_kat at hotmail.com
Wed Sep 1 07:32:41 PDT 2010 

Thanks for the quick response.
 
ParallelRefProcEnabled really improved the weakref processing time.
 
Regarding sizing the survivor space, how do you recommend to do it?
We tried in the past different newGen sizes, but due to the large amounts of allocated objects, young gen gc introduced too 
much latency. So, we decided to move the pressure to the CMS.
 
Thanks.

 
> Date: Tue, 31 Aug 2010 16:57:36 -0700
> From: y.s.ramakrishna at oracle.com
> To: noam_kat at hotmail.com
> CC: hotspot-gc-use at openjdk.java.net
> Subject: Re: Long GC pause time
> 
> 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
 		 	   		  
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20100901/0e80b3e8/attachment-0001.html

More information about the hotspot-gc-use mailing list