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

[Kirk Pepperdine]

Hi John,

Since we're on the subject of consistency, I have this record that reports in "sec" instead of "secs".

634.958: [GC concurrent-mark-end, 0.1525020 sec]

and I have memory being reported as 252M->252M(397M) here;

568.675: [GC cleanup 252M->252M(397M), 0.0055868 secs]

as well as 77M(77M)->0B(77M) here;

[Eden: 77M(77M)->0B(77M) Survivors: 2048K->2048K Heap: 324M(397M)->247M(397M)]

Either format works but it would be nice to have one and not both.
i'll repeat my request to report in K. B seems unnecessarily granular where as M might be too corse for smaller heap sizes.. but then, maybe not. Still sorting out the potential effects on analytics.

I guess you've picked up on the other places where secs is missing.

Regards,
Kirk



On 2013-01-30, at 9:17 PM, John Cuthbertson <john.cuthbertson at oracle.com> wrote:

> 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
>