-
Bug
-
Resolution: Won't Fix
-
P4
-
None
-
8
-
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)
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)