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

[Andreas Eriksson]

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

-------------- next part --------------
A non-text attachment was scrubbed...
Name: gc.log
Type: text/x-log
Size: 32472 bytes
Desc: not available
URL: <https://mail.openjdk.org/pipermail/hotspot-gc-dev/attachments/20130516/061d0b6b/gc.log>