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

Corrupted GC log with -XX:NumberOfGCLogFiles=1 - timestamps at the end of file are before those at the beginning

XMLWordPrintable

    • gc
    • x86_64
    • linux

      FULL PRODUCT VERSION :
      Java HotSpot(TM) 64-Bit Server VM (25.91-b14) for linux-amd64 JRE (1.8.0_91-b14), built on Apr 1 2016 00:57:21 by "java_re" with gcc 4.3.0 20080428 (Red Hat 4.3.0-8)

      FULL OS VERSION :
      Most probably:

      Linux mesos-slave1021 3.19.0-26-generic #28~14.04.1-Ubuntu SMP Wed Aug 12 14:09:17 UTC 2015 x86_64 x86_64 x86_64 GNU/Linux

      EXTRA RELEVANT SYSTEM CONFIGURATION :
      Application running on Marathon

      A DESCRIPTION OF THE PROBLEM :
      Using the following GC logging flags:

      -XX:GCLogFileSize=104857600 -XX:NumberOfGCLogFiles=1 -XX:+PrintClassHistogram -XX:+PrintFlagsFinal -XX:+PrintGC -XX:+PrintGCApplicationStoppedTime -XX:+PrintGCCause -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintTenuringDistribution -XX:+UseG1GC -XX:+UseGCLogFileRotation

      after the GC log reaches 100 MB in size, it becomes corrupted, with the dates at the end of the file being before those at the start. This causes log analysis tools such as Censum to display the length of the log file as a negative amount of time. It seems that it is the flag:

       -XX:NumberOfGCLogFiles=1

      which triggers this behavior as after changing the value to 2, correct log files are generated.

      Example beginning of log file:

      File /var/log/elasticsearch/gc.log rotated at 2016-05-09 10:11:32
      Java HotSpot(TM) 64-Bit Server VM (25.91-b14) for linux-amd64 JRE (1.8.0_91-b14), built on Apr 1 2016 00:57:21 by "java_re" with gcc 4.3.0 20080428 (Red Hat 4.3.0-8)
      Memory: 4k page, physical 32948012k(24415148k free), swap 0k(0k free)
      CommandLine flags: -XX:CICompilerCount=4 -XX:ConcGCThreads=2 -XX:+DisableExplicitGC -XX:G1HeapRegionSize=4194304 -XX:GCLogFileSize=104857600 -XX:+HeapDumpOnOutOfMemoryError -XX:InitialHeapSize=528482304 -XX:MarkStackSize=4194304 -XX:MaxHeapSize=17179869184 -XX:MaxNewSize=10305404928 -XX:MinHeapDeltaBytes=4194304 -XX:NumberOfGCLogFiles=1 -XX:+PrintClassHistogram -XX:+PrintFlagsFinal -XX:+PrintGC -XX:+PrintGCApplicationStoppedTime -XX:+PrintGCCause -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintTenuringDistribution -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseG1GC -XX:+UseGCLogFileRotation
      2016-05-09T10:11:32.647+0200: 261805.287: [GC pause (G1 Evacuation Pause) (young)
      ...
      2016-05-09T10:11:32.662+0200: 261805.303: Total time for which application threads were stopped: 0.0199791 seconds, Stopping threads took: 0.0028582 seconds

      and the end of the same file:

      2016-05-09T10:11:23.099+0200: 261795.739: [GC pause (G1 Evacuation Pause) (young)
      ...
      2016-05-09T10:11:23.116+0200: 261795.756: Total time for which application threads were stopped: 0.0197326 seconds, Stopping threads took: 0.0011604 seconds

      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 :
      Run an application with GC loggin flags

      -XX:GCLogFileSize=104857600 -XX:NumberOfGCLogFiles=1 -XX:+PrintClassHistogram -XX:+PrintFlagsFinal -XX:+PrintGC -XX:+PrintGCApplicationStoppedTime -XX:+PrintGCCause -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintTenuringDistribution -XX:+UseG1GC -XX:+UseGCLogFileRotation

      and let the 100 MB log be filled so that it rotates.

      EXPECTED VERSUS ACTUAL BEHAVIOR :
      Expected:

      GC log file should have later dates at the end than at the beginning

      Actual:

      An earlier date appears at the end of file than at the beginning
      REPRODUCIBILITY :
      This bug can be reproduced often.

      CUSTOMER SUBMITTED WORKAROUND :
      Changing -XX:NumberOfGCLogFiles=1 to -XX:NumberOfGCLogFiles=2 causes generated log files to be correct (but changes their number also)

            fmatte Fairoz Matte
            webbuggrp Webbug Group
            Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

              Created:
              Updated:
              Resolved: