The following is an excerpt from our JBoss EAP 5.1 GC log, running on Java 1.6:
364655.706: [GC 364655.706: [ParNew: 186319K->22912K(206464K), 0.0456839 secs] 1774216K->1611127K(1812096K) icms_dc=4 , 0.0462598 secs] [Times: user=0.81 sys=0.01, real=0.05 secs]
364656.441: [GC 364656.441: [ParNew (promotion failed): 206451K->189950K(206464K), 0.1100582 secs] 1791535K->1780699K(1812096K) icms_dc=12 , 0.1104138 secs] [Times: user=0.27 sys=0.02, real=0.11 secs]
364656.551: [Full GC 364656.552: [CMS364657.837: [CMS-concurrent-sweep: 1.493/97.968 secs] [Times: user=300.13 sys=1.86, real=97.97 secs]
(concurrent mode failure): 1590748K->1090269K(1605632K), 9.2142390 secs] 1780699K->1090269K(1812096K), [CMS Perm : 61890K->61714K(103144K)] icms_dc=12 , 9.2145846 secs] [Times: user=9.21 sys=0.00, real=9.21 secs]
364666.357: [GC [1 CMS-initial-mark: 1090269K(1605632K)] 1171162K(1812096K), 0.1117573 secs] [Times: user=0.11 sys=0.00, real=0.11 secs]
364666.469: [CMS-concurrent-mark-start]
364667.417: [GC 364667.417: [ParNew: 183552K->7298K(206464K), 0.0584138 secs] 1273821K->1097567K(1812096K) icms_dc=12 , 0.0588452 secs] [Times: user=1.11 sys=0.01, real=0.06 secs]
364668.334: [CMS-concurrent-mark: 0.501/1.865 secs] [Times: user=17.46 sys=0.82, real=1.87 secs]
364668.334: [CMS-concurrent-preclean-start]
364669.335: [GC 364669.335: [ParNew: 190850K->5444K(206464K), 0.0148770 secs] 1281119K->1095714K(1812096K) icms_dc=12 , 0.0152002 secs] [Times: user=0.35 sys=0.01, real=0.02 secs]
364671.159: [GC 364671.159: [ParNew: 188996K->5501K(206464K), 0.0111976 secs] 1279266K->1095770K(1812096K) icms_dc=12 , 0.0115905 secs] [Times: user=0.25 sys=0.00, real=0.01 secs]
364673.061: [GC 364673.061: [ParNew: 189053K->5359K(206464K), 0.0124856 secs] 1279322K->1095628K(1812096K) icms_dc=12 , 0.0129190 secs] [Times: user=0.30 sys=0.00, real=0.01 secs]
364675.100: [GC 364675.100: [ParNew: 188911K->1862K(206464K), 0.0225664 secs] 1279180K->1096083K(1812096K) icms_dc=12 , 0.0228625 secs] [Times: user=0.31 sys=0.01, real=0.02 secs]
364677.150: [GC 364677.150: [ParNew: 185414K->1230K(206464K), 0.0195299 secs] 1279635K->1095569K(1812096K) icms_dc=12 , 0.0199073 secs] [Times: user=0.25 sys=0.00, real=0.02 secs]
364679.107: [CMS-concurrent-preclean: 2.004/10.773 secs] [Times: user=45.16 sys=0.72, real=10.77 secs]
364679.107: [CMS-concurrent-abortable-preclean-start]
CMS: abort preclean due to time 364684.161: [CMS-concurrent-abortable-preclean: 0.642/5.054 secs] [Times: user=20.65 sys=0.13, real=5.05 secs]
364684.163: [GC[YG occupancy: 87260 K (206464 K)]364684.163: [Rescan (parallel) , 0.0298602 secs]364684.193: [weak refs processing, 0.4917946 secs] [1 CMS-remark: 1094338K(1605632K)] 1181599K(1812096K), 0.6149585 secs] [Times: user=1.26 sys=0.01, real=0.62 secs]
364684.779: [CMS-concurrent-sweep-start]
364686.357: [CMS-concurrent-sweep: 1.576/1.578 secs] [Times: user=9.17 sys=0.05, real=1.58 secs]
364686.358: [CMS-concurrent-reset-start]
The parts I'm not sure about are CMS-concurrent-sweep. For all I know CMS-concurrent-sweep, unlike ParNew, is not a "stop-the-world" collection. However, we have observed some significant freezes in our application that we are trying to explain and suspecting to be caused by GC. Could it be that 'concurrent mode failure' means that concurrent GC failed and the application did freeze for the time as listed in the 'real' time column, which is 9.21s?
364656.551: [Full GC 364656.552: [CMS364657.837: [CMS-concurrent-sweep: 1.493/97.968 secs] [Times: user=300.13 sys=1.86, real=97.97 secs]
(concurrent mode failure): 1590748K->1090269K(1605632K), 9.2142390 secs] 1780699K->1090269K(1812096K), [CMS Perm : 61890K->61714K(103144K)] icms_dc=12 , 9.2145846 secs] [Times: user=9.21 sys=0.00, real=9.21 secs]
