Increased safepoint cleanup tasks in Java 11 (vs 8)

[coleen.phillimore at oracle.com]

On 6/5/19 9:44 AM, Vitaly Davidovich wrote:
> So after adding "cleanup" to ULF per Thomas' suggestion, I'm seeing the
> following steps taking non-zero time:
>
>     - deflating idle monitors
>     - updating inline caches
>     - compilation policy safepoint handler
>     - purging class loader data graph
>     - resizing system dictionaries
>
> So I was wrong about this being string table rehashing.

Hi, That's good because the string table rehashing should be very rare.
>
> https://github.com/openjdk/jdk11u/blob/737d8437886ad97c6ed21a25b9911c10b3886f61/src/hotspot/share/classfile/classLoaderData.hpp#L145
> suggests
> that CLDG purging is only done when using CMS.  This application isn't
> using CMS (as mentioned, it's running ParallelGC).  It'd be nice if this
> operation was entirely skipped and didn't show up in cleanup=info output.
> I haven't (yet) checked if other cleanup ops (should?) have similar
> "skipability".

Yes, the purging class loader data graph and resizing system 
dictionaries doesn't actually happen at all (or often) but the cleanup 
tasks log when they test if they should happen.  I made a small patch to 
fix this recently. https://bugs.openjdk.java.net/browse/JDK-8224119

Coleen

>
> But as Aleksey mentioned, it sounds like safepoint cleanup itself is now
> additionally predicated on monitor deflation, and not just IC buffer
> cleanup.  I'll test out his suggested (experimental) VM option.
>
> On Wed, Jun 5, 2019 at 8:52 AM Vitaly Davidovich <vitalyd at gmail.com> wrote:
>
>>
>> On Wed, Jun 5, 2019 at 8:47 AM Thomas Schatzl <thomas.schatzl at oracle.com>
>> wrote:
>>
>>> Hi,
>>>
>>> On Wed, 2019-06-05 at 08:33 -0400, Vitaly Davidovich wrote:
>>>> Hi all,
>>>>
>>> [...]
>>>> My guess would be it's SAFEPOINT_CLEANUP_STRING_TABLE_REHASH because
>>>> tiered compilation is disabled, ParallelGC is being used, and biased
>>>> locking is disabled; all of this is the same as on Java 8.  Or might
>>>> this be something else? Presumably it's something "new" in Java 11
>>>> that triggers inside
>>>>
>>> https://github.com/openjdk/jdk11u/blob/737d8437886ad97c6ed21a25b9911c10b3886f61/src/hotspot/share/runtime/safepoint.cpp#L644
>>>> Does anyone have ideas on pinpointing this further? How do I get the
>>>> precise cleanup operation to show up in the log?
>>> Given above link, considering the "TraceTime timer(name,
>>> TRACETIME_LOG(Info, safepoint, cleanup))" lines, I would try adding
>>> safepoint+cleanup=info to your log options.
>>>
>> Ah, thanks Thomas! I "saw" the "cleanup" in there too, but didn't connect
>> the dots that I had to also include that as a ULF tag (since already had
>> "safepoint").  Makes sense.  I will try.
>>
>>> Hth,
>>>    Thomas
>>>
>>>
>>>