G1 concurrent phase durations do not state the time units ("secs")

[John Cuthbertson]

Hi Ramki,

Thanks for the report. Just checked with a log that I generated this 
morning and the issue is still there. It looks like the units weren't 
added to a couple of prints in concurrentMarkThread.cpp

I'll submit a CR. Expect a webrev later today or early tomorrow.

Thanks,

JohnC

On 1/30/2013 11:58 AM, Srinivas Ramakrishna wrote:
>
> Hi John, all --
>
> I'm using 7u9, perhaps this has been fixed subsequently. Here's an 
> example of the missing units (and the inconsistency):-
>
> The young and mixed pauses print duration units of "secs" :-
>
> 2013-01-30T01:46:45.652-0800: 9522.134: [GC pause (young), 1.10620800 
> secs]
> 2013-01-30T01:47:03.563-0800: 9540.045: [GC pause (young), 0.90593900 
> secs]
> 2013-01-30T01:47:18.619-0800: 9555.101: [GC pause (young), 0.81425400 
> secs]
> 2013-01-30T01:47:59.536-0800: 9596.018: [GC pause (young), 0.84935400 
> secs]
> 2013-01-30T01:48:12.097-0800: 9608.579: [GC pause (young) 
> (initial-mark), 0.50153600 secs]
> 2013-01-30T01:48:59.189-0800: 9655.671: [GC pause (young), 0.02815400 
> secs]
> 2013-01-30T01:51:53.952-0800: 9830.457: [GC pause (mixed), 0.66860800 
> secs]
> 2013-01-30T01:53:20.704-0800: 9917.186: [GC pause (mixed), 0.47479200 
> secs]
> 2013-01-30T01:54:41.098-0800: 9997.579: [GC pause (mixed), 0.72149500 
> secs]
> 2013-01-30T01:55:58.944-0800: 10075.426: [GC pause (young), 0.32158300 
> secs]
>
>
> The concurrent phases are often missing the units, but not always 
> (mark phase duration prints "sec", others are mum):-
>
> 2013-01-30T01:12:10.711-0800: 7447.193: [GC 
> concurrent-root-region-scan-end, 1.0222980]
> 2013-01-30T01:12:41.386-0800: 7477.868: [GC concurrent-mark-end, 
> 30.6749800 sec]
> 2013-01-30T01:12:41.626-0800: 7478.108: [GC concurrent-cleanup-end, 
> 0.0063520]
> 2013-01-30T01:24:18.588-0800: 8175.070: [GC 
> concurrent-root-region-scan-end, 0.5868510]
> 2013-01-30T01:25:01.089-0800: 8217.571: [GC concurrent-mark-end, 
> 42.5016130 sec]
> 2013-01-30T01:25:01.321-0800: 8217.803: [GC concurrent-cleanup-end, 
> 0.0057450]
> 2013-01-30T01:36:27.063-0800: 8903.545: [GC 
> concurrent-root-region-scan-end, 0.3746230]
> 2013-01-30T01:37:18.642-0800: 8955.124: [GC concurrent-mark-end, 
> 51.5794260 sec]
> 2013-01-30T01:37:18.869-0800: 8955.351: [GC concurrent-cleanup-end, 
> 0.0048270]
> 2013-01-30T01:48:13.162-0800: 9609.644: [GC 
> concurrent-root-region-scan-end, 0.5630820]
> 2013-01-30T01:48:55.513-0800: 9651.995: [GC concurrent-mark-end, 
> 42.3504330 sec]
> 2013-01-30T01:48:55.769-0800: 9652.251: [GC concurrent-cleanup-end, 
> 0.0041170]
>
>
> Would be nice to have it be consistent across G1 and indeed across all 
> collectors, if not already the case. Also makes for more consistent 
> parsing of logs.
>
> thanks!
> -- ramki