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

Thu Oct 18 08:29:55 PDT 2012

Hi Vladimir,

Yes, that would probably be a better solution.
I will take a look at moving PrintGCDateStamp and PrintGCTimeStamp to a 
GC-specific subclass.

Thanks,
Andreas

On 2012-10-17 23:34, Vladimir Kozlov wrote:
> 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
>>>>
>>>>
>>>>
>>>>
>>>
>>
>>
>>
>>