Fwd: Re: Review request (S): 7176220: 'Full GC' events miss date stamp information occasionally

[Andreas Eriksson]

Hi John,

If that TraceTime is changed to use PrintGC, then the logging becomes 
interleaved:

2012-10-08T12:16:42.121+0200: 0.171: [GC2012-10-08T12:16:42.121+0200: 
0.171: [GC 2667K->1043K(9920K), 0.0040520 secs]
, 0.0043620 secs]2012-10-08T12:16:42.127+0200: 0.177: 
[GC2012-10-08T12:16:42.128+0200: 0.177: [GC 3488K->1835K(9920K), 
0.0234120 secs]

That is probably the reason why it uses PrintGCDetails instead.

Thanks,
Andreas

On 10/04/2012 07:28 PM, John Cuthbertson wrote:
> Hi Andreas,
>
> This looks good to me except I have one question/comment:
>
> In genCollectedHeap.cpp, the old code was:
>
> 386     bool complete = full && (max_level == (n_gens()-1));
> 387     const char* gc_cause_prefix = complete ? "Full GC" : "GC";
> 388     gclog_or_tty->date_stamp(PrintGC && PrintGCDateStamps);
> 389     TraceCPUTime tcpu(PrintGCDetails, true, gclog_or_tty);
> 390     TraceTime t(GCCauseString(gc_cause_prefix, gc_cause()), 
> PrintGCDetails, false, gclog_or_tty);
>
> The new code is:
>
> 386     bool complete = full && (max_level == (n_gens()-1));
> 387     const char* gc_cause_prefix = complete ? "Full GC" : "GC";
> 388     TraceCPUTime tcpu(PrintGCDetails, true, gclog_or_tty);
> 389     TraceTime t(GCCauseString(gc_cause_prefix, gc_cause()), 
> PrintGCDetails, false, gclog_or_tty);
>
>
> In the old code, the date stamp was printed if PrintGC was enabled, 
> but the TraceTime::_doit field is set based upon the value of 
> PrintGCDetails. Looking at the other instantiations of the TraceTime 
> class, this seems inconsistent. I believe that the second parameter to 
> the TraceTime constructor should be PrintGC instead of PrintGCDetails.
>
> Regards,
>
> JohnC
>
> On 10/04/12 04:30, Andreas Eriksson wrote:
>> Hi,
>>
>> Can I have some reviews for the following change please:
>> http://cr.openjdk.java.net/~brutisso/7176220/webrev.00/ 
>> <http://cr.openjdk.java.net/%7Ebrutisso/7176220/webrev.00/>
>>
>> See forwarded mails for more info.
>>
>> Regards,
>> Andreas
>>
>>
>> -------- Original Message --------
>> Subject:     Re: Review request (S): 7176220: 'Full GC' events miss 
>> date stamp information occasionally
>> Date:     Tue, 02 Oct 2012 14:45:07 +0200
>> From:     Bengt Rutisson <bengt.rutisson at oracle.com>
>> To:     Andreas Eriksson <andreas.eriksson at oracle.com>
>> CC:     hotspot-gc-dev at openjdk.java.net
>>
>>
>>
>>
>>
>> Hi Andreas,
>>
>> I think this looks good. I like that we treat PrintGCDateStamps and 
>> PrintGCTimeStamps in a consistent way.
>>
>> One thing that kind of worries me is that the TraceTime class is used 
>> from other parts of the JVM than just the GC. This means that you now 
>> get date stamps on compiler events if you enable PrintGCDateStamps. I 
>> think this is probably fine since they already get time stamps if you 
>> enable PrintGCTimeStamps. See for example how PhaseTraceTime is used 
>> in C1.
>>
>> Maybe we should send this review out on hotspot-dev to make sure that 
>> all teams have a chance to comment on this?
>>
>> Thanks,
>> Bengt
>>
>> On 2012-09-28 12:01, Andreas Eriksson wrote:
>>> Hi,
>>>
>>> Can I have some reviews for the following change please:
>>> http://cr.openjdk.java.net/~brutisso/7176220/webrev.00/ 
>>> <http://cr.openjdk.java.net/%7Ebrutisso/7176220/webrev.00/>
>>>
>>> This fixes GC logs from genCollectedHeap.cpp where sometimes it 
>>> would not print date-stamps.
>>> The fix moves printing of date-stamps into TraceTime, where 
>>> time-stamps are already printed from.
>>>
>>> Bug with flags -XX:+UseConcMarkSweepGC -XX:+UseParNewGC -verbose:gc 
>>> -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps:
>>> 2012-09-28T11:41:38.687+0200: 0.205: [Full GC 8702K->1012K(9920K), 
>>> 0.0108630 secs]
>>> 1.253: [Full GC 3326K->1012K(9920K), 0.0105750 secs]
>>> 2.299: [Full GC 7932K->1012K(9920K), 0.0100470 secs]
>>> 2012-09-28T11:41:41.813+0200: 3.331: [Full GC 8702K->1012K(9920K), 
>>> 0.0103210 secs]
>>>
>>> Another route that was investigated was to add the date-stamp call 
>>> directly in genCollectedHeap.cpp, but because of complex 
>>> interactions when a full GC was initiated from a non-full GC this 
>>> path was not taken.
>>>
>>>
>>> This will slightly change the logging output when using 
>>> -XX:+PrintGCDetails.
>>> Now date-stamps will also be printed inside other lines, as 
>>> time-stamps already are:
>>>
>>> Before:
>>> 2012-09-28T11:29:16.815+0200: 0.177: [GC0.177: [ParNew: 
>>> 2710K->46K(3072K), 0.0053590 secs] 3480K->1835K(9920K), 0.0055500 
>>> secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
>>>
>>> After:
>>> 2012-09-28T11:29:33.260+0200: 0.184: 
>>> [GC2012-09-28T11:29:33.261+0200: 0.184: [ParNew: 2642K->45K(3072K), 
>>> 0.0095770 secs] 3412K->1828K(9920K), 0.0097520 secs] [Times: 
>>> user=0.01 sys=0.00, real=0.01 secs]
>>>
>>> Thanks to Bengt Rutisson for helping with the change and webrev.
>>>
>>> Regards,
>>> Andreas
>>
>>
>>
>>
>