RFR (S): 8204082: Make names of Young GCs more uniform in logs

[Kirk Pepperdine]

> On Jun 15, 2018, at 5:14 PM, Thomas Schatzl <thomas.schatzl at oracle.com> wrote:
> 
> Hi,
> 
> On Fri, 2018-06-15 at 12:44 +0300, Kirk Pepperdine wrote:
>>> On Jun 15, 2018, at 11:46 AM, Stefan Johansson <stefan.johansson at or
>>> acle.com> wrote:
>>> 
>>> Hi Kirk,
>>> 
>>> On 2018-06-15 08:50, Kirk Pepperdine wrote:
>>>> Hi Thomas,
>>>> From a parsing POV would be preferable "Pause Young Normal" would
>>>> be preferable to Pause Young (Normal)".  I know it's a small
>>>> change but it does make a difference. The rest of the code is
>>>> fine (of course not an official review).
>>>> As for the change it's self, [73.077s][info ][gc,start     ]
>>>> GC(262) Pause Initial Mark (G1 Humongous Allocation) is already
>>>> perfectly clear to me. I'm not sure how
>>>> [73.077s][info ][gc,start     ] GC(262) Pause Young (Initial
>>>> Mark)  (G1 Humongous Allocation) clarifies things. IMO, this
>>>> change only adds to the already high level of noise in the GC
>>>> logs. 
>>> 
>>> I think this makes it more clear that Initial Mark is actually
>>> doing a Young GC as well as initiating the concurrent cycle and
>>> with the new proposed tags it will be even more clear IMHO.
>> 
>> Sure… but a GC log is really an audit trail of GC events…… when the
>> collector ran, what the collector did, and how long it took to get
>> the work done. In order to understand the audit trail you have to
>> have some knowledge of how the collector works. Thus adding “Pause”
>> and “Young” to Initial Mark is redundant to those that know and not
>> any more helpful to those that don’t know how the collector works. 
> 
>  it is helpful to me to e.g. to filter out anything that does not
> start with "Pause Young" immediately on a single look.

Then, we should defer to your suggested format as it adds qualitative value to how you process these logs. The only thing that I would ask is if we can drop the braces as it makes it more difficult to me to support rule sets that span multiple versions of the JVM.

> 
>> And when you consider the use case for GC logs, it’s mostly going to
>> be managed by tooling anyways.
> 
> As mentioned in the original name of the CR ("Add indication that this
> is the "Last Young GC before Mixed" to logs") this change is mostly
> intended to ease staring at crash logs (debugging) where you typically
> do not have the chance to do another run (or adding more extensive
> logging makes the problem not appear) or turn on more logging.
> 
> I.e. analysis with no tools at all. Or at most something like grep, awk
> and sed at quick disposal.
> 
> So this is for a different purpose than auditing.

On one shot debugging.. yup, been there.. try debugging device drivers.. if you mess up there, it not only freezes the kernel (forget about any messages at all) and most likely corrupt your boot disk which will need to be reformatted and….
As for the logging comment, myself and a few others have been trying to get people to distinguish between logging (primarily for errors) and journaling. Frameworks such as log4j have been historically (ab)used for the purposes of journaling which generally results in massive performance regressions. Journaling things such as GC events really creates an audit trail and there are far better solutions for journalling than log4j.

> Since JFR is open
> source now I recommend moving to feeding tools from that longer term.
> I agree that at the moment it does not give you the same information,
> but I assume the community will improve that over time.

I would love to move away from our dependency on GC logging. It’s not only a pain for you to hear from me on what are essentially bike shedding issues but it’s also a pain for us to deal with the logs. Logging is the worst source of information save all the others. Unfortunately I think it’s going to be a while before this can happen as our analytics for use in productions systems rely on data that is only found in the logs.

Kind regards,
Kirk