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

[Bengt Rutisson]

Thanks John and Jesper!

All set to push this now.

Bengt

On 2012-09-17 18:34, John Cuthbertson wrote:
> 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
>>>>
>>>
>>
>