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

[John Cuthbertson]

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
>