JEP 271: Unified GC Logging - Second pre-review

[Bengt Rutisson]

Hi Simone,


On 2015-11-09 12:00, Simone Bordet wrote:
> Hi,
>
> On Mon, Nov 9, 2015 at 10:23 AM, Bengt Rutisson
> <bengt.rutisson at oracle.com> wrote:
>> Sorry, but I don't understand how using the value for the Old generation to
>> compute the promotion rate the way you describe it is any different than
>> using the overall heap usage. The overall heap usage is just
>> Eden+Survivor+Old.
> In a mixed GC, where 2 MiB have been promoted and 3 MiB have been
> cleaned up from the old generation, I would see the old generation
> usage decreasing by 1 MiB.
> I could account that with just old generation cleanup. Would be nice
> to know the promotion size (this would apply to Eden -> Survivor too).
>
> A consideration.

Ok. So, the new format is not worse than the old format, right? It is 
just that neither format gives you the information you really need.

More on this below...

>
> The lines tagged with "gc" report something related to gc in certain
> cases (e.g. the type of GC, the time spent), and in some other cases
> they just report sizes (which happen to be measured at GC events, but
> may have little to do with GC).
> For example:
>
> [11.247s][info   ][gc,metaspace] GC#265 Metaspace: 2993K->2993K(1056768K)
>
> just reports size, not GC activity. I would have expected a line
> tagged "gc,metaspace" *only* if there was some GC activity in
> metaspace (e.g. class unloading or such).

This logging is there precisely to allow you to tell you that the GC did 
go through the metaspace to handle class unloading. In the example above 
there was no change so no classes were unloaded. Still it was work 
performed by the GC, so I think it should be tagged with the "gc" tag.

>
> Same for
>
> [11.247s][info   ][gc,heap     ] GC#265 Eden: 38912K->0K(2048K)
>
> it does not say how much of the Eden was promoted, it just reports sizes.
>
> Just to be clear, I'm fine with the current format, I just wanted to
> point out that it would be nicer to give a more precise GC meaning to
> those lines rather than just sizing. I would like to know what the GC
> *did*, not only what the sizes are.
> In a mixed GC, I see no way to figure out the promotion.
> Like Kirk said, it can be interpolated, but while we're at it, well... :)
>
> For example (numbers are not real):
>
> [11.247s][info   ][gc,heap     ] GC#265 Eden: Collected: 38912K
> Promoted: 2048K (0/2048K)
> [11.247s][info   ][gc,heap     ] GC#265 Survivor: Collected: 1024K
> Promoted: 1024K (4096/6144K)
> [11.247s][info   ][gc,heap     ] GC#265 Old: Collected: 0K (73147/131072K)
> [11.247s][info   ][gc,heap     ] GC#265 Humongous: Allocated: 0K
> Collected: 0K (0K)
> [11.247s][info   ][gc,metaspace] GC#265 Metaspace: Collected: 0K (2993/1056768K)
>
> Reporting capacities implicitly reports the expansion/contraction
> activity of the GC.
> Reporting sizes implicitly reports the non-activity of the GC (i.e.
> how much accumulated between 2 GCs).
>
> As I said, this change in meaning of the logged lines could be totally
> out of scope for this work, but perhaps this work could be the driver
> to clarify the semantic.
> I'm interested in the semantic rather than the format. Also for tools,
> a clearer semantic would mean less work to do to figure out implicits.

Right. Thanks for looking at this and providing such good feedback!

I think that as a first step we should try to get the current logging 
converted to using the unified logging framework. Then we can improve on 
it. We can still improve and change the format for JDK 9. But I think we 
should get the big bulk change in first.

Adding the promoted bytes, as you and Poonam suggested, is a good idea. 
However, I would prefer to add it after the main change has been pushed.

Best would be if you have a chance to create a bug report on 
https://bugs.openjdk.java.net to track this enhancement.

>
>> I see your point about using the same unit for both types of logging. The
>> reason I chose different units is that for the single line logging I would
>> like the values to be as compact as possible to avoid that the line gets too
>> long.
> I'm nitpicking here, but when I look at GC logs I am already an
> advanced "reader" that did my homework about GC memory layout, GC
> phases, GC algorithms, etc. so 6 more characters don't seem too much.
> Since I'm looking at the GC logs (an advanced activity not performed
> by a random Joe) I would appreciate the consistency.

I agree that we need to evaluate how to handle this properly. I am not 
sure what is the best solution. Again I would prefer to push the current 
version first and then use it for a while to see how we feel about it.

Thanks,
Bengt

> Thanks !
>