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

[Bengt Rutisson]

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