JDK-6414985 : iCMS: auto-pacing issues
  • Type: Enhancement
  • Component: hotspot
  • Sub-Component: gc
  • Affected Version: 5.0u11,6,6u2
  • Priority: P3
  • Status: Closed
  • Resolution: Won't Fix
  • OS: generic,linux_2.6
  • CPU: generic,x86
  • Submitted: 2006-04-19
  • Updated: 2014-10-01
  • Resolved: 2014-10-01
Related Reports
Relates :  
JDK-6486089 - CMS: CMSInitiatingOccupancyFraction does not take effect
Description
Recent big apps testing of -Xincgc (which enables iCMS with auto-pacing)
appear to indicate that auto-pacing may not be working too well. In one
particular case (ATG with default options?), iCMS obstinately stuck to
a duty-cycle of close to 0 and would repeatedly run into concurrent
mode failures.

here's an example, albeit from a fastdebug run:

[ParNew: 3968K->0K(4032K), 0.2749890 secs] 3968K->593K(16320K), 0.2885700 secs]
[GC [1 CMS-initial-mark: 593K(12288K)] 2757K(16320K), 0.0250730 secs]
[GC [ParNew: 3968K->0K(4032K), 0.0889470 secs] 4561K->618K(16320K), 0.1021480 secs]
[GC [ParNew: 3964K->0K(4032K), 0.0991410 secs] 4582K->2345K(16320K), 0.1068090 secs]
[GC [ParNew: 3963K->0K(4032K), 0.0759430 secs] 6308K->4137K(16320K), 0.0817950 secs]
[GC [ParNew: 3962K->0K(4032K), 0.2536390 secs] 8100K->5867K(16320K), 0.2598500 secs]
[GC [ParNew: 3962K->0K(4032K), 0.0775730 secs] 9830K->7683K(16320K), 0.0841290 secs]
[CMS-concurrent-mark: 1.511/7.588 secs]
[GC [ParNew: 3968K->0K(4032K), 0.8945680 secs] 11651K->8131K(16320K), 0.8989950 secs]
[GC [ParNew: 3964K->0K(4032K), 0.2893990 secs] 12095K->9899K(16320K), 0.2960000 secs]
[CMS-concurrent-preclean: 0.282/2.288 secs]
[CMS-concurrent-abortable-preclean: 0.001/0.103 secs]
[GC[YG occupancy: 2505 K (4032 K)][checkpointRootsFinalWork[Rescan (parallel) , 0.0391710 secs][refProcessi
ngWork[weak refs processing, 0.0002790 secs], 0.0003600 secs], 0.0404190 secs] [1 CMS-remark: 9899K(12288K)
] 12404K(16320K), 0.0406260 secs]
[GC [ParNew: 3961K->0K(4032K), 0.1722770 secs] 13860K->11734K(16320K), 0.1780030 secs]
[CMS-concurrent-sweep: 0.012/0.505 secs]
[GC [ParNew: 3965K->0K(4032K), 0.1698730 secs] 15698K->13557K(23592K), 0.1756600 secs]
[CMS-concurrent-reset: 0.040/0.777 secs]
[GC [ParNew: 3968K->0K(4032K), 0.0675070 secs] 17525K->15361K(23592K) icms_dc=5 , 0.0734810 secs]
[GC [1 CMS-initial-mark: 15361K(19560K)] 18599K(23592K), 0.0967070 secs]
[GC [ParNew: 3968K->0K(4032K), 0.1122390 secs] 19329K->17070K(23592K) icms_dc=5 , 0.1173950 secs]
[CMS-concurrent-mark: 0.202/0.363 secs]
[CMS-concurrent-preclean: 0.005/0.006 secs]
[GC[YG occupancy: 157 K (4032 K)][checkpointRootsFinalWork[Rescan (parallel) , 0.0191160 secs][refProcessin
gWork[weak refs processing, 0.0149090 secs], 0.0156820 secs], 0.0352450 secs] [1 CMS-remark: 17070K(19560K)
] 17228K(23592K), 0.0354280 secs]
[CMS-concurrent-sweep: 0.214/0.214 secs]
[CMS-concurrent-reset: 0.012/0.012 secs]
[GC [1 CMS-initial-mark: 2744K(19560K)] 5032K(23592K), 0.0903140 secs]
[GC [ParNew: 3968K->0K(4032K), 0.6902760 secs] 6712K->3814K(23592K) icms_dc=0 , 0.7114050 secs]
[CMS-concurrent-mark: 0.431/1.221 secs]
[CMS-concurrent-preclean: 0.072/0.074 secs]
[GC[YG occupancy: 376 K (4032 K)][checkpointRootsFinalWork[Rescan (parallel) , 0.1933340 secs][refProcessin
gWork[weak refs processing, 0.0025520 secs], 0.0026870 secs], 0.1965770 secs] [1 CMS-remark: 3814K(19560K)]
 4191K(23592K), 0.1967470 secs]
[CMS-concurrent-sweep: 0.274/0.412 secs]
[CMS-concurrent-reset: 0.014/0.014 secs]
[GC [ParNew: 3960K->0K(4032K), 1.2903710 secs] 5777K->3359K(23592K) icms_dc=0 , 1.3076870 secs]
[GC [ParNew: 3967K->0K(4032K), 0.2974850 secs] 7327K->4981K(23592K) icms_dc=0 , 0.3101230 secs]
[GC [ParNew: 3968K->0K(4032K), 0.2411100 secs] 8949K->6761K(23592K) icms_dc=0 , 0.2490910 secs]
[GC [ParNew: 3968K->0K(4032K), 0.0765620 secs] 10729K->8584K(23592K) icms_dc=0 , 0.0829090 secs]
[GC [ParNew: 3966K->0K(4032K), 0.1574670 secs] 12551K->10407K(23592K) icms_dc=0 , 0.1639160 secs]
[GC [ParNew: 3968K->0K(4032K), 0.3044010 secs] 14375K->12192K(23592K) icms_dc=0 , 0.3113390 secs]
[GC [ParNew: 3967K->0K(4032K), 0.0722010 secs] 16160K->13997K(23592K) icms_dc=0 , 0.0813970 secs]
[GC [ParNew: 3962K->0K(4032K), 0.0725220 secs] 17959K->15770K(23592K) icms_dc=0 , 0.0815660 secs]
[GC [ParNew: 3967K->0K(4032K), 0.0704970 secs] 19738K->17583K(23592K) icms_dc=0 , 0.0794120 secs]
[GC [ParNew: 3964K->0K(4032K), 0.6074360 secs] 21547K->19411K(23720K) icms_dc=0 , 0.6162590 secs]
[GC [ParNew: 3967K->0K(4032K), 0.2511520 secs] 23378K->21233K(25512K) icms_dc=0 , 0.2591340 secs]
[GC [ParNew: 3961K->0K(4032K), 0.2097800 secs] 25194K->23048K(27304K) icms_dc=0 , 0.2184840 secs]
[GC [ParNew: 3961K->0K(4032K), 0.1982940 secs] 27010K->24876K(29224K) icms_dc=0 , 0.2253380 secs]
[GC [ParNew: 3962K->0K(4032K), 0.1602020 secs] 28839K->26697K(31016K) icms_dc=0 , 0.1692120 secs]
[GC [ParNew: 3968K->0K(4032K), 0.1772730 secs] 30665K->28469K(32808K) icms_dc=0 , 0.1864410 secs]
[GC [ParNew: 3967K->0K(4032K), 0.1046300 secs] 32437K->30299K(34600K) icms_dc=0 , 0.1140270 secs]
[GC [ParNew: 3968K->0K(4032K), 0.2668900 secs] 34267K->32129K(36520K) icms_dc=0 , 0.2757080 secs]
[GC [ParNew: 3968K->0K(4032K), 0.4998970 secs] 36097K->33936K(38312K) icms_dc=0 , 0.5083410 secs]
[GC [ParNew: 3962K->0K(4032K), 0.0939820 secs] 37898K->35654K(39976K) icms_dc=0 , 0.1022170 secs]
[GC [ParNew: 3968K->0K(4032K), 0.2714720 secs] 39622K->37475K(41768K) icms_dc=0 , 0.2802820 secs]
[GC [ParNew: 3962K->0K(4032K), 0.1874690 secs] 41437K->39304K(43688K) icms_dc=0 , 0.1957990 secs]
[GC [ParNew: 3966K->0K(4032K), 0.1373540 secs] 43270K->41133K(45480K) icms_dc=0 , 0.1461720 secs]
[GC [ParNew: 3963K->0K(4032K), 0.2667400 secs] 45096K->42906K(47272K) icms_dc=0 , 0.2870410 secs]
[GC [ParNew: 3968K->0K(4032K), 0.5858740 secs] 46874K->44675K(49064K) icms_dc=0 , 0.5960840 secs]
[GC [ParNew: 3968K->0K(4032K), 0.9313580 secs] 48643K->46403K(50728K) icms_dc=0 , 0.9408300 secs]
[GC [ParNew: 3968K->0K(4032K), 0.0755800 secs] 50371K->47972K(52392K) icms_dc=0 , 0.0855960 secs]
[GC [ParNew: 3967K->0K(4032K), 0.0903550 secs] 51940K->49761K(54184K) icms_dc=0 , 0.1005620 secs]
[GC [ParNew: 3968K->0K(4032K), 0.7428410 secs] 53729K->51565K(55976K) icms_dc=0 , 0.7532310 secs]
[GC [ParNew: 3962K->0K(4032K), 0.0705430 secs] 55527K->52312K(56744K) icms_dc=0 , 0.0817450 secs]
[GC [ParNew: 3967K->0K(4032K), 0.3009520 secs] 56280K->54151K(58536K) icms_dc=0 , 0.3111420 secs]
[GC [ParNew: 3968K->0K(4032K), 0.4323650 secs] 58119K->55789K(60200K) icms_dc=0 , 0.4516510 secs]
[GC [ParNew: 3968K->0K(4032K), 0.9389240 secs] 59757K->57596K(61992K) icms_dc=0 , 0.9482630 secs]
[GC [ParNew: 3964K->0K(4032K), 0.0914410 secs] 61561K->59145K(63528K) icms_dc=0 , 0.1015890 secs]
[GC [ParNew: 3965K->0K(4032K), 0.1055800 secs] 63111K->60932K(65448K) icms_dc=0 , 0.1166580 secs]
[GC [ParNew: 3966K->3966K(4032K), 0.0006820 secs][CMS (concurrent mode failure): 60932K->3930K(61416K), 0.6
157990 secs] 64898K->3930K(65448K) icms_dc=0 , 0.6273560 secs]
[GC [1 CMS-initial-mark: 3930K(61440K)] 3952K(65472K), 0.0283330 secs]
[GC [ParNew: 3968K->0K(4032K), 0.3344450 secs] 7898K->5670K(65472K) icms_dc=0 , 0.3438230 secs]
[GC [ParNew: 3967K->0K(4032K), 0.3422460 secs] 9638K->7381K(65472K) icms_dc=0 , 0.3518630 secs]
[GC [ParNew: 3968K->0K(4032K), 0.3301040 secs] 11349K->9101K(65472K) icms_dc=0 , 0.3395650 secs]
[GC [ParNew: 3964K->0K(4032K), 0.1738440 secs] 13066K->10822K(65472K) icms_dc=0 , 0.1833610 secs]
[GC [ParNew: 3968K->0K(4032K), 0.2554660 secs] 14790K->12529K(65472K) icms_dc=0 , 0.2721270 secs]
[GC [ParNew: 3967K->0K(4032K), 2.3883440 secs] 16497K->14306K(65472K) icms_dc=0 , 2.3923040 secs]
[GC [ParNew: 3965K->0K(4032K), 0.1843220 secs] 18272K->15948K(65472K) icms_dc=0 , 0.1938690 secs]
[GC [ParNew: 3968K->0K(4032K), 0.5584250 secs] 19916K->17455K(65472K) icms_dc=0 , 0.5668850 secs]
[GC [ParNew: 3965K->0K(4032K), 0.1456860 secs] 21421K->18931K(65472K) icms_dc=0 , 0.1547750 secs]
[GC [ParNew: 3966K->0K(4032K), 0.1473050 secs] 22898K->20349K(65472K) icms_dc=0 , 0.1553750 secs]
[GC [ParNew: 3968K->0K(4032K), 0.0591310 secs] 24317K->21624K(65472K) icms_dc=0 , 0.0664610 secs]
[GC [ParNew: 3968K->0K(4032K), 0.0980760 secs] 25592K->22580K(65472K) icms_dc=0 , 0.1033190 secs]
[GC [ParNew: 3962K->0K(4032K), 0.2098910 secs] 26543K->23154K(65472K) icms_dc=0 , 0.2134340 secs]
Time = 59227 ms   (168.84 requests/s; average latency = 592 ms)
0 errors out of 10000 requests
[CMS-concurrent-mark: 1.611/13.618 secs]
[CMS-concurrent-preclean: 0.018/0.018 secs]
[CMS-concurrent-abortable-preclean: 0.000/0.000 secs]
[GC[YG occupancy: 2123 K (4032 K)][checkpointRootsFinalWork[Rescan (parallel) , 0.3407410 secs][refProcessi
ngWork[weak refs processing, 0.0002730 secs], 0.0004020 secs], 0.3416230 secs] [1 CMS-remark: 23154K(61440K
)] 25278K(65472K), 0.3418150 secs]
[CMS-concurrent-sweep: 0.078/0.078 secs]
[CMS-concurrent-reset: 0.016/0.016 secs]

etc.

The same (or worse) anomalous behaviour manifested on the server as well.
Comments
iCMS is deprecated since JDK8 and it is bound to be removed in 9. Closing now, reopen (or re-create) if needed.
01-10-2014
EVALUATION A couple of issues have been identified in iCMS triggering which would explain the behaviour seen with ATG and with one customer. A binary with the fixes will be tested.
29-10-2007