JEP 271: Unified GC Logging - Second pre-review

[Simone Bordet]

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).

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 !

-- 
Simone Bordet
http://bordet.blogspot.com
---
Finally, no matter how good the architecture and design are,
to deliver bug-free software with optimal performance and reliability,
the implementation technique must be flawless.   Victoria Livschitz