FULL PRODUCT VERSION :
java version "1.8.0_45"
Java(TM) SE Runtime Environment (build 1.8.0_45-b14)
Java HotSpot(TM) 64-Bit Server VM (build 25.45-b02, mixed mode)
FULL OS VERSION :
Red Hat 6.5 (2.6.32-431.el6.x86_64)
EXTRA RELEVANT SYSTEM CONFIGURATION :
-XX:+PrintGC -XX:-PrintGCDetails -XX:+PrintGCDateStamps -XX:+UseG1GC -XX:MaxGCPauseMillis=30 -Xms1024m -Xmx1024m -XX:MaxMetaspaceSize=128m
A DESCRIPTION OF THE PROBLEM :
We are experienceng a logging issue when we reach the Metadata GC Threashold and a Full GC is commenced. In this case a new GC log message shows up on the output about this action, but instead of writing each and every GC log messages in a separate line, it appears that in this particular case, a line can consist of not one but two GC log messages. See the example below:
2015-05-12T13:26:02.398+0200: [Full GC (Metadata GC Threshold) 2015-05-12T13:26:02.398+0200: [GC concurrent-root-region-scan-start]
2015-05-12T13:26:02.398+0200: [GC concurrent-root-region-scan-end, 0.0002125 secs]
2015-05-12T13:26:02.398+0200: [GC concurrent-mark-start]
290M->189M(1024M), 0.5072168 secs]
As you can see the last line should be in the same line as the line starting with the Full GC log.
THE PROBLEM WAS REPRODUCIBLE WITH -Xint FLAG: Did not try
THE PROBLEM WAS REPRODUCIBLE WITH -server FLAG: Yes
STEPS TO FOLLOW TO REPRODUCE THE PROBLEM :
We are able to reroduce it with the following steps:
We use Wildfly 8.2 app server with the mentioned Java version and when we issue deploys and undeploys several times (with a particular enterprise application) and "Full GC (Metadata GC Threshold)" shows up in the log, then it's written always like in the Description.
EXPECTED VERSUS ACTUAL BEHAVIOR :
Each and every GC log should appear in its separate line
ERROR MESSAGES/STACK TRACES THAT OCCUR :
A snippet from the GC log:
2015-05-12T13:26:01.927+0200: [GC pause (G1 Evacuation Pause) (young) 402M->295M(1024M), 0.0308823 secs]
2015-05-12T13:26:02.373+0200: [GC pause (Metadata GC Threshold) (young) (initial-mark) 317M->290M(1024M), 0.0249139 secs]
2015-05-12T13:26:02.398+0200: [Full GC (Metadata GC Threshold) 2015-05-12T13:26:02.398+0200: [GC concurrent-root-region-scan-start]
2015-05-12T13:26:02.398+0200: [GC concurrent-root-region-scan-end, 0.0002125 secs]
2015-05-12T13:26:02.398+0200: [GC concurrent-mark-start]
290M->189M(1024M), 0.5072168 secs]
2015-05-12T13:26:02.906+0200: [GC concurrent-mark-abort]
2015-05-12T13:26:03.028+0200: [GC pause (Metadata GC Threshold) (young) (initial-mark) 192M->193M(1024M), 0.0134625 secs]
2015-05-12T13:26:03.042+0200: [Full GC (Metadata GC Threshold) 2015-05-12T13:26:03.042+0200: [GC concurrent-root-region-scan-start]
2015-05-12T13:26:03.042+0200: [GC concurrent-root-region-scan-end, 0.0002307 secs]
2015-05-12T13:26:03.042+0200: [GC concurrent-mark-start]
193M->183M(1024M), 0.3746577 secs]
2015-05-12T13:26:03.417+0200: [GC concurrent-mark-abort]
2015-05-12T13:26:03.437+0200: [GC pause (Metadata GC Threshold) (young) (initial-mark) 184M->186M(1024M), 0.0101472 secs]
2015-05-12T13:26:03.447+0200: [Full GC (Metadata GC Threshold) 2015-05-12T13:26:03.447+0200: [GC concurrent-root-region-scan-start]
2015-05-12T13:26:03.448+0200: [GC concurrent-root-region-scan-end, 0.0001437 secs]
2015-05-12T13:26:03.448+0200: [GC concurrent-mark-start]
186M->183M(1024M), 0.3165751 secs]
2015-05-12T13:26:03.764+0200: [Full GC (Last ditch collection) 183M->181M(1024M), 0.3506834 secs]
2015-05-12T13:26:04.115+0200: [GC concurrent-mark-abort]
2015-05-12T13:26:04.116+0200: [GC pause (Metadata GC Threshold) (young) (initial-mark) 181M->181M(1024M), 0.0110965 secs]
2015-05-12T13:26:04.128+02002015-05-12T13:26:04.128+0200: [Full GC (Metadata GC Threshold) : [GC concurrent-root-region-scan-start]
2015-05-12T13:26:04.128+0200: [GC concurrent-root-region-scan-end, 0.0001523 secs]
2015-05-12T13:26:04.128+0200: [GC concurrent-mark-start]
181M->168M(1024M), 0.3077973 secs]
2015-05-12T13:26:04.436+0200: [GC concurrent-mark-abort]
2015-05-12T13:26:38.826+0200: [GC pause (G1 Evacuation Pause) (young) 392M->198M(1024M), 0.0631935 secs]
2015-05-12T13:27:09.168+0200: [GC pause (G1 Evacuation Pause) (young) 221M->180M(1024M), 0.0211185 secs]
2015-05-12T13:27:09.339+0200: [GC pause (G1 Evacuation Pause) (young) 226M->187M(1024M), 0.0184767 secs]
2015-05-12T13:27:09.477+0200: [GC pause (G1 Evacuation Pause) (young) 231M->193M(1024M), 0.0190939 secs]
REPRODUCIBILITY :
This bug can be reproduced always.