Skip to main content

High young generation collection time and continously increasing trend

3 replies [Last post]
jainna
Offline
Joined: 2007-08-16
Points: 0

Environment

Sun SPARC Enterprise T5220
1 Quad core Ultrasparc T2 1
16 GB Physical RAM
JDK 1.6 Update 11
2GHz

Garbage Collection Settings
"-d64 -Xms8192m -Xmx8192m -XX:+UseConcMarkSweepGC -XX:+UseCMSInitiatingOccupancyOnly -XX:CMSInitiatingOccupancyFraction=55"

GC Logs
2009-07-02T05:33:06.405+0300: 5.192: [GC 5.192: [ParNew: 391936K->1668K(440896K), 0.0319798 secs] 391936K->1668K(8339648K), 0.0325461 secs] [Times: user=0.18 sys=0.04, real=0.03 secs]
2009-07-02T05:48:15.007+0300: 913.778: [GC 913.779: [ParNew: 393604K->3764K(440896K), 0.0463449 secs] 393604K->3764K(8339648K), 0.0474910 secs] [Times: user=0.22 sys=0.14, real=0.05 secs]
2009-07-02T05:54:33.533+0300: 1292.298: [GC 1292.299: [ParNew: 395700K->5707K(440896K), 0.0277407 secs] 395700K->5707K(8339648K), 0.0290752 secs] [Times: user=0.42 sys=0.04, real=0.03 secs]
2009-07-02T05:54:58.730+0300: 1317.495: [GC 1317.496: [ParNew: 397643K->9616K(440896K), 0.0466753 secs] 397643K->9616K(8339648K), 0.0479958 secs] [Times: user=0.33 sys=0.13, real=0.05 secs]
2009-07-02T05:56:05.598+0300: 1384.361: [GC 1384.362: [ParNew: 401552K->10249K(440896K), 0.0451478 secs] 401552K->11968K(8339648K), 0.0464465 secs] [Times: user=0.29 sys=0.08, real=0.05 secs]
2009-07-02T05:57:16.556+0300: 1455.318: [GC 1455.319: [ParNew: 402185K->13148K(440896K), 0.0246137 secs] 403904K->16290K(8339648K), 0.0259547 secs] [Times: user=0.28 sys=0.03, real=0.03 secs]
2009-07-02T05:58:05.908+0300: 1504.670: [GC 1504.671: [ParNew: 405084K->14229K(440896K), 0.0288785 secs] 408226K->19177K(8339648K), 0.0301709 secs] [Times: user=0.27 sys=0.05, real=0.03 secs]
2009-07-02T05:58:44.336+0300: 1543.097: [GC 1543.098: [ParNew: 406165K->19940K(440896K), 0.0326924 secs] 411113K->26288K(8339648K), 0.0340019 secs] [Times: user=0.25 sys=0.10, real=0.03 secs]
2009-07-02T05:59:27.747+0300: 1586.507: [GC 1586.508: [ParNew: 411876K->14656K(440896K), 0.0236641 secs] 418224K->23725K(8339648K), 0.0249670 secs] [Times: user=0.20 sys=0.02, real=0.03 secs]
2009-07-02T06:00:18.098+0300: 1636.857: [GC 1636.858: [ParNew: 406592K->20645K(440896K), 0.0242215 secs] 415661K->32491K(8339648K), 0.0255266 secs] [Times: user=0.21 sys=0.01, real=0.03 secs]
2009-07-02T06:00:56.482+0300: 1675.241: [GC 1675.242: [ParNew: 412581K->19408K(440896K), 0.0311651 secs] 424427K->34243K(8339648K), 0.0324523 secs] [Times: user=0.28 sys=0.09, real=0.03 secs]
2009-07-02T06:01:44.997+0300: 1723.754: [GC 1723.755: [ParNew: 411344K->18322K(440896K), 0.0206065 secs] 426179K->36150K(8339648K), 0.0219086 secs] [Times: user=0.22 sys=0.01, real=0.02 secs]
2009-07-02T06:02:38.856+0300: 1777.613: [GC 1777.614: [ParNew: 410258K->18492K(440896K), 0.0242026 secs] 428086K->39291K(8339648K), 0.0255033 secs] [Times: user=0.21 sys=0.02, real=0.03 secs]
2009-07-02T06:06:55.803+0300: 2034.555: [GC 2034.556: [ParNew: 410428K->15832K(440896K), 0.0251398 secs] 431227K->39984K(8339648K), 0.0264367 secs] [Times: user=0.21 sys=0.01, real=0.03 secs]
2009-07-02T06:10:45.413+0300: 2264.161: [GC 2264.162: [ParNew: 407768K->16589K(440896K), 0.0275477 secs] 431920K->43774K(8339648K), 0.0288602 secs] [Times: user=0.31 sys=0.02, real=0.03 secs]
2009-07-02T06:13:08.615+0300: 2407.361: [GC 2407.362: [ParNew: 408525K->15701K(440896K), 0.0391735 secs] 435710K->45927K(8339648K), 0.0404776 secs] [Times: user=0.55 sys=0.09, real=0.04 secs]
2009-07-02T06:15:27.705+0300: 2546.448: [GC 2546.449: [ParNew: 407637K->15650K(440896K), 0.0514922 secs] 437863K->48878K(8339648K), 0.0527958 secs] [Times: user=0.71 sys=0.13, real=0.05 secs]
2009-07-02T06:17:32.560+0300: 2671.301: [GC 2671.302: [ParNew: 407580K->15591K(440896K), 0.0608495 secs] 440808K->51280K(8339648K), 0.0621591 secs] [Times: user=0.90 sys=0.17, real=0.06 secs]
2009-07-02T06:20:04.351+0300: 2823.089: [GC 2823.090: [ParNew: 407521K->17681K(440896K), 0.0766429 secs] 443211K->56286K(8339648K), 0.0779674 secs] [Times: user=1.20 sys=0.27, real=0.08 secs]
2009-07-02T06:22:14.216+0300: 2952.953: [GC 2952.954: [ParNew: 409617K->16709K(440896K), 0.0825036 secs] 448222K->58374K(8339648K), 0.0838220 secs] [Times: user=1.28 sys=0.25, real=0.08 secs]
2009-07-02T06:24:41.041+0300: 3099.775: [GC 3099.776: [ParNew: 408645K->18942K(440896K), 0.0998305 secs] 450310K->63597K(8339648K), 0.1011755 secs] [Times: user=1.38 sys=0.29, real=0.10 secs]
2009-07-02T06:27:04.204+0300: 3242.935: [GC 3242.936: [ParNew: 410878K->18665K(440896K), 0.0995035 secs] 455533K->66354K(8339648K), 0.1008710 secs] [Times: user=1.43 sys=0.32, real=0.10 secs]
2009-07-02T06:29:08.056+0300: 3366.785: [GC 3366.786: [ParNew: 410601K->16236K(440896K), 0.1103226 secs] 458290K->67266K(8339648K), 0.1117468 secs] [Times: user=1.61 sys=0.41, real=0.11 secs]
2009-07-02T06:31:34.079+0300: 3512.806: [GC 3512.807: [ParNew: 408172K->16435K(440896K), 0.1097991 secs] 459202K->70915K(8339648K), 0.1111262 secs] [Times: user=1.62 sys=0.39, real=0.11 secs]
2009-07-02T06:33:56.279+0300: 3655.003: [GC 3655.004: [ParNew: 408371K->16907K(440896K), 0.1177724 secs] 462851K->75051K(8339648K), 0.1191131 secs] [Times: user=1.74 sys=0.47, real=0.12 secs]
2009-07-02T06:36:15.223+0300: 3793.945: [GC 3793.946: [ParNew: 408843K->15953K(440896K), 0.1226248 secs] 466987K->77475K(8339648K), 0.1239858 secs] [Times: user=1.75 sys=0.47, real=0.12 secs]
2009-07-02T06:38:32.169+0300: 3930.889: [GC 3930.890: [ParNew: 407889K->15831K(440896K), 0.1317965 secs] 469411K->80782K(8339648K), 0.1331274 secs] [Times: user=1.89 sys=0.59, real=0.13 secs]
2009-07-02T06:41:11.745+0300: 4090.462: [GC 4090.463: [ParNew: 407767K->15100K(440896K), 0.1345593 secs] 472718K->83295K(8339648K), 0.1358986 secs] [Times: user=1.90 sys=0.63, real=0.14 secs]
2009-07-02T06:43:25.006+0300: 4223.721: [GC 4223.722: [ParNew: 407036K->16175K(440896K), 0.1396390 secs] 475231K->87679K(8339648K), 0.1410184 secs] [Times: user=1.97 sys=0.69, real=0.14 secs]
2009-07-02T06:45:36.783+0300: 4355.495: [GC 4355.496: [ParNew: 408111K->15489K(440896K), 0.1418917 secs] 479615K->90300K(8339648K), 0.1432374 secs] [Times: user=1.98 sys=0.70, real=0.14 secs]
2009-07-02T06:47:49.212+0300: 4487.923: [GC 4487.924: [ParNew: 407425K->16587K(440896K), 0.1533496 secs] 482236K->94687K(8339648K), 0.1546858 secs] [Times: user=2.11 sys=0.84, real=0.16 secs]
2009-07-02T06:49:58.366+0300: 4617.075: [GC 4617.076: [ParNew: 408523K->16022K(440896K), 0.1608905 secs] 486623K->97324K(8339648K), 0.1622167 secs] [Times: user=2.22 sys=0.94, real=0.16 secs]
2009-07-02T06:55:48.732+0300: 4967.435: [GC 4967.436: [ParNew: 407958K->14377K(440896K), 0.1540411 secs] 489260K->98888K(8339648K), 0.1553891 secs] [Times: user=2.10 sys=0.95, real=0.16 secs]
2009-07-02T07:02:16.513+0300: 5355.209: [GC 5355.209: [ParNew: 406313K->13113K(440896K), 0.1497923 secs] 490824K->100919K(8339648K), 0.1511334 secs] [Times: user=1.94 sys=0.92, real=0.15 secs]
2009-07-02T07:07:41.719+0300: 5680.410: [GC 5680.411: [ParNew: 405049K->11416K(440896K), 0.1364118 secs] 492855K->102527K(8339648K), 0.1377451 secs] [Times: user=1.71 sys=0.87, real=0.14 secs]
2009-07-02T07:12:43.816+0300: 5982.501: [GC 5982.502: [ParNew: 403352K->12415K(440896K), 0.1354891 secs] 494463K->106795K(8339648K), 0.1368222 secs] [Times: user=1.55 sys=0.85, real=0.14 secs]
2009-07-02T07:17:16.273+0300: 6254.953: [GC 6254.954: [ParNew: 404351K->12620K(440896K), 0.1252352 secs] 498731K->109284K(8339648K), 0.1265762 secs] [Times: user=1.39 sys=0.90, real=0.13 secs]
2009-07-02T07:21:26.911+0300: 6505.587: [GC 6505.588: [ParNew: 404556K->14945K(440896K), 0.1160003 secs] 501220K->113606K(8339648K), 0.1173344 secs] [Times: user=1.29 sys=0.86, real=0.12 secs]
2009-07-02T07:25:46.527+0300: 6765.198: [GC 6765.199: [ParNew: 406881K->15641K(440896K), 0.1149592 secs] 505542K->116356K(8339648K), 0.1162988 secs] [Times: user=1.24 sys=0.82, real=0.12 secs]
2009-07-02T07:29:57.430+0300: 7016.097: [GC 7016.098: [ParNew: 407577K->11466K(440896K), 0.1241678 secs] 508292K->114339K(8339648K), 0.1255042 secs] [Times: user=1.42 sys=0.91, real=0.13 secs]
2009-07-02T07:32:24.455+0300: 7163.120: [GC 7163.121: [ParNew: 403402K->15691K(440896K), 0.1346061 secs] 506275K->120914K(8339648K), 0.1359401 secs] [Times: user=1.60 sys=0.98, real=0.14 secs]
2009-07-02T07:35:20.328+0300: 7338.989: [GC 7338.990: [ParNew: 407627K->18318K(440896K), 0.1426681 secs] 512850K->125844K(8339648K), 0.1440043 secs] [Times: user=1.69 sys=1.01, real=0.14 secs]
2009-07-02T07:37:51.746+0300: 7490.405: [GC 7490.406: [ParNew: 410254K->13257K(440896K), 0.1462809 secs] 517780K->123054K(8339648K), 0.1478078 secs] [Times: user=1.82 sys=1.04, real=0.15 secs]
2009-07-02T07:40:43.956+0300: 7662.612: [GC 7662.613: [ParNew: 405193K->19397K(440896K), 0.1610205 secs] 514990K->131651K(8339648K), 0.1623517 secs] [Times: user=2.01 sys=1.09, real=0.16 secs]
2009-07-02T07:43:10.774+0300: 7809.428: [GC 7809.429: [ParNew: 411333K->16766K(440896K), 0.1681143 secs] 523587K->131998K(8339648K), 0.1694511 secs] [Times: user=2.14 sys=1.14, real=0.17 secs]
2009-07-02T07:46:24.896+0300: 8003.547: [GC 8003.548: [ParNew: 408702K->15254K(440896K), 0.1607709 secs] 523934K->133362K(8339648K), 0.1621078 secs] [Times: user=2.02 sys=1.11, real=0.16 secs]
2009-07-02T07:51:44.675+0300: 8323.321: [GC 8323.322: [ParNew: 407185K->14642K(440896K), 0.1599685 secs] 525292K->135617K(8339648K), 0.1613364 secs] [Times: user=1.95 sys=1.12, real=0.16 secs]
2009-07-02T07:54:57.561+0300: 8516.203: [GC 8516.204: [ParNew: 406578K->14092K(440896K), 0.1633040 secs] 527553K->137921K(8339648K), 0.1646320 secs] [Times: user=1.94 sys=1.25, real=0.17 secs]
2009-07-02T07:56:26.993+0300: 8605.634: [GC 8605.635: [ParNew: 406028K->15985K(440896K), 0.1506631 secs] 529857K->142844K(8339648K), 0.1520009 secs] [Times: user=1.73 sys=1.10, real=0.15 secs]
2009-07-02T08:00:01.823+0300: 8820.460: [GC 8820.461: [ParNew: 407921K->15207K(440896K), 0.1465479 secs] 534780K->144729K(8339648K), 0.1478874 secs] [Times: user=1.65 sys=1.15, real=0.15 secs]
2009-07-02T08:00:34.948+0300: 8853.584: [GC 8853.585: [ParNew: 407143K->19194K(440896K), 0.1399589 secs] 536665K->150525K(8339648K), 0.1412993 secs] [Times: user=1.53 sys=1.10, real=0.14 secs]
2009-07-02T08:01:05.894+0300: 8884.530: [GC 8884.531: [ParNew: 411119K->21424K(440896K), 0.1417834 secs] 542450K->155078K(8339648K), 0.1431255 secs] [Times: user=1.54 sys=1.11, real=0.14 secs]
2009-07-02T08:01:34.248+0300: 8912.884: [GC 8912.885: [ParNew: 413360K->15901K(440896K), 0.1385308 secs] 547014K->152800K(8339648K), 0.1398703 secs] [Times: user=1.39 sys=1.02, real=0.14 secs]
2009-07-02T08:02:02.355+0300: 8940.990: [GC 8940.991: [ParNew: 407837K->20121K(440896K), 0.1426068 secs] 544736K->160108K(8339648K), 0.1439345 secs] [Times: user=1.47 sys=1.09, real=0.14 secs]
2009-07-02T08:02:30.761+0300: 8969.396: [GC 8969.397: [ParNew: 412057K->20492K(440896K), 0.1392722 secs] 552044K->163743K(8339648K), 0.1406046 secs] [Times: user=1.49 sys=1.12, real=0.14 secs]
2009-07-02T08:02:56.556+0300: 8995.190: [GC 8995.191: [ParNew: 412428K->20230K(440896K), 0.1415768 secs] 555679K->166571K(8339648K), 0.1429169 secs] [Times: user=1.52 sys=1.12, real=0.14 secs]
2009-07-02T08:03:25.092+0300: 9023.725: [GC 9023.726: [ParNew: 412166K->21113K(440896K), 0.1387050 secs] 558507K->170520K(8339648K), 0.1400591 secs] [Times: user=1.48 sys=1.11, real=0.14 secs]
2009-07-02T08:03:53.249+0300: 9051.882: [GC 9051.883: [ParNew: 413049K->21258K(440896K), 0.1411404 secs] 562456K->173856K(8339648K), 0.1425040 secs] [Times: user=1.47 sys=1.09, real=0.14 secs]
2009-07-02T08:04:20.865+0300: 9079.497: [GC 9079.498: [ParNew: 413194K->20601K(440896K), 0.1394565 secs] 565792K->176274K(8339648K), 0.1408330 secs] [Times: user=1.48 sys=1.12, real=0.14 secs]
2009-07-02T08:04:47.605+0300: 9106.237: [GC 9106.238: [ParNew: 412537K->19473K(440896K), 0.1389919 secs] 568210K->178422K(8339648K), 0.1403203 secs] [Times: user=1.42 sys=1.07, real=0.14 secs]
2009-07-02T08:05:15.052+0300: 9133.684: [GC 9133.684: [ParNew: 411409K->20306K(440896K), 0.1390440 secs] 570358K->182362K(8339648K), 0.1403978 secs] [Times: user=1.26 sys=0.97, real=0.14 secs]
2009-07-02T08:05:42.835+0300: 9161.466: [GC 9161.467: [ParNew: 412242K->18593K(440896K), 0.1368850 secs] 574298K->183723K(8339648K), 0.1382273 secs] [Times: user=1.28 sys=0.98, real=0.14 secs]
2009-07-02T08:06:09.427+0300: 9188.058: [GC 9188.059: [ParNew: 410529K->20236K(440896K), 0.1374006 secs] 575659K->188452K(8339648K), 0.1388021 secs] [Times: user=1.33 sys=1.02, real=0.14 secs]
2009-07-02T08:06:33.659+0300: 9212.290: [GC 9212.291: [ParNew: 412172K->20216K(440896K), 0.1388637 secs] 580388K->191497K(8339648K), 0.1401995 secs] [Times: user=1.50 sys=1.12, real=0.14 secs]
2009-07-02T08:07:00.017+0300: 9238.647: [GC 9238.648: [ParNew: 412152K->19762K(440896K), 0.1397648 secs] 583433K->194132K(8339648K), 0.1411720 secs] [Times: user=1.46 sys=1.09, real=0.14 secs]
2009-07-02T08:07:26.984+0300: 9265.614: [GC 9265.615: [ParNew: 411698K->19743K(440896K), 0.1404720 secs] 586068K->197215K(8339648K), 0.1418194 secs] [Times: user=1.44 sys=1.05, real=0.14 secs]
2009-07-02T08:07:53.643+0300: 9292.272: [GC 9292.273: [ParNew: 411679K->19222K(440896K), 0.1338628 secs] 589151K->199764K(8339648K), 0.1351886 secs] [Times: user=1.44 sys=1.05, real=0.14 secs]
2009-07-02T08:08:20.050+0300: 9318.679: [GC 9318.680: [ParNew: 411147K->18085K(440896K), 0.1439036 secs] 591689K->201758K(8339648K), 0.1452399 secs] [Times: user=1.53 sys=1.13, real=0.15 secs]
2009-07-02T08:08:46.720+0300: 9345.348: [GC 9345.349: [ParNew: 410021K->20218K(440896K), 0.1395308 secs] 593694K->206964K(8339648K), 0.1408787 secs] [Times: user=1.36 sys=1.02, real=0.14 secs]
2009-07-02T08:09:13.223+0300: 9371.850: [GC 9371.851: [ParNew: 412154K->19826K(440896K), 0.1430699 secs] 598900K->209672K(8339648K), 0.1444521 secs] [Times: user=1.40 sys=1.07, real=0.15 secs]
2009-07-02T08:09:40.229+0300: 9398.856: [GC 9398.857: [ParNew: 411760K->20322K(440896K), 0.1393364 secs] 601607K->213234K(8339648K), 0.1406752 secs] [Times: user=1.45 sys=1.11, real=0.14 secs]
2009-07-02T08:10:07.384+0300: 9426.011: [GC 9426.012: [ParNew: 412258K->19823K(440896K), 0.1413483 secs] 605170K->215824K(8339648K), 0.1426850 secs] [Times: user=1.37 sys=1.03, real=0.14 secs]
2009-07-02T08:10:33.998+0300: 9452.624: [GC 9452.625: [ParNew: 411759K->23474K(440896K), 0.1382665 secs] 607760K->222665K(8339648K), 0.1396289 secs] [Times: user=1.30 sys=0.98, real=0.14 secs]
2009-07-02T08:11:00.058+0300: 9478.684: [GC 9478.685: [ParNew: 415410K->23027K(440896K), 0.1388240 secs] 614601K->225252K(8339648K), 0.1401745 secs] [Times: user=1.26 sys=0.92, real=0.14 secs]
2009-07-02T08:11:26.218+0300: 9504.843: [GC 9504.844: [ParNew: 414963K->23616K(440896K), 0.1389055 secs] 617188K->228945K(8339648K), 0.1402511 secs] [Times: user=1.33 sys=1.01, real=0.14 secs]
2009-07-02T08:11:53.109+0300: 9531.734: [GC 9531.735: [ParNew: 415552K->22508K(440896K), 0.1396320 secs] 620881K->230914K(8339648K), 0.1409551 secs] [Times: user=1.27 sys=0.94, real=0.14 secs]
2009-07-02T08:12:19.805+0300: 9558.429: [GC 9558.430: [ParNew: 414409K->20544K(440896K), 0.1413539 secs] 622815K->233971K(8339648K), 0.1426850 secs] [Times: user=1.22 sys=0.89, real=0.14 secs]
2009-07-02T08:12:45.873+0300: 9584.497: [GC 9584.498: [ParNew: 412480K->18634K(440896K), 0.1369312 secs] 625907K->236006K(8339648K), 0.1382758 secs] [Times: user=1.28 sys=0.94, real=0.14 secs]
2009-07-02T08:13:12.416+0300: 9611.039: [GC 9611.040: [ParNew: 410570K->19992K(440896K), 0.1384245 secs] 627942K->240421K(8339648K), 0.1397612 secs] [Times: user=1.35 sys=1.00, real=0.14 secs]
2009-07-02T08:13:38.973+0300: 9637.596: [GC 9637.597: [ParNew: 411928K->20853K(440896K), 0.1405121 secs] 632357K->244348K(8339648K), 0.1418729 secs] [Times: user=1.30 sys=0.96, real=0.14 secs]
2009-07-02T08:14:05.322+0300: 9663.945: [GC 9663.946: [ParNew: 412789K->19685K(440896K), 0.1395979 secs] 636284K->246258K(8339648K), 0.1410112 secs] [Times: user=1.43 sys=1.09, real=0.14 secs]
2009-07-02T08:14:30.910+0300: 9689.532: [GC 9689.533: [ParNew: 411620K->19159K(440896K), 0.1417392 secs] 638193K->248815K(8339648K), 0.1430651 secs] [Times: user=1.50 sys=1.13, real=0.14 secs]
2009-07-02T08:14:57.007+0300: 9715.628: [GC 9715.629: [ParNew: 411095K->19174K(440896K), 0.1437888 secs] 640751K->251907K(8339648K), 0.1451357 secs] [Times: user=1.38 sys=1.05, real=0.15 secs]
2009-07-02T08:15:23.151+0300: 9741.772: [GC 9741.773: [ParNew: 411110K->19103K(440896K), 0.1402004 secs] 643843K->254919K(8339648K), 0.1415260 secs] [Times: user=1.38 sys=1.07, real=0.14 secs]
2009-07-02T08:15:52.154+0300: 9770.775: [GC 9770.776: [ParNew: 411039K->19677K(440896K), 0.1391040 secs] 646855K->258596K(8339648K), 0.1404952 secs] [Times: user=1.32 sys=0.99, real=0.14 secs]
2009-07-02T08:16:17.951+0300: 9796.571: [GC 9796.572: [ParNew: 411613K->20105K(440896K), 0.1431126 secs] 650532K->262088K(8339648K), 0.1444343 secs] [Times: user=1.40 sys=1.10, real=0.15 secs]
2009-07-02T08:16:44.087+0300: 9822.707: [GC 9822.708: [ParNew: 412041K->19549K(440896K), 0.1385934 secs] 654024K->264589K(8339648K), 0.1398971 secs] [Times: user=1.20 sys=0.89, real=0.14 secs]
2009-07-02T08:17:10.193+0300: 9848.812: [GC 9848.813: [ParNew: 411485K->19561K(440896K), 0.1398520 secs] 656525K->267664K(8339648K), 0.1411885 secs] [Times: user=1.26 sys=0.96, real=0.14 secs]
2009-07-02T08:17:36.558+0300: 9875.177: [GC 9875.178: [ParNew: 411497K->21769K(440896K), 0.1382375 secs] 659600K->272912K(8339648K), 0.1395678 secs] [Times: user=1.24 sys=0.96, real=0.14 secs]
2009-07-02T08:18:02.
.
. cont....
.
2009-07-07T15:49:52.827+0300: 469003.673: [GC 469003.674: [ParNew: 411783K->15300K(440896K), 2.1688364 secs] 2733678K->2339995K(8339648K), 2.1702789 secs] [Times: user=20.48 sys=19.02, real=2.17 secs]
2009-07-07T15:50:14.472+0300: 469025.318: [GC 469025.319: [ParNew: 407236K->18397K(440896K), 2.1645639 secs] 2731931K->2345930K(8339648K), 2.1659894 secs] [Times: user=20.63 sys=19.21, real=2.17 secs]
2009-07-07T15:50:36.867+0300: 469047.713: [GC 469047.714: [ParNew: 410333K->19327K(440896K), 2.1694079 secs] 2737866K->2349651K(8339648K), 2.1708414 secs] [Times: user=20.44 sys=19.03, real=2.17 secs]
2009-07-07T15:50:57.719+0300: 469068.564: [GC 469068.565: [ParNew: 411263K->15642K(440896K), 2.1625758 secs] 2741587K->2348740K(8339648K), 2.1640032 secs] [Times: user=20.58 sys=19.13, real=2.16 secs]
2009-07-07T15:51:21.130+0300: 469091.975: [GC 469091.976: [ParNew: 407578K->17699K(440896K), 2.1665988 secs] 2740676K->2353599K(8339648K), 2.1680272 secs] [Times: user=20.64 sys=19.19, real=2.17 secs]
2009-07-07T15:51:43.445+0300: 469114.289: [GC 469114.290: [ParNew: 409635K->18837K(440896K), 2.1730595 secs] 2745535K->2357536K(8339648K), 2.1744738 secs] [Times: user=20.61 sys=19.18, real=2.18 secs]
2009-07-07T15:52:07.474+0300: 469138.317: [GC 469138.319: [ParNew: 410773K->18792K(440896K), 2.1710846 secs] 2749472K->2360265K(8339648K), 2.1725206 secs] [Times: user=20.65 sys=19.22, real=2.17 secs]
2009-07-07T15:52:28.375+0300: 469159.218: [GC 469159.219: [ParNew: 410717K->18922K(440896K), 2.1772362 secs] 2752190K->2363211K(8339648K), 2.1786581 secs] [Times: user=20.57 sys=19.17, real=2.18 secs]
2009-07-07T15:52:47.553+0300: 469178.397: [GC 469178.398: [ParNew: 410858K->17757K(440896K), 2.1709764 secs] 2755147K->2364876K(8339648K), 2.1724114 secs] [Times: user=20.55 sys=19.06, real=2.17 secs]
2009-07-07T15:53:12.878+0300: 469203.721: [GC 469203.722: [ParNew: 409693K->18286K(440896K), 2.1770422 secs] 2756812K->2368155K(8339648K), 2.1784741 secs] [Times: user=20.91 sys=19.41, real=2.18 secs]
2009-07-07T15:53:34.117+0300: 469224.960: [GC 469224.961: [ParNew: 410222K->19832K(440896K), 2.1744069 secs] 2760091K->2372474K(8339648K), 2.1758496 secs] [Times: user=20.95 sys=19.43, real=2.18 secs]
2009-07-07T15:53:56.247+0300: 469247.089: [GC 469247.090: [ParNew: 411768K->16761K(440896K), 2.1691993 secs] 2764410K->2372222K(8339648K), 2.1706205 secs] [Times: user=20.42 sys=18.95, real=2.17 secs]
2009-07-07T15:54:17.617+0300: 469268.459: [GC 469268.460: [ParNew: 408697K->17093K(440896K), 2.1778376 secs] 2764158K->2375389K(8339648K), 2.1792695 secs] [Times: user=21.08 sys=19.58, real=2.18 secs]
2009-07-07T15:54:40.893+0300: 469291.734: [GC 469291.735: [ParNew: 409029K->18941K(440896K), 2.1773640 secs] 2767325K->2379941K(8339648K), 2.1787633 secs] [Times: user=20.42 sys=18.97, real=2.18 secs]
2009-07-07T15:55:03.337+0300: 469314.178: [GC 469314.179: [ParNew: 410877K->20615K(440896K), 2.1677915 secs] 2771877K->2384396K(8339648K), 2.1692129 secs] [Times: user=20.35 sys=18.92, real=2.17 secs]
2009-07-07T15:55:28.106+0300: 469338.946: [GC 469338.947: [ParNew: 412542K->15303K(440896K), 2.1666167 secs] 2776323K->2381888K(8339648K), 2.1680432 secs] [Times: user=19.94 sys=18.54, real=2.17 secs]
2009-07-07T15:55:49.583+0300: 469360.423: [GC 469360.424: [ParNew: 407239K->16911K(440896K), 2.1689705 secs] 2773824K->2386289K(8339648K), 2.1703814 secs] [Times: user=19.48 sys=18.01, real=2.17 secs]
2009-07-07T15:56:10.867+0300: 469381.707: [GC 469381.708: [ParNew: 408851K->17575K(440896K), 2.1706240 secs] 2778229K->2389729K(8339648K), 2.1720723 secs] [Times: user=20.47 sys=19.17, real=2.17 secs]
2009-07-07T15:56:32.015+0300: 469402.854: [GC 469402.855: [ParNew: 409511K->17976K(440896K), 2.1595964 secs] 2781665K->2392889K(8339648K), 2.1612083 secs] [Times: user=20.51 sys=19.12, real=2.16 secs]
2009-07-07T15:56:54.545+0300: 469425.384: [GC 469425.385: [ParNew: 409912K->16909K(440896K), 2.1693348 secs] 2784825K->2394528K(8339648K), 2.1707578 secs] [Times: user=20.98 sys=19.55, real=2.17 secs]
2009-07-07T15:57:15.756+0300: 469446.595: [GC 469446.596: [ParNew: 408845K->19855K(440896K), 2.1775778 secs] 2786464K->2400267K(8339648K), 2.1790075 secs] [Times: user=21.10 sys=19.58, real=2.18 secs]
2009-07-07T15:57:38.481+0300: 469469.319: [GC 469469.320: [ParNew: 411791K->15588K(440896K), 2.1787032 secs] 2792203K->2398841K(8339648K), 2.1801305 secs] [Times: user=21.18 sys=19.78, real=2.18 secs]
2009-07-07T15:58:01.848+0300: 469492.685: [GC 469492.686: [ParNew: 407524K->17319K(440896K), 2.1767692 secs] 2790777K->2403319K(8339648K), 2.1781959 secs] [Times: user=20.87 sys=19.36, real=2.18 secs]
2009-07-07T15:58:23.438+0300: 469514.276: [GC 469514.277: [ParNew: 409255K->17296K(440896K), 2.1787312 secs] 2795255K->2406112K(8339648K), 2.1801606 secs] [Times: user=20.84 sys=19.44, real=2.18 secs]
2009-07-07T15:58:46.044+0300: 469536.881: [GC 469536.882: [ParNew: 409232K->18587K(440896K), 2.1813459 secs] 2798048K->2410190K(8339648K), 2.1828104 secs] [Times: user=20.90 sys=19.42, real=2.18 secs]
2009-07-07T15:59:08.954+0300: 469559.791: [GC 469559.792: [ParNew: 410523K->18277K(440896K), 2.1806901 secs] 2802126K->2412621K(8339648K), 2.1821144 secs] [Times: user=20.63 sys=19.20, real=2.18 secs]
2009-07-07T15:59:29.513+0300: 469580.349: [GC 469580.350: [ParNew: 410213K->17283K(440896K), 2.1789972 secs] 2804557K->2414449K(8339648K), 2.1804127 secs] [Times: user=20.81 sys=19.38, real=2.18 secs]
2009-07-07T15:59:49.781+0300: 469600.617: [GC 469600.618: [ParNew: 409219K->20373K(440896K), 2.1755594 secs] 2806385K->2420357K(8339648K), 2.1769952 secs] [Times: user=20.60 sys=19.11, real=2.18 secs]
2009-07-07T16:00:12.228+0300: 469623.063: [GC 469623.064: [ParNew: 412309K->14679K(440896K), 2.1732141 secs] 2812293K->2417489K(8339648K), 2.1746559 secs] [Times: user=20.58 sys=19.09, real=2.18 secs]
2009-07-07T16:00:35.049+0300: 469645.884: [GC 469645.885: [ParNew: 406617K->18016K(440896K), 2.1782877 secs] 2809427K->2423568K(8339648K), 2.1797299 secs] [Times: user=20.86 sys=19.38, real=2.18 secs]
2009-07-07T16:00:57.489+0300: 469668.324: [GC 469668.325: [ParNew: 409952K->16943K(440896K), 2.1805878 secs] 2815504K->2425340K(8339648K), 2.1820072 secs] [Times: user=20.71 sys=19.29, real=2.18 secs]
2009-07-07T16:01:18.773+0300: 469689.607: [GC 469689.608: [ParNew: 408879K->18266K(440896K), 2.1791918 secs] 2817276K->2429518K(8339648K), 2.1806150 secs] [Times: user=20.66 sys=19.21, real=2.18 secs]
2009-07-07T16:01:43.716+0300: 469714.550: [GC 469714.551: [ParNew: 410202K->17792K(440896K), 2.1718885 secs] 2821454K->2431817K(8339648K), 2.1733187 secs] [Times: user=20.37 sys=18.93, real=2.17 secs]
2009-07-07T16:02:06.752+0300: 469737.586: [GC 469737.587: [ParNew: 409728K->19384K(440896K), 2.1814803 secs] 2823753K->2436208K(8339648K), 2.1829229 secs] [Times: user=20.77 sys=19.32, real=2.18 secs]
2009-07-07T16:02:30.795+0300: 469761.628: [GC 469761.629: [ParNew: 411320K->18325K(440896K), 2.1842498 secs] 2828144K->2437975K(8339648K), 2.1856750 secs] [Times: user=20.37 sys=19.08, real=2.19 secs]
2009-07-07T16:02:53.792+0300: 469784.625: [GC 469784.626: [ParNew: 410261K->16773K(440896K), 2.1770963 secs] 2829911K->2439229K(8339648K), 2.1785185 secs] [Times: user=20.16 sys=18.84, real=2.18 secs]
2009-07-07T16:03:18.390+0300: 469809.222: [GC 469809.223: [ParNew: 408709K->17304K(440896K), 2.1741030 secs] 2831165K->2442557K(8339648K), 2.1755294 secs]

Issue
1. High minor collection time
2. Minor collection time is increasing over time

Hi All,

We are facing above issue in production environment. Since we do not have similar configuration in test, we have tried similar tests on following environment:

Solaris Sparc T2000
1 Quad core Ultrasparc T1 1
32 GB RAM (Reduced available RAM to 16 GB)
JDK 1.6 Update 11
1.2 GHZ

We are unable to replicate the same in test environment where not only average minor collection is less than 40 ms but it is stable (not increasing as production). We do not have clue what could be difference between test and production which is not allowing us to replicate problem.

Any one's help shall be highly appreciated.

Reply viewing options

Select your preferred way to display the comments and click "Save settings" to activate your changes.
ijuma
Offline
Joined: 2005-10-19
Points: 0

Hi,

> (1) have you tried the compressed references feature
> available as of 6u14

I would be careful about using this option in production. Even though it's very promising, I don't think it's stable enough yet. I've experienced some crashes that are hard to reproduce while using it and even worse JIT miscompilation:

http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=6851282

Best,
Ismael

ysramakrishna
Offline
Joined: 2005-04-25
Points: 0

Typically large scavenge times with CMS are indicative of
either a fragmented heap (slowing down promotions) or
slow card-scanning (slowing down identification of "roots").
On the T2, you get 64 hardware threads (aka strands)
and unless you explictly specify it, you get for CMS,
roughly 5/8 as many, i.e. ~40, GC worker threads.
Those many threads then are scavenging yr 430 MB
Eden. On the T1, on the other hand, you get half as
many GC worker threads by default, i.e. ~20.
There's probably an optimal number for your appl and
sizing and it might be useful to tune for it. Now, another
reason I brought up the matter of GC worker threads is
that with CMS the space lossage due to fragmentation might
increase as the number of GC worker threads increases.
This will typically show up, like in your example below (although
in your snippet the speed of the transition is not clear, only
that it happens several days later), as a slow degradation
of scavenge times. I do notice that your heap occupancy is
growing nearly montonically during the log snippets you have
posted. Perhaps a complete log mailed to us (see
bleow) would allow us to understand what was happening
here. Do you see CMS collections happen? How frequently?
What is your data set size? Do you need to use the 8 GB heap
that you are employing?

Could you run your log through GChisto and post the
timeline graph, or better still send the complete GC log
to your Sun support engineer, or to the hotspot-gc-use alias on openjdk?

Finally, a couple of asides:
(1) have you tried the compressed references feature available as of 6u14
(2) have you tried reshaping yr heap (smaller Eden, tune survivor space
sizes and promotion rates, check if a smaller total heap might suffice etc.
(3) -XX:PrintFLSStatistics=1 provides some fragmentation information and
... = 2 provides even more verbose (and slightly more expensive/extensive
data.

Sorry I am asking more questions and not really answering any, but more
complete logs would be a great help.

ysramakrishna
Offline
Joined: 2005-04-25
Points: 0

> (2) have you tried reshaping yr heap (smaller Eden,

Please ignore the bit above about a smaller Eden. Clearly your
promotion volume per scavenge is so small that the size
of Eden should not be a concern, or at least will not
affect pause times in any conceivable way. (Except if
it were showing up some issue with a "thin" structure
that lots of worker threads were fighting over).

Based on the low per-scavenge promotion volume,
my money would be on some form of fragmentation
or exposes some degenerate performance corner
that would need to be fixed. Complete logs would
be useful to see how slowly or quickly we transition
from the relatively shorter earlier pauses to the much longer
later pauses.

Message was edited by: ysramakrishna