Can someone please provide some insight into the the following verbosegc lines on a Java runtime with CMS GC enabled? Specifically:
29.490 indicate heap location of the highwater for marking?preclean phase and what is it doing different than marking?reset phase? Why would that take time to complete if it is not just the end of the sweep?Rescan, grey and root rescans and remark areas and metrics on the event at 29.653? Shall we assume these are just reported heap metrics for the subsequent sweep? If so why do they consume time?verbosegc log excerpt:
29.490: [GC [1 CMS-initial-mark: 16225K(17684K)] 16737K(22420K), 0.0030839 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
29.494: [CMS-concurrent-mark-start]
29.652: [CMS-concurrent-mark: 0.158/0.158 secs] [Times: user=0.16 sys=0.00, real=0.16 secs]
29.652: [CMS-concurrent-preclean-start]
29.652: [CMS-concurrent-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
29.653: [GC[YG occupancy: 512 K (4736 K)]29.653: [Rescan (non-parallel) 29.654: [grey object rescan, 0.0001517 secs]29.654: [root rescan, 0.0030887 secs], 0.0033817 secs]29.657: [weak refs processing, 0.0000271 secs] [1 CMS-remark: 16225K(17684K)] 16737K(22420K), 0.0035183 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
29.658: [CMS-concurrent-sweep-start]
29.679: [CMS-concurrent-sweep: 0.022/0.022 secs] [Times: user=0.03 sys=0.00, real=0.03 secs]
29.680: [CMS-concurrent-reset-start]
29.703: [CMS-concurrent-reset: 0.022/0.022 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
29.797: [GC 29.797: [DefNew: 4736K->512K(4736K), 0.0207183 secs] 20800K->17172K(31512K), 0.0209119 secs] [Times: user=0.01 sys=0.02, real=0.03 secs]
Thanks,
Read the "Understanding Concurrent Mark Sweep Garbage Collector Logs" article on the Sun website. I think that answers most of your questions about the logs. For more background information on Java's Concurrent GC, refer to the "Java SE 6 HotSpot[tm] Virtual Machine Garbage Collection Tuning" page.