Long GC pause time

Tue Aug 31 11:28:52 PDT 2010

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
>   
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20100831/d6e7cd34/attachment-0001.html 