RFR: 8291753: Add JFR event for GC CPU Time [v4]

[Albert Mingkun Yang]

On Wed, 31 Aug 2022 14:53:04 GMT, Sangheon Kim <sangheki at openjdk.org> wrote:

>> Hi all,
>> 
>> Could I have reviews to add new JFR event for GC CPU time?
>> Currently only log message is available for CPU time (user, system, real).
>> As there is already GCTraceCPUTime class which is used for a log message, I added GCTracer to deliver the event.
>> The log message of CPU time is printed after GC is completed and tried to keep same.
>> 
>> For G1, manually checked there is not difference.
>> 
>> For test, I had to add an exception as GCCpuTime will be generated after GC end.
>> 
>> Testing: tier 1 ~ 3
>> 
>> Thanks,
>> Sangheon
>
> Sangheon Kim has updated the pull request with a new target base due to a merge or a rebase. The pull request now contains five commits:
> 
>  - Merge branch 'master' into 8291753-cpu-time
>  - Reflect egahlin's comment
>  - Add Serial GC support and split test.
>  - Split G1FullGCMark
>  - Add JFR event of GCCpuTime.

The rest look fine, but the inconsistency should be resolved IMO.

src/hotspot/share/gc/g1/g1FullCollector.hpp line 70:

> 68:   G1FullGCMark() : _gc_id(), _cpu_time() { }
> 69: };
> 70: 

I don't recall the exact reason for this, but I have a faint memory on having some discussion with its author. It's from https://bugs.openjdk.org/browse/JDK-8272651

Before this PR:

[32.328s][info ][gc          ] GC(47) Pause Young (Normal) (G1 Evacuation Pause) 1162M->1032M(3072M) 323.751ms
[32.328s][info ][gc,cpu      ] GC(47) User=3.22s Sys=0.00s Real=0.33s
...
[35.221s][info ][gc             ] GC(48) Pause Full (System.gc()) 1134M->660M(3072M) 2650.824ms
[35.221s][info ][gc,cpu         ] GC(48) User=23.97s Sys=1.49s Real=2.65s

After this PR:


[35.221s][info ][gc             ] GC(48) Pause Full (System.gc()) 1134M->660M(3072M) 2650.824ms
[35.221s][info ][gc,cpu         ] GC(48) User=23.97s Sys=1.49s Real=2.65s
...
[41.337s][info ][gc,cpu         ] GC(49) User=27.86s Sys=1.58s Real=3.28s
[41.337s][info ][gc             ] GC(49) Pause Full (System.gc()) 1094M->660M(3072M) 3283.658ms


Note that for Full-GC, the user/sys/real time is *before* GC-end, which is inconsistent with Young-GC.

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

Changes requested by ayang (Reviewer).

PR: https://git.openjdk.org/jdk/pull/9760