race condition in GC logs

[Srinivas Ramakrishna]

I've attached a webrev/patch to the ticket. Happy to offer it here for code
review if that's a better route.

thanks!
-- ramki

On Tue, Aug 25, 2015 at 12:56 PM, Srinivas Ramakrishna <ysr1729 at gmail.com>
wrote:

> -bcc/hotspot-dev
> +cc/hotspot-gc-dev
>
> I have a patch for JDK-8133818 (on JDK 8): as suggested here earlier,
> besides splitting out Cleaners, it also reports JNI wk refs by counting
> them on-the-fly much like for other Reference types.
>
> I'll attach it to the ticket once my testing completes.
>
> thanks.
> -- ramki
>
> On Wed, Aug 19, 2015 at 3:20 PM, Kirk Pepperdine <kirk at kodewerk.com>
> wrote:
>
>> Hi Bengt,
>>
>> Thanks for filing. I really didn’t consider this a bug but it seems
>> reasonable to add clarity in the log.
>>
>> — Kirk
>>
>> > On Aug 18, 2015, at 8: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]
>> >>
>> >
>>
>>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://mail.openjdk.org/pipermail/hotspot-gc-dev/attachments/20150826/2ed3d06f/attachment.htm>