JDK-8202752 : PrintGCTimestamps cannot be disabled
  • Type: Bug
  • Component: hotspot
  • Sub-Component: gc
  • Affected Version: 7,8
  • Priority: P4
  • Status: Resolved
  • Resolution: Not an Issue
  • OS: windows_7
  • CPU: x86_64
  • Submitted: 2018-05-07
  • Updated: 2018-06-07
  • Resolved: 2018-06-07
Description
ADDITIONAL SYSTEM INFORMATION :
Full commandline from one test.  This one has the explicit parameter to disable PrintGCTimeStamps.

"C:\Program Files\Java\jdk1.8.0_144\bin\java"  -server -Xms512m -Xmx512m -Duser.timezone=UTC -XX:NewRatio=3    -XX:SurvivorRatio=4    -XX:TargetSurvivorRatio=90    -XX:MaxTenuringThreshold=8    -XX:+UseConcMarkSweepGC    -XX:ConcGCThreads=4 -XX:ParallelGCThreads=4    -XX:+CMSScavengeBeforeRemark    -XX:PretenureSizeThreshold=64m    -XX:+UseCMSInitiatingOccupancyOnly    -XX:CMSInitiatingOccupancyFraction=50    -XX:CMSMaxAbortablePrecleanTime=6000    -XX:+CMSParallelRemarkEnabled    -XX:+ParallelRefProcEnabled    -XX:-OmitStackTraceInFastThrow -verbose:gc      -XX:+PrintHeapAtGC      -XX:+PrintGCDetails      -XX:-PrintGCTimeStamps      -XX:+PrintGCDateStamps      -XX:+PrintTenuringDistribution      -XX:+PrintGCApplicationStoppedTime "-Xloggc:C:\Users\sheisey\Downloads\solr-7.3.0\server\logs\solr_gc.log" -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=9 -XX:GCLogFileSize=20M -Xss256k  -Dsolr.log.dir="C:\Users\sheisey\Downloads\solr-7.3.0\server\logs"     -Dlog4j.configuration="file:C:\Users\sheisey\Downloads\solr-7.3.0\server\resources\log4j.properties" -DSTOP.PORT=7983 -DSTOP.KEY=solrrocks     -Dsolr.log.muteconsole     -Dsolr.solr.home="C:\Users\sheisey\Downloads\solr-7.3.0\server\solr" -Dsolr.install.dir="C:\Users\sheisey\Downloads\solr-7.3.0" -Dsolr.default.confdir="C:\Users\sheisey\Downloads\solr-7.3.0\server\solr\configsets\_default\conf"     -Djetty.host=0.0.0.0 -Djetty.port=8983 -Djetty.home="C:\Users\sheisey\Downloads\solr-7.3.0\server"     -Djava.io.tmpdir="C:\Users\sheisey\Downloads\solr-7.3.0\server\tmp" -jar start.jar "--module=http" ""

Also tried with 8u172, and tried Solr 5.5.5 with 7u80, 7u_45, and 7u4, with the same behavior.   

A DESCRIPTION OF THE PROBLEM :
Running latest Solr version.  GC logging on the commandline has PrintGCDateStamps enabled.  Want to disable PrintGCTimeStamps so there is only one timestamp in the log.  Commandline did have -XX:+PrintGCTimeStamps included, so that was removed.  Also tried with -XX:-PrintGCTimeStamps to explicitly disable it.  This did not work -- both the absolute date stamp and the relative seconds-since-JVM-start timestamps are in the GC log.  I used the JDK, not the JRE, for all these tests.  I have only done the testing on Windows, though when I run these things for real, it's on Linux.

STEPS TO FOLLOW TO REPRODUCE THE PROBLEM :
Run a program with GC logging options that include -XX:+PrintGCDateStamps and do NOT include -XX:+PrintGCTimeStamps.  Alternately, use -XX:+PrintGCDateStamps -XX-PrintGCTimeStamps so that the latter is explicitly disabled.

EXPECTED VERSUS ACTUAL BEHAVIOR :
EXPECTED -
The gc logfile should only contain absolute full date/time information, not seconds-since-JVM-start.

ACTUAL -
Both the full date/time information AND seconds-since-JVM-start are included in every log entry.
Comments
This is not a bug as explained in comment 5th and 7th. So I am closing it.
07-06-2018
-Xloggc implicitly enables time stamps. Please use -XX:-PrintGCTimestamps after the specification of -Xloggc to achieve the desired result. From https://docs.oracle.com/javase/8/docs/technotes/tools/windows/java.html : -Xloggc:filename Sets the file to which verbose GC events information should be redirected for logging. The information written to this file is similar to the output of -verbose:gc with the time elapsed since the first GC event preceding each logged event. The -Xloggc option overrides -verbose:gc if both are given with the same java command. Note the "... with the time elapsed since the first GC event...". I.e. -Xloggc is defined to implictly enable time stamps. Since the command line is read and options activated from left to right, -Xloggc "wins" if specified after the -XX:PrintGCTimeStamps options. I.e. the option seems to work as intended.
06-06-2018
shafi@shafi-ahmad:~/Java/OOME$ java -server -Xms512m -Xmx512m -verbose:gc -XX:+PrintGCDateStamps -XX:-PrintGCTimeStamps -Xloggc:gc.log Adder ^C shafi@shafi-ahmad:~/Java/OOME$ cat gc.log Java HotSpot(TM) 64-Bit Server VM (25.172-b31) for linux-amd64 JRE (1.8.0_172-b31), built on Apr 4 2018 01:37:05 by "java_re" with gcc 4.3.0 20080428 (Red Hat 4.3.0-8) Memory: 4k page, physical 4563656k(2004004k free), swap 2095100k(1744904k free) CommandLine flags: -XX:InitialHeapSize=536870912 -XX:MaxHeapSize=536870912 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops 2018-05-29T14:54:58.991+0530: 0.807: [GC (Allocation Failure) 139776K->128668K(506816K), 0.8318962 secs] 2018-05-29T14:54:59.990+0530: 1.806: [GC (Allocation Failure) 268444K->260251K(506816K), 0.6215759 secs] 2018-05-29T14:55:00.736+0530: 2.552: [Full GC (Allocation Failure) 400027K->383642K(506816K), 1.7650385 secs] 2018-05-29T14:55:02.817+0530: 4.633: [Full GC (Allocation Failure) 506815K->506815K(506816K), 3.1543165 secs] 2018-05-29T14:55:05.972+0530: 7.787: [Full GC (Allocation Failure) 506815K->506815K(506816K), 3.3210347 secs] 2018-05-29T14:55:09.293+0530: 11.108: [Full GC (Allocation Failure) 506815K->506802K(506816K), 3.7352396 secs] 2018-05-29T14:55:13.032+0530: 14.847: [Full GC (Allocation Failure) 506815K->506815K(506816K), 2.8483092 secs] . . . shafi@shafi-ahmad:~/Java/OOME$ java -server -Xms512m -Xmx512m -verbose:gc -XX:+PrintGCDateStamps -XX:-PrintGCTimeStamps Adder 2018-05-29T14:55:54.950+0530: [GC (Allocation Failure) 139776K->131335K(506816K), 0.2476636 secs] 2018-05-29T14:55:55.273+0530: [GC (Allocation Failure) 271111K->262407K(506816K), 0.3517540 secs] 2018-05-29T14:55:55.708+0530: [Full GC (Allocation Failure) 402183K->385798K(506816K), 0.8324722 secs] 2018-05-29T14:55:56.797+0530: [Full GC (Allocation Failure) 506815K->506815K(506816K), 0.9750605 secs] 2018-05-29T14:55:57.773+0530: [Full GC (Allocation Failure) 506815K->506815K(506816K), 0.9517600 secs] 2018-05-29T14:55:58.724+0530: [Full GC (Allocation Failure) 506815K->506802K(506816K), 1.1506961 secs] 2018-05-29T14:55:59.875+0530: [Full GC (Allocation Failure) 506815K->506815K(506816K), 1.3734541 secs] . . . GC logging behavior is different if -Xloggc:/path/to/gc.log is specified in the command line. In the presence of JVM option -Xloggc:/path/to/gc.log the effect of presence of JVM option -XX:+/-PrintGCTimeStamps is null and void.
29-05-2018