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

[John Cuthbertson]

Hi Kirk,

This is probably associated with using and instance of the TraceTimer 
class in some cases and direct prints in others. I agree this should be 
cleaned up. I'll standardize on 'secs' since I think that is what the 
other collectors (though their TraceTimers) report.

The reason why the cleanup reports the memory is because the cleanup 
pause can free memory. Any region that's found to have no live data 
within it is freed immediately during the cleanup pause. The others 
don't. Basically if a GC event causes some kind of heap transition, we 
print that transition.

Cheers,

JohnC

On 1/30/2013 2:40 PM, Kirk Pepperdine wrote:
> 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