race condition in GC logs

[charlie hunt]

Hi Bengt,

Do you know if this change back ported to JDK 8 ?

I see Kirk’s example shows a version string of:
Java HotSpot(TM) 64-Bit Server VM (25.51-b03) for linux-amd64 JRE (1.8.0_51-b16)

Also, as Eric (Caspole) observed, there is no # of processed JNI Weak References reported too. That observation is what led us to believe it may be a printing race condition.

thanks,

charlie

> On Aug 18, 2015, at 7:39 AM, Bengt Rutisson <bengt.rutisson at oracle.com> wrote:
> 
> 
> 
> On 2015-08-18 12:47, Bengt Rutisson wrote:
>> 
>> 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.
> 
> Thomas was nice and created a bug report for this :)
> 
> Additional number of processed references printed with -XX:+PrintReferenceGC after JDK-8047125
> https://bugs.openjdk.java.net/browse/JDK-8133818
> 
> Bengt
> 
>> 
>> 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]
>> 
>