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

[Kimura Yukihiro]

On Thu, 26 Jan 2023 01:26:40 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 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

Hello Richard, 
Thank you for your review.

The test is to make sure the difference of elapsed time between the two timers. It might be a flaky test.
I think it should not be included in the jtreg test set, once the effect of the fix has been confirmed.
I removed the test from the commit.

Thanks,
Kimura Yukihiro

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

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