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

[Jon Masamitsu]

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