Hi Ron,
You are correct, the generation of class histograms take a long time.
The feature is enabled under the 'trace' level and should be used with
caution. The reason it takes so long time is that it is not
parallelized, so the whole heap is inspected by a single thread. To my
knowledge this has always been the case. What has changed is that G1,
since JDK 10, does the Full GC in parallel. So in the past the overhead
caused by the creating the class histograms wasn't as big as it is now.
There is currently an RFE out to enable use of parallel threads when
doing heap inspection so this behavior might improve in future releases.
One thing you can do to not always suffer from this overhead is skipping
-Xlog:gc,classhisto=trace and instead generate class histogram just if
you suspect something is wrong. This can be done using the tool jmap:
jmap -histo[:live] <pid>
to connect to running process and print histogram of java object heap
if the "live" suboption is specified, only count live objects
Hope this helps.
Thanks,
Stefan
On 2020-03-02 22:10, Ron Reynolds wrote:
going thru a gc-log of a box that had several Full-GCs (OpenJDK 64-Bit
Server VM (11.0.3+7-201905271830) on CentOS 6.9 with 20 cores and 132GB)
and i came across some really surprising times for the output from
-Xlog:gc*=info,gc+classhisto*=trace:
(notice the timestamps)
[2020-02-29T*02:39:42.403*+0000][trace][gc,classhisto,start] Class
Histogram (before full gc)
[2020-02-29T02:40:37.810+0000][trace][gc,classhisto ] GC(790) num
#instances #bytes class name (module)
...
[2020-02-29T02:40:37.877+0000][trace][gc,classhisto ] GC(790) Total
1714972606 101189395832
[2020-02-29T*02:40:37.878*+0000][trace][gc,classhisto ] GC(790)
Class Histogram (before full gc) *55475.179ms*
[2020-02-29T02:40:37.878+0000][info ][gc,task ] GC(790) Using
15 workers of 15 for full compaction
[2020-02-29T02:40:37.878+0000][info ][gc,start ] GC(790) Pause
Full (G1 Evacuation Pause)
[2020-02-29T02:40:37.954+0000][info ][gc,phases,start ] GC(790) Phase
1: Mark live objects
[2020-02-29T02:40:44.115+0000][info ][gc,stringtable ] GC(790)
Cleaned string and symbol table, strings: 76105 processed, 198 removed,
symbols: 254466 processed, 0 removed
[2020-02-29T02:40:44.115+0000][info ][gc,phases ] GC(790) Phase
1: Mark live objects 6160.375ms
[2020-02-29T02:40:44.115+0000][info ][gc,phases,start ] GC(790) Phase
2: Prepare for compaction
[2020-02-29T02:40:47.010+0000][info ][gc,phases ] GC(790) Phase
2: Prepare for compaction 2894.766ms
[2020-02-29T02:40:47.010+0000][info ][gc,phases,start ] GC(790) Phase
3: Adjust pointers
[2020-02-29T02:40:52.241+0000][info ][gc,phases ] GC(790) Phase
3: Adjust pointers 5231.599ms
[2020-02-29T02:40:52.241+0000][info ][gc,phases,start ] GC(790) Phase
4: Compact heap
[2020-02-29T02:40:56.657+0000][info ][gc,phases ] GC(790) Phase
4: Compact heap 4415.453ms
[2020-02-29T02:40:56.730+0000][info ][gc,heap ] GC(790) Eden
regions: 0->0(161)
[2020-02-29T02:40:56.730+0000][info ][gc,heap ] GC(790)
Survivor regions: 0->0(21)
[2020-02-29T02:40:56.730+0000][info ][gc,heap ] GC(790) Old
regions: 3112->2776
[2020-02-29T02:40:56.730+0000][info ][gc,heap ] GC(790)
Humongous regions: 115->24
[2020-02-29T02:40:56.730+0000][info ][gc,metaspace ] GC(790)
Metaspace: 104224K->104200K(106496K)
[2020-02-29T02:40:56.730+0000][info ][gc ] GC(790) Pause
Full (G1 Evacuation Pause) 103045M->89309M(103264M) *18852.025ms*
[2020-02-29T02:40:56.730+0000][trace][gc,classhisto,start] Class
Histogram (after full gc)
[2020-02-29T02:41:39.715+0000][trace][gc,classhisto ] GC(790) num
#instances #bytes class name (module)
...
[2020-02-29T02:41:39.779+0000][trace][gc,classhisto ] GC(790) Total
1628116065 93487648064
[2020-02-29T02:41:39.780+0000][trace][gc,classhisto ] GC(790) Class
Histogram (after full gc) *43049.823ms*
[2020-02-29T02:41:39.780+0000][info ][gc,cpu ] GC(790)
User=372.08s Sys=0.09s *Real=117.36s*
did the JVM really take 55.4 SECONDS to generate the pre-full-GC and 43
seconds to generate the post-full-GC class-histograms? for a GC that
would have only taken 18.8 seconds otherwise? i mean, sure, avoid
full-GC at all costs but was it always so expensive to get the class
histogram? this feature has helped us narrow down a lot of memory
issues; it would be a shame to have to disable it because it makes
Full-GCs 6x slower. any info/suggestions gratefully accepted.
_______________________________________________
hotspot-gc-use mailing list
hotspot-gc-use@openjdk.java.net
https://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use
_______________________________________________
hotspot-gc-use mailing list
hotspot-gc-use@openjdk.java.net
https://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use
