RFR: 8307346 - Add missing gc+phases logging for ObjectCount(AfterGC) JFR event collection code

[Aleksey Shipilev]

On Wed, 3 May 2023 10:04:14 GMT, olivergillespie <duke at openjdk.org> wrote:

> Add logging for the time taken to collect/report ObjectCount(AfterGC) event to Serial, Parallel and G1 full collectors, for parity with the G1 concurrent collector. This event can be *very* expensive to collect (single threaded STW full heap scan), so it's very important to show it clearly to the user.
> 
> Added output:
> 
> Serial
> 
> [7.976s][debug][gc,phases      ] GC(7) Trigger cleanups 0.002ms
> [7.977s][debug][gc,phases      ] GC(7) Class Unloading 0.556ms
> ++ [7.977s][debug][gc,phases,start] GC(7) Report Object Count
> ++ [8.529s][debug][gc,phases      ] GC(7) Report Object Count 552.065ms
> [8.529s][info ][gc,phases      ] GC(7) Phase 1: Mark live objects 1066.882ms
> [8.529s][info ][gc,phases,start] GC(7) Phase 2: Compute new object addresses
> 
> Parallel
> 
> [5.786s][debug][gc,phases      ] GC(12) Trigger cleanups 0.002ms
> [5.786s][debug][gc,phases      ] GC(12) Class Unloading 0.556ms
> ++ [5.786s][debug][gc,phases,start] GC(12) Report Object Count
> ++ [6.313s][debug][gc,phases      ] GC(12) Report Object Count 526.307ms
> [6.313s][info ][gc,phases      ] GC(12) Marking Phase 889.900ms
> [6.313s][info ][gc,phases,start] GC(12) Summary Phase
> 
> G1 Full
> 
> [3.922s][debug][gc,phases         ] GC(24) Trigger cleanups 0.002ms
> [3.922s][debug][gc,phases         ] GC(24) Phase 1: Class Unloading and Cleanup 0.159ms
> ++ [3.922s][debug][gc,phases,start   ] GC(24) Report Object Count
> ++ [4.442s][debug][gc,phases         ] GC(24) Report Object Count 519.292ms
> [4.442s][info ][gc,phases         ] GC(24) Phase 1: Mark live objects 653.209ms
> [4.442s][info ][gc,phases,start   ] GC(24) Phase 2: Prepare compaction

Some nits.

src/hotspot/share/gc/parallel/psParallelCompact.cpp line 2071:

> 2069: 
> 2070:   {
> 2071:     GCTraceTime(Debug, gc, phases) debug("Report Object Count", &_gc_timer);

Nit: in this file, the holder variables are called `tm`, not `debug`.

src/hotspot/share/gc/serial/genMarkSweep.cpp line 214:

> 212: 
> 213:   {
> 214:     GCTraceTime(Debug, gc, phases) debug("Report Object Count", gc_timer());

Nit: in this file, the holder variables are called `tm_m`, not `debug`.

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

PR Review: https://git.openjdk.org/jdk/pull/13772#pullrequestreview-1410586067
PR Review Comment: https://git.openjdk.org/jdk/pull/13772#discussion_r1183496549
PR Review Comment: https://git.openjdk.org/jdk/pull/13772#discussion_r1183496759