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

[Richard Reingruber]

On Fri, 20 Jan 2023 10:31:44 GMT, Kimura Yukihiro <duke at openjdk.org> wrote:

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

Hi Kimura,

cms changes seem ok.
I'm not sure though if the test is necessary (and worth the CO2). What are the runtimes you are seeing?

Thanks, Richard.

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

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