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
