Full-GC class-histogram generation time

[Stefan Johansson]

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 at openjdk.java.net
> https://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use
>