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

[John Cuthbertson]

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