Small change to the -verbosegc output (CMS)

[Tony Printezis]

PS I forgot to also say: if you really need more detailed information to 
parse / analyze / etc. please use +PrintGCDetails and not -verbosegc. 
This is especially the case for CMS.

Tony Printezis wrote:
> Kirk,
>
> kirk wrote:
>> Hi Tony,
>>
>> Nice change 
> Glad you think so. :-)
>> but if we are going to break something can we go a wee bit more whole 
>> hog on it? How about GC be changed to CMS? Make the awk parsing even 
>> easier.
> Right now, we'd rather do very small changes to be as non-intrusive as 
> possible.
>> And trust me, I've no problems if you broke the entire logging 
>> system.. if it were more easily machine readable ;-)
> :-) We have been talking about this for some time, it's just not at 
> the top of our priority list right now.
>
> Tony, HS GC Group
>> Tony Printezis wrote:
>>> 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
>>>
>>>
>>>
>>