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

[Richard Reingruber]

On Sat, 4 Feb 2023 13:15:17 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%)
>
> 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

You're welcome. This would be a general guide: https://wiki.openjdk.org/display/JDKUpdates/How+to+contribute+or+backport+a+fix
Its only partially applicable to your fix though since it isn't a backport.

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

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