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

[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%)

Kimura Yukihiro has updated the pull request incrementally with one additional commit since the last revision:

  Remove the TEST 8300742: jstat's CGCT is 5 percent higher than the pause time in -Xlog:gc

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

Changes:
  - all: https://git.openjdk.org/jdk11u-dev/pull/1676/files
  - new: https://git.openjdk.org/jdk11u-dev/pull/1676/files/3311e6a4..c1f78569

Webrevs:
 - full: https://webrevs.openjdk.org/?repo=jdk11u-dev&pr=1676&range=01
 - incr: https://webrevs.openjdk.org/?repo=jdk11u-dev&pr=1676&range=00-01

  Stats: 218 lines in 1 file changed: 0 ins; 218 del; 0 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