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

[Bengt Rutisson]

On 2016-02-05 08:58, Stefan Johansson wrote:
> Looks good,

Thanks, Stefan!

Bengt

>
> StefanJ
>
> On 2016-02-04 16:26, Bengt Rutisson wrote:
>>
>> 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
>