Small change to the -verbosegc output (CMS)

[Tony Printezis]

Hi all,

For a while now, the initial-mark / remark pauses were not tagged 
correctly on the CMS logs obtained with -verbosegc:

8.012: [ParNew 84832K->79546K(162816K), 0.0293764 secs]
8.043: [GC 79546K(162816K), 0.0004823 secs]
8.140: [ParNew 89658K->84364K(162816K), 0.0271073 secs]
8.673: [ParNew 94476K->86063K(162816K), 0.0254789 secs]
9.276: [GC 93707K(162816K), 0.0369005 secs]
9.426: [ParNew 83265K->74974K(162816K), 0.0217100 secs]
9.830: [ParNew 85086K->76329K(162816K), 0.0062086 secs]

Above, the pauses at 8.043 and 9.276 are an initial-mark / remark 
respectively, but novice users would never guess that this is the case. 
We are proposing a small change to make the CMS -verbosegc output 
clearer, which is the following:

8.012: [ParNew 84832K->79546K(162816K), 0.0293764 secs]
8.043: [GC (initial-mark) 79546K(162816K), 0.0004823 secs]
8.140: [ParNew 89658K->84364K(162816K), 0.0271073 secs]
8.673: [ParNew 94476K->86063K(162816K), 0.0254789 secs]
9.276: [GC (remark) 93707K(162816K), 0.0369005 secs]
9.426: [ParNew 83265K->74974K(162816K), 0.0217100 secs]
9.830: [ParNew 85086K->76329K(162816K), 0.0062086 secs]

The downside is that your (awk-based?) parser might have to be slightly 
modified to deal with the change. The good news are that the logs will 
be more readable and your parser will now know what to do when it comes 
across such pauses. I opened a CR for this (6916659):

http://bugs.sun.com/view_bug.do?bug_id=6916659

Are there any major objections to making this change?

Yes, we do recommend folks to use -XX:+PrintGCDetails instead of 
-verbosegc, as it will produce a much more detailed and helpful output 
(and don't forget -XX:+PrintGCTimeStamps!!!). But, given that -verbosegc 
is there anyway, might as well fix it.

Regards,

Tony, HS GC Group