Full-GC class-histogram generation time

[Ron Reynolds]

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.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20200302/2e562e8c/attachment.htm>