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

[Bengt Rutisson]

Andreas,

I can push this for you.

Thanks for fixing this!
Bengt

17 maj 2013 kl. 17:38 skrev Andreas Eriksson <andreas.eriksson at oracle.com>:

> Great, thanks for looking at this.
> I think this change is ready to be pushed.
> 
> Could someone be kind enough to sponsor and push this change?
> The changeset can be found at:
> http://cr.openjdk.java.net/~aeriksso/7176220/7176220.export
> 
> Regards,
> Andreas
> 
> 
> On 2013-05-16 20:48, Jon Masamitsu wrote:
>> Andreas,
>> 
>> That file parsed ok also.  Thanks.
>> 
>> Jon
>> 
>> On 5/16/13 2:38 AM, Andreas Eriksson wrote:
>>> Attaching log from running
>>> ./hsx24_hotspot-build/bin/java -Xmx2m -verbose:gc -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps -Xloggc:gc.log -XX:+PrintGCDetails HumongousAlloc
>>> 
>>> /Andreas
>>> 
>>> On 2013-05-15 18:54, Jon Masamitsu wrote:
>>>> Andreas,
>>>> 
>>>> Thanks.  That log parse fine.  Please do a second with "-XX:+PrintGCDetails"
>>>> 
>>>> Jon
>>>> 
>>>> On 5/15/2013 4:41 AM, Andreas Eriksson wrote:
>>>>> Hi,
>>>>> 
>>>>> The format of the regular logs should be the same as before.
>>>>> 
>>>>> A sample of how they look after the change with the default GC is attached (running ./hsx24_hotspot-build/bin/java -Xmx2m -verbose:gc -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps -Xloggc:gc.log HumongousAlloc)
>>>>> 
>>>>> Please let me know if you need me to run with any other flags or some other java program.
>>>>> 
>>>>> /Andreas
>>>>> 
>>>>> On 2013-05-15 06:57, Jon Masamitsu wrote:
>>>>>> Andreas,
>>>>>> 
>>>>>> Please send a short sample of a new log.  I want to see if
>>>>>> our log parsers work on the new log.  If you have not already
>>>>>> done so, please do not push this until I've checked that the
>>>>>> logs still parse.
>>>>>> 
>>>>>> Jon
>>>>>> 
>>>>>> On 5/14/2013 2:21 AM, Andreas Eriksson wrote:
>>>>>>> Hi,
>>>>>>> 
>>>>>>> I changed the date and time stamping calls to use the guarded convenience variants.
>>>>>>> Both of these calls suffixes a ": " automatically. See share/vm/utilities/ostream.hpp line 99 and 105.
>>>>>>> 
>>>>>>> It currently looks like this:
>>>>>>> % ./hsx24_hotspot-build/bin/java -Xmx2m -verbose:gc -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps HumongousAlloc
>>>>>>> 2013-05-14T11:17:28.340+0200: 0.050: [GC 1896K->421K(3136K), 0.0011640 secs]
>>>>>>> 2013-05-14T11:17:28.341+0200: 0.051: [GC 2329K->437K(3136K), 0.0029750 secs]
>>>>>>> 
>>>>>>> This is how it looked before as well:
>>>>>>> % ~/builds/linux-amd64/7u25/bin/java -Xmx2m -verbose:gc -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps HumongousAlloc
>>>>>>> 2013-05-14T11:17:31.603+0200: 0.059: [GC 2025K->417K(3136K), 0.0008100 secs]
>>>>>>> 2013-05-14T11:17:31.605+0200: 0.060: [GC 2325K->417K(3136K), 0.0015140 secs]
>>>>>>> 
>>>>>>> Thanks for looking at this.
>>>>>>> 
>>>>>>> /Andreas
>>>>>>> 
>>>>>>> On 2013-05-14 08:23, Bengt Rutisson wrote:
>>>>>>>> 
>>>>>>>> Hi Andreas,
>>>>>>>> 
>>>>>>>> Looks good.
>>>>>>>> 
>>>>>>>> One question regarding the change in GCTraceTime:
>>>>>>>> 
>>>>>>>> http://cr.openjdk.java.net/~aeriksso/7176220/webrev.00/src/share/vm/gc_implementation/shared/gcTraceTime.cpp.udiff.html 
>>>>>>>> 
>>>>>>>> It looks to me like we are missing a ": " in the new version. Maybe it is ok to loose this character in the log format, but a safer change may be:
>>>>>>>> 
>>>>>>>> if (PrintGCTimeStamps || PrintGCDateStamps) {
>>>>>>>>  gclog_or_tty->date_stamp(PrintGCDateStamps);
>>>>>>>>  gclog_or_tty->stamp(PrintGCTimeStamps);
>>>>>>>> gclog_or_tty->print(": ");
>>>>>>>> }
>>>>>>>> 
>>>>>>>> This actually still changes the ": " behavior since since you didn't use to get a ": " if you only had PrintGCDateStamps enabled. But I think this is a more expected behavior.
>>>>>>>> 
>>>>>>>> Thanks,
>>>>>>>> Bengt
>>>>>>>> 
>>>>>>>> On 5/13/13 6:01 PM, Andreas Eriksson wrote:
>>>>>>>>> Hi all,
>>>>>>>>> 
>>>>>>>>> Please take a look at my changes for bug 7176220.
>>>>>>>>> The problem is that CMS sometimes misses datestamps for time trace printouts.
>>>>>>>>> 
>>>>>>>>> The proposed fix is to move the datestamp print logic into the class that handles time trace printouts, GCTraceTime.
>>>>>>>>> This would make it consistent with timestamps, which are already printed from there.
>>>>>>>>> 
>>>>>>>>> Bugs.sun:
>>>>>>>>> http://bugs.sun.com/view_bug.do?bug_id=7176220
>>>>>>>>> 
>>>>>>>>> JIRA:
>>>>>>>>> https://jbs.oracle.com/bugs/browse/JDK-7176220
>>>>>>>>> 
>>>>>>>>> Webrev:
>>>>>>>>> http://cr.openjdk.java.net/~aeriksso/7176220/webrev.00/
>>>>>>>>> 
>>>>>>>>> Testing:
>>>>>>>>> jprt, jtreg
>>>>>>>>> 
>>>>>>>>> Thanks,
>>>>>>>>> Andreas
>