[jdk11u-dev] RFR: 8300742: jstat's CGCT is 5 percent higher than the pause time in -Xlog:gc.

[Kimura Yukihiro]

Could anyone review the fix please?
I explain the fix below. 
I tested hotspot/gc with rhel and windows x86_64, and no errors found.
I added a test to confirm the fix. There is no risk.

GC time in the gclog is calculated in the GCTraceTime constructor,
and jstat's CGCT is calculated in the TraceCollectorStats constructor.

In my investigation, the cost of the GCTraceTime constructor is larger than that of TraceCollectorStats.
CGCT includes the executing time of GCTraceTime.
Since CGCT is the accmulated time, as the number of CMSGC increases, the difference with the gclog increases.

Only CMSGC, execution order of GCTraceTime and TraceCollectorStats is different from other GCs.

concurrentMarkSweepGeneration.cpp
  TraceCollectorStats
  GCTraceTime

g1CollectedHeap.cpp / vm_operations_g1.cpp / psParallelCompact.cpp / genCollectedHeap.cpp
  GCTraceTime
  TraceCollectorStats

I modified the order of two constructors in concurrentMarkSweepGeneration.cpp.
The following is the result. The difference between two timers bcomes small.
The difference of time a GC should be small, because CGCT is the accmulated time.
The order of two timers should be same for all GCs.
Naturally, the GC time in the gclog will increase slightly which is several micro secs in Xmx512m, 2.5GHz CPU.

Windows 2016 / x64

befor modification
  jstat CGT 6011
  jstat CGCT 8593.0 ms
  gclog invocations 6011
  gclog time 8136.4 ms

  jstat/loggc=1.056  (the difference is 5.6%)

after modification
  jstat CGT 6104
  jstat CGCT 7503.0 ms
  gclog invocations 6104
  gclog time 7603.5 ms

  jstat/loggc=0.987 (the difference is 1.3%)

RHEL 7 / x64

befor modification
  jstat CGT 4576
  jstat CGCT 5010.0ms
  gclog invocations 4576
  gclog time 4871.4 ms

  jstat/loggc=1.028  (the difference is 2.8%)

after modification
  jstat CG 4297
  jstat CGCT 3408.0ms
  gclog invocations 4297
  gclog time 3416.95 ms

  jstat/loggc=0.997  (the difference is 0.3%)

-------------

Commit messages:
 - Remove extra whitespace in the TEST 8300742: jstat's CGCT is 5 percent higher than the pause time in -Xlog:gc
 - Change the bug tag in the TEST 8300742: jstat's CGCT is 5 percent higher than the pause time in -Xlog:gc
 - 8300742: jstat's CGCT is 5 percent higher than the pause time in -Xlog:gc

Changes: https://git.openjdk.org/jdk11u-dev/pull/1676/files
 Webrev: https://webrevs.openjdk.org/?repo=jdk11u-dev&pr=1676&range=00
  Issue: https://bugs.openjdk.org/browse/JDK-8300742
  Stats: 222 lines in 2 files changed: 220 ins; 1 del; 1 mod
  Patch: https://git.openjdk.org/jdk11u-dev/pull/1676.diff
  Fetch: git fetch https://git.openjdk.org/jdk11u-dev pull/1676/head:pull/1676

PR: https://git.openjdk.org/jdk11u-dev/pull/1676