JEP 271: Unified GC Logging - Second pre-review

[Poonam Bajaj Parhar]

Hi,

On 11/9/2015 3:00 AM, 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.
>
> 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).
>
> 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).

I think it would be useful to print this information with additional 
'gc' specific tags, for example 'promotion', 'allocation'.

[11.247s][info   ][gc,heap,promotion] Eden: 38912K->0K(2048K) Promoted: 1024K

Using separate tags allows one to turn on/off this additional logging.

Thanks,
Poonam

> 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.
>
>> 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.
>
> Thanks !
>