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

[Bengt Rutisson]

Hi Jon,

On 2016-02-04 20:39, Jon Masamitsu wrote:
> Bengt,
>
> The changes look good.

Thanks for looking at this!


>
> Is it correct that for
> PSParallelCompact::invoke_no_policy()
>
> the VerifyBeforeGC is now done before the
> heap dump?  That seems like the right order
> but I thought I would note that change.

Yes, that is a correct observation. This is similar to what 
PSMarkSweep::invoke_no_policy() and 
G1CollectedHeap::do_full_collection() already did. So, I think this 
change just makes all GCs work similarly in that sense. If we would like 
to change that order I would prefer to do it as a separate change for 
all GCs.

Thanks,
Bengt

>
> Jon
>
>
> On 02/04/2016 07:26 AM, 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
>

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://mail.openjdk.org/pipermail/hotspot-gc-dev/attachments/20160205/261e1a76/attachment.htm>