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

[Bengt Rutisson]

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