race condition in GC logs

[Bengt Rutisson]

Hi Kirk,

On 2015-08-18 12:31, Kirk Pepperdine wrote:
> Hi all,
>
> I found this.. in a few logs. Before I started trolling the source trying to sort out what the second PhantomReferences count was, I pinged Charlie and asked him. He suggested it was a (concurrency??) bug witnessed only once by someone else. I’ve now seen it in several logs where the numbers reported are different. Sorry for being lazy for not trolling the code before asking but is this a bug?

The second ref count is for cleaner references. They used to be treated 
the same way as phantom references, but a recent improvement was to 
separate the handling of the cleaners to after all phantom references 
have been handled. So, the first count is the "real" phantom references 
and the second count is the cleaner references.

It's confusing logging, I agree.

This came in with this fix:
http://hg.openjdk.java.net/jdk9/jdk9/hotspot/rev/2194fdf3fbd9

since this adds one more call to preclean_discovered_reflist(), which is 
the method that prints the refs count.

Thanks,
Bengt

>
> Regards,
> Kirk
>
> Java HotSpot(TM) 64-Bit Server VM (25.51-b03) for linux-amd64 JRE (1.8.0_51-b16), built on Jun  8 2015 19:28:07 by "java_re" with gcc 4.3.0 20080428 (Red Hat 4.3.0-8)
> Memory: 4k page, physical 9570132k(9340292k free), swap 4095996k(4095996k free)
> CommandLine flags: -XX:+AggressiveOpts -XX:G1HeapRegionSize=16777216 -XX:InitialHeapSize=3221225472 -XX:InitiatingHeapOccupancyPercent=75 -XX:+ManagementServer -XX:MaxGCPauseMillis=250 -XX:MaxHeapSize=3221225472 -XX:+ParallelRefProcEnabled -XX:+PerfDisableSharedMem -XX:+PrintAdaptiveSizePolicy -XX:+PrintGC -XX:+PrintGCApplicationStoppedTime -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintReferenceGC -XX:+PrintTenuringDistribution -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseG1GC -XX:+UseLargePages
>   0.198: [G1Ergonomics (Heap Sizing) expand the heap, requested expansion amount: 3221225472 bytes, attempted expansion amount: 3221225472 bytes]
> 2015-08-11T08:23:02.219+0200: 7.630: [GC pause (G1 Evacuation Pause) (young)
> Desired survivor size 16777216 bytes, new threshold 15 (max 15)
>   7.631: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 0, predicted base time: 10.00 ms, remaining time: 240.00 ms, target pause time: 250.00 ms]
>   7.631: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 9 regions, survivors: 0 regions, predicted young region time: 3626.58 ms]
>   7.631: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 9 regions, survivors: 0 regions, old: 0 regions, predicted pause time: 3636.58 ms, target pause time: 250.00 ms]
> 7.642: [SoftReference, 0 refs, 0.0006965 secs]7.643: [WeakReference, 40 refs, 0.0003039 secs]7.643: [FinalReference, 3477 refs, 0.0036191 secs]7.647: [PhantomReference, 0 refs, 0 refs, 0.0006649 secs]7.647: [JNI Weak Reference, 0.0000119 secs], 0.0173298 secs]