Request for review (S): 7198130: G1: PrintReferenceGC output comes out of order

[John Cuthbertson]

Hi Bengt,

Looks good. Ship it.

JohnC

On 09/17/12 01:40, Bengt Rutisson wrote:
>
> Hi John,
>
> Thanks for the review. Good point about using 
> "gclog_or_tty->stamp(PrintGCTimeStamps)".  I found the same pattern in 
> a few more places so I updated those as well. Here is an updated webrev:
>
> http://cr.openjdk.java.net/~brutisso/7198130/webrev.03/
>
> I still need one more review. Any takers?
>
> Bengt
>
>
> On 2012-09-14 23:05, John Cuthbertson wrote:
>> Hi Bengt,
>>
>> This looks good. One nit:
>>
>> Instead of:
>>
>> 3671   if (PrintGCTimeStamps) {
>> 3672     gclog_or_tty->stamp();
>> 3673     gclog_or_tty->print(": ");
>> 3674   }
>>
>> How about:
>>
>> 3672     gclog_or_tty->stamp(PrintGCTimeStamps);
>>
>>
>> Regards,
>>
>> JohnC
>>
>> On 09/14/12 01:41, Bengt Rutisson wrote:
>>>
>>> Hi again,
>>>
>>> Updated webrev based on merging a similar patch from John Cuthbertson:
>>> http://cr.openjdk.java.net/~brutisso/7198130/webrev.02/
>>>
>>> Bengt
>>>
>>>
>>> On 2012-09-13 10:07, Bengt Rutisson wrote:
>>>>
>>>> Hi all,
>>>>
>>>> Can I have some reviews for this change?
>>>> http://cr.openjdk.java.net/~brutisso/7198130/webrev.01/
>>>>
>>>> This fixes two issues that were introduced by a previous change I 
>>>> made to the G1 logging. Most importantly the time stamp for the GC 
>>>> log entry is now the start of the GC. Secondly, any interleaved 
>>>> logging that is done by other modules will be seen within the GC 
>>>> log entry. This is the way it used to be.
>>>>
>>>> As an example using these switches on the command line 
>>>> "-XX:+UseG1GC -XX:+PrintGCDetails -XX:+PrintReferenceGC" currently 
>>>> produce output like:
>>>>
>>>> 3.648: [SoftReference, 0 refs, 0.0000110 secs]3.648: 
>>>> [WeakReference, 207 refs, 0.0000440 secs]3.648: [FinalReference, 
>>>> 14473 refs, 0.0499260 secs]3.698: [PhantomReference, 0 refs, 
>>>> 0.0000050 secs]3.698: [JNI Weak Reference, 0.0000120 secs]3.700: 
>>>> [GC pause (G1 Evacuation Pause) (young), 0.0853910 secs]
>>>>    [Parallel Time: 31.9 ms, GC Workers: 8]
>>>>
>>>> But with my suggested fix it will be:
>>>>
>>>> 5.814: [GC pause (young)6.030: [SoftReference, 0 refs, 0.0000924 
>>>> secs]6.030: [WeakReference, 3 refs, 0.0001098 secs]6.031: 
>>>> [FinalReference, 6 refs, 0.0000924 secs]6.032: [PhantomReference, 0 
>>>> refs, 0.0000893 secs]6.032: [JNI Weak Reference, 0 refs, 0.0001699 
>>>> secs], 0.2200814 secs]
>>>>    [Parallel Time: 214.3 ms, GC Workers: 4]
>>>>
>>>>
>>>> This is consistent with the way it looked before my previous change 
>>>> to the G1 logging:
>>>>
>>>> 3.746: [GC pause (young)3.802: [SoftReference, 0 refs, 0.0000090 
>>>> secs]3.802: [WeakReference, 148 refs, 0.0000400 secs]3.802: 
>>>> [FinalReference, 13020 refs, 0.0462290 secs]3.848: 
>>>> [PhantomReference, 7 refs, 0.0000110 secs]3.848: [JNI Weak 
>>>> Reference, 0.0000150 secs], 0.10515900 secs]
>>>>    [Parallel Time:  52.2 ms]
>>>>
>>>>
>>>> Thanks,
>>>> Bengt
>>>
>>
>