RFR: JDK-8149035: Make the full_gc_dump() calls be recorded as part of the GC
Jon Masamitsu
jon.masamitsu at oracle.com
Thu Feb 4 19:39:08 UTC 2016
Bengt,
The changes look good.
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.
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/20160204/1c5d96f8/attachment.htm>
More information about the hotspot-gc-dev
mailing list