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

Stefan Johansson stefan.johansson at oracle.com
Fri Feb 5 07:58:29 UTC 2016


Looks good,

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



More information about the hotspot-gc-dev mailing list