JFR Event for Full GCs

[Thomas Schatzl]

Hi,

On Fri, 2018-12-07 at 09:11 -0500, Andrew Azores wrote:
> Hi,
> 
> On 2018-12-05 4:54 p.m., Thomas Schatzl wrote:
> > Hi,
> > 
> > On Wed, 2018-12-05 at 12:23 -0500, Andrew Azores wrote:
> > > Hmm. It's along the right lines (and I had overlooked it before)
> > > but I don't think this event meets the requirement. I modified my
> > > JMC testing rule to look for those events while running my
> > > reproducer applet with -XX:+UseG1GC -XX:+PrintGCDetails. My run
> > > saw one OldGarbageCollection event emitted but the GC log output
> > > does not show any Full GC events. I also tried reading through
> > > the JFR and GC sources again to trace the execution path where
> > > this event is emitted, and although I wasn't 100% confident, it
> > > didn't look to me like this event is 1:1 with Full collections -
> > > perhaps a Full collection implies this event emission but not
> > > vice-versa? From my limited understanding of the GC phases and
> > > generations this would seem to make sense.
> > 
> >    iirc a completed marking cycle also counts as "full" collection
> > in some cases as it completely considers the old generation too.
> > PrintGCDetails should show them.
> > 
> > (Young collections may actually also reclaim space in old gen but
> > does not send this event - so actually this OldGarbageCollection
> > event may actually be considered as some kind of backwards
> > compatibility hack for G1 in any case)
> > 
> > Thanks,
> >    Thomas
> > 
> 
> Sorry, I'm not sure I've fully understood. Are you saying that the 
> OldGarbageCollection event really should signify that a full
> collection has occurred? I don't think I saw any instances of a
> marking cycle showing as a full collection in the logs, but maybe it
> was there and I just didn't know what I was looking for.

Since the OldGarbageCollection event is not well defined, it seems
purely incidental that it works (or not) depending on what you believe
it indicates.

The situation gets worse because particularly with G1 it is a bit
unclear (to me) what an OldGarbageCollection event actually indicates.

Since G1 may always collect the old generation with any GC, does this
mean it should always send that event or not (or only if it also
collects parts of the old gen; should G1 also send the event during the
remark phase where it also collects completely empty old gen regions
instead of the end of concurrent mark)?

Or is it reserved for the typically more time consuming events like stw
full gc, and eventually concurrent cycle for backwards compatibility to
Serial and Parallel where the situation is relatively clear?

>From very briefly looking at jdk11 sources, it should trigger for both
concurrent cycle end and regular Full GC in G1. Not so sure whether
latest JDK8u also triggers it at concurrent cycle end from looking
there even more briefly.

For CMS (which should not have changed since jdk8u, so assuming the
code is the same), it looks like it is sent at both concurrent cycle
end and stw old generation compaction.

> The GarbageCollection event's gcName field seems that it may actually
> do the trick for G1, since G1 has distinct gcNames for
> G1New/G1Old/*G1Full* which are tagged on by the various GCTracers.  

I wonder what "G1Old" means - probably Mixed GC?

> Testing a JMC rule that looks for those and comparing its results to
> PrintGCDetails looks like it is working as expected, with one event
> seen for each "Pause Full" in  the logs. Should OldGarbageCollection
> be a CMS analog to these events?

I recommend using this event and the gcname field for CMS too as it
seems to work currently. As mentioned, CMS should send
OldGarbageCollection both for stw full gc and end of concurrent cycle
afaict (without testing).

Hth,
  Thomas