Extend gc+heap=info output with subspace occupancy info for young gen

[Tony Printezis]

FWIW, the gc+metaspace=info output has a similar issue when compressed oops
are enabled:

[30.210s][info][gc,metaspace ] GC(16) Metaspace: 7972K->7972K(1056768K)

This hides the information that users care about (i.e., what they set with
-XX:MetaspaceSize). It will be valuable to provide a sub-space breakdown
for this too, like:

[30.210s][info][gc,metaspace ] GC(16) Metaspace: 7972K->7972K(1056768K)
ClassMetadata: 7248K->7248K(8192K) ClassSpace: 724K->724K(1048576K)

Again, the change is straightforward. :-)

Tony


—————
Tony Printezis | @TonyPrintezis | tprintezis at twitter.com


On April 18, 2019 at 6:49:49 PM, Kodewerk (kirk at kodewerk.com) wrote:

+1



On Apr 18, 2019, at 9:26 PM, Tony Printezis <tprintezis at twitter.com> wrote:

Hi all,

I’ve been looking at the gc+heap=info output for post-9 JDKs:

[16.607s][info][gc,heap     ] GC(55) PSYoungGen: 1383840K->1600K(1612800K)

[16.607s][info][gc,heap     ] GC(55) ParOldGen: 1348K->1348K(253952K)

Unfortunately, there doesn’t seem to be a way to get the eden and survivor
space occupancy at the info level. If we use gc+heap=debug we get the old
PrintHeapAtGC output (twice per GC: once before and once after):

[4.194s][debug][gc,heap     ] GC(11) Heap before GC invocations=12 (full
0): PSYoungGen      total 1612800K, used 1383968K [0x000000008f800000,
0x0000000100000000, 0x0000000100000000)
[4.194s][debug][gc,heap     ] GC(11)   eden space 1382400K, 100% used
[0x000000008f800000,0x00000000e3e00000,0x00000000e3e00000)
[4.194s][debug][gc,heap     ] GC(11)   from space 230400K, 0% used
[0x00000000e3e00000,0x00000000e3f88000,0x00000000f1f00000)
[4.194s][debug][gc,heap     ] GC(11)   to   space 230400K, 0% used
[0x00000000f1f00000,0x00000000f1f00000,0x0000000100000000)
[4.194s][debug][gc,heap     ] GC(11)  ParOldGen       total 253952K, used
1296K [0x0000000080000000, 0x000000008f800000, 0x000000008f800000)
[4.194s][debug][gc,heap     ] GC(11)   object space 253952K, 0% used
[0x0000000080000000,0x00000000801440e0,0x000000008f800000)
[4.194s][debug][gc,heap     ] GC(11)  Metaspace       used 7923K, capacity
8115K, committed 8320K, reserved 1056768K
[4.194s][debug][gc,heap     ] GC(11)   class space    used 722K, capacity
790K, committed 896K, reserved 1048576K

This contains the required information but it also increases the log size
by 4x to 5x as it contains a lot of mostly useless and duplicated
information.

I have a couple of changes (for ParNew and ParallelGC) to extend the
gc+heap=info output with the occupancy info for eden and the survivors -
the output looks like this:

[16.607s][info][gc,heap     ] GC(55) PSYoungGen: 1383840K->1600K(1612800K)
Eden: 1382400K->0K(1382400K) From: 1440K->1600K(230400K) To: 0K->0K(230400K)
[16.607s][info][gc,heap     ] GC(55) ParOldGen: 1348K->1348K(253952K)

Is there interest in this? The changes are straightforward.

Tony



—————
Tony Printezis | @TonyPrintezis | tprintezis at twitter.com
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://mail.openjdk.org/pipermail/hotspot-gc-dev/attachments/20190419/652660a9/attachment.htm>