Uploaded image for project: 'JDK'
  1. JDK
  2. JDK-8085886

Noticable log issue during Full GC when Metadata GC Threshold is reached

    XMLWordPrintable

Details

    • gc
    • x86_64
    • linux

    Description

      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.

      Attachments

        Issue Links

          Activity

            People

              Unassigned Unassigned
              webbuggrp Webbug Group
              Votes:
              0 Vote for this issue
              Watchers:
              4 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved: