RFR: JDK-8149035: Make the full_gc_dump() calls be recorded as part of the GC

[Bengt Rutisson]

Hi everyone,

Could I have a couple of reviews for this change?

http://cr.openjdk.java.net/~brutisso/8149035/webrev.00/
https://bugs.openjdk.java.net/browse/JDK-8149035

There are two actions that can be taken before and after a full GC. We 
can do a a heap dump and we can produce a class histogram.

Both these actions now use their own GC ID and are logged and recorded 
as separate GCs. It is more natural that they are considered part of the 
full GC. Especially since they make up a significant part of the pause 
that the application experience.

We should move these two actions inside of the GC pause reporting.

The log now looks like this (truncated the class histogram for readability):

[1,930s][info   ][gc,start    ] GC(1) Pause Full (System.gc()) (1,930s)
[1,930s][info   ][gc,start    ] GC(1) Heap Dump (before full gc) (1,930s)
[1,985s][info   ][gc          ] GC(1) Heap Dump (before full gc) 
(1,930s, 1,985s) 54,830ms
[1,994s][trace  ][gc,classhisto] GC(1)  num #instances         #bytes  
class name
[1,994s][trace  ][gc,classhisto] GC(1) 
----------------------------------------------
[1,994s][trace  ][gc,classhisto] GC(1)    1: 9059         601136  [B
[1,994s][trace  ][gc,classhisto] GC(1)    2: 466         480144  [I
[1,994s][trace  ][gc,classhisto] GC(1)    3: 1788         205608  
java.lang.Class
...
[1,999s][trace  ][gc,classhisto] GC(1)  584: 1             16 
sun.util.resources.cldr.provider.CLDRLocaleDataMetaInfo_jdk_localedata
[1,999s][trace  ][gc,classhisto] GC(1) Total 40164        2413832
[1,999s][trace  ][gc,classhisto] GC(1) Class Histogram (before full gc) 
(1,985s, 1,999s) 13,485ms
[2,051s][info   ][gc,heap      ] GC(1) PSYoungGen: 2349K->0K(57344K)
[2,051s][info   ][gc,heap      ] GC(1) ParOldGen: 8K->1902K(65536K)
[2,051s][info   ][gc,metaspace ] GC(1) Metaspace: 10738K->10738K(1058816K)
[2,062s][trace  ][gc,classhisto] GC(1)  num #instances         #bytes  
class name
[2,062s][trace  ][gc,classhisto] GC(1) 
----------------------------------------------
[2,062s][trace  ][gc,classhisto] GC(1)    1: 9059         601136  [B
[2,062s][trace  ][gc,classhisto] GC(1)    2: 1788         205608  
java.lang.Class
[2,062s][trace  ][gc,classhisto] GC(1)    3: 8551         205224  
java.lang.String
...
[2,067s][trace  ][gc,classhisto] GC(1)  584: 1             16 
sun.util.resources.cldr.provider.CLDRLocaleDataMetaInfo_jdk_localedata
[2,067s][trace  ][gc,classhisto] GC(1) Total 40093        1948480
[2,067s][trace  ][gc,classhisto] GC(1) Class Histogram (after full gc) 
(2,051s, 2,067s) 16,486ms
[2,067s][info   ][gc           ] GC(1) Pause Full (System.gc()) 
2M->1M(120M) (1,930s, 2,067s) 137,013ms
[2,067s][info   ][gc,cpu       ] GC(1) User=0,87s Sys=0,03s Real=0,14s

Several things had to be fixed for this to work properly:

- The calls to pre/post_full_gc_dump()  in genCollectedHeap.cpp were 
moved to concurrentMarkSweepGeneration.cpp and tenuredGeneration.cpp
- In psMarkSweep and parallelCompact the calls to 
pre/post_full_gc_dump() were moved to inside the GC start/end.
- In CollectedHeap::full_gc_dump() the setup of a new GC id was removed.
- In CollectedHeap::full_gc_dump() the use of FormatBuffer was removed. 
This is necessary since the "title" passed to GCTraceTime is stored and 
used later to send a trace event.
- In heapInspection.cpp the logging for the title was moved to be able 
to use two print_cr calls to make it log the title with decorations 
properly.
- A log prefix was added for [gc, classhisto]

Thanks,
Bengt