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

Wed Oct 17 14:34:58 PDT 2012

I don't like that these GC changes affect log information in compilers (for 
which we have own parsing tools). You can create subclass GCTraceTime for what 
you are doing to avoid such affects.

Thanks,
Vladimir

Andreas Eriksson wrote:
>   Hi,
> 
> Just wanted to make sure some eyes from the compiler team was on this.
> 
> This review changes how date-stamps are printed in relation to TraceTime 
> and PrintGCDateStamp, which is mostly used in GC logging.
> The problem is that it is also used for example in C1 with PhaseTraceTime.
> This means that for C1 the output will include date stamps when used with
> -XX:+PrintGCDateStamps and -XX:+Verbose together with -XX:+CITimeEach or 
> -XX:+CITime
> 
> This will make it consistent with -XX:+PrintGCTimeStamps, which already 
> affect the output of C1.
> 
> The webrev is available at 
> http://cr.openjdk.java.net/~brutisso/7176220/webrev.00/
> 
> Regards,
> Andreas
> 
> 
> -------- Original Message --------
> Subject: 	Re: Fwd: Re: Review request (S): 7176220: 'Full GC' events 
> miss date stamp information occasionally
> Date: 	Mon, 08 Oct 2012 12:23:00 +0200
> From: 	Andreas Eriksson <andreas.eriksson at oracle.com>
> To: 	John Cuthbertson <john.cuthbertson at oracle.com>
> CC: 	hotspot-dev at openjdk.java.net
> 
> 
> 
> 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
>>>
>>>
>>>
>>>
>>
> 
> 
> 
> 