I am using Java 6_13.
My gc.log shows that I run into concurrent mode failure. However, part of the line shown here confuses me a lot since the Full GC does not clean the memory but instead increases the occupied memory.
(concurrent mode failure): 778598K->781522K(786432K), 1.2618790 secs]
Is it normal? In addition, if anyone has any explanations on why I run into this problem, please share too. As this problem does not always happen when I do load testing, but when it happens, it slows everything down (which is quite expected as a result of Full GC).
I also include my log here in case you need a complete picture.
2014-12-17T10:36:21.839-0500: 22.094: [GC 22.094: [ParNew: 262144K->5947K(327680K), 0.0186840 secs] 262144K->5947K(720896K), 0.0188600 secs] [Times: user=0.09 sys=0.02, real=0.02 secs]
2014-12-17T10:37:40.865-0500: 101.119: [GC [1 CMS-initial-mark: 0K(393216K)] 133041K(720896K), 0.1643040 secs] [Times: user=0.16 sys=0.01, real=0.17 secs]
2014-12-17T10:37:41.029-0500: 101.284: [CMS-concurrent-mark-start]
2014-12-17T10:37:41.210-0500: 101.464: [CMS-concurrent-mark: 0.067/0.180 secs] [Times: user=0.31 sys=0.01, real=0.18 secs]
2014-12-17T10:37:41.210-0500: 101.464: [CMS-concurrent-preclean-start]
2014-12-17T10:37:41.256-0500: 101.510: [CMS-concurrent-preclean: 0.044/0.046 secs] [Times: user=0.08 sys=0.00, real=0.04 secs]
2014-12-17T10:37:41.256-0500: 101.510: [CMS-concurrent-abortable-preclean-start]
2014-12-17T10:37:45.249-0500: 105.503: [GC 105.503: [ParNew: 268091K->55535K(327680K), 0.0379060 secs] 268091K->55535K(720896K), 0.0381190 secs] [Times: user=0.18 sys=0.05, real=0.03 secs]
CMS: abort preclean due to time 2014-12-17T10:40:13.781-0500: 254.036: [CMS-concurrent-abortable-preclean: 0.246/152.525 secs] [Times: user=14.81 sys=1.02, real=152.51 secs]
2014-12-17T10:40:13.782-0500: 254.036: [GC[YG occupancy: 181472 K (327680 K)]254.036: [Rescan (parallel) , 0.0427610 secs]254.079: [weak refs processing, 0.0017680 secs]254.081: [class unloading, 0.0083440 secs]254.090: [scrub symbol & string tables, 0.0096400 secs] [1 CMS-remark: 0K(393216K)] 181472K(720896K), 0.0638280 secs] [Times: user=0.29 sys=0.01, real=0.06 secs]
2014-12-17T10:40:13.846-0500: 254.101: [CMS-concurrent-sweep-start]
2014-12-17T10:40:13.879-0500: 254.134: [CMS-concurrent-sweep: 0.033/0.033 secs] [Times: user=0.04 sys=0.00, real=0.03 secs]
2014-12-17T10:40:13.880-0500: 254.134: [CMS-concurrent-reset-start]
2014-12-17T10:40:13.885-0500: 254.139: [CMS-concurrent-reset: 0.005/0.005 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
2014-12-17T10:44:17.055-0500: 497.309: [GC 497.310: [ParNew: 317679K->65536K(327680K), 0.1915580 secs] 317679K->117282K(720896K), 0.1917720 secs] [Times: user=0.62 sys=0.08, real=0.19 secs]
2014-12-17T10:44:18.806-0500: 499.061: [GC [1 CMS-initial-mark: 51746K(393216K)] 243278K(720896K), 0.0321840 secs] [Times: user=0.04 sys=0.00, real=0.04 secs]
2014-12-17T10:44:18.839-0500: 499.093: [CMS-concurrent-mark-start]
2014-12-17T10:44:19.919-0500: 500.174: [GC 500.174: [ParNew: 327680K->64521K(327680K), 0.0353730 secs] 379426K->149606K(720896K), 0.0356140 secs] [Times: user=0.17 sys=0.02, real=0.03 secs]
2014-12-17T10:44:21.201-0500: 501.455: [CMS-concurrent-mark: 0.105/2.362 secs] [Times: user=3.07 sys=0.85, real=2.36 secs]
2014-12-17T10:44:21.201-0500: 501.455: [CMS-concurrent-preclean-start]
2014-12-17T10:44:21.242-0500: 501.497: [CMS-concurrent-preclean: 0.038/0.041 secs] [Times: user=0.13 sys=0.00, real=0.04 secs]
2014-12-17T10:44:21.242-0500: 501.497: [CMS-concurrent-abortable-preclean-start]
2014-12-17T10:46:30.890-0500: 631.144: [GC 631.145: [ParNew: 326364K->26707K(327680K), 0.0217020 secs] 411449K->111798K(720896K), 0.0219820 secs] [Times: user=0.09 sys=0.01, real=0.02 secs]
CMS: abort preclean due to time 2014-12-17T10:46:31.979-0500: 632.233: [CMS-concurrent-abortable-preclean: 0.040/130.736 secs] [Times: user=12.26 sys=1.46, real=130.72 secs]
2014-12-17T10:46:32.009-0500: 632.264: [GC[YG occupancy: 161330 K (327680 K)]632.264: [Rescan (parallel) , 0.0620470 secs]632.326: [weak refs processing, 0.0017350 secs]632.328: [class unloading, 0.0114700 secs]632.339: [scrub symbol & string tables, 0.0088820 secs] [1 CMS-remark: 85090K(393216K)] 246420K(720896K), 0.0858470 secs] [Times: user=0.43 sys=0.01, real=0.08 secs]
2014-12-17T10:46:32.096-0500: 632.350: [CMS-concurrent-sweep-start]
2014-12-17T10:46:32.591-0500: 632.846: [GC 632.846: [ParNew: 288851K->65536K(327680K), 0.1166790 secs] 373892K->298985K(720896K), 0.1170040 secs] [Times: user=0.52 sys=0.06, real=0.12 secs]
2014-12-17T10:46:33.741-0500: 633.995: [GC 633.995: [ParNew: 322304K->65536K(327680K), 0.1065110 secs] 555561K->477757K(744488K), 0.1067870 secs] [Times: user=0.48 sys=0.09, real=0.10 secs]
2014-12-17T10:46:33.950-0500: 634.204: [CMS-concurrent-sweep: 0.109/1.854 secs] [Times: user=12.42 sys=0.42, real=1.86 secs]
2014-12-17T10:46:33.951-0500: 634.205: [CMS-concurrent-reset-start]
2014-12-17T10:46:34.038-0500: 634.292: [GC 634.292: [ParNew: 327374K->64235K(327680K), 0.3638820 secs] 739596K->738053K(1014720K), 0.3641410 secs] [Times: user=0.72 sys=1.30, real=0.37 secs]
2014-12-17T10:46:34.462-0500: 634.716: [CMS-concurrent-reset: 0.006/0.511 secs] [Times: user=1.71 sys=1.32, real=0.51 secs]
2014-12-17T10:46:34.521-0500: 634.776: [GC 634.776: [ParNew: 324988K->324988K(327680K), 0.0000430 secs]634.776: [CMS: 673817K->686118K(687040K), 1.2695600 secs] 998806K->941293K(1014720K), [CMS Perm : 58268K->57873K(86016K)], 1.2711070 secs] [Times: user=1.26 sys=0.01, real=1.27 secs]
2014-12-17T10:46:35.797-0500: 636.052: [GC [1 CMS-initial-mark: 686118K(786432K)] 957705K(1441792K), 0.0145640 secs] [Times: user=0.01 sys=0.00, real=0.02 secs]
2014-12-17T10:46:35.812-0500: 636.067: [CMS-concurrent-mark-start]
2014-12-17T10:46:42.519-0500: 642.774: [Full GC 642.774: [CMS2014-12-17T10:46:42.763-0500: 643.018: [CMS-concurrent-mark: 0.271/6.951 secs] [Times: user=31.85 sys=5.96, real=6.95 secs]
(concurrent mode failure): 711857K->775949K(786432K), 1.7010100 secs] 1367217K->1071092K(1441792K), [CMS Perm : 58431K->58320K(86016K)], 1.7013000 secs] [Times: user=1.96 sys=0.01, real=1.71 secs]
2014-12-17T10:46:47.668-0500: 647.922: [GC [1 CMS-initial-mark: 775949K(786432K)] 1181108K(1441792K), 0.1282060 secs] [Times: user=0.13 sys=0.00, real=0.13 secs]
2014-12-17T10:46:47.797-0500: 648.051: [CMS-concurrent-mark-start]
2014-12-17T10:46:47.979-0500: 648.234: [CMS-concurrent-mark: 0.167/0.183 secs] [Times: user=0.53 sys=0.02, real=0.18 secs]
2014-12-17T10:46:47.979-0500: 648.234: [CMS-concurrent-preclean-start]
2014-12-17T10:46:48.209-0500: 648.463: [CMS-concurrent-preclean: 0.229/0.229 secs] [Times: user=0.26 sys=0.00, real=0.23 secs]
2014-12-17T10:46:48.209-0500: 648.463: [CMS-concurrent-abortable-preclean-start]
2014-12-17T10:46:48.209-0500: 648.463: [CMS-concurrent-abortable-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2014-12-17T10:46:48.209-0500: 648.464: [GC[YG occupancy: 411214 K (655360 K)]648.464: [Rescan (parallel) , 0.1109340 secs]648.575: [weak refs processing, 0.0028000 secs]648.578: [class unloading, 0.0214210 secs]648.599: [scrub symbol & string tables, 0.0097890 secs] [1 CMS-remark: 775949K(786432K)] 1187163K(1441792K), 0.1492660 secs] [Times: user=0.81 sys=0.00, real=0.15 secs]
2014-12-17T10:46:48.359-0500: 648.614: [CMS-concurrent-sweep-start]
2014-12-17T10:47:06.474-0500: 666.729: [Full GC 666.729: [CMS2014-12-17T10:47:06.493-0500: 666.747: [CMS-concurrent-sweep: 0.105/18.133 secs] [Times: user=11.42 sys=0.74, real=18.13 secs]
(concurrent mode failure): 778598K->781522K(786432K), 1.2618790 secs] 1433958K->1056111K(1441792K), [CMS Perm : 58638K->58559K(86016K)], 1.2621660 secs] [Times: user=1.26 sys=0.00, real=1.26 secs]
