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

[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 with a new target base due to a merge or a rebase. The incremental webrev excludes the unrelated changes brought in by the merge/rebase. The pull request contains five additional commits since the last revision:

 - Merge branch 'master' into 8300742
 - Remove the TEST 8300742: jstat's CGCT is 5 percent higher than the pause time in -Xlog:gc
 - 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:
  - all: https://git.openjdk.org/jdk11u-dev/pull/1676/files
  - new: https://git.openjdk.org/jdk11u-dev/pull/1676/files/c1f78569..3e450760

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

  Stats: 3002 lines in 68 files changed: 1846 ins; 859 del; 297 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