race condition in GC logs

[Bengt Rutisson]

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